I'm currently using the live image to do some tests and I noticed that the write speed on my usb flash drive was horribly slow: root@yocto-machine:~# time (dd if=/dev/zero of=test.img bs=4096 count=30000 && sync) 30000+0 records in 30000+0 records out real 3m50.780s user 0m0.048s sys 0m2.572s Using the same hardware but this time with the flash drive directly formatted in ext2 (instead of the loop mounted ext3 fs): root@yocto-machine:~# time (dd if=/dev/zero of=test.img bs=4096 count=30000 && sync) 30000+0 records in 30000+0 records out real 0m23.216s user 0m0.016s sys 0m0.720 That's ~10 times slower when using the loop mounted ext3 fs. I also did a similar test using core-image-sato-crownbay.hddimg (denzil) and the results are similar looking: root@crownbay:~# time (dd if=/dev/zero of=test.img bs=4096 count=15000 && sync) 15000+0 records in 15000+0 records out real 2m2.786s user 0m0.004s sys 0m1.204s Surprisingly using core-image-sato-crownbay.hddimg (edison) gives much better results: root@crownbay:~# time (dd if=/dev/zero of=test.img bs=4096 count=15000 && sync) 15000+0 records in 15000+0 records out real 0m21.364s user 0m0.036s sys 0m1.132s Bottom line: My denzil image (live): 0.5 MB/s My denzil image (ext2): 5 MB/s core-image-sato-crownbay denzil: 0.5 MB/s core-image-sato-crownbay edison: 2.7 MB/s
What would you expect it to be? Do you have results from another system that are significantly better? I'm not surprised that a loop mount is significantly slower than a raw filesystem partition, although 10x is rather high. Do you see similar results on different USB sticks? What about on an HDD or an MMC device?
.
I would at least expect the performance to be similar between the edison and the denzil versions. Part of the tests I did previously were using the images provided by the yocto website (tests were done with core-image-sato-crownbay.hddimg from edison _and_ denzil) I haven't tested with an HDD yet. I'll do this and post the results.
Same test, this time using an HDD: denzil: root@crownbay:~# time (dd if=/dev/zero of=test.img bs=4096 count=15000 && sync) 15000+0 records in 15000+0 records out real 0m49.867s user 0m0.012s sys 0m1.188s edison: root@crownbay:~# time (dd if=/dev/zero of=test.img bs=4096 count=15000 && sync) 15000+0 records in 15000+0 records out real 0m2.542s user 0m0.012s sys 0m1.172s The hardware is exactly the same. The only difference is the hddimg used (one is core-sato from denzil, the other core-sato from edison). BTW, the file produced is 58.6M. Let me know if you need more info.
OK, the delta between edison and denzil is interesting and definitely worth investigating - especially since it isn't just on a USB flash drive. I would suggest next trying the denzil kernel on the edison image. I'd switch to core-image-minimal as you shouldn't need anything more than dd for your tests. I suspect the performance will not change here. Next I would attempt the inverse, edison kernel on a denzil image. I suspect this will still result in slow writes. This should show us that there is some difference in how the image is prepared, mounted, or something like that which is responsible for the difference. At this point, it's a matter of comparing the systems and browsing the git log to see what may have changed.
Results so far: denzil rootfs + edison kernel = ok edison rootfs + denzil kernel = slow! edison rootfs + edison kernel = ok So far it looks like the kernel is the culprit.
Great progress. Next I'd suggest comparing the .config from each kernel (available in your build/tmp directory under $MACHINE*/linux-yocto*/linux-*build/.config) and see if you can spot any obvious culprits. Consider a diff of the two configs and posting the sanitized results here.
Created attachment 774 [details] unified diff of .config Darren, Here's the unified diff between edison and denzil. I've look at it but quite frankly I don't really know what could be wrong... Maybe things like: +CONFIG_UNION_FS=y I'll disable it and see if it helps.
(In reply to comment #8) > Maybe things like: > +CONFIG_UNION_FS=y > > I'll disable it and see if it helps. Nope. Removing unionfs doesn't change anything.
Thanks for sticking with it. Nothing jumped out at me in the .config delta as a likely culprit. How is the HDD attached to the system? SATA? USB? To determine if this is a kernel sources or a config issue, consider building the denzil kernel with the edison config, and vice versa. Once we know that, we can begin to look at the deltas and possibly bisect the changes.
(In reply to comment #10) > Thanks for sticking with it. Nothing jumped out at me in the .config delta > as a likely culprit. > > How is the HDD attached to the system? SATA? USB? > USB
Asking our resident USB expert for ideas.
Since the device in question is attached via USB, consider this response from our resident USB expert: The only thing that jumps out at me is this: -# CONFIG_USB_EHCI_ROOT_HUB_TT is not set +CONFIG_USB_EHCI_ROOT_HUB_TT=y ... -CONFIG_USB_UHCI_HCD=y +# CONFIG_USB_UHCI_HCD is not set What system was this tested on? Some Intel systems have an integrated "rate matching hub" under the EHCI host. It looks like a high speed hub attached to the roothub. When that's used, USB 1.1 devices end up under the rate matching hub, rather than being under the companion controller (OHCI or UHCI). So perhaps try having the reporter turn off CONFIG_USB_EHCI_ROOT_HUB_TT and turn on CONFIG_USB_UHCI_HCD? I have no idea why having the device under EHCI rather than UHCI would make a difference, but it's one thing to rule out. Sarah Sharp
Ok, I followed Sarah's advices: *Turning off CONFIG_USB_EHCI_ROOT_HUB_TT and turning on CONFIG_USB_UHCI_HCD: Same results (slow). *Turning off CONFIG_USB_EHCI_ROOT_HUB_TT only: Same results (slow).
I'm currently building core-image-minimal with 'tools-profile'. Maybe oprofile will help identify who's fault it is. I'll also try the edison config with denzil. Thanks for your help!
Marc, with the HDD attached can you provide the output of "lsusb -t" for each of the kernels?
Marc, it may be time to take this to the usb-storage maintainer. But first we will need to determine if we can reproduce on a recent kernel (3.5+ for example). Is that something you can do fairly readily?
(In reply to comment #17) > Marc, it may be time to take this to the usb-storage maintainer. But first > we will need to determine if we can reproduce on a recent kernel (3.5+ for > example). Is that something you can do fairly readily? I'll try generating an image with linux-yocto-dev and meta/meta-intel from master.
Darren, I've tested with 3.6.0-rc4 and I still have the same issue. Just to be sure, I've also retested with the 3.0.10-yocto-standard kernel (using the exact same image, just replaced the vmlinuz file) and the problem isn't there. The test that I've run is: dd if=/dev/zero of=test.img bs=4096 count=500 && sync With 3.6.0-rc4 I get ~1.8 second and with 3.0.10 I get ~0.2 second.
That's excellent. If you will post the 3.0 and the 3.6 configs, I'll take this along to the usb-storage maintainer and lkml. This appears to be something we may need to fix upstream. Thanks for following through!
Created attachment 784 [details] 3.6.0-rc4 config
Created attachment 785 [details] 3.0.10 config
Marc, can you share the mount options for the fast and slow cases?
Created attachment 801 [details] Output of mount command on edison
Created attachment 802 [details] Output of mount command on denzil
Thanks Marc, these can be summarized as: denzil /dev/sda on /media/sda type vfat (rw,sync,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) /dev/loop0 on / type ext3 (rw,noatime,nodiratime,barrier=1,data=ordered) edison /dev/sda on /media/sda type vfat (rw,sync,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) /dev/loop0 on / type ext3 (rw,noatime,nodiratime,barrier=0,data=ordered) The only difference I see is barrier for the loop device. Can you experiment with barrier set to 0 and 1 (using the -o remount option might make this easier) and see if that has an impact? MOUNT(8): barrier=0 / barrier=1 This enables/disables barriers. barrier=0 disables it, barrier=1 enables it. Write barriers enforce proper on-disk ordering of journal commits, making volatile disk write caches safe to use, at some performance penalty. The ext3 filesystem does not enable write barriers by default. Be sure to enable barriers unless your disks are battery-backed one way or another. Otherwise you risk filesystem corruption in case of power failure.
Interesting. The 'barrier' option seems to be linked to the kernel used: denzil image + edison kernel -> barrier=0 denzil image + denzil kernel -> barrier=1 On a clean denzil image (core-image-minimal-crownbay.hddimg) remounting with barrier=0 or barrier=1 doesn't seem to have any effect.
I did another test involving an ordinary usb flash drive. I just copied a 2Mb file from the "internal" drive (rootfs) to the "external" flash drive and it took 17sec. So it looks like it might not only be related to the loop mounted ext3 image.
I looked into this over the weekend a bit, just reporting what I found and a possible commit to try reverting. Basically, on denzil I used the same dd test with different kernels on a the same USB flash drive (dd if=/dev/zero of=test.img bs=4096 count=30000 && sync but in a bash script called 'ddtest'). First, simple timings: With a 3.0 kernel, we get (I assume) normal times: time ./ddtest 30000+0 records in 30000+0 records out real 1m2.329s user 0m0.028s sys 0m2.520s With a 3.2 kernel, we get much higher times: time ./ddtest 30000+0 records in 30000+0 records out real 5m37.627s user 0m0.024s sys 0m2.488s And with a 3.4 kernel (using master), we get normal times again: time ./ddtest 30000+0 records in 30000+0 records out real 0m55.601s user 0m0.062s sys 0m2.580s So something in the 3.2 kernel seems to be causing the slower times. Next, I did a 'perf stat' for each to see if anything jumped out (this test is the same as ddtest, but only writing 300 blocks to keep traces manageable): Here's the 3.0 kernel: time perf stat -a ./ddtest.300 300+0 records in 300+0 records out Performance counter stats for './ddtest.300': 442.836325 task-clock # 2.006 CPUs utilized 531 context-switches # 0.001 M/sec 72 CPU-migrations # 0.000 M/sec 571 page-faults # 0.001 M/sec 97672514 cycles # 0.221 GHz <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 33386839 instructions # 0.34 insns per cycle 6389947 branches # 14.430 M/sec 409664 branch-misses # 6.41% of all branches 0.220779929 seconds time elapsed real 0m0.371s user 0m0.000s sys 0m0.036s Here's the same test using the 3.2 kernel. This shows many more context switches: time perf stat -a ./ddtest.300 300+0 records in 300+0 records out Performance counter stats for './ddtest.300': 6372.734041 task-clock # 2.000 CPUs utilized [100.0 0%] 16331 context-switches # 0.003 M/sec [100.0 0%] 55 CPU-migrations # 0.000 M/sec [100.0 0%] 573 page-faults # 0.000 M/sec 791572929 cycles # 0.124 GHz [100.0 0%] <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 159085861 instructions # 0.20 insns per cycle [100.0 0%] 28412920 branches # 4.459 M/sec [100.0 0%] 3417082 branch-misses # 12.03% of all branches 3.185630803 seconds time elapsed real 0m3.336s user 0m0.000s sys 0m0.036s With the 3.4 kernel and master, it looks like we're back to normal again: time perf stat -a ./ddtest.300 300+0 records in 300+0 records out Performance counter stats for './ddtest.300': 1593.630810 task-clock # 2.004 CPUs utilized [100.0 0%] 512 context-switches # 0.321 K/sec [100.0 0%] 18 CPU-migrations # 0.011 K/sec [100.0 0%] 595 page-faults # 0.373 K/sec 93092898 cycles # 0.058 GHz [100.0 0%] <not supported> stalled-cycles-frontend <not supported> stalled-cycles-backend 30479446 instructions # 0.33 insns per cycle [100.0 0%] 5933468 branches # 3.723 M/sec [100.0 0%] 355591 branch-misses # 5.99% of all branches 0.795144907 seconds time elapsed real 0m0.809s user 0m0.001s sys 0m0.043s To get some more information about what might be happening, I did a trace with each kernel using 'perf script': perf record -e sched:sched_switch -e sched:sched_wakeup -e block:* -o /media/sdc/perf.data -ag ./ddtest.300 perf script This records a couple scheduler events and all available block events. The approximate numbers of events is much higher from looking at the output of the perf script file sizes: [trz@empanada reports]$ wc -l perfscript-block-3.0.txt 2664 perfscript-block-3.0.txt [trz@empanada reports]$ wc -l perfscript-block-3.2.txt 42143 perfscript-block-3.2.txt [trz@empanada reports]$ wc -l perfscript-block-3.4.txt 4747 perfscript-block-3.4.txt Looking at the 3.2 output first, the file mostly consists of repeated blocks like the following. Basically it looks like the loop device is continually submitting 2 sectors at a time and unplugging: loop0 484 [001] 109.273798: block_bio_queue: 8,0 WS 362197 + 1 [loop0] loop0 484 [001] 109.273807: block_getrq: 8,0 WS 362197 + 1 [loop0] loop0 484 [001] 109.273813: block_plug: [loop0] loop0 484 [001] 109.273819: block_bio_queue: 8,0 WS 362198 + 1 [loop0] loop0 484 [001] 109.273824: block_bio_backmerge: 8,0 WS 362198 + 1 [loop0] loop0 484 [001] 109.273835: block_rq_insert: 8,0 WS 0 () 362197 + 2 [loop0] loop0 484 [001] 109.273841: block_unplug: [loop0] 1 loop0 484 [001] 109.273847: block_rq_issue: 8,0 WS 0 () 362197 + 2 [loop0] swapper 0 [000] 109.273868: sched_wakeup: comm=usb-storage pid=39 prio=120 success=1 target_cpu=000 loop0 484 [001] 109.273871: sched_switch: prev_comm=loop0 prev_pid=484 prev_prio=100 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120 swapper 0 [000] 109.273885: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=usb-storage next_pid=39 next_prio=120 usb-storage 39 [000] 109.273902: sched_switch: prev_comm=usb-storage prev_pid=39 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 swapper 0 [000] 109.273990: sched_wakeup: comm=usb-storage pid=39 prio=120 success=1 target_cpu=000 swapper 0 [000] 109.274024: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=usb-storage next_pid=39 next_prio=120 usb-storage 39 [000] 109.274039: sched_switch: prev_comm=usb-storage prev_pid=39 prev_prio=120 prev_state=D ==> next_comm=swapper/0 next_pid=0 next_prio=120 swapper 0 [000] 109.274490: sched_wakeup: comm=usb-storage pid=39 prio=120 success=1 target_cpu=000 swapper 0 [000] 109.274523: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=usb-storage next_pid=39 next_prio=120 usb-storage 39 [000] 109.274536: sched_switch: prev_comm=usb-storage prev_pid=39 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 swapper 0 [000] 109.275238: sched_wakeup: comm=usb-storage pid=39 prio=120 success=1 target_cpu=000 swapper 0 [000] 109.275272: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=usb-storage next_pid=39 next_prio=120 usb-storage 39 [000] 109.275283: sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 success=1 target_cpu=000 usb-storage 39 [000] 109.275290: sched_switch: prev_comm=usb-storage prev_pid=39 prev_prio=120 prev_state=R+ ==> next_comm=ksoftirqd/0 next_pid=3 next_prio=120 ksoftirqd/0 3 [000] 109.275297: block_rq_complete: 8,0 WS () 362197 + 2 [0] swapper 0 [001] 109.275315: sched_wakeup: comm=loop0 pid=484 prio=100 success=1 target_cpu=001 ksoftirqd/0 3 [000] 109.275320: sched_wakeup: comm=kworker/0:1 pid=10 prio=120 success=1 target_cpu=000 swapper 0 [001] 109.275338: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=loop0 next_pid=484 next_prio=100 ksoftirqd/0 3 [000] 109.275341: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=120 prev_state=S ==> next_comm=kworker/0:1 next_pid=10 next_prio=120 kworker/0:1 10 [000] 109.275354: sched_switch: prev_comm=kworker/0:1 prev_pid=10 prev_prio=120 prev_state=S ==> next_comm=usb-storage next_pid=39 next_prio=120 usb-storage 39 [000] 109.275364: sched_switch: prev_comm=usb-storage prev_pid=39 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 The output of the 3.0 case doesn't show any block write activity at all coming from loop0 (only reads). The output of the 3.4 case does show block write activity from loop0, but much more merging and considation of requests going on: loop0 515 [000] 47.309061: block_bio_queue: 8,0 W 552659 + 48 [loop0] loop0 515 [000] 47.309078: block_getrq: 8,0 W 552659 + 48 [loop0] loop0 515 [000] 47.309088: block_plug: [loop0] loop0 515 [000] 47.309099: block_bio_queue: 8,0 WS 552707 + 1 [loop0] loop0 515 [000] 47.309128: sched_wakeup: comm=usb-storage pid=45 prio=120 success=1 target_cpu=001 swapper 0 [001] 47.309158: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=usb-storage next_pid=45 next_prio=120 loop0 515 [000] 47.309170: block_bio_backmerge: 8,0 WS 552707 + 1 [loop0] loop0 515 [000] 47.309178: block_bio_queue: 8,0 WS 552708 + 1 [loop0] loop0 515 [000] 47.309185: block_bio_backmerge: 8,0 WS 552708 + 1 [loop0] usb-storage 45 [001] 47.309192: sched_switch: prev_comm=usb-storage prev_pid=45 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120 loop0 515 [000] 47.309193: block_bio_queue: 8,0 WS 552709 + 1 [loop0] loop0 515 [000] 47.309200: block_bio_backmerge: 8,0 WS 552709 + 1 [loop0] loop0 515 [000] 47.309207: block_bio_queue: 8,0 WS 552710 + 1 [loop0] loop0 515 [000] 47.309213: block_bio_backmerge: 8,0 WS 552710 + 1 [loop0] loop0 515 [000] 47.309228: block_bio_queue: 8,0 W 575155 + 20 [loop0] loop0 515 [000] 47.309237: block_getrq: 8,0 W 575155 + 20 [loop0] loop0 515 [000] 47.309248: block_bio_queue: 8,0 WS 576609 + 1 [loop0] loop0 515 [000] 47.309255: block_getrq: 8,0 WS 576609 + 1 [loop0] loop0 515 [000] 47.309262: block_bio_queue: 8,0 WS 576610 + 1 [loop0] loop0 515 [000] 47.309267: block_bio_backmerge: 8,0 WS 576610 + 1 [loop0] loop0 515 [000] 47.309276: block_bio_queue: 8,0 W 576611 + 2 [loop0] loop0 515 [000] 47.309281: block_bio_backmerge: 8,0 W 576611 + 2 [loop0] loop0 515 [000] 47.309290: block_bio_queue: 8,0 WS 596317 + 1 [loop0] loop0 515 [000] 47.309297: block_getrq: 8,0 WS 596317 + 1 [loop0] loop0 515 [000] 47.309303: block_bio_queue: 8,0 WS 596318 + 1 [loop0] loop0 515 [000] 47.309307: block_bio_backmerge: 8,0 WS 596318 + 1 [loop0] loop0 515 [000] 47.309312: block_bio_queue: 8,0 WS 596319 + 1 [loop0] loop0 515 [000] 47.309316: block_bio_backmerge: 8,0 WS 596319 + 1 [loop0] loop0 515 [000] 47.309321: block_bio_queue: 8,0 WS 596320 + 1 [loop0] loop0 515 [000] 47.309307: block_bio_backmerge: 8,0 WS 596318 + 1 [loop0] loop0 515 [000] 47.309312: block_bio_queue: 8,0 WS 596319 + 1 [loop0] loop0 515 [000] 47.309316: block_bio_backmerge: 8,0 WS 596319 + 1 [loop0] loop0 515 [000] 47.309321: block_bio_queue: 8,0 WS 596320 + 1 [loop0] loop0 515 [000] 47.309325: block_bio_backmerge: 8,0 WS 596320 + 1 [loop0] loop0 515 [000] 47.309330: block_bio_queue: 8,0 WS 596321 + 1 [loop0] loop0 515 [000] 47.309334: block_bio_backmerge: 8,0 WS 596321 + 1 [loop0] loop0 515 [000] 47.309339: block_bio_queue: 8,0 WS 596322 + 1 [loop0] loop0 515 [000] 47.309343: block_bio_backmerge: 8,0 WS 596322 + 1 [loop0] loop0 515 [000] 47.309426: block_bio_queue: 8,0 W 596323 + 240 [loop0] loop0 515 [000] 47.309435: block_getrq: 8,0 W 596323 + 240 [loop0] loop0 515 [000] 47.309485: block_bio_queue: 8,0 W 596563 + 156 [loop0] loop0 515 [000] 47.309492: block_getrq: 8,0 W 596563 + 156 [loop0] loop0 515 [000] 47.309565: block_bio_queue: 8,0 W 596723 + 240 [loop0] loop0 515 [000] 47.309573: block_getrq: 8,0 W 596723 + 240 [loop0] loop0 515 [000] 47.309598: block_bio_queue: 8,0 W 596963 + 42 [loop0] loop0 515 [000] 47.309625: sched_wakeup: comm=usb-storage pid=45 prio=120 success=1 target_cpu=001 swapper 0 [001] 47.309656: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=usb-storage next_pid=45 next_prio=120 loop0 515 [000] 47.309666: block_getrq: 8,0 W 596963 + 42 [loop0] usb-storage 45 [001] 47.309682: sched_switch: prev_comm=usb-storage prev_pid=45 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120 loop0 515 [000] 47.309683: block_bio_queue: 8,0 WS 622503 + 1 [loop0] loop0 515 [000] 47.309695: block_getrq: 8,0 WS 622503 + 1 [loop0] loop0 515 [000] 47.309706: block_bio_queue: 8,0 WS 622504 + 1 [loop0] loop0 515 [000] 47.309711: block_bio_backmerge: 8,0 WS 622504 + 1 [loop0] loop0 515 [000] 47.309716: block_bio_queue: 8,0 WS 622505 + 1 [loop0] loop0 515 [000] 47.309720: block_bio_backmerge: 8,0 WS 622505 + 1 [loop0] loop0 515 [000] 47.309725: block_bio_queue: 8,0 WS 622506 + 1 [loop0] loop0 515 [000] 47.309729: block_bio_backmerge: 8,0 WS 622506 + 1 [loop0] loop0 515 [000] 47.309750: block_bio_queue: 8,0 W 622507 + 42 [loop0] loop0 515 [000] 47.309755: block_bio_backmerge: 8,0 W 622507 + 42 [loop0] loop0 515 [000] 47.309764: block_bio_queue: 8,0 WS 680393 + 1 [loop0] loop0 515 [000] 47.309772: block_getrq: 8,0 WS 680393 + 1 [loop0] loop0 515 [000] 47.309778: block_bio_queue: 8,0 WS 680394 + 1 [loop0] loop0 515 [000] 47.309755: block_bio_backmerge: 8,0 W 622507 + 42 [loop0] loop0 515 [000] 47.309764: block_bio_queue: 8,0 WS 680393 + 1 [loop0] loop0 515 [000] 47.309772: block_getrq: 8,0 WS 680393 + 1 [loop0] loop0 515 [000] 47.309778: block_bio_queue: 8,0 WS 680394 + 1 [loop0] loop0 515 [000] 47.309783: block_bio_backmerge: 8,0 WS 680394 + 1 [loop0] loop0 515 [000] 47.309814: block_bio_queue: 8,0 W 680395 + 80 [loop0] loop0 515 [000] 47.309819: block_bio_backmerge: 8,0 W 680395 + 80 [loop0] loop0 515 [000] 47.309826: block_rq_insert: 8,0 W 0 () 552659 + 52 [loop0] loop0 515 [000] 47.309833: block_rq_insert: 8,0 W 0 () 575155 + 20 [loop0] loop0 515 [000] 47.309838: block_rq_insert: 8,0 WS 0 () 576609 + 4 [loop0] loop0 515 [000] 47.309849: block_rq_insert: 8,0 WS 0 () 596317 + 6 [loop0] loop0 515 [000] 47.309854: block_rq_insert: 8,0 W 0 () 596323 + 240 [loop0] loop0 515 [000] 47.309859: block_rq_insert: 8,0 W 0 () 596563 + 156 [loop0] loop0 515 [000] 47.309863: block_rq_insert: 8,0 W 0 () 596723 + 240 [loop0] loop0 515 [000] 47.309867: block_rq_insert: 8,0 W 0 () 596963 + 42 [loop0] loop0 515 [000] 47.309871: block_rq_insert: 8,0 WS 0 () 622503 + 46 [loop0] loop0 515 [000] 47.309876: block_rq_insert: 8,0 WS 0 () 680393 + 82 [loop0] loop0 515 [000] 47.309882: block_unplug: [loop0] 10 loop0 515 [000] 47.309896: sched_switch: prev_comm=loop0 prev_pid=515 prev_prio=100 prev_state=D ==> next_comm=perf next_pid=1111 next_prio=120 Looking at the perf report output (we recorded with -g so get to see the stack) we see this for 3.2: 7.10% loop0 [kernel.kallsyms] [k] __schedule | --- __schedule schedule | |--99.35%-- io_schedule | | | |--99.84%-- sleep_on_page | | | | | |--99.67%-- __wait_on_bit | | | wait_on_page_bit | | | filemap_fdatawait_range | | | filemap_write_and_wait_range | | | generic_file_fsync | | | fat_file_fsync | | | generic_write_sync | | | generic_file_aio_write | | | do_sync_write | | | __do_lo_send_write | | | do_lo_send_direct_write | | | loop_thread | | | kthread | | | kernel_thread_helper | | --0.33%-- [...] | --0.16%-- [...] | --0.65%-- loop_thread kthread kernel_thread_helper And for 3.0: 4.57% loop0 [kernel.kallsyms] [k] schedule | --- schedule | |--56.67%-- loop_thread | kthread | kernel_thread_helper | |--40.00%-- io_schedule | | | |--91.67%-- sleep_on_page | | __wait_on_bit_lock | | __lock_page | | __generic_file_splice_read | | generic_file_splice_read | | do_splice_to | | splice_direct_to_actor | | loop_thread | | kthread | | kernel_thread_helper | | | --8.33%-- sleep_on_buffer | __wait_on_bit | out_of_line_wait_on_bit | __wait_on_buffer | __bread | fat_ent_bread | fat_ent_read | fat_get_cluster | fat_bmap | fat_get_block | do_mpage_readpage | mpage_readpages | fat_readpages | __do_page_cache_readahead | ondemand_readahead | page_cache_sync_readahead | __generic_file_splice_read | generic_file_splice_read | do_splice_to | splice_direct_to_actor | loop_thread | kthread | kernel_thread_helper | --3.33%-- preempt_schedule_irq need_resched Looking at the changes to the loop device since 3.0 the only commit that touches this area of code is: commit 456be1484ffc72a24bdb4200b5847c4fa90139d9 Author: Christoph Hellwig <hch@infradead.org> Date: Mon Oct 17 12:57:20 2011 +0200 loop: remove the incorrect write_begin/write_end shortcut Reverting this commit in denzil 'fixes' the problem for me - the ddtest time is pretty much the same as with 3.0. So please try reverting this commit and see if that helps. If this is the problem, the actual cause needs more analysis - the change seems to match what we see in the trace data, but to really explain it will take some digging around in the code. Also, the fact is that it's apparently fixed in 3.4 since at least I don't see the problem with poky/master and linux-yocto-3.4. Also, annoyingly, a quick test of replacing the 3.4 kernel with the same 3.2 kernel that exhibited the problem didn't show a problem - the ddtest was fast again in that case, unexpectedly, so we may be missing something simpler in the system configuration.
Great thorought performance analysis! I will try reverting this commit as soon as I can and redo the tests on my platform. Would it be possible to have the numbers for the 3.6 kernel? My tests indicated that the problem was still present in that version.
Tried the 3.6 kernel with denzil, and indeed we do get the slow write speeds: Linux crownbay 3.6.0-rc4-yocto-standard #1 SMP PREEMPT Tue Sep 18 15:18:36 CDT 2012 i6 86 GNU/Linux time ./ddtest 30000+0 records in 30000+0 records out real 5m41.701s user 0m0.040s sys 0m1.948s The same kernel with master shows 'normal' writes: Linux crownbay 3.6.0-rc4-yocto-standard #2 SMP PREEMPT Tue Sep 18 17:42:25 CDT 2012 i6 86 GNU/Linux time ./ddtest 30000+0 records in 30000+0 records out real 0m42.841s user 0m0.047s sys 0m2.049s The same kernel with denzil, but with the reverted loop commit, also shows normal writes: Linux crownbay 3.6.0-rc4-yocto-standard #1 SMP PREEMPT Tue Sep 18 18:49:54 CDT 2012 i6 86 GNU/Linux time ./ddtest 30000+0 records in 30000+0 records out real 0m53.733s user 0m0.051s sys 0m2.054s As far as denzil goes, reverting that commit gets back to normal speeds, but something in master renders it irrevant either way. So I'd expect that if you reverted the loop commit in denzil you'd have normal speeds as well as if you tried current master, which uses the 3.4 kernel, but doesn't exhibit the problem. If you could verify those cases it would be great and in the meantime the task will be to figure out what in master has caused the problem to not be seen there (for now).
Tom, Darren, I've tried reverting the commit and it does fix the problem for me. One thing I also noticed is that, by default, drives are mounted _sync_ by udev with the mount.sh script. This same mount.sh script is also used in the core-image-minimal-initramfs image. This could explain the slow rootfs _and_ the slow "external" drives. I will try removing the sync option from the mount.sh script and post the results here. One question remains though: Why does it work in edison even with the sync option? Kernel bug that got fixed in 3.2? Still present in 3.4?
I think you're right about the sync mounts in mount.sh, and in fact if you look at recent git history, there's this patch that removes it, and which explains why we don't see the slow writes any more in master even with the loop: commit (I haven't tried it yet, but my guess is that if you pulled this patch into denzil you'd see normal write times again without having to revert the loop: patch): commit 9eea1ebe3e4b27529780dfafaf424d373bfb2867 Author: Jesse Zhang <sen.zhang@windriver.com> Date: Wed Jul 4 10:03:13 2012 +0800 udev: don't mount with -o sync So it all seems to make more sense now and fits the trace data. In edison (3.0), if you look at the code the commit 'loop: remove the incorrect write_begin/write_end shortcut' removes, it's code that writes directly to the pagecache and doesn't actually hit the vfs write path. In my earlier analysis, I mentioned that before that commit, you don't see any writes to the loop device like you do afterwards. I didn't show any trace data for that but here's a sample of where the writes do happen in that case: flush-8:0 904 [001] 75.380141: block_bio_queue: 8,0 W 12737 + 1 [flush-8:0] flush-8:0 904 [001] 75.380152: block_getrq: 8,0 W 12737 + 1 [flush-8:0] flush-8:0 904 [001] 75.380160: block_plug: [flush-8:0] flush-8:0 904 [001] 75.380166: block_bio_queue: 8,0 W 12738 + 1 [flush-8:0] flush-8:0 904 [001] 75.380171: block_bio_backmerge: 8,0 W 12738 + 1 [flush-8:0] flush-8:0 904 [001] 75.380184: block_bio_queue: 8,0 W 12743 + 4 [flush-8:0] flush-8:0 904 [001] 75.380190: block_getrq: 8,0 W 12743 + 4 [flush-8:0] flush-8:0 904 [001] 75.380201: block_bio_queue: 8,0 W 995951 + 2 [flush-8:0] flush-8:0 904 [001] 75.380209: block_getrq: 8,0 W 995951 + 2 [flush-8:0] flush-8:0 904 [001] 75.380219: block_bio_queue: 8,0 W 1142139 + 1 [flush-8:0] flush-8:0 904 [001] 75.380225: block_getrq: 8,0 W 1142139 + 1 [flush-8:0] flush-8:0 904 [001] 75.380232: block_bio_queue: 8,0 W 1142140 + 1 [flush-8:0] flush-8:0 904 [001] 75.380237: block_bio_backmerge: 8,0 W 1142140 + 1 [flush-8:0] flush-8:0 904 [001] 75.380242: block_bio_queue: 8,0 W 1142141 + 1 [flush-8:0] flush-8:0 904 [001] 75.380246: block_bio_backmerge: 8,0 W 1142141 + 1 [flush-8:0] flush-8:0 904 [001] 75.380251: block_bio_queue: 8,0 W 1142142 + 1 [flush-8:0] flush-8:0 904 [001] 75.380255: block_bio_backmerge: 8,0 W 1142142 + 1 [flush-8:0] flush-8:0 904 [001] 75.380264: block_bio_queue: 8,0 W 1142159 + 2 [flush-8:0] flush-8:0 904 [001] 75.380271: block_getrq: 8,0 W 1142159 + 2 [flush-8:0] flush-8:0 904 [001] 75.380280: block_bio_queue: 8,0 W 1145195 + 1 [flush-8:0] flush-8:0 904 [001] 75.380287: block_getrq: 8,0 W 1145195 + 1 [flush-8:0] flush-8:0 904 [001] 75.380294: block_bio_queue: 8,0 W 1145196 + 1 [flush-8:0] flush-8:0 904 [001] 75.380298: block_bio_backmerge: 8,0 W 1145196 + 1 [flush-8:0] flush-8:0 904 [001] 75.380306: block_bio_queue: 8,0 W 1387659 + 1 [flush-8:0] flush-8:0 904 [001] 75.380313: block_getrq: 8,0 W 1387659 + 1 [flush-8:0] flush-8:0 904 [001] 75.380319: block_bio_queue: 8,0 W 1387660 + 1 [flush-8:0] flush-8:0 904 [001] 75.380324: block_bio_backmerge: 8,0 W 1387660 + 1 [flush-8:0] flush-8:0 904 [001] 75.380329: block_bio_queue: 8,0 W 1387661 + 1 [flush-8:0] flush-8:0 904 [001] 75.380333: block_bio_backmerge: 8,0 W 1387661 + 1 [flush-8:0] flush-8:0 904 [001] 75.380338: block_bio_queue: 8,0 W 1387662 + 1 [flush-8:0] flush-8:0 904 [001] 75.380343: block_bio_backmerge: 8,0 W 1387662 + 1 [flush-8:0] flush-8:0 904 [001] 75.380359: block_bio_queue: 8,0 W 1387679 + 2 [flush-8:0] swapper 0 [000] 75.380369: sched_wakeup: comm=usb-storage pid=38 prio=120 success=1 target_cpu=000 . . . flush-8:0 904 [001] 75.380560: block_rq_insert: 8,0 W 0 () 995951 + 2 [flush-8:0] flush-8:0 904 [001] 75.380567: block_rq_insert: 8,0 W 0 () 1142139 + 4 [flush-8:0] flush-8:0 904 [001] 75.380572: block_rq_insert: 8,0 W 0 () 1142159 + 2 [flush-8:0] flush-8:0 904 [001] 75.380577: block_rq_insert: 8,0 W 0 () 1145195 + 2 [flush-8:0] flush-8:0 904 [001] 75.380582: block_rq_insert: 8,0 W 0 () 1387659 + 4 [flush-8:0] flush-8:0 904 [001] 75.380587: block_rq_insert: 8,0 W 0 () 1387679 + 2 [flush-8:0] flush-8:0 904 [001] 75.380592: block_rq_insert: 8,0 W 0 () 1389693 + 2 [flush-8:0] flush-8:0 904 [001] 75.380597: block_rq_insert: 8,0 W 0 () 1813227 + 4 [flush-8:0] flush-8:0 904 [001] 75.380603: block_rq_insert: 8,0 W 0 () 1813247 + 2 [flush-8:0] flush-8:0 904 [001] 75.380608: block_unplug: [flush-8:0] 11 So basically this is what you'd expect, the 'flush' thread flushing the pagecache for that device, and not in the extremely inefficient way the loop device writes would happen after the 'loop: remove shortcut' commit forced the loop device to use vfs writes and thereby directly honor the sync mount option. Removing the sync option rather than reverting the loop: commit should get things back to normal again, since writes to the loop device are no longer forced synchronous and the block layer can do its job at scheduling the I/O again as it should...
I have applied the commit Tom mentionned and it does indeed fix the issue completely. Big thanks to both of you!
Targeted for 1.2.2 as this is not a problem in current 1.3/master builds. A backport to denzil is all that is necessary here.
Patch submitted to oe-core. And thanks for persevering and providing the insights and data!
Fixed in oe-core and poky denzil as of: http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?h=denzil&id=b4bb378261cea2deb413fbb797e381a693dab7ae