On Mon, Feb 21, 2011 at 03:36:14PM +0800, Gui Jianfeng wrote:

Dominik,

Would you try "oflag=direct" when you do tests in Guests. And make sure /sys/block/xxx/queue/iosched/group_isolation is set to 1.

oflag=direct in guest might be good for testing and understanding the problem, but in practice we will not have a control over what a user is running inside guest. The only control we will have is to use cache=none for guest and then control any traffic coming out of guest. Thanks Vivek

I guess with such setting, your tests should goes well.

Thanks, Gui

Vivek Goyal wrote:

...

On Fri, Feb 18, 2011 at 03:42:45PM +0100, Dominik Klein wrote:

...

Hi Vivek

I don't know whether you follow the libvirt list, I assume you don't. So I thought I'd forward you an E-Mail involving the blkio controller and a terrible situation arising from using it (maybe in a wrong way).

I'd truely appreciate it if you read it and commented on it. Maybe I did something wrong, but maybe also I found a bug in some way.

Hi Dominik,

Thanks for forwarding me this mail. Yes, I am not on libvir-list. I have just now subscribed.

Few questions inline.

...

-------- Original Message -------- Subject: Re: [libvirt] [PATCH 0/6 v3] Add blkio cgroup support Date: Fri, 18 Feb 2011 14:42:51 +0100 From: Dominik Klein <dk@in-telegence.net> To: libvir-list@redhat.com

Hi

back with some testing results.

...

...

how about the start Guest with option "cache=none" to bypass pagecache? This should help i think. I will read up on where to set that and give it a try. Thanks for the hint. So here's what I did and found out:

The host system has 2 12 core CPUs and 128 GB of Ram.

I have 8 test VMs named kernel1 to kernel8. Each VM has 4 VCPUs, 2 GB of RAm and one disk, which is an lv on the host. Cache mode is "none":

So you have only one root SATA disk and setup a linear logical volume on that? I not, can you give more info about the storage configuration?

- I am assuming you are using CFQ on your underlying physical disk.

- What kernel version are you testing with.

- Cache=none mode is good which should make all the IO O_DIRECT on host and should show up as SYNC IO on CFQ without losing io context info. The onlly probelm is intermediate dm layer and if it is changing the io context somehow. I am not sure at this point of time.

- Is it possible to capture 10-15 second blktrace on your underlying physical device. That should give me some idea what's happening.

- Can you also try setting /sys/block/<disk>/queue/iosched/group_isolation=1 on your underlying physical device where CFQ is running and see if it makes any difference.

...

for vm in kernel1 kernel2 kernel3 kernel4 kernel5 kernel6 kernel7 kernel8; do virsh dumpxml $vm|grep cache; done <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/> <driver name='qemu' type='raw' cache='none'/>

My goal is to give more I/O time to kernel1 and kernel2 than to the rest of the VMs.

mount -t cgroup -o blkio none /mnt cd /mnt mkdir important mkdir notimportant

echo 1000 > important/blkio.weight echo 100 > notimportant/blkio.weight for vm in kernel3 kernel4 kernel5 kernel6 kernel7 kernel8; do cd /proc/$(pgrep -f "qemu-kvm.*$vm")/task for task in *; do /bin/echo $task > /mnt/notimportant/tasks done done

for vm in kernel1 kernel2; do cd /proc/$(pgrep -f "qemu-kvm.*$vm")/task for task in *; do /bin/echo $task > /mnt/important/tasks done done

Then I used cssh to connect to all 8 VMs and execute dd if=/dev/zero of=testfile bs=1M count=1500 in all VMs simultaneously.

Results are: kernel1: 47.5593 s, 33.1 MB/s kernel2: 60.1464 s, 26.2 MB/s kernel3: 74.204 s, 21.2 MB/s kernel4: 77.0759 s, 20.4 MB/s kernel5: 65.6309 s, 24.0 MB/s kernel6: 81.1402 s, 19.4 MB/s kernel7: 70.3881 s, 22.3 MB/s kernel8: 77.4475 s, 20.3 MB/s

Results vary a little bit from run to run, but it is nothing spectacular, as weights of 1000 vs. 100 would suggest.

So I went and tried to throttle I/O of kernel3-8 to 10MB/s instead of weighing I/O. First I rebooted everything so that no old configuration of cgroup was left in place and then setup everything except the 100 and 1000 weight configuration.

quote from blkio.txt: ------------ - blkio.throttle.write_bps_device - Specifies upper limit on WRITE rate to the device. IO rate is specified in bytes per second. Rules are per deivce. Following is the format.

echo "<major>:<minor> <rate_bytes_per_second>" > /cgrp/blkio.write_bps_device -------------

for vm in kernel1 kernel2 kernel3 kernel4 kernel5 kernel6 kernel7 kernel8; do ls -lH /dev/vdisks/$vm; done brw-rw---- 1 root root 254, 23 Feb 18 13:45 /dev/vdisks/kernel1 brw-rw---- 1 root root 254, 24 Feb 18 13:45 /dev/vdisks/kernel2 brw-rw---- 1 root root 254, 25 Feb 18 13:45 /dev/vdisks/kernel3 brw-rw---- 1 root root 254, 26 Feb 18 13:45 /dev/vdisks/kernel4 brw-rw---- 1 root root 254, 27 Feb 18 13:45 /dev/vdisks/kernel5 brw-rw---- 1 root root 254, 28 Feb 18 13:45 /dev/vdisks/kernel6 brw-rw---- 1 root root 254, 29 Feb 18 13:45 /dev/vdisks/kernel7 brw-rw---- 1 root root 254, 30 Feb 18 13:45 /dev/vdisks/kernel8

