<div>Hi Ben,</div><div><br></div><div>I would bet on the same memory issues Simon mentioned. But... while you're at it would you mind trying a little experiment to share your work items through a lockfree queue rather than a TQueue?</div>
<div><br></div><div> <a href="http://hackage.haskell.org/package/lockfree-queue">http://hackage.haskell.org/package/lockfree-queue</a></div><div><br></div><div>Under some situations this can yield some benefit. But again, you didn't see workers retrying transactions so this is probably not an issue.</div>
<div><br></div> -Ryan <br><br><div class="gmail_quote">On Mon, Oct 1, 2012 at 4:18 AM, Simon Marlow <span dir="ltr"><<a href="mailto:marlowsd@gmail.com" target="_blank">marlowsd@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hi Ben,<br>
<br>
My guess would be that you're running into some kind of memory bottleneck. Three common ones are:<br>
<br>
(1) total memory bandwidth<br>
(2) cache ping-ponging<br>
(3) NUMA overheads<br>
<br>
You would run into (1) if you were using an allocation area size (-A or -H) larger than the L2 cache. Your stats seem to indicate that you're running with a large heap - could that be the case?<br>
<br>
(2) happens if you share data a lot between cores. It can also happen if the RTS shares data between cores, but I've tried to squash as much of that as I can.<br>
<br>
(3) is sadly something that happens on these large AMD machines (and to some extent large multicore Intel boxes too). Improving our NUMA support is something we really need to do. NUMA overheads tend to manifest as very unpredictable runtimes.<br>
<br>
I suggest using perf to gather some low-level stats about cache misses and suchlike.<br>
<br>
<a href="http://hackage.haskell.org/trac/ghc/wiki/Debugging/LowLevelProfiling/Perf" target="_blank">http://hackage.haskell.org/<u></u>trac/ghc/wiki/Debugging/<u></u>LowLevelProfiling/Perf</a><br>
<br>
Cheers,<br>
Simon<div class="HOEnZb"><div class="h5"><br>
<br>
<br>
On 29/09/2012 07:47, Ben Gamari wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Simon Marlow <<a href="mailto:marlowsd@gmail.com" target="_blank">marlowsd@gmail.com</a>> writes:<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
On 28/09/12 17:36, Ben Gamari wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Unfortunately, after poking around I found a few obvious problems with<br>
both the code and my testing configuration which explained the<br>
performance drop. Things seem to be back to normal now. Sorry for the<br>
noise! Great job on the new codegen.<br>
</blockquote>
<br>
That's good to hear, thanks for letting me know!<br>
<br>
</blockquote>
Of course!<br>
<br>
That being said, I have run in to a bit of a performance issue which<br>
could be related to the runtime system. In particular, as I scale up in<br>
thread count (from 6 up to 48, the core count of the machine) in my<br>
program[1] (test data available), I'm seeing the total runtime increase,<br>
as well as a corresponding increase in CPU-seconds used. This despite<br>
the RTS claiming consistently high (~94%) productivity. Meanwhile<br>
Threadscope shows that nearly all of my threads are working busily with<br>
very few STM retries and no idle time. This in an application which<br>
should scale reasonably well (or so I believe). Attached below you will<br>
find a crude listing of various runtime statistics over a variety of<br>
thread counts (ranging into what should probably be regarded as the<br>
absurdly large).<br>
<br>
The application is a parallel Gibbs sampler for learning probabilistic<br>
graphical models. It involves a set of worker threads (updateWorkers)<br>
pulling work units off of a common TQueue. After grabbing a work unit,<br>
the thread will read a reference to the current global state from an<br>
IORef. It will then begin a long-running calculation, resulting in a<br>
small value (forced to normal form with deepseq) which it then<br>
communicates back to a global update thread (diffWorker) in the form of<br>
a lambda through another TQueue. The global update thread then maps the<br>
global state (the same as was read from the IORef earlier) through this<br>
lambda with atomicModifyIORef'. This is all implemented in [2].<br>
<br>
I do understand that I'm asking a lot of the language and I have been<br>
quite impressed by how well Haskell and GHC have stood up to the<br>
challenge thusfar. That being said, the behavior I'm seeing seems a bit<br>
strange. If synchronization overhead were the culprit, I'd expect to<br>
observe STM retries or thread blocking, which I do not see (by eye it<br>
seems that STM retries occur on the order of 5/second and worker threads<br>
otherwise appear to run uninterrupted except for GC; GHC event log<br>
from a 16 thread run available here[3]). If GC were the problem, I would<br>
expect this to be manifested in the productivity, which it is clearly<br>
not. Do you have any idea what else might be causing such extreme<br>
performance degradation with higher thread counts? I would appreciate<br>
any input you would have to offer.<br>
<br>
Thanks for all of your work!<br>
<br>
Cheers,<br>
<br>
- Ben<br>
<br>
<br>
[1] <a href="https://github.com/bgamari/bayes-stack/v2" target="_blank">https://github.com/bgamari/<u></u>bayes-stack/v2</a><br>
[2] <a href="https://github.com/bgamari/bayes-stack/blob/v2/BayesStack/Core/Gibbs.hs" target="_blank">https://github.com/bgamari/<u></u>bayes-stack/blob/v2/<u></u>BayesStack/Core/Gibbs.hs</a><br>
[3] <a href="http://goldnerlab.physics.umass.edu/~bgamari/RunCI.eventlog" target="_blank">http://goldnerlab.physics.<u></u>umass.edu/~bgamari/RunCI.<u></u>eventlog</a><br>
<br>
<br>
<br>
Performance of Citation Influence model on lda-handcraft data set<br>
1115 arcs, 702 nodes, 50 items per node average<br>
100 sweeps in blocks of 10, 200 topics<br>
Running with +RTS -A1G<br>
ghc-7.7 9c15249e082642f9c4c0113133afd7<u></u>8f07f1ade2<br>
<br>
Cores User time (s) Walltime (s) CPU % Productivity<br>
====== ============= ============= ====== =============<br>
2 488.66 269.41 188% 93.7%<br>
3 533.43 195.28 281% 94.1%<br>
4 603.92 166.94 374% 94.3%<br>
5 622.40 138.16 466% 93.8%<br>
6 663.73 123.00 558% 94.2%<br>
7 713.96 114.17 647% 94.0%<br>
8 724.66 101.98 736% 93.7%<br>
9 802.75 100.59 826% .<br>
10 865.05 97.69 917% .<br>
11 966.97 99.09 1010% .<br>
12 1238.42 114.28 1117%<br>
13 1242.43 106.53 1206%<br>
14 1428.59 112.48 1310%<br>
15 1299.40 97.52 1387%<br>
16 1559.99 108.86 1481%<br>
17 1972.02 126.49 1604%<br>
18 2157.03 130.91 1696%<br>
19 1966.24 115.29 1770% .<br>
20 2693.64 146.76 1887% .<br>
21 3051.16 158.48 1990% .<br>
22 4100.88 199.18 2109% 93.7%<br>
23 4156.94 193.38 2201% 93.5%<br>
24 4780.46 212.13 2303% 94.3%<br>
25 5733.64 242.78 2407% .<br>
26 7806.47 313.92 2526% .<br>
27 6368.32 249.65 2596% .<br>
28 8563.18 320.26 2717%<br>
<br>
<br>
<br>
-sstderr output from 2 cores:<br>
==============================<u></u>========<br>
<br>
214,358,463,960 bytes allocated in the heap<br>
2,261,367,592 bytes copied during GC<br>
71,053,384 bytes maximum residency (7 sample(s))<br>
2,077,816 bytes maximum slop<br>
2299 MB total memory in use (0 MB lost due to fragmentation)<br>
<br>
Tot time (elapsed) Avg pause Max pause<br>
Gen 0 100 colls, 100 par 28.58s 14.27s 0.1427s 0.3345s<br>
Gen 1 7 colls, 6 par 3.36s 1.74s 0.2486s 0.3241s<br>
<br>
Parallel GC work balance: 25.06% (serial 0%, perfect 100%)<br>
<br>
TASKS: 4 (1 bound, 3 peak workers (3 total), using -N2)<br>
<br>
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)<br>
<br>
INIT time 0.03s ( 0.03s elapsed)<br>
MUT time 474.28s (252.98s elapsed)<br>
GC time 31.94s ( 16.01s elapsed)<br>
EXIT time 0.12s ( 0.12s elapsed)<br>
Total time 506.49s (269.26s elapsed)<br>
<br>
Alloc rate 451,969,681 bytes per MUT second<br>
<br>
Productivity 93.7% of total user, 176.2% of total elapsed<br>
<br>
gc_alloc_block_sync: 108391<br>
whitehole_spin: 0<br>
gen[0].sync: 7392<br>
gen[1].sync: 97126<br>
<br>
<br>
<br>
-sstderr output from 24 cores:<br>
==============================<u></u>=========<br>
<br>
262,335,150,000 bytes allocated in the heap<br>
1,323,818,912 bytes copied during GC<br>
67,648,048 bytes maximum residency (7 sample(s))<br>
2,927,176 bytes maximum slop<br>
25172 MB total memory in use (0 MB lost due to fragmentation)<br>
<br>
Tot time (elapsed) Avg pause Max pause<br>
Gen 0 29 colls, 29 par 162.40s 6.77s 0.2335s 0.3469s<br>
Gen 1 7 colls, 6 par 118.34s 5.32s 0.7600s 1.2448s<br>
<br>
Parallel GC work balance: 5.61% (serial 0%, perfect 100%)<br>
<br>
TASKS: 27 (1 bound, 26 peak workers (26 total), using -N24)<br>
<br>
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)<br>
<br>
INIT time 0.34s ( 0.34s elapsed)<br>
MUT time 4606.75s (197.59s elapsed)<br>
GC time 280.74s ( 12.09s elapsed)<br>
EXIT time 0.40s ( 0.40s elapsed)<br>
Total time 4888.61s (210.80s elapsed)<br>
<br>
Alloc rate 56,945,837 bytes per MUT second<br>
<br>
Productivity 94.3% of total user, 2185.8% of total elapsed<br>
<br>
gc_alloc_block_sync: 5397994<br>
whitehole_spin: 0<br>
gen[0].sync: 32282<br>
gen[1].sync: 5072<br>
<br>
</blockquote>
<br>
<br>
______________________________<u></u>_________________<br>
Glasgow-haskell-users mailing list<br>
<a href="mailto:Glasgow-haskell-users@haskell.org" target="_blank">Glasgow-haskell-users@haskell.<u></u>org</a><br>
<a href="http://www.haskell.org/mailman/listinfo/glasgow-haskell-users" target="_blank">http://www.haskell.org/<u></u>mailman/listinfo/glasgow-<u></u>haskell-users</a><br>
</div></div></blockquote></div><br>