dslreports logo
 
    All Forums Hot Topics Gallery
spc
Search similar:


uniqs
1371

houkouonchi
join:2002-07-22
Ontario, CA

houkouonchi

Member

weird JFS behavior

I noticed some weird JFS behavior recently as I was making a backup image of my windows volume onto my linux volume to try to restore my old 32-bit windows install and while dumping the volume (80GB) about 35GB into it all the sudden jfsCommit processes start sucking up a bunch of CPU usage and the transfer just starts getting slower and slower. top output shows:

top - 11:02:44 up 4 days,  2:51,  8 users,  load average: 2.49, 1.88, 1.32
Tasks: 265 total,   4 running, 261 sleeping,   0 stopped,   0 zombie
Cpu(s):  5.3%us, 51.7%sy,  0.0%ni, 11.5%id, 30.1%wa,  0.7%hi,  0.8%si,  0.0%st
Mem:   8185348k total,  8141012k used,    44336k free,  3042308k buffers
Swap:  2047992k total,    15952k used,  2032040k free,  3197980k cached
 
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
  285 root      15  -5     0    0    0 S   77  0.0   4:00.84 jfsCommit
  284 root      15  -5     0    0    0 R   13  0.0   4:10.24 jfsCommit
 6957 root      20   0  8100 2820  644 R   13  0.0   1:33.99 dd
 6780 root      20   0  797m 759m  30m S    8  9.5 246:01.60 Xgl
18261 root      20   0  207m  88m  23m S    4  1.1   1:07.87 firefox-bin
 8543 root      20   0  279m 118m  11m S    2  1.5  71:47.44 beryl-xgl
 

Here is a image from gkrellm which shows the transfers gradually go down as CPU usage goes up:



And it just gets worse as the dump continues:



Anyone ever seen anything like this on JFS before?
pablo
MVM
join:2003-06-23

pablo

MVM

I suspect what happened was you filled all your available kernel buffers and were forced to write at the speed of your disks.

`sar -d 3 10000' would probably show a disk bottleneck.

I see the same issue when people use RAID with on-board RAM and are writing tons of data. Once the RAM Cache is filled, the incoming writes are gated by the speed of the backend drives.

houkouonchi
join:2002-07-22
Ontario, CA

houkouonchi

Member

said by pablo:

I suspect what happened was you filled all your available kernel buffers and were forced to write at the speed of your disks.

`sar -d 3 10000' would probably show a disk bottleneck.

I see the same issue when people use RAID with on-board RAM and are writing tons of data. Once the RAM Cache is filled, the incoming writes are gated by the speed of the backend drives.
I don't think that is what it is as it didn't start happening until 35 GB into the copy. Also it wasn't disk bottlenecked it was CPU bottlenecked (the jfsCommit started using 100% CPU). For the first 35GB the copy went at about 160 megabytes/sec yet at the end it ended up at around 18 MB/sec as it gradually got slower and slower:

83850428416 bytes (84 GB) copied, 4433.23 s, 18.9 MB/s
40005+0 records in
40005+0 records out
83896565760 bytes (84 GB) copied, 4443.56 s, 18.9 MB/s
40027+0 records in
40027+0 records out
83942703104 bytes (84 GB) copied, 4453.43 s, 18.8 MB/s
40048+0 records in
40048+0 records out
83986743296 bytes (84 GB) copied, 4463.25 s, 18.8 MB/s
40053+1 records in
40053+1 records out
83998801920 bytes (84 GB) copied, 4465.93 s, 18.8 MB/s

Interesting enough speed is still good if I just create a file right after the slow transfer:

root@sabayonx86-64: 03:00 PM :/data# dd bs=2M count=10000 if=/dev/zero of=./20gb.bin
10000+0 records in
10000+0 records out
20971520000 bytes (21 GB) copied, 31.7737 s, 660 MB/s

During this process only dd used CPU usage and I never saw jfsCommit start using up a bunch of CPU usage. Maybe it has problems only when writing large files (over 30 gigabytes)?
houkouonchi

houkouonchi

Member

Hmm, just tried it right now by using dd with a if from /dev/zero and didn't specify the count and as soon as the file was about 25GB it started massively slowing down. Weird..

Its also not effecting reading the data later since I had no slowdowns issues when reading the 80GB image and it pretty much stayed the same speed the entire time:

root@sabayonx86-64: 03:04 PM :/data# dd bs=2M if=win_xp_64_image.img of=/dev/null
40053+1 records in
40053+1 records out
83998801920 bytes (84 GB) copied, 110.033 s, 763 MB/s