/bin/echo 254:25 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device /bin/echo 254:26 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device /bin/echo 254:27 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device /bin/echo 254:28 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device /bin/echo 254:29 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device /bin/echo 254:30 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device /bin/echo 254:30 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device

Then I ran the previous test again. This resulted in an ever increasing load (last I checked was ~ 300) on the host system. (This is perfectly reproducible).

uptime Fri Feb 18 14:42:17 2011 14:42:17 up 12 min, 9 users, load average: 286.51, 142.22, 56.71

Have you run top or something to figure out why load average is shooting up. I suspect that because of throttling limit, IO threads have been blocked and qemu is forking more IO threads. Can you just run top/ps and figure out what's happening.

Again, is it some kind of linear volume group from which you have carved out logical volumes for each virtual machine?

For throttling to begin with, can we do a simple test first. That is run a single virtual machine, put some throttling limit on logical volume and try to do READs. Once READs work, lets test WRITES and check why does system load go up.

Thanks Vivek

-- libvir-list mailing list libvir-list@redhat.com https://www.redhat.com/mailman/listinfo/libvir-list

-- Regards Gui Jianfeng

...

- Is it possible to capture 10-15 second blktrace on your underlying physical device. That should give me some idea what's happening.

Will do, read on.

Just realized I missed this one ... Had better done it right away. So here goes. Setup as in first email. 8 Machines, 2 important, 6 not important ones with a throttle of ~10M. group_isolation=1. Each vm dd'ing zeroes. blktrace -d /dev/sdb -w 30 === sdb === CPU 0: 4769 events, 224 KiB data CPU 1: 28079 events, 1317 KiB data CPU 2: 1179 events, 56 KiB data CPU 3: 5529 events, 260 KiB data CPU 4: 295 events, 14 KiB data CPU 5: 649 events, 31 KiB data CPU 6: 185 events, 9 KiB data CPU 7: 180 events, 9 KiB data CPU 8: 17 events, 1 KiB data CPU 9: 12 events, 1 KiB data CPU 10: 6 events, 1 KiB data CPU 11: 55 events, 3 KiB data CPU 12: 28005 events, 1313 KiB data CPU 13: 1542 events, 73 KiB data CPU 14: 4814 events, 226 KiB data CPU 15: 389 events, 19 KiB data CPU 16: 1545 events, 73 KiB data CPU 17: 119 events, 6 KiB data CPU 18: 3019 events, 142 KiB data CPU 19: 62 events, 3 KiB data CPU 20: 800 events, 38 KiB data CPU 21: 17 events, 1 KiB data CPU 22: 243 events, 12 KiB data CPU 23: 1 events, 1 KiB data Total: 81511 events (dropped 0), 3822 KiB data Very constant 296 blocked processes in vmstat during this run. But... apparently no data is written at all (see "bo" column). vmstat 2 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 296 0 125254224 21432 142016 0 0 16 633 181 331 0 0 93 7 0 296 0 125253728 21432 142016 0 0 0 0 17115 33794 0 0 25 75 0 296 0 125254112 21432 142016 0 0 0 0 17084 33721 0 0 25 74 1 296 0 125254352 21440 142012 0 0 0 18 17047 33736 0 0 25 75 0 296 0 125304224 21440 131060 0 0 0 0 17630 33989 0 1 23 76 1 296 0 125306496 21440 130260 0 0 0 0 16810 33401 0 0 20 80 4 296 0 125307208 21440 129856 0 0 0 0 17169 33744 0 0 26 74 0 296 0 125307496 21448 129508 0 0 0 14 17105 33650 0 0 36 64 0 296 0 125307712 21452 129672 0 0 2 1340 17117 33674 0 0 22 78 1 296 0 125307752 21452 129520 0 0 0 0 16875 33438 0 0 29 70 1 296 0 125307776 21452 129520 0 0 0 0 16959 33560 0 0 21 79 1 296 0 125307792 21460 129520 0 0 0 12 16700 33239 0 0 15 85 1 296 0 125307808 21460 129520 0 0 0 0 16750 33274 0 0 25 74 1 296 0 125307808 21460 129520 0 0 0 0 17020 33601 0 0 26 74 1 296 0 125308272 21460 129520 0 0 0 0 17080 33616 0 0 20 80 1 296 0 125308408 21460 129520 0 0 0 0 16428 32972 0 0 42 58 1 296 0 125308016 21460 129524 0 0 0 0 17021 33624 0 0 22 77 Regards Dominik

On Mon, Feb 21, 2011 at 09:30:32AM +0100, Dominik Klein wrote:

On 02/21/2011 09:19 AM, Dominik Klein wrote:

...

...

...

- Is it possible to capture 10-15 second blktrace on your underlying physical device. That should give me some idea what's happening.

Will do, read on.

Just realized I missed this one ... Had better done it right away.

So here goes.

Setup as in first email. 8 Machines, 2 important, 6 not important ones with a throttle of ~10M. group_isolation=1. Each vm dd'ing zeroes.

