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.