For a while now I have had a customer call that has been causing me a lot of pain to diagnose.

The symptom is that occasionally they will see the load average spike to 500ish and then decay back to normal. There is no other performance effect on the system.

The latest approach that I had been taking was to attempt to get DTrace to watch when a thread was put onto a dispatch queue and if that dispatch queue had more than a threshold number of threads on it, then to run mdb to get a list of the dispatch queues (echo ::cpulist -l | mdb -l).

Turns out that even this was too slow and the threads had been dealt with by the time I got the output.

OK this actually tells us something. These threads are being placed onto the dispatch queue incredibly quickly and also going to cpu and being dealt with incredibly quickly.

At this stage it occurred to me that it was too fast for the threads to be created. It had to be some kind of wakeup of a lot of threads, like a cv_broadcast(9F).

So I did up this script and asked the customer to run it.

#!/usr/sbin/dtrace -s #pragma D option quiet /* * This D script will notify when any one process wakes up more * than threshold threads currently sleeping on a synchronisation * object. */ int threshold; BEGIN { threshold = 20; printf("Monitoring, ...\n"); } fbt::sleepq_wakeall_chan:entry { self->wakeups = 0; self->interest = 1; } wakeup /self->interest/ { self->wakeups++; } fbt::sleepq_wakeall_chan:return /self->interest && self->wakeup > threshold/ { printf("\n%Y %s [%d]: woke up %d threads", walltimestamp, execname, pid, self->wakeups); stack(20); } fbt::sleepq_wakeall_chan:return /self->interest/ { self->interest = self->wakeups = 0; } We got immediate results. An excerpt of the output was:

2010 Mar 29 14:10:20 oracle [3102]: woke up 472 threads genunix`cv_broadcast+0x44 zfs`zil_commit+0x78 zfs`zfs_write+0x5d0 genunix`fop_write+0x20 genunix`pwrite+0x22c unix`syscall_trap+0xac 2010 Mar 29 14:10:20 oracle [3100]: woke up 94 threads genunix`cv_broadcast+0x44 zfs`zil_commit+0x78 zfs`zfs_write+0x5d0 genunix`fop_write+0x20 genunix`pwrite+0x22c unix`syscall_trap+0xac 2010 Mar 29 14:10:20 oracle [3102]: woke up 112 threads genunix`cv_broadcast+0x44 zfs`zil_commit+0x78 zfs`zfs_write+0x5d0 genunix`fop_write+0x20 genunix`pwrite+0x22c unix`syscall_trap+0xac 2010 Mar 29 14:10:20 oracle [3102]: woke up 59 threads genunix`cv_broadcast+0x44 zfs`zil_commit+0x78 zfs`zfs_write+0x5d0 genunix`fop_write+0x20 genunix`pwrite+0x22c unix`syscall_trap+0xac 2010 Mar 29 14:10:20 oracle [3100]: woke up 571 threads genunix`cv_broadcast+0x44 zfs`zil_commit+0x78 zfs`zfs_write+0x5d0 genunix`fop_write+0x20 genunix`pwrite+0x22c unix`syscall_trap+0xac What we have here is Oracle doing a LOT of parallel writes at one time. The system is actually behaving normally and processing things quickly, the only issue is that we occasionally see load average spike to large numbers then decay back to normal. Perhaps a better way to monitor the system activity might be to look at the ‘r’ column in vmstat which shows snapshots of how many threads are in dispatch queues.

So now we know what is going on, we can actually move on.




Read More about [DTrace helping to get to the bottom of load spikes...