blktrace -d /dev/sdb -w 30 === sdb === CPU 0: 4769 events, 224 KiB data CPU 1: 28079 events, 1317 KiB data CPU 2: 1179 events, 56 KiB data CPU 3: 5529 events, 260 KiB data CPU 4: 295 events, 14 KiB data CPU 5: 649 events, 31 KiB data CPU 6: 185 events, 9 KiB data CPU 7: 180 events, 9 KiB data CPU 8: 17 events, 1 KiB data CPU 9: 12 events, 1 KiB data CPU 10: 6 events, 1 KiB data CPU 11: 55 events, 3 KiB data CPU 12: 28005 events, 1313 KiB data CPU 13: 1542 events, 73 KiB data CPU 14: 4814 events, 226 KiB data CPU 15: 389 events, 19 KiB data CPU 16: 1545 events, 73 KiB data CPU 17: 119 events, 6 KiB data CPU 18: 3019 events, 142 KiB data CPU 19: 62 events, 3 KiB data CPU 20: 800 events, 38 KiB data CPU 21: 17 events, 1 KiB data CPU 22: 243 events, 12 KiB data CPU 23: 1 events, 1 KiB data Total: 81511 events (dropped 0), 3822 KiB data

Very constant 296 blocked processes in vmstat during this run. But... apparently no data is written at all (see "bo" column).

Hm..., this sounds bad. If you have put a limit of ~10Mb/s then no "bo" is bad. That would explain that why your box is not responding and you need to do power reset. - I am assuming that you have not put any throttling limits on root group. Is your system root also on /dev/sdb or on a separate disk altogether. - This sounds like a bug in throttling logic. To narrow it down can you start running "deadline" on end device. If it still happens, it is more or less in throttling layer. - We can also try to remove dm layers and just create partitions on /dev/sdb and export as virtio disks to virtual machines and take dm layer out of picture and see if it still happens. - In one of the mails you mentioned that with 1 virutal machine throttling READs and WRITEs is working for you. So it looks like 1 virtual machine does not hang but once you launch 8 virtual machines it hangs. Can we try increasing the number of vitual machines gragually and confirm that it happens only if some certain number of virtual machines are launched. - Can you also paste me the rules you have put on important and non-important groups. Somehow I suspect that some of the rule has gone horribly bad in the sense that it is very low and effectively no virtual machine is making any progress. - How long does it take to reach in this locked state where bo=0. - you can also try to redirect blktrace output to blkparse and redirect it to standard output and see capture some output by copying pasting last messages. In the mean time, I will try to launch more machines and see if I can reproduce the issue. Thanks Vivek

...

vmstat 2 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 296 0 125254224 21432 142016 0 0 16 633 181 331 0 0 93 7 0 296 0 125253728 21432 142016 0 0 0 0 17115 33794 0 0 25 75 0 296 0 125254112 21432 142016 0 0 0 0 17084 33721 0 0 25 74 1 296 0 125254352 21440 142012 0 0 0 18 17047 33736 0 0 25 75 0 296 0 125304224 21440 131060 0 0 0 0 17630 33989 0 1 23 76 1 296 0 125306496 21440 130260 0 0 0 0 16810 33401 0 0 20 80 4 296 0 125307208 21440 129856 0 0 0 0 17169 33744 0 0 26 74 0 296 0 125307496 21448 129508 0 0 0 14 17105 33650 0 0 36 64 0 296 0 125307712 21452 129672 0 0 2 1340 17117 33674 0 0 22 78 1 296 0 125307752 21452 129520 0 0 0 0 16875 33438 0 0 29 70 1 296 0 125307776 21452 129520 0 0 0 0 16959 33560 0 0 21 79 1 296 0 125307792 21460 129520 0 0 0 12 16700 33239 0 0 15 85 1 296 0 125307808 21460 129520 0 0 0 0 16750 33274 0 0 25 74 1 296 0 125307808 21460 129520 0 0 0 0 17020 33601 0 0 26 74 1 296 0 125308272 21460 129520 0 0 0 0 17080 33616 0 0 20 80 1 296 0 125308408 21460 129520 0 0 0 0 16428 32972 0 0 42 58 1 296 0 125308016 21460 129524 0 0 0 0 17021 33624 0 0 22 77

While we're on that ... It is impossible for me now to recover from this state without pulling the power plug.

On the VMs console I see messages like INFO: task (kjournald|flush-254|dd|rs:main|...) blocked for more than 120 seconds.

If VMs are completely blocked and not making any progress, it is expected.

While the ssh sessions through which the dd was started seem intact (pressing enter gives a new line), it is impossible to cancel the dd command. Logging in on the VMs console also is impossible.

Opening a new ssh session to the host also does not work. Killing the qemu-kvm processes from a session opened earlier leaves zomby processes. Moving the VMs back to the root cgroup makes no difference either.

Regards Dominik

-- libvir-list mailing list libvir-list@redhat.com https://www.redhat.com/mailman/listinfo/libvir-list

On Tue, Feb 22, 2011 at 02:29:31PM +0100, Dominik Klein wrote:

Hi

to be as verbose and clear as possible, I will write every command I use.

Thanks Dominik for detailed explanation and tests.

This sets everything up for the test:

# setup start

importantvms="kernel1 kernel2" notimportantvms="kernel3 kernel4 kernel5 kernel6 kernel7 kernel8"

