Le 03.08.2006 17:07, Laurent Riffard a écrit :
>
> Le 03.08.2006 08:09, Alexander Zarochentsev a écrit :
>> On Tuesday 01 August 2006 01:29, Laurent Riffard wrote:
>>> Le 31.07.2006 21:55, Vladimir V. Saveliev a écrit :
>>>> Hello
>>>>
>>>> What kind of load did you run on reiser4 at that time?
>>> I just formatted a new 2GB Reiser4 FS, then I moved a whole ccache
>>> cache tree to this new FS (cache size was about 20~30 Mbytes).
>>> Something like:
>>>
>>> # mkfs.reiser4 /dev/vglinux1/ccache
>>> # mount -tauto -onoatime /dev/vglinux1/ccache /mnt/disk
>>> # mv ~laurent/.ccache/* /mnt/disk/
>> I was not able to reproduce it. Can you please try the following patch?
>>
>>
>> lock validator friendly locking of new atom in
>> atom_begin_and_assign_to_txnh and locking of two atoms.
>>
>> Signed-off-by: Alexander Zarochentsev <[EMAIL PROTECTED]>
>> ---
>>
>> fs/reiser4/txnmgr.c | 14 ++++++++------
>> fs/reiser4/txnmgr.h | 15 +++++++++++++++
>> 2 files changed, 23 insertions(+), 6 deletions(-)
>>
[patch snipped]
>
> I tried this patch: it's slow as hell (CPU is ~100% system) and it
> panics when syncing...
>
> reiser4 panicked cowardly: reiser4[shutdown(1904)]: spin_lock_atom
> (fs/reiser4/txmgr.h:509)[]:
>
Hello,
I tried again with linux 2.6.18-rc3-mm2+hotfixes.
# booted to runlevel 1
~$ mount
...
/dev/mapper/vglinux1-lvhome on /home type reiserfs (rw)
/dev/mapper/vglinux1-lvccache on /home/laurent/.ccache type reiser4
(rw,nosuid,nodev,noatime)
...
~$ df ~/.ccache
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/vglinux1-lvccache
2.0G 53M 1.9G 3% /home/laurent/.ccache
~$ time mv ~/.ccache/* ~/tmp/ccache
0.10user 6.01system 0:07.92elapsed 77%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+296minor)pagefaults 0swaps
dmesg output:
=======================================================
[ INFO: possible circular locking dependency detected ]
-------------------------------------------------------
mv/1255 is trying to acquire lock:
(&txnh->hlock){--..}, at: [<e101f0cf>] txn_end+0x191/0x368 [reiser4]
but task is already holding lock:
(&atom->alock){--..}, at: [<e101b674>] txnh_get_atom+0xf6/0x39e [reiser4]
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #1 (&atom->alock){--..}:
[<c012ce82>] lock_acquire+0x60/0x80
[<c0291c08>] _spin_lock+0x19/0x28
[<e101cc0b>] try_capture+0x7cf/0x1cd7 [reiser4]
[<e10096e5>] longterm_lock_znode+0x427/0x84f [reiser4]
[<e1038fe7>] seal_validate+0x221/0x5ee [reiser4]
[<e10652a1>] find_entry+0x126/0x307 [reiser4]
[<e1065974>] rem_entry_common+0xe9/0x4ba [reiser4]
[<e104c9bc>] unlink_common+0x258/0x364 [reiser4]
[<c015f7bc>] vfs_unlink+0x47/0x87
[<c01611b4>] do_unlinkat+0x8c/0x122
[<c016125a>] sys_unlink+0x10/0x12
[<c0102c39>] sysenter_past_esp+0x56/0x8d
-> #0 (&txnh->hlock){--..}:
[<c012ce82>] lock_acquire+0x60/0x80
[<c0291c08>] _spin_lock+0x19/0x28
[<e101f0cf>] txn_end+0x191/0x368 [reiser4]
[<e10109b5>] reiser4_exit_context+0x1c2/0x571 [reiser4]
[<e104cabd>] unlink_common+0x359/0x364 [reiser4]
[<c015f7bc>] vfs_unlink+0x47/0x87
[<c01611b4>] do_unlinkat+0x8c/0x122
[<c016125a>] sys_unlink+0x10/0x12
[<c0102c39>] sysenter_past_esp+0x56/0x8d
other info that might help us debug this:
3 locks held by mv/1255:
#0: (&inode->i_mutex/1){--..}, at: [<c0161181>] do_unlinkat+0x59/0x122
#1: (&inode->i_mutex){--..}, at: [<c0290a94>] mutex_lock+0x21/0x24
#2: (&atom->alock){--..}, at: [<e101b674>] txnh_get_atom+0xf6/0x39e
[reiser4]
stack backtrace:
[<c0103a97>] show_trace+0xd/0x10
[<c0103ff6>] dump_stack+0x19/0x1b
[<c012c20d>] print_circular_bug_tail+0x59/0x64
[<c012ca2c>] __lock_acquire+0x814/0x9a5
[<c012ce82>] lock_acquire+0x60/0x80
[<c0291c08>] _spin_lock+0x19/0x28
[<e101f0cf>] txn_end+0x191/0x368 [reiser4]
[<e10109b5>] reiser4_exit_context+0x1c2/0x571 [reiser4]
[<e104cabd>] unlink_common+0x359/0x364 [reiser4]
[<c015f7bc>] vfs_unlink+0x47/0x87
[<c01611b4>] do_unlinkat+0x8c/0x122
[<c016125a>] sys_unlink+0x10/0x12
[<c0102c39>] sysenter_past_esp+0x56/0x8d
~$ time sync
0.00user 0.02system 0:00.49elapsed 4%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+202minor)pagefaults 0swaps
Move the files backward...
~$ time mv ~/tmp/ccache/* ~/.ccache/
0.11user 3.98system 0:04.09elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+286minor)pagefaults 0swaps
~$ time sync
0.00user 0.00system 0:01.86elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+204minor)pagefaults 0swaps
So this problem still appears in 2.6.18-rc3-mm2+hotfixes.
I applied the patch zam sent 01 August 2006. Compile, boot to
runlevel 1 and test again. The warning went away but it's now really
really slow:
~$ time mv ~/.ccache/* ~/tmp/ccache
0.09user 15.82system 0:16.08elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+299minor)pagefaults 0swaps
ouch! 16s versus 8s.
~$ time sync
0.00user 0.10system 0:00.58elapsed 17%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+205minor)pagefaults 0swaps
Move the files backward...
~$ time mv ~/tmp/ccache/* ~/.ccache/
0.11user 27.20system 0:27.33elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+286minor)pagefaults 0swaps
27s versus 4s previously.
~$ time sync
0.00user 0.02system 0:04.35elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+204minor)pagefaults 0swaps
once again...
~$ time ~/.ccache/* ~/tmp/ccache
0.09user 37.43system 0:37.71elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+298minor)pagefaults 0swaps
~$ time sync
0.00user 0.08system 0:00.44elapsed 19%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+204minor)pagefaults 0swaps
What's going on ? Let's have a look at vmstat output
~$ vmstat 3 &
[1] 1394
~$ procs -----------memory---------- ---swap-- -----io---- --system--
----cpu----
r b swpd free buff cache si so bi bo in cs us sy id
wa
1 0 0 438688 9684 45612 0 0 70 90 269 50 1 15 81
3
0 0 0 438688 9684 45612 0 0 0 0 350 58 0 1 99
0
0 0 0 438688 9688 45612 0 0 0 3 251 10 0 0
100 0
0 0 0 438704 9688 45612 0 0 0 0 257 10 0 0
100 0
time mv ~/tmp/ccache/* ~/.ccache/
1 0 0 437944 9728 45684 0 0 0 13 270 25 0 76 23
0
1 0 0 437448 9732 46384 0 0 0 4 251 8 0 100
0 0
1 0 0 437448 9784 46096 0 0 0 17 252 16 0 100
0 0
1 0 0 436828 9908 45984 0 0 0 43 254 12 0 100
0 0
1 0 0 436580 9908 45844 0 0 0 0 250 8 0 100
0 0
1 0 0 436208 10004 46252 0 0 0 42 260 12 0 100
0 0
1 0 0 435836 10004 46176 0 0 0 0 251 7 1 99 0
0
1 0 0 434968 10096 46868 0 0 0 31 251 11 0 100
0 0
1 0 0 435092 10144 46112 0 0 0 16 251 12 0 100
0 0
0.07user 29.02system 0:29.10elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+287minor)pagefaults 0swaps
~$
0 0 0 434968 10144 45960 0 0 0 0 251 11 0 92 8
0
0 0 0 434968 10192 45960 0 0 0 29 255 11 0 0 99
1
0 0 0 434984 10192 45960 0 0 0 0 255 27 0 0
100 0
kill %1
~$
[1]+ Complete vmstat 3
See? 100% system CPU. Without the patch, I have about 60% user and
30% system.
This patch seems to solve the "possible circular locking dependency
detected in txn_end". Moreover, it seems to solve the "possible
circular locking dependency detected wile unmounting reiser4 FS" I
reported in another thread.
But it still panics while syncing:
reiser4 panicked cowardly: reiser4[sync(23302)]: spin_lock_atom
(fs/reiser4/txnmgr.h:509)[]:
Kernel panic - not syncing: reiser4[sync(23302)]: spin_lock_atom
(fs/reiser4/txnmgr.h:509)[]:
~~
laurent
