reiserfs lockdep complaint

reiserfs lockdep complaint

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 6346 bytes --]

Hi,

I get the following lockdep complaint when test reiserfs in the 3.4
kernel using xfstests. Ideas?

[453445.527861] ======================================================
[453445.527977] [ INFO: possible circular locking dependency detected ]
[453445.528085] 3.4.0+ #73 Not tainted
[453445.528085] -------------------------------------------------------
[453445.528085] setfattr/25622 is trying to acquire lock:
[453445.528085]  (&ei->tailpack){+.+.+.}, at: [<ffffffffa00d42b9>] reiserfs_vfs_truncate_file+0x29/0x50 [reiserfs]
[453445.528085] 
[453445.528085] but task is already holding lock:
[453445.528085]  (&REISERFS_SB(s)->lock){+.+.+.}, at: [<ffffffffa00f1299>] reiserfs_write_lock+0x39/0x60 [reiserfs]
[453445.528085] 
[453445.528085] which lock already depends on the new lock.
[453445.528085] 
[453445.528085] 
[453445.528085] the existing dependency chain (in reverse order) is:
[453445.528085] 
[453445.528085] -> #1 (&REISERFS_SB(s)->lock){+.+.+.}:
[453445.528085]        [<ffffffff810b90e2>] lock_acquire+0x92/0x140
[453445.528085]        [<ffffffff8161ff40>] mutex_lock_nested+0x70/0x360
[453445.528085]        [<ffffffffa00f1299>] reiserfs_write_lock+0x39/0x60 [reiserfs]
[453445.528085]        [<ffffffffa00d459f>] reiserfs_file_release+0x14f/0x340 [reiserfs]
[453445.528085]        [<ffffffff8119569d>] fput+0xfd/0x270
[453445.528085]        [<ffffffff81191a96>] filp_close+0x66/0x90
[453445.528085]        [<ffffffff8105daf3>] put_files_struct+0x103/0x1c0
[453445.528085]        [<ffffffff8105dc72>] exit_files+0x52/0x60
[453445.528085]        [<ffffffff8105e134>] do_exit+0x174/0x900
[453445.528085]        [<ffffffff8105ec0c>] do_group_exit+0x4c/0xb0
[453445.528085]        [<ffffffff8105ec87>] sys_exit_group+0x17/0x20
[453445.528085]        [<ffffffff8162bee9>] system_call_fastpath+0x16/0x1b
[453445.528085] 
[453445.528085] -> #0 (&ei->tailpack){+.+.+.}:
[453445.528085]        [<ffffffff810b85d8>] __lock_acquire+0x1658/0x1b80
[453445.528085]        [<ffffffff810b90e2>] lock_acquire+0x92/0x140
[453445.528085]        [<ffffffff8161ff40>] mutex_lock_nested+0x70/0x360
[453445.528085]        [<ffffffffa00d42b9>] reiserfs_vfs_truncate_file+0x29/0x50 [reiserfs]
[453445.528085]        [<ffffffff8113e383>] vmtruncate+0x53/0x60
[453445.528085]        [<ffffffffa00d41da>] reiserfs_setattr+0x2ea/0x3a0 [reiserfs]
[453445.528085]        [<ffffffffa00f06bb>] reiserfs_xattr_set_handle+0x47b/0x4e0 [reiserfs]
[453445.528085]        [<ffffffffa00f07dc>] reiserfs_xattr_set+0xbc/0x160 [reiserfs]
[453445.528085]        [<ffffffffa00f1467>] user_set+0x77/0x90 [reiserfs]
[453445.528085]        [<ffffffffa00f0cc8>] reiserfs_setxattr+0xb8/0xf0 [reiserfs]
[453445.528085]        [<ffffffff811b724b>] __vfs_setxattr_noperm+0x7b/0x1c0
[453445.528085]        [<ffffffff811b7454>] vfs_setxattr+0xc4/0xd0
[453445.528085]        [<ffffffff811b7553>] setxattr+0xf3/0x1a0
[453445.528085]        [<ffffffff811b78e5>] sys_lsetxattr+0x95/0xb0
[453445.528085]        [<ffffffff8162bee9>] system_call_fastpath+0x16/0x1b
[453445.528085] 
[453445.528085] other info that might help us debug this:
[453445.528085] 
[453445.528085]  Possible unsafe locking scenario:
[453445.528085] 
[453445.528085]        CPU0                    CPU1
[453445.528085]        ----                    ----
[453445.528085]   lock(&REISERFS_SB(s)->lock);
[453445.528085]                                lock(&ei->tailpack);
[453445.528085]                                lock(&REISERFS_SB(s)->lock);
[453445.528085]   lock(&ei->tailpack);
[453445.528085] 
[453445.528085]  *** DEADLOCK ***
[453445.528085] 
[453445.528085] 4 locks held by setfattr/25622:
[453445.528085]  #0:  (&sb->s_type->i_mutex_key#14){+.+.+.}, at: [<ffffffff811b740d>] vfs_setxattr+0x7d/0xd0
[453445.528085]  #1:  (&REISERFS_I(inode)->i_xattr_sem){++++..}, at: [<ffffffffa00f02de>] reiserfs_xattr_set_handle+0x9e/0x4e0 [reiserfs]
[453445.528085]  #2:  (&sb->s_type->i_mutex_key#14/3){+.+...}, at: [<ffffffffa00f0696>] reiserfs_xattr_set_handle+0x456/0x4e0 [reiserfs]
[453445.528085]  #3:  (&REISERFS_SB(s)->lock){+.+.+.}, at: [<ffffffffa00f1299>] reiserfs_write_lock+0x39/0x60 [reiserfs]
[453445.528085] 
[453445.528085] stack backtrace:
[453445.528085] Pid: 25622, comm: setfattr Not tainted 3.4.0+ #73
[453445.528085] Call Trace:
[453445.528085]  [<ffffffff816180a5>] print_circular_bug+0x1fb/0x20c
[453445.528085]  [<ffffffff811319ca>] ? find_get_pages+0x2a/0x210
[453445.528085]  [<ffffffff810b85d8>] __lock_acquire+0x1658/0x1b80
[453445.528085]  [<ffffffff810b9b95>] ? trace_hardirqs_on_caller+0x105/0x190
[453445.528085]  [<ffffffff81620e45>] ? __mutex_unlock_slowpath+0xe5/0x180
[453445.528085]  [<ffffffffa00d42b9>] ? reiserfs_vfs_truncate_file+0x29/0x50 [reiserfs]
[453445.528085]  [<ffffffff810b90e2>] lock_acquire+0x92/0x140
[453445.528085]  [<ffffffffa00d42b9>] ? reiserfs_vfs_truncate_file+0x29/0x50 [reiserfs]
[453445.528085]  [<ffffffff8161ff40>] mutex_lock_nested+0x70/0x360
[453445.528085]  [<ffffffffa00d42b9>] ? reiserfs_vfs_truncate_file+0x29/0x50 [reiserfs]
[453445.528085]  [<ffffffffa00d42b9>] reiserfs_vfs_truncate_file+0x29/0x50 [reiserfs]
[453445.528085]  [<ffffffff8113e383>] vmtruncate+0x53/0x60
[453445.528085]  [<ffffffffa00d41da>] reiserfs_setattr+0x2ea/0x3a0 [reiserfs]
[453445.528085]  [<ffffffff81620160>] ? mutex_lock_nested+0x290/0x360
[453445.528085]  [<ffffffffa00f06bb>] reiserfs_xattr_set_handle+0x47b/0x4e0 [reiserfs]
[453445.528085]  [<ffffffffa00f07dc>] reiserfs_xattr_set+0xbc/0x160 [reiserfs]
[453445.528085]  [<ffffffffa00f1467>] user_set+0x77/0x90 [reiserfs]
[453445.528085]  [<ffffffffa00f0cc8>] reiserfs_setxattr+0xb8/0xf0 [reiserfs]
[453445.528085]  [<ffffffff811b724b>] __vfs_setxattr_noperm+0x7b/0x1c0
[453445.528085]  [<ffffffff811b7454>] vfs_setxattr+0xc4/0xd0
[453445.528085]  [<ffffffff811b7553>] setxattr+0xf3/0x1a0
[453445.528085]  [<ffffffff8119f403>] ? putname+0x33/0x50
[453445.528085]  [<ffffffff811a3cb3>] ? user_path_at_empty+0x63/0xa0
[453445.528085]  [<ffffffff8115c556>] ? do_brk+0x246/0x360
[453445.528085]  [<ffffffff81623cd5>] ? retint_swapgs+0x13/0x1b
[453445.528085]  [<ffffffff811b78e5>] sys_lsetxattr+0x95/0xb0
[453445.528085]  [<ffffffff8162bee9>] system_call_fastpath+0x16/0x1b