for vm in $importantvms $notimportantvms; do virsh domstate $vm|grep -q running || virsh start $vm; done

echo 1 > /sys/block/sdb/queue/iosched/group_isolation

mount -t cgroup -o blkio none /mnt cd /mnt mkdir important mkdir notimportant

for vm in $notimportantvms; do cd /proc/$(pgrep -f "qemu-kvm.*$vm")/task for task in *; do /bin/echo $task > /mnt/notimportant/tasks done done

for vm in $importantvms; do cd /proc/$(pgrep -f "qemu-kvm.*$vm")/task for task in *; do /bin/echo $task > /mnt/important/tasks done done

#ls -lH /dev/vdisks/kernel[3-8] #brw-rw---- 1 root root 254, 25 Feb 22 13:42 kernel3 #brw-rw---- 1 root root 254, 26 Feb 22 13:42 kernel4 #brw-rw---- 1 root root 254, 27 Feb 22 13:42 kernel5 #brw-rw---- 1 root root 254, 28 Feb 22 13:42 kernel6 #brw-rw---- 1 root root 254, 29 Feb 22 13:43 kernel7 #brw-rw---- 1 root root 254, 30 Feb 22 13:43 kernel8

for i in $(seq 25 30); do /bin/echo 254:$i 10000000 > /mnt/notimportant/blkio.throttle.write_bps_device done

# setup complete

...

Hm..., this sounds bad. If you have put a limit of ~10Mb/s then no "bo" is bad. That would explain that why your box is not responding and you need to do power reset.

- I am assuming that you have not put any throttling limits on root group. Is your system root also on /dev/sdb or on a separate disk altogether.

No throttling on root. Correct.

system root is on sda vms are on sdb

...

- This sounds like a bug in throttling logic. To narrow it down can you start running "deadline" on end device. If it still happens, it is more or less in throttling layer.

cat /sys/block/sdb/queue/scheduler noop deadline [cfq] echo deadline > /sys/block/sdb/queue/scheduler cat /sys/block/sdb/queue/scheduler noop [deadline] cfq

This changes things:

vmstat before test (nothing going on): r b swpd free buff cache si so bi bo in cs us sy id wa 1 0 0 130231696 17968 69424 0 0 0 0 16573 32834 0 0 100 0

vmstat during test while all 8 vms are writing (2 unthrottled, 6 at 10M): r b swpd free buff cache si so bi bo in cs us sy id wa 2 9 0 126257984 17968 69424 0 0 8 164462 20114 36751 5 4 52 39

vmstat during test when only throttled vms are still dd'ing 2 21 0 124518928 17976 69424 0 0 0 63876 17410 33670 1 1 59 39

Load is 12-ish during the test and the results are as expected: Throttled VMs write with approx 10M, unthrottled get like 80 each, which sums up to about the 200M max capacity of the device for direct io.

Ok, so deadline works just fine and there are no hangs. So it sounds more like CFQ issue.

...

- We can also try to remove dm layers and just create partitions on /dev/sdb and export as virtio disks to virtual machines and take dm layer out of picture and see if it still happens.

Did that. Also happens when scheduler is cfq. Also does not happen when scheduler is deadline. So it does not seem to be a dm issue.

Ok, so dm is not the culprit then.

...

- In one of the mails you mentioned that with 1 virutal machine throttling READs and WRITEs is working for you. So it looks like 1 virtual machine does not hang but once you launch 8 virtual machines it hangs. Can we try increasing the number of vitual machines gragually and confirm that it happens only if some certain number of virtual machines are launched.

Back on cfq here.

1 throttled vm: works, load ~4 2 throttled vms: works, load ~6 3 throttled vms: works, load ~9 4 throttled vms: works, load ~12 6 throttled vms: works, load ~20

The number of blocked threads increases with the number of vms dd'ing.

At the beginning of each test, the blocked threads number goes really high (4 vms 160, 6 vms 220), but then drops significantly and stays low.

So it seems that when only throttled vms are running, the problem does not occur.

1 throttled + 1 unthrottled vm: works, load ~5 2 throttled + 1 unthrottled vm: boom

That't interesting. I will try to run 2 throttled VMs and 1 Unthrottled and see if I can hit the same situation.

Constantly 144 blocked threads, bo=0, load increasing to 144. System needs power reset.

So, thinking about what I did in the initial setup, I re-tested without the

for vm in $importantvms; do cd /proc/$(pgrep -f "qemu-kvm.*$vm")/task for task in *; do /bin/echo $task > /mnt/important/tasks done done

since I don't do anything with that "important" cgroup (yet) anyway. It did not make a difference though.

...

- Can you also paste me the rules you have put on important and non-important groups. Somehow I suspect that some of the rule has gone horribly bad in the sense that it is very low and effectively no virtual machine is making any progress.

See setup commands in the beginning of this email.

...

- How long does it take to reach in this locked state where bo=0.

It goes there "instantly", right after the dd commands start.

...

- you can also try to redirect blktrace output to blkparse and redirect it to standard output and see capture some output by copying pasting last messages.

I hope this is what you meant:

blktrace -d /dev/sdb -o - | blkparse -i -

