Bug 1366869 - 4.9.0-0.rc0.git4.1.fc26.x86_64: possible recursive locking detected
Summary: 4.9.0-0.rc0.git4.1.fc26.x86_64: possible recursive locking detected
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-08-13 18:33 UTC by Tomasz Kłoczko
Modified: 2017-04-16 17:29 UTC (History)
6 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2017-04-16 17:29:56 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Tomasz Kłoczko 2016-08-13 18:33:01 UTC
Description of problem:

Found in logs:

Aug 13 11:02:04 domek kernel: =============================================
Aug 13 11:02:04 domek kernel: [ INFO: possible recursive locking detected ]
Aug 13 11:02:04 domek kernel: 4.8.0-0.rc1.git3.1.fc26.x86_64 #1 Not tainted
Aug 13 11:02:04 domek kernel: ---------------------------------------------
Aug 13 11:02:04 domek kernel: StreamTrans #2/4621 is trying to acquire lock:
Aug 13 11:02:04 domek kernel:  (&ei->log_mutex){+.+...}, at: [<ffffffffc0741e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel: 
                              but task is already holding lock:
Aug 13 11:02:04 domek kernel:  (&ei->log_mutex){+.+...}, at: [<ffffffffc0741e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel: 
                              other info that might help us debug this:
Aug 13 11:02:04 domek kernel:  Possible unsafe locking scenario:
Aug 13 11:02:04 domek kernel:        CPU0
Aug 13 11:02:04 domek kernel:        ----
Aug 13 11:02:04 domek kernel:   lock(&ei->log_mutex);
Aug 13 11:02:04 domek kernel:   lock(&ei->log_mutex);
Aug 13 11:02:04 domek kernel: 
                               *** DEADLOCK ***
Aug 13 11:02:04 domek kernel:  May be due to missing lock nesting notation
Aug 13 11:02:04 domek kernel: 6 locks held by StreamTrans #2/4621:
Aug 13 11:02:04 domek kernel:  #0:  (sb_writers#8){.+.+.+}, at: [<ffffffff8c2a6cf4>] __sb_start_write+0xb4/0xf0
Aug 13 11:02:04 domek kernel:  #1:  (&type->i_mutex_dir_key#3/1){+.+.+.}, at: [<ffffffff8c2af66a>] lock_rename+0xda/0x100
Aug 13 11:02:04 domek kernel:  #2:  (&sb->s_type->i_mutex_key#12){+.+.+.}, at: [<ffffffff8c2c3dde>] lock_two_nondirectories+0x3e/0x70
Aug 13 11:02:04 domek kernel:  #3:  (&sb->s_type->i_mutex_key#12/4){+.+...}, at: [<ffffffff8c2c3e06>] lock_two_nondirectories+0x66/0x70
Aug 13 11:02:04 domek kernel:  #4:  (sb_internal){.+.+..}, at: [<ffffffff8c2a6cb8>] __sb_start_write+0x78/0xf0
Aug 13 11:02:04 domek kernel:  #5:  (&ei->log_mutex){+.+...}, at: [<ffffffffc0741e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel: 
                              stack backtrace:
Aug 13 11:02:04 domek kernel: CPU: 2 PID: 4621 Comm: StreamTrans #2 Not tainted 4.8.0-0.rc1.git3.1.fc26.x86_64 #1
Aug 13 11:02:04 domek kernel: Hardware name: Sony Corporation VPCSB2M9E/VAIO, BIOS R2087H4 06/15/2012
Aug 13 11:02:04 domek kernel:  0000000000000086 000000009af71bf4 ffff9fc3058fb780 ffffffff8c467a83
Aug 13 11:02:04 domek kernel:  ffffffff8dbf2680 ffff9fc318f03240 ffff9fc3058fb848 ffffffff8c10f22e
Aug 13 11:02:04 domek kernel:  0000000000000005 ffffffff00000006 000000007c850543 ffffffff8d50f000
Aug 13 11:02:04 domek kernel: Call Trace:
Aug 13 11:02:04 domek kernel:  [<ffffffff8c467a83>] dump_stack+0x86/0xc3
Aug 13 11:02:04 domek kernel:  [<ffffffff8c10f22e>] __lock_acquire+0x78e/0x1290
Aug 13 11:02:04 domek kernel:  [<ffffffff8c0ea6c7>] ? sched_clock_cpu+0xa7/0xc0
Aug 13 11:02:04 domek kernel:  [<ffffffff8c8f658e>] ? mutex_unlock+0xe/0x10
Aug 13 11:02:04 domek kernel:  [<ffffffff8c110196>] lock_acquire+0xf6/0x1f0
Aug 13 11:02:04 domek kernel:  [<ffffffffc0741e12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffff8c8f5916>] mutex_lock_nested+0x86/0x3f0
Aug 13 11:02:04 domek kernel:  [<ffffffffc0741e12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffffc07580d5>] ? __btrfs_release_delayed_node+0x75/0x1c0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffffc0741e12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffffc0759f79>] ? btrfs_commit_inode_delayed_inode+0xe9/0x130 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffffc0741e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffff8c0deb69>] ? __might_sleep+0x49/0x80
Aug 13 11:02:04 domek kernel:  [<ffffffffc074293c>] btrfs_log_inode+0xc8c/0x10f0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffff8c037f19>] ? sched_clock+0x9/0x10
Aug 13 11:02:04 domek kernel:  [<ffffffffc0743070>] btrfs_log_inode_parent+0x240/0x940 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffff8c8f9257>] ? _raw_spin_unlock+0x27/0x40
Aug 13 11:02:04 domek kernel:  [<ffffffffc06fddba>] ? btrfs_update_inode+0xda/0x110 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffffc0744cf1>] btrfs_log_new_name+0x71/0x90 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffffc0707cd0>] btrfs_rename2+0x1090/0x17a0 [btrfs]
Aug 13 11:02:04 domek kernel:  [<ffffffff8c12deed>] ? debug_lockdep_rcu_enabled+0x1d/0x20
Aug 13 11:02:04 domek kernel:  [<ffffffff8c2c3e06>] ? lock_two_nondirectories+0x66/0x70
Aug 13 11:02:04 domek kernel:  [<ffffffff8c2b12a2>] vfs_rename+0x5c2/0x970
Aug 13 11:02:04 domek kernel:  [<ffffffff8c2af500>] ? __lookup_hash+0x10/0xa0
Aug 13 11:02:04 domek kernel:  [<ffffffff8c2b7e27>] SyS_rename+0x3a7/0x3d0
Aug 13 11:02:04 domek kernel:  [<ffffffff8c003efc>] do_syscall_64+0x6c/0x1e0
Aug 13 11:02:04 domek kernel:  [<ffffffff8c8f9c7f>] entry_SYSCALL64_slow_path+0x25/0x25


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Tomasz Kłoczko 2016-08-22 11:22:29 UTC
Just rebooted on nw kernel ans stil I see the same issue.