-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: reiserfs lockdep complaint

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 347 bytes --]

On Wed, 2012-05-30 at 15:18 +0300, Artem Bityutskiy wrote:
> Hi,
> 
> I get the following lockdep complaint when test reiserfs in the 3.4
> kernel using xfstests. Ideas?

Reiserfs subsequently deadlocks, but it does not look like this lockdep
warning is related to that deadlock, but I am not sure.

-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: reiserfs lockdep complaint

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 4963 bytes --]

On Wed, 2012-05-30 at 16:22 +0300, Artem Bityutskiy wrote:
> On Wed, 2012-05-30 at 15:18 +0300, Artem Bityutskiy wrote:
> > Hi,
> > 
> > I get the following lockdep complaint when test reiserfs in the 3.4
> > kernel using xfstests. Ideas?
> 
> Reiserfs subsequently deadlocks, but it does not look like this lockdep
> warning is related to that deadlock, but I am not sure.

Not sure I'll have enough time to dig into this because reiserfs locking
is crazy - there is the reiserfs-specific BKL which probably pushed down
in the past and broke reiserfs. Anyway, I have useful dump:

It looks like what is happening is that the first fsstress takes the
rieserfs write lock and then tries to take a quota lock.

The second fsstress took the write lock, then the quota lock, then
dropped the write lock, and it was taken by the first fsstress, and then
it tries to re-acquire the write lock.