Yes, that's what I meant. Few observations from this trace. - After a while all the IO coming in seems to be sleeping on get_request(). "S" signifies that. That means some other threads have already consumed the available request descriptors and new threads are being put to sleep and will be woken up when request descriptors are available. Not sure why that is happening here. - CFQ was idling on a queue and idle timer fired and it scheduled another dispatch. After that there is no request dispatched at all. Something went wrong for sure. 8,16 1 0 55.806298452 0 m N cfq idle timer fired 8,16 1 0 55.806300924 0 m N cfq3564 slice expired t=0 8,16 1 0 55.806303380 0 m N cfq3564 sl_used=2 disp=1 charge =2 iops=0 sect=8 8,16 1 0 55.806303770 0 m N cfq3564 del_from_rr 8,16 1 0 55.806304555 0 m N cfq schedule dispatch - Following seems odd 8,16 7 925 55.890489350 3768 Q WS 3407925696 + 480 [qemu-kvm] 8,16 7 926 55.890494793 3768 S WS 3407925696 + 480 [qemu-kvm] 8,16 1 1 1266874889.707163736 0 C R 3390363000 + 48 [0] 8,16 1 0 1266874889.707181482 0 m N cfq3273 complete rqnoidl Time in fourth column jumps from 55.x to 1266874889.X. Sounds like some corruption. - I don't see any throttling messages. They are prefixed by "throtl". So it seems all this IO is happening in root group. I believe it belongs to unthrottled VM. So to me it looks that system reached in bad shape even before throttled VMs were started. - So it sounds more and more like a CFQ issue which happens in conjuction with throttling. I will try to reproduce it. - Need little more info about how did you capture the blktrace. So you started blktrace and then started dd in parallel in all the three VMs and immediately system freezes and these are the only logs we see on console? Thanks Vivek

Hi List Vivek and I talked yesterday via IRC and here's what we found. First of all, I need to define the "freeze"- or "hang"-situation in order to avoid misunderstandings. When the "hang" state occures, this means it is impossible to do any io on the system. vmstat shows 250-300 blocked threads. Therefore, it is not possible to open new ssh connections or log into the servers console. Established ssh connections however, keep working. It is possible to run commands. Just don't touch any files. That immediately hangs the connections. Okay, now that we got that cleared up ... During the "hang" situation, it is possible to change from cfq to deadline scheduler for /dev/sdb (the pv for the lvs). This makes the io happen and the system is responsive as usual. After applying the patch correctly (my mistake), we could see these debug messages from debugfs: qemu-kvm-3955 [004] 823.360594: 8,16 Q WS 3408164104 + 480 [qemu-kvm] qemu-kvm-3955 [004] 823.360594: 8,16 S WS 3408164104 + 480 [qemu-kvm] <...>-3252 [016] 823.361146: 8,16 m N cfq idle timer fired <...>-3252 [016] 823.361151: 8,16 m N cfq3683 slice expired t=0 <...>-3252 [016] 823.361154: 8,16 m N cfq3683 sl_used=2 disp=25 charge=2 iops=0 sect=9944 <...>-3252 [016] 823.361154: 8,16 m N cfq3683 del_from_rr <...>-3252 [016] 823.361161: 8,16 m N cfq schedule dispatch: busy_queues=38 rq_queued=132 rq_in_driver=0 quote Vivek Goyal cfq has 38 busy queues and 132 requests queued and it tries to schedule a dispatch and that dispatch never happens for some reason and cfq is hung /quote So the next idea was to try with 2.6.38-rc6, just in case there is a bug in workqueue logic which got fixed? And it turns out: With 2.6.38-rc6, the problem does not happen. I will see whether I can bisect the kernel patches and see which one was the good one. I have to figure out a way to do that, but if I do it and find out, I will keep you posted. Vivek then asked me to use another 2.6.37 debug patch and re-run the test. Attached are the logs from that run. Regards Dominik On 02/23/2011 02:37 PM, Dominik Klein wrote:

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=... and look for "Invalid buffer"

fwiw, with 2.6.37.1, it does not work either.

Hello, On Thu, Feb 24, 2011 at 09:23:03AM -0500, Vivek Goyal wrote:

On Thu, Feb 24, 2011 at 10:18:00AM +0100, Dominik Klein wrote:

Hi Dominik,

Thanks for the tests and reports. I checked the latest logs also and I see that cfq has scheduled a work but that work never gets scheduled. I never see the trace message which says cfq_kick_queue().

I am ccing it to lkml and tejun to see if he has any suggestions.

Tejun,

I will give you some details about what we have discussed so far.

Dominik is trying blkio throttling feature and trying to throttle some virtual machines. He is using 2.6.37 kernels and once he launches 3 virtual machines he notices that system is kind of frozen. After running some traces we noticed that CFQ has requests but it is not dispatching these to devices any more.

This problem does not show up with deadline scheduler and also goes away with 2.6.38-rc6 kernels.

Hmmm... Maybe the following commit? commit 7576958a9d5a4a677ad7dd40901cdbb6c1110c98 Author: Tejun Heo <tj@kernel.org> Date: Mon Feb 14 14:04:46 2011 +0100 workqueue: wake up a worker when a rescuer is leaving a gcwq After executing the matching works, a rescuer leaves the gcwq whether there are more pending works or not. This may decrease the concurrency level to zero and stall execution until a new work item is queued on the gcwq. Make rescuer wake up a regular worker when it leaves a gcwq if there are more works to execute, so that execution isn't stalled. Signed-off-by: Tejun Heo <tj@kernel.org> Reported-by: Ray Jui <rjui@broadcom.com> Cc: stable@kernel.org -- tejun

