All threads allocating parallelism scaling experiment

[NHDaly]

This experiment is testing how multithreaded performance scales with CPUs if all tasks allocate and produce garbage that needs to be garbage collected.

In this test, we issue a number of queries, all of which allocate and immediately discard memory during their computation. This causes contention since, currently, (I think) garbage collection pauses all allocations.

This experiment lives here:
bench/all_tasks_allocating.jl

Tracking issue: #1

EDIT: Julia repo discussion issue: JuliaLang/julia#33033

[NHDaly]

Results from benchmark:

Full output from 96 vCPU machine (r5d.24xlarge) at bae621b:
https://gist.github.com/rai-nhdaly/da9f522eea01ea320a83c8192236f374

The answer is, not surprisingly, that it does not scale at all. But in fact, surprisingly, adding more cores makes the task run slower, not remaining constant as one might expect from full contention!

You'll notice that the speedup chart is empty, because the numbers are all negative:

This plot shows the absolute time that each run took, which is increasing for each thread added. Note that in this plot, higher values are bad -- they're slower.

Below are the complete results for this experiment:

Results (omitted printing latencies column):
5×6 DataFrames.DataFrame
│ Row │ nthreads │ time_secs │ allocs   │ memory     │ gctime_secs │ thread_counts                                                                                                                                                                                                                                                                                                                                                                               │
│     │ Int64    │ Float64   │ Int64    │ Int64      │ Float64     │ Array{Int64,1}                                                                                                                                                                                                                                                                                                                                                                              │
├─────┼──────────┼───────────┼──────────┼────────────┼─────────────┼─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ 1   │ 1        │ 6.5724    │ 30007507 │ 2240817296 │ 0.0389597   │ [1000]                                                                                                                                                                                                                                                                                                                                                                                      │
│ 2   │ 24       │ 38.1511   │ 30008062 │ 2240826528 │ 7.70597     │ [41, 41, 41, 41, 37, 41, 37, 37, 41, 47, 41, 43, 46, 41, 47, 41, 41, 37, 43, 42, 46, 46, 41, 41]                                                                                                                                                                                                                                                                                            │
│ 3   │ 48       │ 64.3176   │ 30008040 │ 2240826624 │ 15.8991     │ [21, 21, 22, 21, 20, 22, 19, 20, 20, 19, 22, 21, 23, 21, 22, 20, 20, 21, 20, 20, 19, 22, 22, 22, 23, 22, 21, 18, 19, 17, 22, 21, 20, 21, 18, 21, 21, 20, 22, 21, 23, 22, 23, 21, 22, 22, 20, 20]                                                                                                                                                                                            │
│ 4   │ 72       │ 55.573    │ 30008032 │ 2240826848 │ 0.0         │ [11, 12, 11, 16, 20, 12, 19, 17, 18, 13, 17, 20, 11, 13, 12, 18, 12, 18, 18, 18, 12, 18, 18, 11, 11, 17, 11, 11, 13, 19, 12, 19, 12, 11, 12, 19, 12, 11, 11, 13, 13, 11, 12, 18, 12, 20, 18, 17, 11, 13, 12, 11, 12, 10, 11, 20, 11, 18, 11, 13, 18, 11, 13, 12, 11, 13, 12, 11, 11, 11, 13, 11]                                                                                            │
│ 5   │ 96       │ 62.7971   │ 30008035 │ 2240827344 │ 0.0         │ [10, 12, 11, 11, 11, 10, 11, 10, 10, 10, 10, 10, 11, 11, 11, 11, 10, 12, 10, 11, 11, 10, 12, 11, 11, 11, 10, 11, 10, 10, 11, 10, 9, 10, 10, 10, 12, 10, 11, 10, 10, 10, 10, 9, 10, 12, 10, 10, 10, 10, 12, 10, 12, 10, 10, 12, 9, 10, 9, 9, 10, 10, 10, 12, 11, 10, 11, 10, 10, 10, 10, 10, 11, 11, 10, 10, 10, 10, 10, 12, 10, 10, 10, 10, 10, 10, 10, 12, 10, 10, 10, 12, 10, 10, 11, 10] │
Processed:
5×6 DataFrames.DataFrame
│ Row │ nthreads │ time_secs │ speedup_factor │ marginal_speedup │ utilization │ latency_quantiles_ms                                                  │
│     │ Int64    │ Float64   │ Float64        │ Float64          │ Float64     │ Tuple…                                                                │
├─────┼──────────┼───────────┼────────────────┼──────────────────┼─────────────┼───────────────────────────────────────────────────────────────────────┤
│ 1   │ 1        │ 6.5724    │ 1.0            │ 1.0              │ 1.0         │ (0.1=>6.40091, 0.5=>6.55782, 0.9=>6.60541, 0.99=>7.4244, 1=>8.1062)   │
│ 2   │ 24       │ 38.1511   │ 0.172273       │ -0.0359881       │ 0.00717805  │ (0.1=>655.433, 0.5=>740.248, 0.9=>825.405, 0.99=>4604.75, 1=>4687.0)  │
│ 3   │ 48       │ 64.3176   │ 0.102187       │ -0.00292027      │ 0.00212889  │ (0.1=>2147.38, 0.5=>2320.23, 0.9=>2591.33, 0.99=>18357.2, 1=>18700.6) │
│ 4   │ 72       │ 55.573    │ 0.118266       │ 0.000669972      │ 0.00164258  │ (0.1=>2819.2, 0.5=>4391.8, 0.9=>5093.33, 0.99=>5375.65, 1=>5513.55)   │
│ 5   │ 96       │ 62.7971   │ 0.104661       │ -0.000566884     │ 0.00109022  │ (0.1=>5283.95, 0.5=>6078.71, 0.9=>6555.81, 0.99=>6826.54, 1=>6948.68) │

Analysis

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.

Extras

Finally, here is the additional plot output from this run:

[NHDaly]

I also collected some CPU profiles for this experiment running on my local machine for various nthreads:

NOTE: these profiles were collected via Profile.@profile and displayed via https://github.com/vchuravy/PProf.jl.

---

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

---

With NTHREADS=1:

With NTHREADS=2:

With NTHREADS=6:

The main, obvious takeaway is that as nthreads increases, we spend increasing percentage of time in jl_mutex_wait.

GC Time?

It's not clear to me if these profiles reflect the GC time. Was GC happening here? And if so, was it picked up by our profile?

EDIT: It does seem like the GC is happening during the @profiled code, but I'm just not sure if somehow Profile is not measuring it, or filtering it?:

julia> PProf.clear(); Profile.@profile @time main(n, N); PProf.pprof(out="profile-all-threads-alloc-1thread.pb.gz")
  9.098085 seconds (30.01 M allocations: 2.087 GiB, 10.46% gc time)
"profile-all-threads-alloc-1thread.pb.gz"

EDIT2: Okay the documentation seems to say that yes, garbage collection should be reflected here. So it must be in this graph somewhere:

(Since Julia's garbage collector is written in C, such events can be detected using the C=true output mode described below, or by using ProfileView.jl.)

[NHDaly]

This is being discussed here:
JuliaLang/julia#33033

My understanding is that optimizing multithreading for this kind of "slow code" hasn't been a priority so far. Instead, they've been focusing on making fast code faster.

[dpinol]

Hi,
the link to the experiment code is broken:

This experiment lives here: src/bench/all_tasks_allocating.jl

[NHDaly]

Thanks, fixed