How to debug high system load?

[Suvayu Ali]

Hi Bryn,

On Thu, Jul 12, 2012 at 03:34:56PM +0100, Bryn M. Reeves wrote:
> 
> It's possible that you have processes spending brief periods in
> D-state - short enough that they are hard to spot in top with the
> default sample period but long enough to count toward the load average
> (it's possible there's some other explanation though but that's what
> I'd try to rule out first).
> 
> You could use tools like blktrace, iotop and latencytop to try to
> investigate further or if you're willing to install systemtap you
> could use the "sleepingBeauties.stp" script to look for processes
> spending >10ms in this state (and dump their stacks when they do).
> 


With latencytop I see that the large latency processes are usually
caused by

1. `fsync() on a file': Firefox, Google Chrome, pidgin, emacs
2. `Waiting for buffer IO to complete': jbd2/dm-*
3. `SCSI disk ioctl': hddtemp

The wait times are of the order of 60ms - 200ms.

`btrace /dev/sda' gives me the following:

CPU0 (8,0):
 Reads Queued:    1,572, 22,536KiB  Writes Queued:     5,211, 32,112KiB
 Read Dispatches: 1,612, 22,896KiB  Write Dispatches:  3,956, 39,424KiB
 Reads Requeued:      2             Writes Requeued:      11
 Reads Completed: 2,156, 27,844KiB  Writes Completed:  7,028, 69,784KiB
 Read Merges:         0,      0KiB  Write Merges:      1,568,  6,280KiB
 Read depth:         98             Write depth:          33
 PC Reads Queued:     0,      0KiB  PC Writes Queued:      0,      0KiB
 PC Read Disp.:     136,      0KiB  PC Write Disp.:        0,      0KiB
 PC Reads Req.:      22             PC Writes Req.:        0
 PC Reads Compl.:    90             PC Writes Compl.:      0
 IO unplugs:      1,224             Timer unplugs:        35
CPU1 (8,0):
 Reads Queued:      107,  1,272KiB  Writes Queued:     1,162,  6,768KiB
 Read Dispatches:    95,  1,140KiB  Write Dispatches:    244,  4,708KiB
 Reads Requeued:      0             Writes Requeued:       2
 Reads Completed:     0,      0KiB  Writes Completed:      0,      0KiB
 Read Merges:         0,      0KiB  Write Merges:        612,  2,448KiB
 Read depth:         98             Write depth:          33
 PC Reads Queued:     0,      0KiB  PC Writes Queued:      0,      0KiB
 PC Read Disp.:      28,      0KiB  PC Write Disp.:        0,
    0KiB
 PC Reads Req.:       0             PC Writes Req.:        0
 PC Reads Compl.:     0             PC Writes Compl.:      0
 IO unplugs:        264             Timer unplugs:         0
CPU2 (8,0):
 Reads Queued:      249,  2,284KiB  Writes Queued:     4,206, 26,020KiB
 Read Dispatches:   238,  2,220KiB  Write Dispatches:  1,463, 22,116KiB
 Reads Requeued:      0             Writes Requeued:       1
 Reads Completed:     0,      0KiB  Writes Completed:      0,
    0KiB
 Read Merges:         0,      0KiB  Write Merges:      2,214,  8,952KiB
 Read depth:         98             Write depth:          33
 PC Reads Queued:     0,      0KiB  PC Writes Queued:      0,      0KiB
 PC Read Disp.:      21,      0KiB  PC Write Disp.:        0,
    0KiB
 PC Reads Req.:       0             PC Writes Req.:        0
 PC Reads Compl.:     0             PC Writes Compl.:      0
 IO unplugs:        736             Timer unplugs:         9
CPU3 (8,0):
 Reads Queued:      247,  1,752KiB  Writes Queued:       448,  4,884KiB
 Read Dispatches:   214,  1,588KiB  Write Dispatches:    210,  3,536KiB
 Reads Requeued:      1             Writes Requeued:       0
 Reads Completed:     0,      0KiB  Writes Completed:      0,      0KiB
 Read Merges:        18,     72KiB  Write Merges:        184,    736KiB
 Read depth:         98             Write depth:          33
 PC Reads Queued:     0,      0KiB  PC Writes Queued:      0,      0KiB
 PC Read Disp.:      23,      0KiB  PC Write Disp.:        0,      0KiB
 PC Reads Req.:       0             PC Writes Req.:        0
 PC Reads Compl.:     0             PC Writes Compl.:      0
 IO unplugs:        171             Timer unplugs:         1

Total (8,0):
 Reads Queued:    2,175, 27,844KiB  Writes Queued:    11,027, 69,784KiB
 Read Dispatches: 2,159, 27,844KiB  Write Dispatches:  5,873, 69,784KiB
 Reads Requeued:      3             Writes Requeued:      14
 Reads Completed: 2,156, 27,844KiB  Writes Completed:  7,028, 69,784KiB
 Read Merges:        18,     72KiB  Write Merges:      4,578, 18,416KiB
 PC Reads Queued:     0,      0KiB  PC Writes Queued:      0,      0KiB
 PC Read Disp.:     208,      0KiB  PC Write Disp.:        0,      0KiB
 PC Reads Req.:      22             PC Writes Req.:        0
 PC Reads Compl.:    90             PC Writes Compl.:      0
 IO unplugs:      2,395             Timer unplugs:        45

Throughput (R/W): 6KiB/s / 16KiB/s
Events (8,0): 147,334 entries
Skips: 0 forward (0 -   0.0%)

iotop doesn't show anything in particular other than once or twice one
of the desktop apps like Firefox showing up and going away almost
immediately.

I don't quiet know how to interpret any of the above output though.

PS: I will run the systemtap script later tonight.

-- 
Suvayu

Open source is the future. It sets us free.