On Thu, Feb 24, 2011 at 03:58:22PM +0100, Dominik Klein wrote:

Hi

...

Hmmm... Maybe the following commit?

commit 7576958a9d5a4a677ad7dd40901cdbb6c1110c98

Unfortunately not. This does not fix it for me.

Vivek introduced me to git bisect and I will try to do that tomorrow to find the changeset.

Maybe watching what the workqueue is doing using the following trace events could be helpful. # grep workqueue /sys/kernel/debug/tracing/available_events workqueue:workqueue_insertion workqueue:workqueue_execution workqueue:workqueue_creation workqueue:workqueue_destruction Thanks. -- tejun

On Fri, Feb 25, 2011 at 08:24:15AM +0100, Dominik Klein wrote:

...

Maybe watching what the workqueue is doing using the following trace events could be helpful.

# grep workqueue /sys/kernel/debug/tracing/available_events workqueue:workqueue_insertion workqueue:workqueue_execution workqueue:workqueue_creation workqueue:workqueue_destruction

Since I've never done this before, I will tell you how I captured the trace so you know what I did and can see whether I did something wrong and can correct me if necessary.

echo blk > /sys/kernel/debug/tracing/current_tracer echo 1 > /sys/block/sdb/trace/enable echo workqueue_queue_work >> /sys/kernel/debug/tracing/set_event echo workqueue_activate_work >> /sys/kernel/debug/tracing/set_event echo workqueue_execute_start >> /sys/kernel/debug/tracing/set_event echo workqueue_execute_end >> /sys/kernel/debug/tracing/set_event cat /sys/kernel/debug/tracing/trace_pipe

And that output i gzip'd.

This was taken with 2.6.37 plus the patch you mentioned on a Dell R815 with 2 12 core AMD Opteron 6174 CPUs. If you need any more information, please let me know.

Hmmm... well, I have no idea what you were trying to do but here are some info which might be helpful. * queue_work happens when the work item is queued. * activate_work happens when the work item becomes eligible for execution. e.g. If the workqueue's @max_active is limited and maximum number of work items are already in flight, a new item will only get activated after one of the in flight ones retires. * execute_start marks the actual starting of execution. * execute_end marks the end of execution. So, I would look for the matching work function and then try to follow what happens to it after being scheduled and if it doesn't get executed what's going on with the target workqueue. Thanks. -- tejun

Hello, On Fri, Feb 25, 2011 at 12:46:16PM +0100, Dominik Klein wrote:

With 2.6.37 (also tried .1 and .2) it does not work but end up like I documented. With 2.6.38-rc1, it does work. With deadline scheduler, it also works in 2.6.37.

Okay, here's the problematic part. <idle>-0 [013] 1640.975562: workqueue_queue_work: work struct=ffff88080f14f270 function=blk_throtl_work workqueue=ffff88102c8fc700 req_cpu=13 cpu=13 <idle>-0 [013] 1640.975564: workqueue_activate_work: work struct ffff88080f14f270 <...>-477 [013] 1640.975574: workqueue_execute_start: work struct ffff88080f14f270: function blk_throtl_work <idle>-0 [013] 1641.087450: workqueue_queue_work: work struct=ffff88080f14f270 function=blk_throtl_work workqueue=ffff88102c8fc700 req_cpu=13 cpu=13 The workqueue is per-cpu, so we only need to follow cpu=13 cases. @1640, blk_throtl_work() is queued, activated and starts executing but never finishes. The same work item is never executed more than once at the same on the same CPU, so when the next work item is queued, it doesn't get activated until the previous execution is complete. The next thing to do would be finding out why blk_throtl_work() isn't finishing. sysrq-t or /proc/PID/stack should show us where it's stalled. Thanks. -- tejun

Hello, On Fri, Feb 25, 2011 at 03:41:47PM +0100, Dominik Klein wrote:

See attached logs of another run.

sysctl -w kernel.sysrq=1

echo blk > /sys/kernel/debug/tracing/current_tracer echo 1 > /sys/block/sdb/trace/enable echo workqueue_queue_work >> /sys/kernel/debug/tracing/set_event echo workqueue_activate_work >> /sys/kernel/debug/tracing/set_event echo workqueue_execute_start >> /sys/kernel/debug/tracing/set_event echo workqueue_execute_end >> /sys/kernel/debug/tracing/set_event

That makes attachment trace_pipe5.gz

echo 8 > /proc/sysrq-trigger echo t > /proc/sysrq-trigger

That makes attachment console.gz