Aug 22 07:08:23 domek kernel: 
Aug 22 07:08:23 domek kernel: =============================================
Aug 22 07:08:23 domek kernel: [ INFO: possible recursive locking detected ]
Aug 22 07:08:23 domek kernel: 4.8.0-0.rc2.git4.1.fc26.x86_64 #1 Not tainted
Aug 22 07:08:23 domek kernel: ---------------------------------------------
Aug 22 07:08:23 domek kernel: StreamTrans #1/4653 is trying to acquire lock:
Aug 22 07:08:23 domek kernel: (&ei->log_mutex){+.+...}, at: [<ffffffffc07e1e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: #012but task is already holding lock:
Aug 22 07:08:23 domek kernel: (&ei->log_mutex){+.+...}, at: [<ffffffffc07e1e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: #012other info that might help us debug this:
Aug 22 07:08:23 domek kernel: Possible unsafe locking scenario:
Aug 22 07:08:23 domek kernel:       CPU0
Aug 22 07:08:23 domek kernel:       ----
Aug 22 07:08:23 domek kernel:  lock(&ei->log_mutex);
Aug 22 07:08:23 domek kernel:  lock(&ei->log_mutex);
Aug 22 07:08:23 domek kernel: #012 *** DEADLOCK ***
Aug 22 07:08:23 domek kernel: May be due to missing lock nesting notation
Aug 22 07:08:23 domek kernel: 6 locks held by StreamTrans #1/4653:
Aug 22 07:08:23 domek kernel: #0:  (sb_writers#8){.+.+.+}, at: [<ffffffffb72a70b4>] __sb_start_write+0xb4/0xf0
Aug 22 07:08:23 domek kernel: #1:  (&type->i_mutex_dir_key#3/1){+.+.+.}, at: [<ffffffffb72afa2a>] lock_rename+0xda/0x100
Aug 22 07:08:23 domek kernel: #2:  (&sb->s_type->i_mutex_key#12){+.+.+.}, at: [<ffffffffb72c419e>] lock_two_nondirectories+0x3e/0x70
Aug 22 07:08:23 domek kernel: #3:  (&sb->s_type->i_mutex_key#12/4){+.+...}, at: [<ffffffffb72c41c6>] lock_two_nondirectories+0x66/0x70
Aug 22 07:08:23 domek kernel: #4:  (sb_internal){.+.+..}, at: [<ffffffffb72a7078>] __sb_start_write+0x78/0xf0
Aug 22 07:08:23 domek kernel: #5:  (&ei->log_mutex){+.+...}, at: [<ffffffffc07e1e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: #012stack backtrace:
Aug 22 07:08:23 domek kernel: CPU: 3 PID: 4653 Comm: StreamTrans #1 Not tainted 4.8.0-0.rc2.git4.1.fc26.x86_64 #1
Aug 22 07:08:23 domek kernel: Hardware name: Sony Corporation VPCSB2M9E/VAIO, BIOS R2087H4 06/15/2012
Aug 22 07:08:23 domek kernel: 0000000000000086 000000009c8d5211 ffffa11570b73780 ffffffffb7467e73
Aug 22 07:08:23 domek kernel: ffffffffb8bef420 ffffa11555828000 ffffa11570b73848 ffffffffb710f27e
Aug 22 07:08:23 domek kernel: 0000000000000005 ffffffff00000006 00000000cac354ab ffffffffb8510b00
Aug 22 07:08:23 domek kernel: Call Trace:
Aug 22 07:08:23 domek kernel: [<ffffffffb7467e73>] dump_stack+0x86/0xc3
Aug 22 07:08:23 domek kernel: [<ffffffffb710f27e>] __lock_acquire+0x78e/0x1290
Aug 22 07:08:23 domek kernel: [<ffffffffb70ea687>] ? sched_clock_cpu+0xa7/0xc0
Aug 22 07:08:23 domek kernel: [<ffffffffb78f661e>] ? mutex_unlock+0xe/0x10
Aug 22 07:08:23 domek kernel: [<ffffffffb71101e6>] lock_acquire+0xf6/0x1f0
Aug 22 07:08:23 domek kernel: [<ffffffffc07e1e12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffb78f59a6>] mutex_lock_nested+0x86/0x3f0
Aug 22 07:08:23 domek kernel: [<ffffffffc07e1e12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffc07f80d5>] ? __btrfs_release_delayed_node+0x75/0x1c0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffc07e1e12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffc07f9f79>] ? btrfs_commit_inode_delayed_inode+0xe9/0x130 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffc07e1e12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffb70deb69>] ? __might_sleep+0x49/0x80
Aug 22 07:08:23 domek kernel: [<ffffffffc07e293c>] btrfs_log_inode+0xc8c/0x10f0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffb7037f29>] ? sched_clock+0x9/0x10
Aug 22 07:08:23 domek kernel: [<ffffffffc07e3070>] btrfs_log_inode_parent+0x240/0x940 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffb78f92e7>] ? _raw_spin_unlock+0x27/0x40
Aug 22 07:08:23 domek kernel: [<ffffffffc079ddba>] ? btrfs_update_inode+0xda/0x110 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffc07e4cf1>] btrfs_log_new_name+0x71/0x90 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffc07a7cd0>] btrfs_rename2+0x1090/0x17a0 [btrfs]
Aug 22 07:08:23 domek kernel: [<ffffffffb712df4d>] ? debug_lockdep_rcu_enabled+0x1d/0x20
Aug 22 07:08:23 domek kernel: [<ffffffffb72c41c6>] ? lock_two_nondirectories+0x66/0x70
Aug 22 07:08:23 domek kernel: [<ffffffffb72b1662>] vfs_rename+0x5c2/0x970
Aug 22 07:08:23 domek kernel: [<ffffffffb72af800>] ? follow_managed+0x310/0x360
Aug 22 07:08:23 domek kernel: [<ffffffffb72b81e7>] SyS_rename+0x3a7/0x3d0
Aug 22 07:08:23 domek kernel: [<ffffffffb7003efc>] do_syscall_64+0x6c/0x1e0
Aug 22 07:08:23 domek kernel: [<ffffffffb78f9cff>] entry_SYSCALL64_slow_path+0x25/0x25

