Bug 10549 - very bad I/O performance with linux kernel in 2.6.24
Summary: very bad I/O performance with linux kernel in 2.6.24
Status: CLOSED UNREPRODUCIBLE
Alias: None
Product: IO/Storage
Classification: Unclassified
Component: Block Layer (show other bugs)
Hardware: All Linux
: P1 high
Assignee: Jens Axboe
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-04-24 10:45 UTC by Ritesh Raj Sarraf
Modified: 2012-05-21 15:10 UTC (History)
2 users (show)

See Also:
Kernel Version: 2.6.24
Tree: Mainline
Regression: No


Attachments
dmesg output during low i/o (45.74 KB, text/plain)
2008-04-24 10:46 UTC, Ritesh Raj Sarraf
Details
iostat output during I/O (60.40 KB, text/plain)
2008-04-24 13:57 UTC, Ritesh Raj Sarraf
Details

Description Ritesh Raj Sarraf 2008-04-24 10:45:13 UTC
Latest working kernel version: N/A

Earliest failing kernel version: 2.6.24

Distribution: Kubuntu 8.04

Hardware Environment:
Dell XPS M1210
 Proc 2.0Ghz
 RAM: 2 GB
 HDD: SATA 60 GB

Software Environment:
rrs@learner:~$ lsb_release -rd
 Description: Ubuntu 8.04
 Release: 8.04
Kernel:
 rrs@learner:~$ uname -a
 Linux learner 2.6.24-16-generic #1 SMP Thu Apr 10 13:23:42 UTC 2008 i686 GNU/Linux

Problem Description:
I see very bad I/O performance when doing a large copy of small files on my laptop.
 I'm using dm-crypt for my root filesystem and am using dm-crypt on my external USB HDD. I try to copy around 16 GB of data from my root filesystem to the external USB HDD and the performance is very bad. I eventually end up getting a speed of 50 kB/S. The system is barely responsive.
From dmesg, these are some very interesting messages I see.....
[12485.056379] ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
 [12485.056729] ata2.00: cmd a0/00:00:00:0c:00/00:00:00:00:00/a0 tag 0 pio 12 in
 [12485.056761] cdb 43 00 00 00 00 00 00 00 0c 00 00 00 00 00 00 00
 [12485.056823] res 51/20:03:00:0c:00/00:00:00:00:00/a0 Emask 0x3 (HSM violation)
 [12485.056919] ata2.00: status: { DRDY ERR }
 [12485.057436] ata2: soft resetting link
 [12487.704204] ata2.00: configured for UDMA/33
 [12487.704652] ata2: EH complete
 [13077.097783] CPU0 attaching NULL sched-domain.
 [13077.097911] CPU1 attaching NULL sched-domain.
 [13077.122603] CPU0 attaching sched-domain:
 [13077.122698] domain 0: span 03
 [13077.122731] groups: 01 02
 [13077.122825] domain 1: span 03
 [13077.122858] groups: 03
 [13077.122921] CPU1 attaching sched-domain:
 [13077.122954] domain 0: span 03
 [13077.122987] groups: 02 01
 [13077.123051] domain 1: span 03
 [13077.123113] groups: 03
 [13257.567642] CPU0 attaching NULL sched-domain.
 [13257.567768] CPU1 attaching NULL sched-domain.
 [13257.817747] CPU0 attaching sched-domain:
 [13257.818066] domain 0: span 03
 [13257.818100] groups: 01 02
 [13257.818194] CPU1 attaching sched-domain:
 [13257.818227] domain 0: span 03
 [13257.818260] groups: 02 01
 [16918.726319] CPU0 attaching NULL sched-domain.
 [16918.726478] CPU1 attaching NULL sched-domain.
 [16918.742973] CPU0 attaching sched-domain:
 [16918.743068] domain 0: span 03
 [16918.743131] groups: 01 02
 [16918.743196] domain 1: span 03
 [16918.743258] groups: 03
 [16918.743322] CPU1 attaching sched-domain:
 [16918.743354] domain 0: span 03
 [16918.743387] groups: 02 01
 [16918.743481] domain 1: span 03
 [16918.743513] groups: 03
 [17708.858904] CPU0 attaching NULL sched-domain.
 [17708.859125] CPU1 attaching NULL sched-domain.
 [17708.884150] CPU0 attaching sched-domain:
 [17708.884278] domain 0: span 03
 [17708.884343] groups: 01 02
 [17708.884469] CPU1 attaching sched-domain:
 [17708.884501] domain 0: span 03
 [17708.884534] groups: 02 01
 [18584.899435] CPU0 attaching NULL sched-domain.
 [18584.899593] CPU1 attaching NULL sched-domain.
 [18584.918651] CPU0 attaching sched-domain:
 [18584.918747] domain 0: span 03
 [18584.918810] groups: 01 02
 [18584.918875] domain 1: span 03
 [18584.918937] groups: 03
 [18584.918971] CPU1 attaching sched-domain:
 [18584.919033] domain 0: span 03
 [18584.919065] groups: 02 01
 [18584.919129] domain 1: span 03
 [18584.919162] groups: 03