So, the following work item never finished. We can tell that pid 549 started execution from the last line. <idle>-0 [017] 1497.601733: workqueue_queue_work: work struct=ffff880809f3fe70 function=blk_throtl_work workqueue=ffff88102c8ba700 req_cpu=17 cpu=17 <idle>-0 [017] 1497.601736: workqueue_activate_work: work struct ffff880809f3fe70 <...>-549 [017] 1497.601754: workqueue_execute_start: work struct ffff880809f3fe70: function blk_throtl_work And the stack trace of pid 549 is... [ 1522.220046] kworker/17:1 D ffff88202fc53600 0 549 2 0x00000000 [ 1522.220046] ffff88082c5bd7c0 0000000000000046 ffff88180a822600 ffff88082c578000 [ 1522.220046] 0000000000013600 ffff88080afaffd8 0000000000013600 0000000000013600 [ 1522.220046] ffff88082c5bda98 ffff88082c5bdaa0 ffff88082c5bd7c0 0000000000013600 [ 1522.220046] Call Trace: [ 1522.220046] [<ffffffff810395c6>] ? __wake_up+0x35/0x46 [ 1522.220046] [<ffffffff81315de3>] ? io_schedule+0x68/0xa7 [ 1522.220046] [<ffffffff81182168>] ? get_request_wait+0xee/0x17d [ 1522.220046] [<ffffffff810604f1>] ? autoremove_wake_function+0x0/0x2a [ 1522.220046] [<ffffffff811826b6>] ? __make_request+0x313/0x45d [ 1522.220046] [<ffffffff81180ebd>] ? generic_make_request+0x30d/0x385 [ 1522.220046] [<ffffffff8105cc79>] ? queue_delayed_work_on+0xfc/0x10a [ 1522.220046] [<ffffffff8118c607>] ? blk_throtl_work+0x312/0x32b [ 1522.220046] [<ffffffff8118c2f5>] ? blk_throtl_work+0x0/0x32b [ 1522.220046] [<ffffffff8105b754>] ? process_one_work+0x1d1/0x2ee [ 1522.220046] [<ffffffff8105d1e3>] ? worker_thread+0x12d/0x247 [ 1522.220046] [<ffffffff8105d0b6>] ? worker_thread+0x0/0x247 [ 1522.220046] [<ffffffff8105d0b6>] ? worker_thread+0x0/0x247 [ 1522.220046] [<ffffffff8106009f>] ? kthread+0x7a/0x82 [ 1522.220046] [<ffffffff8100a824>] ? kernel_thread_helper+0x4/0x10 [ 1522.220046] [<ffffffff81060025>] ? kthread+0x0/0x82 [ 1522.220046] [<ffffffff8100a820>] ? kernel_thread_helper+0x0/0x10 The '?'s are because frame pointer is disabled and means that the stack trace is a guesswork. Can you please turn on CONFIG_FRAME_POINTER just to be sure? But at any rate, it looks like blk_throtl_work() got stuck trying to allocate a request. I don't think workqueue is causing any problem here. It seems like a resource deadlock on request. Vivek, any ideas? Thanks. -- tejun

Hello, On Fri, Feb 25, 2011 at 09:57:08AM -0500, Vivek Goyal wrote:

blk_throtl_work() calls generic_make_request() to dispatch some bios and I guess blk_throtl_work() has been put to sleep because threre are no request descriptors available and CFQ is frozen so no requests descriptors get freed hence blk_throtl_work() never finishes.

Following caught my eye.

ksoftirqd/0-3 [000] 1640.983585: 8,16 m N cfq4810 slice expired t=0 ksoftirqd/0-3 [000] 1640.983588: 8,16 m N cfq4810 sl_used=2 disp=6 charge=2 iops=0 sect=2080 ksoftirqd/0-3 [000] 1640.983589: 8,16 m N cfq4810 del_from_rr ksoftirqd/0-3 [000] 1640.983591: 8,16 m N cfq schedule dispatch sshd-3125 [004] 1640.983597: workqueue_queue_work: work struct=ffff88102c3a3110 function=flush_to_ldisc workqueue=ffff88182c834a00 req_cpu=4 cpu=4 sshd-3125 [004] 1640.983598: workqueue_activate_work: work struct ffff88102c3a3110

CFQ tries to schedule a work and but there is no associated "workqueue_queue_work" trace. So it looks like that work never got queued.

CFQ calls following.

cfq_log(cfqd, "schedule dispatch"); kblockd_schedule_work(cfqd->queue, &cfqd->unplug_work);

We do see "schedule dispatch" message and kblockd_schedule_work() calls queue_work(). So what happended here? This is strange. I will put one more trace after kblockd_schedule_work() to trace that function returned.

It could be that the unplug work was already queued and in pending state. The second queueing request will be ignored then. So, I think the problem is that blk_throtl_work() occupies kblockd but requires another work item (unplug_work) to make forward progress. In such cases, forward progress cannot be guaranteed. Either blk_throtl_work() or cfq unplug work should use a separate workqueue. Thanks. -- tejun

On Fri, Feb 25, 2011 at 10:11:13AM -0500, Vivek Goyal wrote:

On Fri, Feb 25, 2011 at 04:03:29PM +0100, Tejun Heo wrote:

...

Hello,

On Fri, Feb 25, 2011 at 09:57:08AM -0500, Vivek Goyal wrote:

...

blk_throtl_work() calls generic_make_request() to dispatch some bios and I guess blk_throtl_work() has been put to sleep because threre are no request descriptors available and CFQ is frozen so no requests descriptors get freed hence blk_throtl_work() never finishes.

Following caught my eye.

ksoftirqd/0-3 [000] 1640.983585: 8,16 m N cfq4810 slice expired t=0 ksoftirqd/0-3 [000] 1640.983588: 8,16 m N cfq4810 sl_used=2 disp=6 charge=2 iops=0 sect=2080 ksoftirqd/0-3 [000] 1640.983589: 8,16 m N cfq4810 del_from_rr ksoftirqd/0-3 [000] 1640.983591: 8,16 m N cfq schedule dispatch sshd-3125 [004] 1640.983597: workqueue_queue_work: work struct=ffff88102c3a3110 function=flush_to_ldisc workqueue=ffff88182c834a00 req_cpu=4 cpu=4 sshd-3125 [004] 1640.983598: workqueue_activate_work: work struct ffff88102c3a3110

