"All-threads allocating garbage" Multithreading Benchmark shows significant slowdown as nthreads increases

[NHDaly]

The https://github.com/RelationalAI-oss/MultithreadingBenchmarks.jl package contains benchmarking experiments we've written to measure performance scaling for the new experimental cooperative multithreading introduced in Julia v1.3.

I'm opening this issue to discuss surprising results from our "all-threads allocating garbage" experiment, detailed here:
RelationalAI-oss/MultithreadingBenchmarks.jl#3

In that benchmark, we @spawn 1000 "queries", each of which perform work(...), which performs 1e6 multiplications in a type-unstable way, causing O(1e6) allocations.

The experiment then runs this benchmark with increasing values for JULIA_NUM_THREADS= to measure the performance scaling on the benchmark as julia has more threads. The experiment was run on a 48-core (96-vCPU) machine, though the results are similar on my local 6-core laptop.

The experiment shows that, surprisingly, total time increases as the number of threads increases, despite the total work remaining constant (number of queries handled, number of allocations, and total memory allocated):

This seems to be explained by two factors, as outlined in the linked results:

Notice that there seem to be two causes of the increase in time for each addition of threads:

1. The gc_time is increasing in each run, until we hit nthreads > number of physical cores. After that, the gc_time drops to 0, presumably because the GC never gets run at all. This is one surprise: we would expect the GC time to remain constant, since the number of allocations and size of allocated memory remain constant.
2. The latency for every individual query is increasing in each run -- even though the gc_time drops to 0 between 48 threads and 72 threads. So this increase is (at least in part) independent of the increase in gc_time.

So the GC time is actually taking longer as you add threads, even though there's the same amount of work to do, and also something else is also taking longer as you add threads (maybe the allocation), even though there's the same amount of work to do.

@staticfloat and I have noticed via profiling (detailed in: RelationalAI-oss/MultithreadingBenchmarks.jl#3 (comment)) that the profiles spend increasing amounts of time in jl_mutex_wait as the number of threads increase.
It's not clear to me whether the profiles reflect GC time or not.

---

To summarize:

This benchmark is getting slower when adding threads, which is surprising. Even if garbage collection / allocation acquired a single global lock, forcing everything to run serially, I would still expect near constant time as you add threads. Instead, the time increases linearly, with a slope greater than 1. So this seems like maybe a bug somewhere?

[staticfloat]

To be a little more specific on the jl_mutex_wait(), it appears that a very large chunk of time is spent right here:

julia/src/jltypes.c

Line 1096 in 050160c

JL_LOCK(&typecache_lock); // Might GC

I don't know this code well enough to know why we need to lock the typecache when constructing datatypes; it seems to me that the fast path should be that the type is already in the typecache, so we need read-only access, but I don't actually know how this works.

[StefanKarpinski]

@vtjnash, @JeffBezanson: could the lock be put only on the case where the typecache actually needs to be modified?

[JeffBezanson]

Could you provide instructions for running this?

Yes, it looks like the typecache lock scope could be narrowed somehow.

[NHDaly]

Could you provide instructions for running this?

Oops, sorry! Yep i've just added them to the readme: https://github.com/RelationalAI-oss/MultithreadingBenchmarks.jl/blob/master/README.md

But basically you can just run Pkg.test() on the MultithreadingBenchmarks package to run the benchmarks in the current configuration. Annoyingly, right now you have to edit the configuration in the test/runbench.jl file if you want to make changes, or you can just call the functions in that file yourself at the REPL.

[NHDaly]

Also, I should have included this earlier, but if you want to explore them i've just added the complete pprof profile files to the experiment results page:

The complete profiles themselves are here, which you can view interactly in PProf.jl via PProf.refresh(file="..."):
profiles-all-threads-1-2-6-threads.zip

[robsmith11]

I've experienced this effect (poor scaling with Threads relative to Distributed) with some of my GC-heavy projects as well, but obviously not as dramatic as in the extreme case tested here.

[benhamad]

We're still facing this when scaling the number of threads. We're producing a constant amount of garbage for the whole program independently from the number of threads.

As you can see, the time we spend doing gc scale with the number of threads.

[jpsamaroo]

Just taking a guess here from limited understanding of the GC, but maybe it's possible that the amount of time spent waiting to stop all threads is simply increasing because we're having to reach more GC safepoints per GC cycle as the number of threads increases?

[benhamad]

@jpsamaroo Indeed that was our understanding as well for the second chart that I posted above! But for the first one we're measuring wall-time. Which shouldn't (at least my assumption) increase because we're still doing the same amount of work (collecting garbage).

[jpsamaroo]

Hitting all GC safepoints shouldn't have to do with how much garbage you're generating, but instead what code you're running. If you're in a ccall, you can't hit a GC safepoint, because they only exist in Julia code. So if a thread is stuck on a 5 second ccall when another thread decides it needs to do a GC cycle, we have to wait at least 5 seconds for the ccall-ing thread to return before it could hit a safepoint and thus be ready to "contribute" to the GC cycle (where contribute currently just means go to sleep).

[NHDaly]

@jpsamaroo Hrmm, seems plausible, but like @Chakerbh was saying, i don't really see how that alone could make it slower than running with only a single thread. If all-but-one of your threads are blocked waiting for GC, at worst it should slow down to approximately the single-threaded performance, right? Since there's always one thread making progress, which is exactly the thing that's starving the GC in your proposed explanation?