Thanks for the reply, I haven't actually tried threadscope yet, I will have a look at that tomorrow at some point. I also had no idea you could use valgrind on haskell programs, so I will look into that as well. <div><br>
</div><div>I think the program certainly does have problems scaling, since I made a very basic attempt at parallelism that wasn't dividing the work equally (although this was because in an early version of the program, this seemed to work better than dividing the work more finely and evenly, possibly because of the issue with parallel GC I mention below...)</div>
<div><br></div><div>I just changed the code to split the work into smaller chunks and more evenly, using Control.Parallel, and it seems much better -- conditional on one thing. If I switch off the parallel GC by setting -qg, my code suddenly runs much faster and outperforms the sequential version, coming in at around 20 seconds walltime, and spends only 1% of its time on GC. top seems to be sitting at around 800%. I can post the output from +RTS -s as well if that would help.</div>
<div><br></div><div>The only problem is that now I am getting random occasional segmentation faults that I was not been getting before, and once got a message saying:</div><div><font face="'courier new', monospace">Main: schedule: re-entered unsafely</font></div>
<div><font face="'courier new', monospace">Perhaps a 'foreign import unsafe' should be 'safe'?</font></div><div>I think this may be something to do with creating a lot of sparks though, since this occurs whether I have the parallel GC on or not.</div>
<div><br></div><div>But it also seems that turning on the parallel GC makes the fine grained parallel code, which is creating around 1,000,000 sparks, and outperforms the sequential version if I turn off parallel GC, run much slower (260s walltime) than the coarse grained parallel code (50,000 sparks, 82s walltime). I think this is what led me to originally use the coarse grained parallel version that divides the work unequally.</div>
<div><br></div><div>I imagine there is still some room for improvement, since 20s is only about 3 times faster than the sequential version, but I think that is more an issue of me being something of a novice haskell programmer! It does seem to me like there is something very strange going on with the GC though. </div>
<div><br></div><div>Unfortunately the code is for a paper (nothing to do with computer science or haskell incidentally), and although I'm planning on open sourcing it, I can't do that until the paper is published.</div>
<div><br></div><div>thanks again</div><div><br></div><div>Tom<br><br><div class="gmail_quote">On Wed, Oct 5, 2011 at 9:36 PM, Ryan Newton <span dir="ltr"><<a href="mailto:rrnewton@gmail.com">rrnewton@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 Tom,<div><br></div><div>I think debugging this sort of problem is exactly what we need to be doing (and making easier). Have you tried Duncan's newest version of Threadscope by the way?<br>
<br>It looks like -- completely aside from the GC time -- this program is not scaling. The mutator time itself, disregarding GC, isn't going down much with parallelism (with the total mutator time increasing drastically). Either this is completely memory bottlenecked or there is some other kind of bad interaction (e.g. false sharing, contention on a hot lock, etc).</div>
<div><br></div><div>My inclination would be to figure this out first before worrying about the GC time. Is this code that you would be able to share for debugging?</div><div><br></div><div>I think we need to get together some general documentation on how to debug this kind of problem. For example, you can get some hints as to the memory behavior by running valgrind/cachegrind on the program. Also, what does "top" say, by the way? Is the process using 1200% CPU?</div>
<div><br></div><div>Cheers,</div><div> -Ryan</div><div><br></div><div><br></div>
<div><br></div><div><br><div class="gmail_quote"><div><div></div><div class="h5">On Wed, Oct 5, 2011 at 2:15 PM, Tom Thorne <span dir="ltr"><<a href="mailto:thomas.thorne21@gmail.com" target="_blank">thomas.thorne21@gmail.com</a>></span> wrote:<br>
</div></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div></div><div class="h5">
<div>I am having some strange performance issues when using SMP parallelism, that I think may be something to do with GC. Apologies for the large readouts below but I'm not familiar enough to know what is and isn't relevant!</div>
<div><br></div><div>I have a pure function that is mapped over a list of around 10 values, and this happens several times for each iteration of my program. It does some fairly intensive calculations using hmatrix, generating intermediate matrices along the way. The computation is significantly more complex for some values, so the work done by each call is not spread equally. I did some profiling and it seems like the program is spending about 50% of its time in that function. First of all, without any attempts at parallelism, I see this from ./Main +RTS -s</div>
<div><br></div><div><div> <font face="'courier new', monospace">67,142,126,336 bytes allocated in the heap</font></div><div><font face="'courier new', monospace"> 147,759,264 bytes copied during GC</font></div>
<div><font face="'courier new', monospace"> 109,384 bytes maximum residency (58 sample(s))</font></div><div><font face="'courier new', monospace"> 354,408 bytes maximum slop</font></div>
<div><font face="'courier new', monospace"> 3 MB total memory in use (0 MB lost due to fragmentation)</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> Generation 0: 104551 collections, 0 parallel, 1.13s, 1.11s elapsed</font></div><div><font face="'courier new', monospace"> Generation 1: 58 collections, 0 parallel, 0.01s, 0.01s elapsed</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> Parallel GC work balance: -nan (0 / 0, ideal 1)</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> MUT time (elapsed) GC time (elapsed)</font></div>
<div><font face="'courier new', monospace"> Task 0 (worker) : 0.00s ( 67.06s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 1 (worker) : 0.00s ( 67.09s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 2 (bound) : 66.95s ( 67.09s) 1.14s ( 1.12s)</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> SPARKS: 0 (0 converted, 0 pruned)</font></div><div><font face="'courier new', monospace"><br></font></div>
<div><font face="'courier new', monospace"> INIT time 0.00s ( 0.00s elapsed)</font></div><div><font face="'courier new', monospace"> MUT time 66.95s ( 67.09s elapsed)</font></div>
<div><font face="'courier new', monospace"> GC time 1.14s ( 1.12s elapsed)</font></div><div><font face="'courier new', monospace"> EXIT time 0.00s ( 0.00s elapsed)</font></div>
<div><font face="'courier new', monospace"> Total time 68.09s ( 68.21s elapsed)</font></div><div><font face="'courier new', monospace"><br></font></div>
<div><font face="'courier new', monospace"> %GC time 1.7% (1.6% elapsed)</font></div><div><font face="'courier new', monospace"><br></font></div><div>
<font face="'courier new', monospace"> Alloc rate 1,002,835,517 bytes per MUT second</font></div><div><font face="'courier new', monospace"><br></font></div>
<div><font face="'courier new', monospace"> Productivity 98.3% of total user, 98.2% of total elapsed</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace">gc_alloc_block_sync: 0</font></div><div><font face="'courier new', monospace">whitehole_spin: 0</font></div>
<div><font face="'courier new', monospace">gen[0].sync_large_objects: 0</font></div><div><font face="'courier new', monospace">gen[1].sync_large_objects: 0</font></div>
</div><div><br></div><div>This looks ok to me...</div><div><br></div><div><font face="arial, helvetica, sans-serif">Then if I try to use Control.Parallel to parallelise my code, simpy replacing a map with parMap (rdeepseq), on a 12 core machine using +RTS -N12 -s I get this:</font></div>
<div><font face="arial, helvetica, sans-serif"><br></font></div><div><div><font face="'courier new', monospace"> 66,065,148,144 bytes allocated in the heap</font></div>
<div><font face="'courier new', monospace"> 197,202,056 bytes copied during GC</font></div><div><font face="'courier new', monospace"> 181,312 bytes maximum residency (251 sample(s))</font></div>
<div><font face="'courier new', monospace"> 387,240 bytes maximum slop</font></div><div><font face="'courier new', monospace"> 12 MB total memory in use (3 MB lost due to fragmentation)</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> Generation 0: 37592 collections, 37591 parallel, 245.32s, 26.67s elapsed</font></div>
<div><font face="'courier new', monospace"> Generation 1: 251 collections, 251 parallel, 3.12s, 0.33s elapsed</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> Parallel GC work balance: 2.41 (24219609 / 10058220, ideal 12)</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> MUT time (elapsed) GC time (elapsed)</font></div><div><font face="'courier new', monospace"> Task 0 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 1 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 2 (worker) : 0.00s ( 17.97s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 3 (worker) : 0.00s ( 19.35s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 4 (worker) : 0.00s ( 40.28s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 5 (worker) : 0.00s ( 45.08s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 6 (worker) : 0.00s ( 47.06s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 7 (worker) : 18.30s ( 49.73s) 16.24s ( 1.71s)</font></div><div><font face="'courier new', monospace"> Task 8 (worker) : 0.00s ( 51.22s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 9 (worker) : 0.00s ( 53.75s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 10 (worker) : 0.00s ( 54.17s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 11 (worker) : 5.65s ( 54.30s) 0.70s ( 0.08s)</font></div><div><font face="'courier new', monospace"> Task 12 (worker) : 0.00s ( 54.41s) 0.41s ( 0.04s)</font></div>
<div><font face="'courier new', monospace"> Task 13 (worker) : 4.34s ( 54.58s) 4.50s ( 0.48s)</font></div><div><font face="'courier new', monospace"> Task 14 (worker) : 5.82s ( 54.76s) 5.91s ( 0.64s)</font></div>
<div><font face="'courier new', monospace"> Task 15 (worker) : 6.50s ( 55.01s) 3.37s ( 0.38s)</font></div><div><font face="'courier new', monospace"> Task 16 (worker) : 7.60s ( 55.21s) 8.56s ( 0.94s)</font></div>
<div><font face="'courier new', monospace"> Task 17 (worker) : 11.05s ( 55.21s) 9.04s ( 0.96s)</font></div><div><font face="'courier new', monospace"> Task 18 (worker) : 11.75s ( 55.21s) 12.94s ( 1.43s)</font></div>
<div><font face="'courier new', monospace"> Task 19 (worker) : 16.02s ( 55.21s) 13.32s ( 1.43s)</font></div><div><font face="'courier new', monospace"> Task 20 (worker) : 26.98s ( 55.23s) 7.43s ( 0.77s)</font></div>
<div><font face="'courier new', monospace"> Task 21 (worker) : 7.36s ( 55.23s) 7.47s ( 0.83s)</font></div><div><font face="'courier new', monospace"> Task 22 (worker) : 16.08s ( 55.23s) 10.25s ( 1.12s)</font></div>
<div><font face="'courier new', monospace"> Task 23 (worker) : 7.04s ( 55.23s) 4.99s ( 0.57s)</font></div><div><font face="'courier new', monospace"> Task 24 (worker) : 28.47s ( 55.23s) 8.78s ( 0.94s)</font></div>
<div><font face="'courier new', monospace"> Task 25 (worker) : 7.43s ( 55.23s) 1.62s ( 0.18s)</font></div><div><font face="'courier new', monospace"> Task 26 (worker) : 6.33s ( 55.23s) 11.42s ( 1.23s)</font></div>
<div><font face="'courier new', monospace"> Task 27 (worker) : 9.80s ( 55.23s) 8.72s ( 0.95s)</font></div><div><font face="'courier new', monospace"> Task 28 (worker) : 4.88s ( 55.26s) 8.92s ( 0.99s)</font></div>
<div><font face="'courier new', monospace"> Task 29 (worker) : 0.00s ( 55.26s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 30 (bound) : 5.59s ( 55.26s) 0.59s ( 0.06s)</font></div>
<div><font face="'courier new', monospace"> Task 31 (worker) : 41.16s ( 55.26s) 3.48s ( 0.38s)</font></div><div><font face="'courier new', monospace"> Task 32 (worker) : 17.03s ( 55.26s) 3.90s ( 0.42s)</font></div>
<div><font face="'courier new', monospace"> Task 33 (worker) : 14.89s ( 55.26s) 5.29s ( 0.58s)</font></div><div><font face="'courier new', monospace"> Task 34 (worker) : 6.30s ( 55.26s) 1.99s ( 0.21s)</font></div>
<div><font face="'courier new', monospace"> Task 35 (worker) : 16.13s ( 55.26s) 13.95s ( 1.50s)</font></div><div><font face="'courier new', monospace"> Task 36 (worker) : 16.70s ( 55.26s) 13.02s ( 1.41s)</font></div>
<div><font face="'courier new', monospace"> Task 37 (worker) : 11.68s ( 55.26s) 15.45s ( 1.68s)</font></div><div><font face="'courier new', monospace"> Task 38 (worker) : 7.65s ( 55.26s) 13.61s ( 1.50s)</font></div>
<div><font face="'courier new', monospace"> Task 39 (worker) : 14.18s ( 55.26s) 12.48s ( 1.35s)</font></div><div><font face="'courier new', monospace"> Task 40 (worker) : 5.51s ( 55.26s) 11.92s ( 1.31s)</font></div>
<div><font face="'courier new', monospace"> Task 41 (worker) : 3.10s ( 55.26s) 8.17s ( 0.93s)</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> SPARKS: 42525 (37707 converted, 519 pruned)</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> INIT time 0.00s ( 0.00s elapsed)</font></div><div><font face="'courier new', monospace"> MUT time 365.55s ( 55.26s elapsed)</font></div>
<div><font face="'courier new', monospace"> GC time 248.45s ( 27.00s elapsed)</font></div><div><font face="'courier new', monospace"> EXIT time 0.00s ( 0.00s elapsed)</font></div>
<div><font face="'courier new', monospace"> Total time 614.01s ( 82.26s elapsed)</font></div><div><font face="'courier new', monospace"><br></font></div>
<div><font face="'courier new', monospace"> %GC time 40.5% (32.8% elapsed)</font></div><div><font face="'courier new', monospace"><br></font></div><div>
<font face="'courier new', monospace"> Alloc rate 180,724,403 bytes per MUT second</font></div><div><font face="'courier new', monospace"><br></font></div>
<div><font face="'courier new', monospace"> Productivity 59.5% of total user, 444.4% of total elapsed</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace">gc_alloc_block_sync: 1339708</font></div><div><font face="'courier new', monospace">whitehole_spin: 36</font></div>
<div><font face="'courier new', monospace">gen[0].sync_large_objects: 197621</font></div><div><font face="'courier new', monospace">gen[1].sync_large_objects: 6396</font></div>
</div><div><font face="'courier new', monospace"><br></font></div><div><font face="arial, helvetica, sans-serif">It seems like suddenly GC is taking a lot longer.</font></div>
<div><font face="arial, helvetica, sans-serif"><br></font></div><div><font face="arial, helvetica, sans-serif">I also tried using Control.Monad.Par, with runPar $ do parMap, and using +RTS -N12 -s I get this:</font></div>
<div><div style="font-family:arial, helvetica, sans-serif"> </div><div><font face="'courier new', monospace">71,480,561,920 bytes allocated in the heap</font></div><div><font face="'courier new', monospace"> 275,752,912 bytes copied during GC</font></div>
<div><font face="'courier new', monospace"> 198,704 bytes maximum residency (343 sample(s))</font></div><div><font face="'courier new', monospace"> 394,232 bytes maximum slop</font></div>
<div><font face="'courier new', monospace"> 12 MB total memory in use (3 MB lost due to fragmentation)</font></div><div><font face="'courier new', monospace"><br>
</font></div><div><font face="'courier new', monospace"> Generation 0: 37575 collections, 37574 parallel, 169.08s, 16.67s elapsed</font></div><div><font face="'courier new', monospace"> Generation 1: 343 collections, 343 parallel, 6.24s, 0.61s elapsed</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> Parallel GC work balance: 2.56 (33928871 / 13275450, ideal 12)</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> MUT time (elapsed) GC time (elapsed)</font></div>
<div><font face="'courier new', monospace"> Task 0 (worker) : 0.70s ( 46.46s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 1 (worker) : 2.94s ( 46.46s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 2 (worker) : 0.10s ( 46.46s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 3 (worker) : 0.06s ( 46.47s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 4 (worker) : 1.70s ( 46.47s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 5 (worker) : 0.07s ( 46.47s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 6 (worker) : 2.75s ( 46.47s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 7 (worker) : 1.21s ( 46.47s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 8 (worker) : 0.43s ( 46.47s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 9 (worker) : 10.44s ( 46.47s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 10 (worker) : 0.06s ( 46.47s) 0.00s ( 0.00s)</font></div><div><font face="'courier new', monospace"> Task 11 (worker) : 1.36s ( 46.47s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 12 (worker) : 0.00s ( 46.50s) 46.69s ( 4.63s)</font></div><div><font face="'courier new', monospace"> Task 13 (worker) : 0.00s ( 46.50s) 0.00s ( 0.00s)</font></div>
<div><font face="'courier new', monospace"> Task 14 (bound) : 0.05s ( 46.50s) 0.56s ( 0.06s)</font></div><div><font face="'courier new', monospace"> Task 15 (worker) : 24.84s ( 46.50s) 2.24s ( 0.21s)</font></div>
<div><font face="'courier new', monospace"> Task 16 (worker) : 28.00s ( 46.50s) 1.95s ( 0.19s)</font></div><div><font face="'courier new', monospace"> Task 17 (worker) : 35.30s ( 46.50s) 2.79s ( 0.27s)</font></div>
<div><font face="'courier new', monospace"> Task 18 (worker) : 29.03s ( 46.50s) 4.06s ( 0.39s)</font></div><div><font face="'courier new', monospace"> Task 19 (worker) : 32.71s ( 46.50s) 7.04s ( 0.69s)</font></div>
<div><font face="'courier new', monospace"> Task 20 (worker) : 32.74s ( 46.50s) 11.47s ( 1.09s)</font></div><div><font face="'courier new', monospace"> Task 21 (worker) : 23.35s ( 46.50s) 15.16s ( 1.49s)</font></div>
<div><font face="'courier new', monospace"> Task 22 (worker) : 36.00s ( 46.50s) 7.94s ( 0.76s)</font></div><div><font face="'courier new', monospace"> Task 23 (worker) : 0.00s ( 46.50s) 35.84s ( 3.63s)</font></div>
<div><font face="'courier new', monospace"> Task 24 (worker) : 24.70s ( 46.50s) 21.26s ( 2.06s)</font></div><div><font face="'courier new', monospace"> Task 25 (worker) : 23.07s ( 46.50s) 18.33s ( 1.82s)</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> SPARKS: 0 (0 converted, 0 pruned)</font></div><div>
<font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> INIT time 0.00s ( 0.00s elapsed)</font></div><div>
<font face="'courier new', monospace"> MUT time 307.74s ( 46.50s elapsed)</font></div><div><font face="'courier new', monospace"> GC time 175.32s ( 17.29s elapsed)</font></div>
<div><font face="'courier new', monospace"> EXIT time 0.00s ( 0.00s elapsed)</font></div><div><font face="'courier new', monospace"> Total time 483.06s ( 63.79s elapsed)</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> %GC time 36.3% (27.1% elapsed)</font></div><div>
<font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> Alloc rate 232,274,501 bytes per MUT second</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace"> Productivity 63.7% of total user, 482.4% of total elapsed</font></div>
<div><font face="'courier new', monospace"><br></font></div><div><font face="'courier new', monospace">gc_alloc_block_sync: 1619540</font></div><div><font face="'courier new', monospace">whitehole_spin: 258</font></div>
<div><font face="'courier new', monospace">gen[0].sync_large_objects: 232661</font></div><div><font face="'courier new', monospace">gen[1].sync_large_objects: 6378</font></div>
</div><div><font face="'courier new', monospace"><br></font></div><div><font face="arial, helvetica, sans-serif">This seems slightly better, but the GC time is still much bigger than I would expect it to be.</font></div>
<div><font face="arial, helvetica, sans-serif"><br></font></div><div><font face="arial, helvetica, sans-serif">I don't think it is solely because of parallel GC, since running the parallel code with +RTS -N1 gives results similar to the non-parallel version.</font></div>
<div><font face="arial, helvetica, sans-serif"><br></font></div><div><font face="arial, helvetica, sans-serif">Am I simply misunderstanding the way the GC time is represented in this output, or is there something amiss?</font></div>
<div><font face="arial, helvetica, sans-serif"><br></font></div><div><font face="arial, helvetica, sans-serif">(I also noticed that there seem to be a lot more than 12 threads running if I look at top while the program is running, but I assume this is something to do with the runtime spawning more threads for GC etc)</font></div>
<br></div></div>_______________________________________________<br>
Haskell-Cafe mailing list<br>
<a href="mailto:Haskell-Cafe@haskell.org" target="_blank">Haskell-Cafe@haskell.org</a><br>
<a href="http://www.haskell.org/mailman/listinfo/haskell-cafe" target="_blank">http://www.haskell.org/mailman/listinfo/haskell-cafe</a><br>
<br></blockquote></div><br></div>
</blockquote></div><br></div>