Comment 2 Tomasz Kłoczko 2016-08-25 18:15:45 UTC
Just after rebooting on new kernel found the same issue logged in kernel logs:

  206.737726] =============================================
[  206.737728] [ INFO: possible recursive locking detected ]
[  206.737730] 4.8.0-0.rc3.git1.1.fc26.x86_64 #1 Not tainted
[  206.737732] ---------------------------------------------
[  206.737733] gvfsd-metadata/4645 is trying to acquire lock:
[  206.737735]  (&ei->log_mutex){+.+...}, at: [<ffffffffc089ae12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.737768] 
               but task is already holding lock:
[  206.737770]  (&ei->log_mutex){+.+...}, at: [<ffffffffc089ae12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.737791] 
               other info that might help us debug this:
[  206.737793]  Possible unsafe locking scenario:

[  206.737795]        CPU0
[  206.737796]        ----
[  206.737797]   lock(&ei->log_mutex);
[  206.737800]   lock(&ei->log_mutex);
[  206.737802] 
                *** DEADLOCK ***

[  206.737804]  May be due to missing lock nesting notation

[  206.737807] 6 locks held by gvfsd-metadata/4645:
[  206.737808]  #0:  (sb_writers#8){.+.+.+}, at: [<ffffffff8f2a70b4>] __sb_start_write+0xb4/0xf0
[  206.737816]  #1:  (&type->i_mutex_dir_key#3/1){+.+.+.}, at: [<ffffffff8f2afa2a>] lock_rename+0xda/0x100
[  206.737823]  #2:  (&sb->s_type->i_mutex_key#12){+.+.+.}, at: [<ffffffff8f2c419e>] lock_two_nondirectories+0x3e/0x70
[  206.737830]  #3:  (&sb->s_type->i_mutex_key#12/4){+.+...}, at: [<ffffffff8f2c41c6>] lock_two_nondirectories+0x66/0x70
[  206.737837]  #4:  (sb_internal){.+.+..}, at: [<ffffffff8f2a7078>] __sb_start_write+0x78/0xf0
[  206.737842]  #5:  (&ei->log_mutex){+.+...}, at: [<ffffffffc089ae12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.737863] 
               stack backtrace:
[  206.737866] CPU: 3 PID: 4645 Comm: gvfsd-metadata Not tainted 4.8.0-0.rc3.git1.1.fc26.x86_64 #1
[  206.737868] Hardware name: Sony Corporation VPCSB2M9E/VAIO, BIOS R2087H4 06/15/2012
[  206.737870]  0000000000000086 0000000068b649e2 ffff9ef62c1ff780 ffffffff8f467e73
[  206.737875]  ffffffff90bf20b0 ffff9ef62c200000 ffff9ef62c1ff848 ffffffff8f10f27e
[  206.737879]  0000000000000005 ffffffff00000006 0000000090a97609 ffffffff90513d00
[  206.737883] Call Trace:
[  206.737888]  [<ffffffff8f467e73>] dump_stack+0x86/0xc3
[  206.737892]  [<ffffffff8f10f27e>] __lock_acquire+0x78e/0x1290
[  206.737896]  [<ffffffff8f0ea687>] ? sched_clock_cpu+0xa7/0xc0
[  206.737899]  [<ffffffff8f8f661e>] ? mutex_unlock+0xe/0x10
[  206.737902]  [<ffffffff8f1101e6>] lock_acquire+0xf6/0x1f0
[  206.737919]  [<ffffffffc089ae12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.737922]  [<ffffffff8f8f59a6>] mutex_lock_nested+0x86/0x3f0
[  206.737939]  [<ffffffffc089ae12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.737957]  [<ffffffffc08b10d5>] ? __btrfs_release_delayed_node+0x75/0x1c0 [btrfs]
[  206.737974]  [<ffffffffc089ae12>] ? btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.737991]  [<ffffffffc08b2f79>] ? btrfs_commit_inode_delayed_inode+0xe9/0x130 [btrfs]
[  206.738007]  [<ffffffffc089ae12>] btrfs_log_inode+0x162/0x10f0 [btrfs]
[  206.738012]  [<ffffffff8f0deb69>] ? __might_sleep+0x49/0x80
[  206.738029]  [<ffffffffc089b93c>] btrfs_log_inode+0xc8c/0x10f0 [btrfs]
[  206.738033]  [<ffffffff8f037f29>] ? sched_clock+0x9/0x10
[  206.738050]  [<ffffffffc089c070>] btrfs_log_inode_parent+0x240/0x940 [btrfs]
[  206.738052]  [<ffffffff8f8f92e7>] ? _raw_spin_unlock+0x27/0x40
[  206.738070]  [<ffffffffc0856dba>] ? btrfs_update_inode+0xda/0x110 [btrfs]
[  206.738087]  [<ffffffffc089dcf1>] btrfs_log_new_name+0x71/0x90 [btrfs]
[  206.738105]  [<ffffffffc0860cd0>] btrfs_rename2+0x1090/0x17a0 [btrfs]
[  206.738108]  [<ffffffff8f12df4d>] ? debug_lockdep_rcu_enabled+0x1d/0x20
[  206.738111]  [<ffffffff8f2c41c6>] ? lock_two_nondirectories+0x66/0x70
[  206.738115]  [<ffffffff8f2b1662>] vfs_rename+0x5c2/0x970
[  206.738118]  [<ffffffff8f2af800>] ? follow_managed+0x310/0x360
[  206.738120]  [<ffffffff8f2b81e7>] SyS_rename+0x3a7/0x3d0
[  206.738124]  [<ffffffff8f003efc>] do_syscall_64+0x6c/0x1e0
[  206.738127]  [<ffffffff8f8f9cff>] entry_SYSCALL64_slow_path+0x25/0x25

