[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

Re: [libvirt] blkio cgroup



Hi

so I ran these tests again. No patch applied yet. And - at least once -
it worked. I did everything exactly the same way as before. Since the
logs are 8 MB, even when best-bzip2'd, and I don't want everybody to
have to download these, I uploaded them to an external hoster:
http://www.megaupload.com/?d=SWKTC0V4

Traces were created with
blktrace -n 64 -b 16384 -d /dev/sdb -o - | blkparse -i -
blktrace -n 64 -b 16384 -d /dev/vdisks/kernel3 -o - | blkparse -i -

> Can you please apply attached patch. 

Unfortunately not. Cannot be applied to 2.6.37. I guess your source is
newer and I fail to find the places in the file to patch manually.

> This just makes CFQ output little
> more verbose and run the test again and capture the trace.
> 
> - Start the trace on /dev/sdb
> - Start the dd jobs in virt machines
> - Wait for system to hang
> - Press CTRL-C
> - Make sure there were no lost events otherwise increase the size and
>   number of buffers.

Tried that. Unfortunately, even with max buffer size of 16 M [1], this
leaves some Skips. I also tried to increase the number of buffers over
64, but that produced Oops'es.

However, I attached kernel3's blktrace of a case where the error
occured. Maybe you can read something from that.

> Can you also open tracing in another window and also trace one of the
> throttled dm deivces, say /dev/disks/kernel3. Following the same procedure
> as above. So let the two traces run in parallel.

So what next?

Regards
Dominik

[1]
http://git.kernel.org/?p=linux/kernel/git/axboe/blktrace.git;a=blob_plain;f=blktrace.c;hb=HEAD
and look for "Invalid buffer"
blktrace -n 64 -b 16384 -d /dev/vdisks/kernel3 -o - | blkparse -i -
254,25   1        1     0.000000000     0  C  WS 33403560 + 152 [0]
^C254,25   1        0     0.000122104     0  m   N throtl /notimportant [W] bio. bdisp=798144 sz=245760 bps=10000000 iodisp=3 iops=4294967295 queued=0/143
254,25   1        0     0.000140283     0  m   N throtl /notimportant [W] bio. bdisp=798144 sz=245760 bps=10000000 iodisp=3 iops=4294967295 queued=0/144
254,25   1        0     0.000156251     0  m   N throtl /notimportant [W] bio. bdisp=798144 sz=155648 bps=10000000 iodisp=3 iops=4294967295 queued=0/145
254,25   1        2     0.000157274  3753  U   N [qemu-kvm] 0
254,25   1        3     0.000295027     0  C  WS 33403712 + 480 [0]
254,25   1        4     0.000316287     0  C  WS 33404192 + 480 [0]
254,25   1        5     0.000434196     0  C  WS 33404672 + 480 [0]
254,25   3        0     0.000760552     0  m   N throtl /notimportant [W] bio. bdisp=798144 sz=245760 bps=10000000 iodisp=3 iops=4294967295 queued=0/146
254,25   3        0     0.000775394     0  m   N throtl /notimportant [W] bio. bdisp=798144 sz=192512 bps=10000000 iodisp=3 iops=4294967295 queued=0/147
254,25   3        6     0.000776845  3814  U   N [qemu-kvm] 0
254,25   3        0     0.099825192     0  m   N throtl dispatch nr_queued=148 read=0 write=148
254,25   3        0     0.099828429     0  m   N throtl /notimportant [W] extend slice start=4295010014 end=4295010075 jiffies=4295010040
254,25   3        0     0.099831100     0  m   N throtl /notimportant [W] trim slice nr=1 bytes=1000000 io=429496729 start=4295010039 end=4295010075 jiffies=4295010040
254,25   3        0     0.099833751     0  m   N throtl bios disp=5
254,25   3        0     0.099835752     0  m   N throtl schedule work. delay=27 jiffies=4295010040
254,25   3        7     0.099838159   485  Q  WS 33405152 + 480 [kworker/3:1]
254,25   3        8     0.099856682   485  Q  WS 33405632 + 480 [kworker/3:1]
254,25   3        9     0.099861824   485  Q  WS 33406112 + 256 [kworker/3:1]
254,25   3       10     0.099900841   485  Q  WS 33406368 + 480 [kworker/3:1]
254,25   3       11     0.099910061   485  Q  WS 33406848 + 480 [kworker/3:1]
254,25   3       12     0.099935372   485  U   N [kworker/3:1] 0
254,25   1        6     0.100349152     0  C  WS 33405632 + 480 [0]
254,25   1        7     0.100354988     0  C  WS 33405152 + 480 [0]
254,25   1        8     0.100836456     0  C  WS 33406368 + 480 [0]
254,25   1        9     0.100842199     0  C  WS 33406848 + 480 [0]
254,25   1       10     0.100845180     0  C  WS 33406112 + 256 [0]
254,25   1        0     0.100933070     0  m   N throtl /notimportant [W] bio. bdisp=912256 sz=4096 bps=10000000 iodisp=4 iops=4294967295 queued=0/143
254,25   1       11     0.100934493  3754  U   N [qemu-kvm] 0
254,25   3        0     0.207812916     0  m   N throtl dispatch nr_queued=144 read=0 write=144
254,25   3        0     0.207815442     0  m   N throtl /notimportant [W] extend slice start=4295010039 end=4295010100 jiffies=4295010067
254,25   3        0     0.207817686     0  m   N throtl /notimportant [W] trim slice nr=1 bytes=1000000 io=429496729 start=4295010064 end=4295010100 jiffies=4295010067
254,25   3        0     0.207820439     0  m   N throtl bios disp=6
254,25   3        0     0.207822168     0  m   N throtl schedule work. delay=23 jiffies=4295010067
254,25   3       13     0.207823157   485  Q  WS 33407328 + 480 [kworker/3:1]
254,25   3       14     0.207830523   485  Q  WS 33407808 + 48 [kworker/3:1]
254,25   3       15     0.207833596   485  Q  WS 33407864 + 480 [kworker/3:1]
254,25   3       16     0.207837361   485  Q  WS 33408344 + 480 [kworker/3:1]
254,25   3       17     0.207841101   485  Q  WS 33408824 + 56 [kworker/3:1]
254,25   3       18     0.207844084   485  Q  WS 33408880 + 144 [kworker/3:1]
254,25   3       19     0.207848057   485  U   N [kworker/3:1] 0
254,25   1       12     0.218236185     0  C  WS 33407808 + 48 [0]
254,25   1       13     0.218249222     0  C  WS 33407328 + 480 [0]
254,25   1       14     0.218288739  3659  C  WS 33407864 + 480 [0]
254,25   3        0     0.218331025     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/138
254,25   3        0     0.218348178     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/139
254,25   3        0     0.218365013     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/140
254,25   3        0     0.218380791     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/141
254,25   3        0     0.218396397     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/142
254,25   3        0     0.218412518     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/143
254,25   3        0     0.218418538     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=77824 bps=10000000 iodisp=5 iops=4294967295 queued=0/144
254,25   3       20     0.218419836  3755  U   N [qemu-kvm] 0
254,25   1       15     0.219849783     0  C  WS 33408824 + 56 [0]
254,25   1       16     0.219850886     0  C  WS 33408880 + 144 [0]
254,25   1       17     0.219867346     0  C  WS 33408344 + 480 [0]
254,25   3        0     0.219924854     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=8192 bps=10000000 iodisp=5 iops=4294967295 queued=0/145
254,25   3       21     0.219930309  3756  U   N [qemu-kvm] 0
254,25   1        0     0.219943422     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/146
254,25   1        0     0.219969139     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/147
254,25   1        0     0.219985715     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/148
254,25   1        0     0.220001491     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/149
254,25   1        0     0.220017719     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/150
254,25   1        0     0.220034195     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=245760 bps=10000000 iodisp=5 iops=4294967295 queued=0/151
254,25   1        0     0.220039806     0  m   N throtl /notimportant [W] bio. bdisp=776512 sz=77824 bps=10000000 iodisp=5 iops=4294967295 queued=0/152
254,25   1       18     0.220040765  3757  U   N [qemu-kvm] 0
254,25   3        0     0.299819416     0  m   N throtl dispatch nr_queued=153 read=0 write=153
254,25   3        0     0.299821891     0  m   N throtl /notimportant [W] extend slice start=4295010064 end=4295010125 jiffies=4295010090
254,25   3        0     0.299824342     0  m   N throtl /notimportant [W] trim slice nr=1 bytes=1000000 io=429496729 start=4295010089 end=4295010125 jiffies=4295010090
254,25   3        0     0.299826876     0  m   N throtl bios disp=5
254,25   3        0     0.299828406     0  m   N throtl schedule work. delay=25 jiffies=4295010090
254,25   3       22     0.299829722   485  Q  WS 33411584 + 480 [kworker/3:1]
254,25   3       23     0.343892373   485  Q  WS 33412064 + 480 [kworker/3:1]
254,25   3       24     0.343902311   485  Q  WS 33412544 + 480 [kworker/3:1]
254,25   3       25     0.343905823   485  Q  WS 33413024 + 480 [kworker/3:1]
254,25   3       26     0.343909295   485  Q  WS 33413504 + 104 [kworker/3:1]
254,25   3       27     0.343912320   485  U   N [kworker/3:1] 0
254,25   1       19     0.385082759     0  C  WS 33412064 + 480 [0]
254,25   1       20     0.385095303     0  C  WS 33411584 + 480 [0]
254,25   1       21     0.385972488     0  C  WS 33413024 + 480 [0]
254,25   1       22     0.385989075     0  C  WS 33413504 + 104 [0]
254,25   1       23     0.386003645     0  C  WS 33412544 + 480 [0]
254,25   3        0     0.386076045     0  m   N throtl /notimportant [W] bio. bdisp=812800 sz=245760 bps=10000000 iodisp=4 iops=4294967295 queued=0/148
254,25   3        0     0.386094537     0  m   N throtl /notimportant [W] bio. bdisp=812800 sz=245760 bps=10000000 iodisp=4 iops=4294967295 queued=0/149
254,25   3        0     0.386112874     0  m   N throtl /notimportant [W] bio. bdisp=812800 sz=245760 bps=10000000 iodisp=4 iops=4294967295 queued=0/150
254,25   3        0     0.386130213     0  m   N throtl /notimportant [W] bio. bdisp=812800 sz=245760 bps=10000000 iodisp=4 iops=4294967295 queued=0/151
254,25   3        0     0.386140202     0  m   N throtl /notimportant [W] bio. bdisp=812800 sz=94208 bps=10000000 iodisp=4 iops=4294967295 queued=0/152
254,25   3       28     0.386141308  3758  U   N [qemu-kvm] 0
254,25   3        0     0.465033350     0  m   N throtl dispatch nr_queued=153 read=0 write=153
254,25   3        0     0.465035309     0  m   N throtl /notimportant [W] new slice start=4295010131 end=4295010156 jiffies=4295010131
254,25   3        0     0.465037689     0  m   N throtl bios disp=4
254,25   3        0     0.465039514     0  m   N throtl schedule work. delay=30 jiffies=4295010131
254,25   3       29     0.465040021   485  Q  WS 33413608 + 480 [kworker/3:1]
254,25   3       30     0.465044569   485  Q  WS 33414088 + 480 [kworker/3:1]
254,25   3       31     0.465050773   485  Q  WS 33414568 + 480 [kworker/3:1]
254,25   3       32     0.465055521   485  Q  WS 33415048 + 480 [kworker/3:1]
254,25   3       33     0.465059274   485  U   N [kworker/3:1] 0
254,25   3        0 1266874889.709370470     0  m   N throtl dispatch nr_queued=147 read=0 write=147
254,25   3        0 1266874889.709373700     0  m   N throtl /notimportant [W] extend slice start=4295009989 end=4295010050 jiffies=4295010015
254,25   3        0 1266874889.709376574     0  m   N throtl /notimportant [W] trim slice nr=1 bytes=1000000 io=429496729 start=4295010014 end=4295010050 jiffies=4295010015
254,25   3        0 1266874889.709378973     0  m   N throtl bios disp=4
254,25   3        0 1266874889.709380910     0  m   N throtl schedule work. delay=25 jiffies=4295010015
254,25   3        1 1266874889.709382849   485  Q  WS 33403560 + 152 [kworker/3:1]
254,25   3        2 1266874889.709407336   485  Q  WS 33403712 + 480 [kworker/3:1]
254,25   3        3 1266874889.709411964   485  Q  WS 33404192 + 480 [kworker/3:1]
254,25   3        4 1266874889.709416459   485  Q  WS 33404672 + 480 [kworker/3:1]
254,25   3        5 1266874889.709419852   485  U   N [kworker/3:1] 0
CPU1 (254,25):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:       20,     3740KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             3        	 Timer unplugs:           0
CPU3 (254,25):
 Reads Queued:           0,        0KiB	 Writes Queued:          24,     4700KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             9        	 Timer unplugs:           0

Total (254,25):
 Reads Queued:           0,        0KiB	 Writes Queued:          24,     4700KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:       20,     3740KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 IO unplugs:            12        	 Timer unplugs:           0

Throughput (R/W): 0KiB/s / 0KiB/s
Events (254,25): 106 entries
Skips: 11 forward (166 -  61.0%)
blktrace -n 64 -b 16384 -d /dev/sdb -o - | blkparse -i -
  8,16  14        0     0.000000000     0  m   N cfq3689 put_queue
  8,16  19        0     0.000840668     0  m   N cfq3691 put_queue
  8,16  15        0     0.002907432     0  m   N cfq3625 put_queue
  8,16  13        0     0.003521784     0  m   N cfq3709 put_queue
  8,16  17        0     0.003891896     0  m   N cfq3697 put_queue
^C  8,16  13        0     0.004013048     0  m   N cfq3624 put_queue
  8,16  19        0     0.004133484     0  m   N cfq3618 put_queue
  8,16  17        0     0.004451615     0  m   N cfq3720 put_queue
  8,16  13        0     0.004553737     0  m   N cfq3716 put_queue
  8,16  21        0     0.004786891     0  m   N cfq3712 put_queue
  8,16  13        0     0.005103572     0  m   N cfq3658 put_queue
  8,16   5        0     1.000024123     0  m   N cfq3677 put_queue
  8,16  12        0     1.000489071     0  m   N cfq3634 put_queue
  8,16   1        0     1.001100421     0  m   N cfq3727 put_queue
  8,16   5        0     1.001545793     0  m   N cfq3684 put_queue
CPU1 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU5 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU12 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU13 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU14 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU15 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU17 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU19 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0
CPU21 (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 Read depth:             0        	 Write depth:             0
 IO unplugs:             0        	 Timer unplugs:           0

Total (8,16):
 Reads Queued:           0,        0KiB	 Writes Queued:           0,        0KiB
 Read Dispatches:        0,        0KiB	 Write Dispatches:        0,        0KiB
 Reads Requeued:         0		 Writes Requeued:         0
 Reads Completed:        0,        0KiB	 Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB	 Write Merges:            0,        0KiB
 IO unplugs:             0        	 Timer unplugs:           0

Throughput (R/W): 0KiB/s / 0KiB/s
Events (8,16): 15 entries
Skips: 0 forward (0 -   0.0%)
vmstat 2
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  0      0 129965576  12556  39608    0    0    81     1  408  782  1  1 97  2
 0  0      0 129965552  12556  39632    0    0     0     0 16551 32802  0  0 100  0
 0  0      0 129965632  12556  39632    0    0     0     0 16533 32809  0  0 100  0
 2  0      0 127859992  12556  39632    0    0    40     0 16439 32671  0  1 99  0
 1  0      0 121543616  12556  39712    0    0     0     4 16842 32828  0  4 96  0
 1  0      0 115227888  12564  39704    0    0     0    10 16842 32774  0  4 96  0
 4 157      0 107141264  12564  39712    0    0    38 93220 19812 34620  9  7 76  8
 4 132      0 99558056  12564  39712    0    0    14 333486 23417 38402  7  6 37 49
 3 134      0 93181904  12564  39712    0    0     0  2688 17863 33844  0  4 43 52
 3 134      0 86859600  12564  39712    0    0     0     0 17832 33800  0  4 45 51
 2 134      0 80061888  12564  39712    0    0     0     0 17615 33609  0  4 44 52
 0 134      0 76332352  12564  39712    0    0     0     0 18305 34343  0  3 45 52
 0 134      0 76331696  12564  39712    0    0     0     0 19424 34878  0  1 45 54
 2 134      0 76331920  12564  39712    0    0     0     0 19305 34779  0  1 45 54
 0 134      0 76332408  12564  39712    0    0     0     0 19191 34821  0  0 46 54
 3 134      0 86835888  12564  39712    0    0     0     0 19287 34667  0  1 45 53

[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]