Steps to reproduce:
* Create your root filesystem on top of dm-crypt
* Create your other external usb filesystem on top of dm-crypt
* cp a large amount of data (10GB) which contains a lot of small files to the External USB HDD
* Look at the I/O (Or even the system) Performance
Comment 1 Ritesh Raj Sarraf 2008-04-24 10:46:06 UTC
Created attachment 15894 [details]
dmesg output during low i/o
Comment 2 Ritesh Raj Sarraf 2008-04-24 13:56:56 UTC
Attached is the output of iostat when the copy was taking place.
 Interesting thing to notice is that the I/O starts up at a good speed, copies at good speed and then eventually the performance starts degrading.
I'm also adding the output of top which is pretty interesting....
 rrs@learner:~$ top
 top - 02:17:22 up 4:11, 1 user, load average: 8.93, 8.99, 5.34
 Tasks: 152 total, 4 running, 148 sleeping, 0 stopped, 0 zombie
 Cpu(s): 61.3%us, 28.9%sy, 1.2%ni, 0.0%id, 0.0%wa, 0.5%hi, 8.1%si, 0.0%st
 Mem: 2074320k total, 2018768k used, 55552k free, 3588k buffers
 Swap: 2621432k total, 38436k used, 2582996k free, 1088672k cached
  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
  6460 rrs 20 0 38224 19m 15m R 57 1.0 11:29.92 kded
  7419 rrs 20 0 785m 545m 35m R 49 26.9 7:01.30 kontact
 13698 rrs 20 0 181m 67m 26m S 38 3.3 0:46.24 firefox
  6613 rrs 20 0 95940 47m 25m S 20 2.4 2:50.79 kopete
  5585 root 20 0 79964 51m 5468 R 16 2.6 5:09.88 Xorg
 25743 rrs 20 0 2308 1144 856 R 15 0.1 0:04.24 top
  6824 rrs 20 0 34048 16m 11m S 7 0.8 0:38.62 konsole
  2663 root 15 -5 0 0 0 S 5 0.0 8:57.19 kcryptd
 18011 rrs 39 19 93568 30m 10m S 3 1.5 3:50.96 beagled-helper
    48 root 15 -5 0 0 0 S 1 0.0 0:09.40 kblockd/1
  6455 rrs 20 0 25912 3260 1688 S 1 0.2 0:18.60 dcopserver
  6637 rrs 20 0 35012 3724 2920 S 1 0.2 0:03.50 pulseaudio
  6642 rrs 20 0 31892 11m 9148 S 1 0.6 0:03.48 klipper
  6522 rrs 20 0 31624 8160 5812 S 1 0.4 0:13.23 artsd
     1 root 20 0 2844 1692 544 S 0 0.1 0:01.42 init
     2 root 15 -5 0 0 0 S 0 0.0 0:00.00 kthreadd
This was captured after around 20 seconds when I interrupted the copy (Sorry, no early could I do it. The machine was not that responsive at that stage). Interesting thing to note is that why are the KDE applications eating up so much of CPU cycles. I'm doing the copy from the KDE filemanager, Dolphin.
Also to point is that when I/O is run, kcryptd takes up a good amount of CPU cycles (around 20-25%), but I think that should be correct because encryption/decryption itself is expensive. What is most bothering is the degradation of the entire OS during such I/O.
Comment 3 Ritesh Raj Sarraf 2008-04-24 13:57:34 UTC
Created attachment 15900 [details]
iostat output during I/O
Comment 4 Diego Calleja 2008-04-30 07:52:18 UTC
Does still happens in 2.6.25?
Comment 5 Ritesh Raj Sarraf 2008-04-30 11:26:07 UTC
No idea. Haven't checked it on 2.6.25.

Note You need to log in before you can comment on or make changes to this bug.