headers
Ben Gamari | 26 Jan 2013 01:28
Picon
Gravatar

Extended periods of "waking up thread %d on cap %d"

Recently I've been benchmarking my concurrent Gibbs sampler[1] on a
largish multicore machine. I've been using GHC HEAD due to various
GC-related fixes that are present. One thing that I've noticed in
looking over the event logs is that there are large durations (tens of
milliseconds) when HECs appear to be constantly bombarded with wake-ups
from other capabilities.

In these periods, the eventlog will be filled with blocks of messages
such as this snippet from one benchmark run[2] (long repeated blocks
marked with ellipses, a few irrelevant messages have been omitted yet
not marked, see eventlog for full log),

     28.320958s    HEC 7: running thread 293
     ...
     28.391802s    HEC 6: running thread 209
     28.392070s    HEC 6: waking up thread 284 on cap 7
     28.392302s    HEC 6: waking up thread 284 on cap 7
     28.392579s    HEC 6: waking up thread 284 on cap 7
     28.392808s    HEC 6: waking up thread 284 on cap 7
     .
     .
     .
     28.405971s    HEC 16: waking up thread 284 on cap 7
     28.406026s    HEC 15: waking up thread 284 on cap 7
     28.406080s    HEC 12: waking up thread 284 on cap 7
     28.406091s    HEC 23: waking up thread 284 on cap 7
     28.406095s    HEC 6: waking up thread 284 on cap 7
     28.406095s    HEC 23: waking up thread 284 on cap 7
     28.406225s    HEC 16: waking up thread 284 on cap 7
     .
(Continue reading)

Permalink | Reply |
headers
Ben Gamari | 26 Jan 2013 19:05
Picon
Gravatar

Re: Extended periods of "waking up thread %d on cap %d"

Ben Gamari <bgamari.foss <at> gmail.com> writes:

> Recently I've been benchmarking my concurrent Gibbs sampler[1] on a
> largish multicore machine. I've been using GHC HEAD due to various
> GC-related fixes that are present. One thing that I've noticed in
> looking over the event logs is that there are large durations (tens of
> milliseconds) when HECs appear to be constantly bombarded with wake-ups
> from other capabilities.
>
> In these periods, the eventlog will be filled with blocks of messages
> such as this snippet from one benchmark run[2] (long repeated blocks
> marked with ellipses, a few irrelevant messages have been omitted yet
> not marked, see eventlog for full log),
>
>      28.320958s    HEC 7: running thread 293

I should note that this brings up what might be a related (perhaps more
significant from a performance perspective) issue. Notice that around
28.320s in eventlog [2], the benchmark began a new iteration (with a
corresponding lull in the CPU activity shown in the log). At this
point, a new batch of worker threads were created. Strangely, it seems
that the newly created threads begin execution in two groups: 
While HECs 0 and 2 through 16 begin immediately, HECs 1 and 17 through
23 all only begin at around 28.40s, after the "waking up thread 284 on
cap 7" storm subsides. Given this coincidence, it seems that these two
issues may be related.

Thoughts?

Cheers,
(Continue reading)

Permalink | Reply |
headers
Simon Marlow | 28 Jan 2013 12:40
Picon

Re: Extended periods of "waking up thread %d on cap %d"

On 26/01/13 00:28, Ben Gamari wrote:
> Recently I've been benchmarking my concurrent Gibbs sampler[1] on a
> largish multicore machine. I've been using GHC HEAD due to various
> GC-related fixes that are present. One thing that I've noticed in
> looking over the event logs is that there are large durations (tens of
> milliseconds) when HECs appear to be constantly bombarded with wake-ups
> from other capabilities.
>
> In these periods, the eventlog will be filled with blocks of messages
> such as this snippet from one benchmark run[2] (long repeated blocks
> marked with ellipses, a few irrelevant messages have been omitted yet
> not marked, see eventlog for full log),
>
>       28.320958s    HEC 7: running thread 293
>       ...
>       28.391802s    HEC 6: running thread 209
>       28.392070s    HEC 6: waking up thread 284 on cap 7
>       28.392302s    HEC 6: waking up thread 284 on cap 7
>       28.392579s    HEC 6: waking up thread 284 on cap 7
>       28.392808s    HEC 6: waking up thread 284 on cap 7
>       .
>       .
>       .
>       28.405971s    HEC 16: waking up thread 284 on cap 7
>       28.406026s    HEC 15: waking up thread 284 on cap 7
>       28.406080s    HEC 12: waking up thread 284 on cap 7
>       28.406091s    HEC 23: waking up thread 284 on cap 7
>       28.406095s    HEC 6: waking up thread 284 on cap 7
>       28.406095s    HEC 23: waking up thread 284 on cap 7
>       28.406225s    HEC 16: waking up thread 284 on cap 7
(Continue reading)

Permalink | Reply |
headers
Ben Gamari | 29 Jan 2013 16:18
Picon
Gravatar

Re: Extended periods of "waking up thread %d on cap %d"

Simon Marlow <marlowsd <at> gmail.com> writes:

> So I think we could adopt a similar policy for STM.  The mutex is 
> lockTSO()/unlockTSO(), which is already taken in STM.c:unpark_tso().  To 
> indicate that a thread has already been sent a wakeup message, we could 
> set tso->block_info.closure to a special value - normally it would be 
> END_TSO_QUEUE for a thread blocked in STM.  I've been peering at the 
> code a bit, and I'm pretty sure this is safe and doesn't involve many 
> changes to the RTS.
>
> Do you want to try this out and let me know if you get stuck?
>
Here[1] is a first stab at this. I'm currently waiting for a testsuite
run to finish but the patch at very least doesn't seem to break
anything obvious. Moreover, the number of wake-ups sent in my benchmark
appears to be much more reasonable now. Let me know if there's anything
obviously wrong here.

Cheers,

- Ben

[1] https://github.com/bgamari/ghc/commits/stm-mutex
Permalink | Reply |

Gmane