Comment 3 Tomasz Kłoczko 2016-09-15 15:56:45 UTC
Just for the record: issue still is present in latest kernel


[  637.994270] =============================================
[  637.994272] [ INFO: possible recursive locking detected ]
[  637.994277] 4.8.0-0.rc5.git2.1.fc26.x86_64 #1 Tainted: G        W      
[  637.994279] ---------------------------------------------
[  637.994282] BrowserBlocking/3937 is trying to acquire lock:
[  637.994285]  (&ei->log_mutex){+.+...}, at: [<ffffffffc069f352>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994332] 
               but task is already holding lock:
[  637.994335]  (&ei->log_mutex){+.+...}, at: [<ffffffffc069f352>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994371] 
               other info that might help us debug this:
[  637.994374]  Possible unsafe locking scenario:

[  637.994377]        CPU0
[  637.994379]        ----
[  637.994381]   lock(&ei->log_mutex);
[  637.994385]   lock(&ei->log_mutex);
[  637.994390] 
                *** DEADLOCK ***

[  637.994394]  May be due to missing lock nesting notation

[  637.994398] 3 locks held by BrowserBlocking/3937:
[  637.994400]  #0:  (&type->i_mutex_dir_key#3){++++++}, at: [<ffffffffc066da83>] btrfs_sync_file+0x163/0x4c0 [btrfs]
[  637.994433]  #1:  (sb_internal){.+.+..}, at: [<ffffffffa32a7594>] __sb_start_write+0xb4/0xf0
[  637.994444]  #2:  (&ei->log_mutex){+.+...}, at: [<ffffffffc069f352>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994480] 
               stack backtrace:
[  637.994485] CPU: 1 PID: 3937 Comm: BrowserBlocking Tainted: G        W       4.8.0-0.rc5.git2.1.fc26.x86_64 #1
[  637.994488] Hardware name: Sony Corporation VPCSB2M9E/VAIO, BIOS R2087H4 06/15/2012
[  637.994492]  0000000000000086 000000005900dfed ffff8bf88f6cb760 ffffffffa3468a73
[  637.994499]  ffffffffa4beece0 ffff8bf8c592b240 ffff8bf88f6cb828 ffffffffa310f67e
[  637.994506]  0000000000000000 ffffffff00000003 00000000c9e61ce6 ffffffffa452c800
[  637.994513] Call Trace:
[  637.994518]  [<ffffffffa3468a73>] dump_stack+0x86/0xc3
[  637.994524]  [<ffffffffa310f67e>] __lock_acquire+0x78e/0x1290
[  637.994530]  [<ffffffffa30eaa87>] ? sched_clock_cpu+0xa7/0xc0
[  637.994535]  [<ffffffffa38f677e>] ? mutex_unlock+0xe/0x10
[  637.994540]  [<ffffffffa31105e6>] lock_acquire+0xf6/0x1f0
[  637.994570]  [<ffffffffc069f352>] ? btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994575]  [<ffffffffa38f5b06>] mutex_lock_nested+0x86/0x3f0
[  637.994604]  [<ffffffffc069f352>] ? btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994633]  [<ffffffffc06b5ac5>] ? __btrfs_release_delayed_node+0x75/0x1c0 [btrfs]
[  637.994660]  [<ffffffffc069f352>] ? btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994687]  [<ffffffffc06b798a>] ? btrfs_commit_inode_delayed_inode+0x10a/0x130 [btrfs]
[  637.994716]  [<ffffffffc069f352>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  637.994722]  [<ffffffffa30def49>] ? __might_sleep+0x49/0x80
[  637.994752]  [<ffffffffc069ff0b>] btrfs_log_inode+0xd1b/0x1190 [btrfs]
[  637.994783]  [<ffffffffc06df399>] log_new_dir_dentries+0x1e3/0x4bb [btrfs]
[  637.994813]  [<ffffffffc06a0cab>] btrfs_log_inode_parent+0x89b/0x940 [btrfs]
[  637.994819]  [<ffffffffa32c0e49>] ? dget_parent+0x99/0x2a0
[  637.994846]  [<ffffffffc06a1d12>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
[  637.994877]  [<ffffffffc066dc31>] btrfs_sync_file+0x311/0x4c0 [btrfs]
[  637.994883]  [<ffffffffa32e1eab>] vfs_fsync_range+0x4b/0xb0
[  637.994888]  [<ffffffffa32e1f6d>] do_fsync+0x3d/0x70
[  637.994893]  [<ffffffffa32e2253>] SyS_fdatasync+0x13/0x20
[  637.994898]  [<ffffffffa38f9dbc>] entry_SYSCALL_64_fastpath+0x1f/0xbd

Comment 4 Tomasz Kłoczko 2016-10-12 14:23:13 UTC
Looks like this bug still is around:

[  208.035291] =============================================
[  208.035294] [ INFO: possible recursive locking detected ]
[  208.035298] 4.9.0-0.rc0.git4.1.fc26.x86_64 #1 Not tainted
[  208.035301] ---------------------------------------------
[  208.035304] gvfsd-metadata/4328 is trying to acquire lock:
[  208.035306]  (&ei->log_mutex){+.+...}, at: [<ffffffffc0783a72>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035353] 
               but task is already holding lock:
[  208.035356]  (&ei->log_mutex){+.+...}, at: [<ffffffffc0783a72>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035391] 
               other info that might help us debug this:
[  208.035394]  Possible unsafe locking scenario:

[  208.035398]        CPU0
[  208.035400]        ----
[  208.035402]   lock(&ei->log_mutex);
[  208.035406]   lock(&ei->log_mutex);
[  208.035410] 
                *** DEADLOCK ***

[  208.035413]  May be due to missing lock nesting notation

[  208.035417] 3 locks held by gvfsd-metadata/4328:
[  208.035420]  #0:  (&type->i_mutex_dir_key#3){++++++}, at: [<ffffffffc07525a3>] btrfs_sync_file+0x163/0x4c0 [btrfs]
[  208.035456]  #1:  (sb_internal){.+.+..}, at: [<ffffffffc07394cb>] start_transaction+0x2fb/0x550 [btrfs]
[  208.035488]  #2:  (&ei->log_mutex){+.+...}, at: [<ffffffffc0783a72>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035523] 
               stack backtrace:
[  208.035528] CPU: 0 PID: 4328 Comm: gvfsd-metadata Not tainted 4.9.0-0.rc0.git4.1.fc26.x86_64 #1
[  208.035532] Hardware name: Sony Corporation VPCSB2M9E/VAIO, BIOS R2087H4 06/15/2012
[  208.035535]  ffffbaadc4be7760 ffffffffb046c303 ffffffffb1bdcba0 ffff93e0fd5b0000
[  208.035543]  ffffbaadc4be7828 ffffffffb011125e 0000000000000002 ffffffff00000003
[  208.035550]  00000000a0164e48 ffffffffb150ad00 98d1bce9a9bc16d8 ffff93e0fd5b0ca8
[  208.035557] Call Trace:
[  208.035564]  [<ffffffffb046c303>] dump_stack+0x86/0xc3
[  208.035570]  [<ffffffffb011125e>] __lock_acquire+0x78e/0x1290
[  208.035576]  [<ffffffffb00ec1d7>] ? sched_clock_cpu+0xa7/0xc0
[  208.035581]  [<ffffffffb0903cde>] ? mutex_unlock+0xe/0x10
[  208.035587]  [<ffffffffb01121c6>] lock_acquire+0xf6/0x1f0
[  208.035616]  [<ffffffffc0783a72>] ? btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035621]  [<ffffffffb0903066>] mutex_lock_nested+0x86/0x3f0
[  208.035649]  [<ffffffffc0783a72>] ? btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035679]  [<ffffffffc079a0f5>] ? __btrfs_release_delayed_node+0x75/0x1c0 [btrfs]
[  208.035707]  [<ffffffffc0783a72>] ? btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035736]  [<ffffffffc079bf89>] ? btrfs_commit_inode_delayed_inode+0xe9/0x130 [btrfs]
[  208.035763]  [<ffffffffc0783a72>] btrfs_log_inode+0x162/0x1190 [btrfs]
[  208.035769]  [<ffffffffb00e02fa>] ? __might_sleep+0x4a/0x80
[  208.035796]  [<ffffffffc0784628>] btrfs_log_inode+0xd18/0x1190 [btrfs]
[  208.035827]  [<ffffffffc07c37a7>] log_new_dir_dentries+0x1e1/0x4c0 [btrfs]
[  208.035855]  [<ffffffffc07853c8>] btrfs_log_inode_parent+0x898/0x940 [btrfs]
[  208.035862]  [<ffffffffb02c4439>] ? dget_parent+0x99/0x2a0
[  208.035889]  [<ffffffffc0786452>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
[  208.035918]  [<ffffffffc0752751>] btrfs_sync_file+0x311/0x4c0 [btrfs]
[  208.035923]  [<ffffffffb02e560b>] vfs_fsync_range+0x4b/0xb0
[  208.035928]  [<ffffffffb02e56cd>] do_fsync+0x3d/0x70
[  208.035932]  [<ffffffffb02e5990>] SyS_fsync+0x10/0x20
[  208.035937]  [<ffffffffb09072c1>] entry_SYSCALL_64_fastpath+0x1f/0xc2

Comment 5 Tomasz Kłoczko 2017-04-16 17:29:56 UTC
Seems no longer happens


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