2.6.16-rc6-mm2: slow writes on reiser4.

[Laurent Riffard <laurent.riffard@free.fr>]

Hello,

Writing big files is very slow on reiser4 now. 

"dd if=/dev/zero of=toto bs=1k count=102400; sync" takes more than 2 minutes on 
reiser4 fs, but only 15 seconds on reiserfs fs.

Actually, writing on reiser4 is not uniformly slow, it seems to be blocked for 
ages from time to time. I monitored the number of dirty pages from /proc/meminfo 
an I hit sysrq-T when the system was stalling:  

dd            D 000017DE     0 21930  21929                     (NOTLB)
       d7169c74 e0c98b05 00000246 000017de 00000000 f396aa00 003d1249 d0b68140
       d0b68030 f396aa00 003d1249 6d519e00 00000002 c0396434 d8bf8e30 d8bf8e38
       00000246 d7169ca0 c0270f08 d0b68030 00000001 d0b68030 c0113b25 d8bf8e38
Call Trace:
 [<c0270f08>] __down+0x81/0xdc
 [<c026f3ba>] __down_failed+0xa/0x10
 [<e0c91a62>] .text.lock.lock+0x15/0x1b [reiser4]
 [<e0c90faf>] longterm_lock_znode+0x5b4/0x7b0 [reiser4]
 [<e0cba16a>] cbk_level_lookup+0x8a/0x954 [reiser4]
 [<e0cbb186>] traverse_tree+0x752/0xa0d [reiser4]
 [<e0cbbbc2>] coord_by_handle+0x781/0x789 [reiser4]
 [<e0cbbdb5>] object_lookup+0x1eb/0x230 [reiser4]
 [<e0cdb201>] find_file_item+0x18d/0x1b7 [reiser4]
 [<e0cdd873>] write_flow+0x208/0x6e1 [reiser4]
 [<e0cde208>] write_unix_file+0x3d9/0x5b0 [reiser4]
 [<c0147d36>] vfs_write+0x8a/0x133
 [<c0148569>] sys_write+0x3b/0x60
 [<c01029bb>] sysenter_past_esp+0x54/0x75

Below are the detailed test I ran. Feel free to ask for more information.

Reiser4 FS
==========

Desktop$ cd ~/kernel

kernel$ df .
Sys. de fich.         Tail. Occ. Disp. %Occ. Monté sur
/dev/hda8             925M  825M  101M  90% /home/laurent/kernel

kernel$ grep hda8 /proc/mounts
/dev/hda8 /home/laurent/kernel reiser4 rw,nosuid,nodev,atom_max_size=0x7e0c,atom_max_age=0x249f0,atom_min_size=0x100,atom_max_flushers=0x1,cbk_cache_slots=0x10 0 0

kernel$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.06user 13.95system 1:42.09elapsed 13%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+250minor)pagefaults 0swaps
0.00user 0.00system 1:22.90elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+191minor)pagefaults 0swaps

kernel$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.08user 14.01system 1:45.57elapsed 13%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+249minor)pagefaults 0swaps
0.00user 0.00system 0:09.78elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+191minor)pagefaults 0swaps

kernel$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.06user 14.13system 2:18.27elapsed 10%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+251minor)pagefaults 0swaps
0.00user 0.00system 0:08.48elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+190minor)pagefaults 0swaps

kernel$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.06user 14.27system 1:56.34elapsed 12%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+251minor)pagefaults 0swaps
0.00user 0.00system 0:10.46elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+190minor)pagefaults 0swaps


Reiserfs FS
===========
kernel$ cd

~$ df .
Sys. de fich.         Tail. Occ. Disp. %Occ. Monté sur
/dev/mapper/vglinux1-lvhome
                      7,0G  4,8G  2,3G  68% /home
[/dev/mapper/vglinux1-lvhome resides on /dev/hda4]

~$ grep lvhome /proc/mounts
/dev/vglinux1/lvhome /home reiserfs rw 0 0

~$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.04user 1.75system 0:02.05elapsed 87%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+249minor)pagefaults 0swaps
0.00user 0.10system 0:12.93elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+191minor)pagefaults 0swaps

~$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.04user 1.83system 0:01.98elapsed 94%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+250minor)pagefaults 0swaps
0.00user 0.16system 0:14.45elapsed 1%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+191minor)pagefaults 0swaps

~$ sync; time dd if=/dev/zero of=toto bs=1k count=102400; time sync 
102400+0 enregistrements lus.
102400+0 enregistrements écrits.
0.04user 1.79system 0:01.95elapsed 93%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+250minor)pagefaults 0swaps
0.00user 0.10system 0:13.47elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+190minor)pagefaults 0swaps

~~
laurent