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
-- libvir-list mailing list libvir-list@xxxxxxxxxx https://www.redhat.com/mailman/listinfo/libvir-list