CFQ tries to schedule a work and but there is no associated "workqueue_queue_work" trace. So it looks like that work never got queued.

CFQ calls following.

cfq_log(cfqd, "schedule dispatch"); kblockd_schedule_work(cfqd->queue, &cfqd->unplug_work);

We do see "schedule dispatch" message and kblockd_schedule_work() calls queue_work(). So what happended here? This is strange. I will put one more trace after kblockd_schedule_work() to trace that function returned.

It could be that the unplug work was already queued and in pending state. The second queueing request will be ignored then. So, I think the problem is that blk_throtl_work() occupies kblockd but requires another work item (unplug_work) to make forward progress. In such cases, forward progress cannot be guaranteed. Either blk_throtl_work() or cfq unplug work should use a separate workqueue.

Ok, that would make sense. So blk_throtl_work() can not finish as CFQ is not making progress and no request descriptors are being freed and unplug_work() is not being called because blk_throtl_work() has not finished. So that's cyclic dependency and I should use a separate work queue for queueing throttle related work. I will write a patch.

The only thing unexplained is why same problem does not happen in 2.6.38-rc kernels. Thanks Vivek

On Fri, Feb 25, 2011 at 08:24:15AM +0100, Dominik Klein wrote:

...

Maybe watching what the workqueue is doing using the following trace events could be helpful.

# grep workqueue /sys/kernel/debug/tracing/available_events workqueue:workqueue_insertion workqueue:workqueue_execution workqueue:workqueue_creation workqueue:workqueue_destruction

Since I've never done this before, I will tell you how I captured the trace so you know what I did and can see whether I did something wrong and can correct me if necessary.

echo blk > /sys/kernel/debug/tracing/current_tracer echo 1 > /sys/block/sdb/trace/enable echo workqueue_queue_work >> /sys/kernel/debug/tracing/set_event echo workqueue_activate_work >> /sys/kernel/debug/tracing/set_event echo workqueue_execute_start >> /sys/kernel/debug/tracing/set_event echo workqueue_execute_end >> /sys/kernel/debug/tracing/set_event cat /sys/kernel/debug/tracing/trace_pipe

Just an FYI, If you download trace-cmd from: git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git You could do the following: # trace-cmd record -p blk -e workqueue_queue_work -e workqueue_activate_work -e workqueue_execute_start -e workqueue_execute_end <cmd> Where <cmd> could be sh -c "echo 1 > /sys/block/sdb/trace/enable; sleep 10" This will create a trace.dat file that you can read with trace-cmd report Another way, if you want to do more than just that echo is to use: # trace-cmd start -p blk -e workqueue_queue_work -e workqueue_activate_work -e workqueue_execute_start -e workqueue_execute_end # echo 1 > /sys/block/sdb/trace/enable # <do anyting you want> # trace-cmd stop # trace-cmd extract The start just enable ftrace (like you did with the echos). The extract will create the trace.dat file from the ftrace ring buffers. You could alse just cat trace_pipe, which would do the same, or you could do the echos, and then the trace-cmd stop and extract to get the file. It's your choice ;) You can then gzip the trace.dat file and send it to others that can read it as well, as all the information needed to read the trace is recorded in the file. You could even send the data over the network instead of writing the trace.dat locally. On another box: $ trace-cmd listen -p 12345 Then on the target: # trace-cmd record -N host:12345 ... This will send the data to the listening host and the file will be created on the host side. One added benefit of having the trace.dat file. kernelshark can read it. -- Steve

And that output i gzip'd.

This was taken with 2.6.37 plus the patch you mentioned on a Dell R815 with 2 12 core AMD Opteron 6174 CPUs. If you need any more information, please let me know.

On Fri, 2011-02-25 at 15:18 -0500, Vivek Goyal wrote:

Thanks Steve. In this case this feature of sending trace data over network would have helped. We were running into issues where IO scheduler was freezing so we could not read anything from disk(including saved traces). Hence we were directing everything to console and then doing copy paste.

So sending it over network would have probably worked even in this case.

Will give trace-cmd a try next time.

Hi Vivek, I just pushed out a hack that lets trace-cmd read the blktrace. I found that the blktrace never exported its structure to the /debug/tracing/events/ftrace/blktrace/format. So userspace has no real way to know how to parse it. Instead, I wrote a hack that creates this file semi dynamically, based on the information of other events. I also copied a lot of the blktrace code from the kernel so that it can print out the same format. You need to install the plugin that is built with trace-cmd. It will either be automatically installed if you do a make install, but if you do not have root access, just cp the plugin_blk.so into ~/.trace-cmd/plugins directory (you may need to make that directory yourself). Then when you run trace-cmd report on a file made with the blk tracer, it will give you a nice output. If you already have a trace.dat file from a previous extract, you don't need to run the trace again. The trace-cmd report will work on that file now. I'll be heading out to NYC on Monday for the End Users Conf and this weekend I need to get all my chores done around the house for the misses to let me go ;) Thus, I wont be doing much more till I get back at the end of next week. -- Steve