Not sure though.

[ 2760.486253] INFO: lockdep is turned off.
[ 2760.486474] INFO: task fsstress:1066 blocked for more than 120 seconds.
[ 2760.487186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2760.487627] fsstress        D ffff88030c68fa80     0  1066   1057 0x00000000
[ 2760.487925]  ffff8801cd9a1be8 0000000000000046 ffffffff811eec4d 0000000000000002
[ 2760.488409]  ffff8801cd985f40 ffff8801cd9a1fd8 ffff8801cd9a1fd8 ffff8801cd9a1fd8
[ 2760.488862]  ffff8801cd980000 ffff8801cd985f40 0000000000000000 ffff8801cd9a0000
[ 2760.489352] Call Trace:
[ 2760.489547]  [<ffffffff811eec4d>] ? dquot_acquire+0x4d/0x150
[ 2760.489798]  [<ffffffff81622089>] schedule+0x29/0x70
[ 2760.490063]  [<ffffffff816223c7>] schedule_preempt_disabled+0x27/0x40
[ 2760.490330]  [<ffffffff81620047>] mutex_lock_nested+0x177/0x360
[ 2760.490585]  [<ffffffff811eec4d>] ? dquot_acquire+0x4d/0x150
[ 2760.490836]  [<ffffffff811f0410>] ? dqget+0xa0/0x3a0
[ 2760.491099]  [<ffffffff811eec4d>] dquot_acquire+0x4d/0x150
[ 2760.491351]  [<ffffffffa0055e28>] reiserfs_acquire_dquot+0x78/0xc0 [reiserfs]
[ 2760.491629]  [<ffffffff811f0660>] dqget+0x2f0/0x3a0
[ 2760.491873]  [<ffffffff811f255f>] dquot_transfer+0x5f/0xd0
[ 2760.492149]  [<ffffffffa005020b>] reiserfs_setattr+0x31b/0x3a0 [reiserfs]
[ 2760.492422]  [<ffffffff811afb7a>] notify_change+0x1aa/0x340
[ 2760.492675]  [<ffffffff81191972>] chown_common+0x72/0x90
[ 2760.492921]  [<ffffffff81192a5e>] sys_lchown+0x7e/0x90
[ 2760.493192]  [<ffffffff8162bee9>] system_call_fastpath+0x16/0x1b
[ 2760.493450] INFO: lockdep is turned off.
[ 2760.493669] INFO: task fsstress:1067 blocked for more than 120 seconds.
[ 2760.493934] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2760.494397] fsstress        D ffff88030c489e68     0  1067   1057 0x00000000
[ 2760.494689]  ffff8802ff5bd9d8 0000000000000046 ffffffffa006d299 0000000000000002
[ 2760.495168]  ffff8801cd980000 ffff8802ff5bdfd8 ffff8802ff5bdfd8 ffff8802ff5bdfd8
[ 2760.495623]  ffffffff81c13020 ffff8801cd980000 ffff8802ff5bd9b8 ffff8802ff5bc000
[ 2760.496109] Call Trace:
[ 2760.496308]  [<ffffffffa006d299>] ? reiserfs_write_lock+0x39/0x60 [reiserfs]
[ 2760.496585]  [<ffffffff81622089>] schedule+0x29/0x70
[ 2760.496823]  [<ffffffff816223c7>] schedule_preempt_disabled+0x27/0x40
[ 2760.497114]  [<ffffffff81620047>] mutex_lock_nested+0x177/0x360
[ 2760.497373]  [<ffffffffa006d299>] ? reiserfs_write_lock+0x39/0x60 [reiserfs]
[ 2760.497650]  [<ffffffff8162192f>] ? __schedule+0x3bf/0x810
[ 2760.497902]  [<ffffffff810f86bf>] ? rcu_irq_exit+0x8f/0xe0
[ 2760.498181]  [<ffffffffa006d299>] reiserfs_write_lock+0x39/0x60 [reiserfs]
[ 2760.498458]  [<ffffffffa006e95c>] reiserfs_cond_resched.part.8+0x1b/0x1f [reiserfs]
[ 2760.498911]  [<ffffffffa004d35e>] reiserfs_update_sd_size+0x2be/0x2d0 [reiserfs]
[ 2760.499372]  [<ffffffffa0065b00>] ? reiserfs_add_ordered_list+0x30/0x110 [reiserfs]
[ 2760.499817]  [<ffffffffa005696b>] reiserfs_dirty_inode+0x8b/0xa0 [reiserfs]
[ 2760.500119]  [<ffffffff811bd8bc>] __mark_inode_dirty+0x3c/0x240
[ 2760.500378]  [<ffffffffa0056c1d>] reiserfs_quota_write+0x29d/0x340 [reiserfs]
[ 2760.500655]  [<ffffffff811f45f3>] qtree_write_dquot+0xc3/0x160
[ 2760.500911]  [<ffffffffa006d299>] ? reiserfs_write_lock+0x39/0x60 [reiserfs]
[ 2760.501217]  [<ffffffff811f299c>] v2_write_dquot+0x2c/0x30
[ 2760.501467]  [<ffffffff811f1d4e>] dquot_commit+0xce/0xe0
[ 2760.501713]  [<ffffffffa0055ee8>] reiserfs_write_dquot+0x78/0xc0 [reiserfs]
[ 2760.501988]  [<ffffffff811f1c5c>] dquot_quota_sync+0x30c/0x330
[ 2760.502272]  [<ffffffff811c2510>] ? __sync_filesystem+0x90/0x90
[ 2760.502529]  [<ffffffff811c24bc>] __sync_filesystem+0x3c/0x90
[ 2760.502782]  [<ffffffff811c252f>] sync_one_sb+0x1f/0x30
[ 2760.503050]  [<ffffffff81197211>] iterate_supers+0xf1/0x100
[ 2760.503302]  [<ffffffff811c25e0>] sys_sync+0x30/0x70
[ 2760.503541]  [<ffffffff8162bee9>] system_call_fastpath+0x16/0x1b


-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]