diff mbox series

block_dump: don't put the last refcount when marking inode dirty

Message ID 20210226103103.3048803-1-yi.zhang@huawei.com (mailing list archive)
State New, archived
Headers show
Series block_dump: don't put the last refcount when marking inode dirty | expand

Commit Message

Zhang Yi Feb. 26, 2021, 10:31 a.m. UTC
There is an AA deadlock problem when using block_dump on ext4 file
system with data=journal mode.

  watchdog: BUG: soft lockup - CPU#19 stuck for 22s! [jbd2/pmem0-8:1002]
  CPU: 19 PID: 1002 Comm: jbd2/pmem0-8
  RIP: 0010:queued_spin_lock_slowpath+0x60/0x3b0
  ...
  Call Trace:
   _raw_spin_lock+0x57/0x70
   jbd2_journal_invalidatepage+0x166/0x680
   __ext4_journalled_invalidatepage+0x8c/0x120
   ext4_journalled_invalidatepage+0x12/0x40
   truncate_cleanup_page+0x10e/0x1c0
   truncate_inode_pages_range+0x2c8/0xec0
   truncate_inode_pages_final+0x41/0x90
   ext4_evict_inode+0x254/0xac0
   evict+0x11c/0x2f0
   iput+0x20e/0x3a0
   dentry_unlink_inode+0x1bf/0x1d0
   __dentry_kill+0x14c/0x2c0
   dput+0x2bc/0x630
   block_dump___mark_inode_dirty.cold+0x5c/0x111
   __mark_inode_dirty+0x678/0x6b0
   mark_buffer_dirty+0x16e/0x1d0
   __jbd2_journal_temp_unlink_buffer+0x127/0x1f0
   __jbd2_journal_unfile_buffer+0x24/0x80
   __jbd2_journal_refile_buffer+0x12f/0x1b0
   jbd2_journal_commit_transaction+0x244b/0x3030

The problem is a race between jbd2 committing data buffer and user
unlink the file concurrently. The jbd2 will get jh->b_state_lock and
redirty the inode's data buffer and inode itself. If block_dump is
enabled, it will try to find inode's dentry and invoke the last dput()
after the inode was unlinked. Then the evict procedure will unmap
buffer and get jh->b_state_lock again in journal_unmap_buffer(), and
finally lead to deadlock. It works fine if block_dump is not enabled
because the last evict procedure is not invoked in jbd2 progress and
the jh->b_state_lock will also prevent inode use after free.

jbd2                                xxx
                                    vfs_unlink
                                     ext4_unlink
jbd2_journal_commit_transaction
**get jh->b_state_lock**
jbd2_journal_refile_buffer
 mark_buffer_dirty
  __mark_inode_dirty
   block_dump___mark_inode_dirty
    d_find_alias
                                     d_delete
                                      unhash
    dput  //put the last refcount
     evict
      journal_unmap_buffer
       **get jh->b_state_lock again**

In most cases of where invoking mark_inode_dirty() will get inode's
refcount and the last iput may not happen, but it's not safe. After
checking the block_dump code, it only want to dump the file name of the
dirty inode, so there is no need to get and put denrty, and dump an
unhashed dentry is also fine. This patch remove the dget() && dput(),
print the dentry name directly.

Signed-off-by: zhangyi (F) <yi.zhang@huawei.com>
Signed-off-by: yebin (H) <yebin10@huawei.com>
---
 fs/fs-writeback.c | 20 ++++++++++++++------
 1 file changed, 14 insertions(+), 6 deletions(-)

Comments

Jan Kara March 1, 2021, 11:21 a.m. UTC | #1
On Fri 26-02-21 18:31:03, zhangyi (F) wrote:
> There is an AA deadlock problem when using block_dump on ext4 file
> system with data=journal mode.
> 
>   watchdog: BUG: soft lockup - CPU#19 stuck for 22s! [jbd2/pmem0-8:1002]
>   CPU: 19 PID: 1002 Comm: jbd2/pmem0-8
>   RIP: 0010:queued_spin_lock_slowpath+0x60/0x3b0
>   ...
>   Call Trace:
>    _raw_spin_lock+0x57/0x70
>    jbd2_journal_invalidatepage+0x166/0x680
>    __ext4_journalled_invalidatepage+0x8c/0x120
>    ext4_journalled_invalidatepage+0x12/0x40
>    truncate_cleanup_page+0x10e/0x1c0
>    truncate_inode_pages_range+0x2c8/0xec0
>    truncate_inode_pages_final+0x41/0x90
>    ext4_evict_inode+0x254/0xac0
>    evict+0x11c/0x2f0
>    iput+0x20e/0x3a0
>    dentry_unlink_inode+0x1bf/0x1d0
>    __dentry_kill+0x14c/0x2c0
>    dput+0x2bc/0x630
>    block_dump___mark_inode_dirty.cold+0x5c/0x111
>    __mark_inode_dirty+0x678/0x6b0
>    mark_buffer_dirty+0x16e/0x1d0
>    __jbd2_journal_temp_unlink_buffer+0x127/0x1f0
>    __jbd2_journal_unfile_buffer+0x24/0x80
>    __jbd2_journal_refile_buffer+0x12f/0x1b0
>    jbd2_journal_commit_transaction+0x244b/0x3030
> 
> The problem is a race between jbd2 committing data buffer and user
> unlink the file concurrently. The jbd2 will get jh->b_state_lock and
> redirty the inode's data buffer and inode itself. If block_dump is
> enabled, it will try to find inode's dentry and invoke the last dput()
> after the inode was unlinked. Then the evict procedure will unmap
> buffer and get jh->b_state_lock again in journal_unmap_buffer(), and
> finally lead to deadlock. It works fine if block_dump is not enabled
> because the last evict procedure is not invoked in jbd2 progress and
> the jh->b_state_lock will also prevent inode use after free.
> 
> jbd2                                xxx
>                                     vfs_unlink
>                                      ext4_unlink
> jbd2_journal_commit_transaction
> **get jh->b_state_lock**
> jbd2_journal_refile_buffer
>  mark_buffer_dirty
>   __mark_inode_dirty
>    block_dump___mark_inode_dirty
>     d_find_alias
>                                      d_delete
>                                       unhash
>     dput  //put the last refcount
>      evict
>       journal_unmap_buffer
>        **get jh->b_state_lock again**
> 
> In most cases of where invoking mark_inode_dirty() will get inode's
> refcount and the last iput may not happen, but it's not safe. After
> checking the block_dump code, it only want to dump the file name of the
> dirty inode, so there is no need to get and put denrty, and dump an
> unhashed dentry is also fine. This patch remove the dget() && dput(),
> print the dentry name directly.
> 
> Signed-off-by: zhangyi (F) <yi.zhang@huawei.com>
> Signed-off-by: yebin (H) <yebin10@huawei.com>

Hrm, ok. Honestly, I wanted to just delete that code for a long time. IMO
tracepoints (and we have one in __mark_inode_dirty) are much more useful
for tracing anyway. This code exists only because it was there much before
tracepoints existed... Do you have a strong reason why are you using
block_dump instead of tracepoint trace_writeback_mark_inode_dirty() for
your monitoring?

								Honza

> ---
>  fs/fs-writeback.c | 20 ++++++++++++++------
>  1 file changed, 14 insertions(+), 6 deletions(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index c41cb887eb7d..e9b0952fe236 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -2199,21 +2199,29 @@ int dirtytime_interval_handler(struct ctl_table *table, int write,
>  static noinline void block_dump___mark_inode_dirty(struct inode *inode)
>  {
>  	if (inode->i_ino || strcmp(inode->i_sb->s_id, "bdev")) {
> -		struct dentry *dentry;
> +		struct dentry *dentry = NULL;
>  		const char *name = "?";
>  
> -		dentry = d_find_alias(inode);
> -		if (dentry) {
> -			spin_lock(&dentry->d_lock);
> -			name = (const char *) dentry->d_name.name;
> +		if (!hlist_empty(&inode->i_dentry)) {
> +			spin_lock(&inode->i_lock);
> +			if (!hlist_empty(&inode->i_dentry)) {
> +				dentry = hlist_entry(inode->i_dentry.first,
> +						     struct dentry, d_u.d_alias);
> +				spin_lock(&dentry->d_lock);
> +				name = (const char *) dentry->d_name.name;
> +			} else {
> +				spin_unlock(&inode->i_lock);
> +			}
>  		}
> +
>  		printk(KERN_DEBUG
>  		       "%s(%d): dirtied inode %lu (%s) on %s\n",
>  		       current->comm, task_pid_nr(current), inode->i_ino,
>  		       name, inode->i_sb->s_id);
> +
>  		if (dentry) {
>  			spin_unlock(&dentry->d_lock);
> -			dput(dentry);
> +			spin_unlock(&inode->i_lock);
>  		}
>  	}
>  }
> -- 
> 2.25.4
>
Zhang Yi March 4, 2021, 1:37 p.m. UTC | #2
On 2021/3/1 19:21, Jan Kara wrote:
> On Fri 26-02-21 18:31:03, zhangyi (F) wrote:
>> There is an AA deadlock problem when using block_dump on ext4 file
>> system with data=journal mode.
>>
>>   watchdog: BUG: soft lockup - CPU#19 stuck for 22s! [jbd2/pmem0-8:1002]
>>   CPU: 19 PID: 1002 Comm: jbd2/pmem0-8
>>   RIP: 0010:queued_spin_lock_slowpath+0x60/0x3b0
>>   ...
>>   Call Trace:
>>    _raw_spin_lock+0x57/0x70
>>    jbd2_journal_invalidatepage+0x166/0x680
>>    __ext4_journalled_invalidatepage+0x8c/0x120
>>    ext4_journalled_invalidatepage+0x12/0x40
>>    truncate_cleanup_page+0x10e/0x1c0
>>    truncate_inode_pages_range+0x2c8/0xec0
>>    truncate_inode_pages_final+0x41/0x90
>>    ext4_evict_inode+0x254/0xac0
>>    evict+0x11c/0x2f0
>>    iput+0x20e/0x3a0
>>    dentry_unlink_inode+0x1bf/0x1d0
>>    __dentry_kill+0x14c/0x2c0
>>    dput+0x2bc/0x630
>>    block_dump___mark_inode_dirty.cold+0x5c/0x111
>>    __mark_inode_dirty+0x678/0x6b0
>>    mark_buffer_dirty+0x16e/0x1d0
>>    __jbd2_journal_temp_unlink_buffer+0x127/0x1f0
>>    __jbd2_journal_unfile_buffer+0x24/0x80
>>    __jbd2_journal_refile_buffer+0x12f/0x1b0
>>    jbd2_journal_commit_transaction+0x244b/0x3030
>>
>> The problem is a race between jbd2 committing data buffer and user
>> unlink the file concurrently. The jbd2 will get jh->b_state_lock and
>> redirty the inode's data buffer and inode itself. If block_dump is
>> enabled, it will try to find inode's dentry and invoke the last dput()
>> after the inode was unlinked. Then the evict procedure will unmap
>> buffer and get jh->b_state_lock again in journal_unmap_buffer(), and
>> finally lead to deadlock. It works fine if block_dump is not enabled
>> because the last evict procedure is not invoked in jbd2 progress and
>> the jh->b_state_lock will also prevent inode use after free.
>>
>> jbd2                                xxx
>>                                     vfs_unlink
>>                                      ext4_unlink
>> jbd2_journal_commit_transaction
>> **get jh->b_state_lock**
>> jbd2_journal_refile_buffer
>>  mark_buffer_dirty
>>   __mark_inode_dirty
>>    block_dump___mark_inode_dirty
>>     d_find_alias
>>                                      d_delete
>>                                       unhash
>>     dput  //put the last refcount
>>      evict
>>       journal_unmap_buffer
>>        **get jh->b_state_lock again**
>>
>> In most cases of where invoking mark_inode_dirty() will get inode's
>> refcount and the last iput may not happen, but it's not safe. After
>> checking the block_dump code, it only want to dump the file name of the
>> dirty inode, so there is no need to get and put denrty, and dump an
>> unhashed dentry is also fine. This patch remove the dget() && dput(),
>> print the dentry name directly.
>>
>> Signed-off-by: zhangyi (F) <yi.zhang@huawei.com>
>> Signed-off-by: yebin (H) <yebin10@huawei.com>
> 
> Hrm, ok. Honestly, I wanted to just delete that code for a long time. IMO
> tracepoints (and we have one in __mark_inode_dirty) are much more useful
> for tracing anyway. This code exists only because it was there much before
> tracepoints existed... Do you have a strong reason why are you using
> block_dump instead of tracepoint trace_writeback_mark_inode_dirty() for
> your monitoring?
> 

Hi, Jan. We just do some stress tests and find this issue, I'm not sure who
are still using this old debug interface and gather it may need time. Could
we firstly fix this issue, and then delete this code if no opposed?

Thanks,
Yi.
Jan Kara March 5, 2021, 10:10 a.m. UTC | #3
On Thu 04-03-21 21:37:42, zhangyi (F) wrote:
> On 2021/3/1 19:21, Jan Kara wrote:
> > On Fri 26-02-21 18:31:03, zhangyi (F) wrote:
> >> There is an AA deadlock problem when using block_dump on ext4 file
> >> system with data=journal mode.
> >>
> >>   watchdog: BUG: soft lockup - CPU#19 stuck for 22s! [jbd2/pmem0-8:1002]
> >>   CPU: 19 PID: 1002 Comm: jbd2/pmem0-8
> >>   RIP: 0010:queued_spin_lock_slowpath+0x60/0x3b0
> >>   ...
> >>   Call Trace:
> >>    _raw_spin_lock+0x57/0x70
> >>    jbd2_journal_invalidatepage+0x166/0x680
> >>    __ext4_journalled_invalidatepage+0x8c/0x120
> >>    ext4_journalled_invalidatepage+0x12/0x40
> >>    truncate_cleanup_page+0x10e/0x1c0
> >>    truncate_inode_pages_range+0x2c8/0xec0
> >>    truncate_inode_pages_final+0x41/0x90
> >>    ext4_evict_inode+0x254/0xac0
> >>    evict+0x11c/0x2f0
> >>    iput+0x20e/0x3a0
> >>    dentry_unlink_inode+0x1bf/0x1d0
> >>    __dentry_kill+0x14c/0x2c0
> >>    dput+0x2bc/0x630
> >>    block_dump___mark_inode_dirty.cold+0x5c/0x111
> >>    __mark_inode_dirty+0x678/0x6b0
> >>    mark_buffer_dirty+0x16e/0x1d0
> >>    __jbd2_journal_temp_unlink_buffer+0x127/0x1f0
> >>    __jbd2_journal_unfile_buffer+0x24/0x80
> >>    __jbd2_journal_refile_buffer+0x12f/0x1b0
> >>    jbd2_journal_commit_transaction+0x244b/0x3030
> >>
> >> The problem is a race between jbd2 committing data buffer and user
> >> unlink the file concurrently. The jbd2 will get jh->b_state_lock and
> >> redirty the inode's data buffer and inode itself. If block_dump is
> >> enabled, it will try to find inode's dentry and invoke the last dput()
> >> after the inode was unlinked. Then the evict procedure will unmap
> >> buffer and get jh->b_state_lock again in journal_unmap_buffer(), and
> >> finally lead to deadlock. It works fine if block_dump is not enabled
> >> because the last evict procedure is not invoked in jbd2 progress and
> >> the jh->b_state_lock will also prevent inode use after free.
> >>
> >> jbd2                                xxx
> >>                                     vfs_unlink
> >>                                      ext4_unlink
> >> jbd2_journal_commit_transaction
> >> **get jh->b_state_lock**
> >> jbd2_journal_refile_buffer
> >>  mark_buffer_dirty
> >>   __mark_inode_dirty
> >>    block_dump___mark_inode_dirty
> >>     d_find_alias
> >>                                      d_delete
> >>                                       unhash
> >>     dput  //put the last refcount
> >>      evict
> >>       journal_unmap_buffer
> >>        **get jh->b_state_lock again**
> >>
> >> In most cases of where invoking mark_inode_dirty() will get inode's
> >> refcount and the last iput may not happen, but it's not safe. After
> >> checking the block_dump code, it only want to dump the file name of the
> >> dirty inode, so there is no need to get and put denrty, and dump an
> >> unhashed dentry is also fine. This patch remove the dget() && dput(),
> >> print the dentry name directly.
> >>
> >> Signed-off-by: zhangyi (F) <yi.zhang@huawei.com>
> >> Signed-off-by: yebin (H) <yebin10@huawei.com>
> > 
> > Hrm, ok. Honestly, I wanted to just delete that code for a long time. IMO
> > tracepoints (and we have one in __mark_inode_dirty) are much more useful
> > for tracing anyway. This code exists only because it was there much before
> > tracepoints existed... Do you have a strong reason why are you using
> > block_dump instead of tracepoint trace_writeback_mark_inode_dirty() for
> > your monitoring?
> > 
> 
> Hi, Jan. We just do some stress tests and find this issue, I'm not sure who
> are still using this old debug interface and gather it may need time. Could
> we firstly fix this issue, and then delete this code if no opposed?

I'd do it the other way around :) Delete the code and only fix it if
someone complains that the feature is still used and so we should not
delete it. Will you send a patch or should I do it?

								Honza
Zhang Yi March 5, 2021, 12:01 p.m. UTC | #4
On 2021/3/5 18:10, Jan Kara wrote:
> On Thu 04-03-21 21:37:42, zhangyi (F) wrote:
>> On 2021/3/1 19:21, Jan Kara wrote:
>>> On Fri 26-02-21 18:31:03, zhangyi (F) wrote:
>>>> There is an AA deadlock problem when using block_dump on ext4 file
>>>> system with data=journal mode.
>>>>
>>>>   watchdog: BUG: soft lockup - CPU#19 stuck for 22s! [jbd2/pmem0-8:1002]
>>>>   CPU: 19 PID: 1002 Comm: jbd2/pmem0-8
>>>>   RIP: 0010:queued_spin_lock_slowpath+0x60/0x3b0
>>>>   ...
>>>>   Call Trace:
>>>>    _raw_spin_lock+0x57/0x70
>>>>    jbd2_journal_invalidatepage+0x166/0x680
>>>>    __ext4_journalled_invalidatepage+0x8c/0x120
>>>>    ext4_journalled_invalidatepage+0x12/0x40
>>>>    truncate_cleanup_page+0x10e/0x1c0
>>>>    truncate_inode_pages_range+0x2c8/0xec0
>>>>    truncate_inode_pages_final+0x41/0x90
>>>>    ext4_evict_inode+0x254/0xac0
>>>>    evict+0x11c/0x2f0
>>>>    iput+0x20e/0x3a0
>>>>    dentry_unlink_inode+0x1bf/0x1d0
>>>>    __dentry_kill+0x14c/0x2c0
>>>>    dput+0x2bc/0x630
>>>>    block_dump___mark_inode_dirty.cold+0x5c/0x111
>>>>    __mark_inode_dirty+0x678/0x6b0
>>>>    mark_buffer_dirty+0x16e/0x1d0
>>>>    __jbd2_journal_temp_unlink_buffer+0x127/0x1f0
>>>>    __jbd2_journal_unfile_buffer+0x24/0x80
>>>>    __jbd2_journal_refile_buffer+0x12f/0x1b0
>>>>    jbd2_journal_commit_transaction+0x244b/0x3030
>>>>
>>>> The problem is a race between jbd2 committing data buffer and user
>>>> unlink the file concurrently. The jbd2 will get jh->b_state_lock and
>>>> redirty the inode's data buffer and inode itself. If block_dump is
>>>> enabled, it will try to find inode's dentry and invoke the last dput()
>>>> after the inode was unlinked. Then the evict procedure will unmap
>>>> buffer and get jh->b_state_lock again in journal_unmap_buffer(), and
>>>> finally lead to deadlock. It works fine if block_dump is not enabled
>>>> because the last evict procedure is not invoked in jbd2 progress and
>>>> the jh->b_state_lock will also prevent inode use after free.
>>>>
>>>> jbd2                                xxx
>>>>                                     vfs_unlink
>>>>                                      ext4_unlink
>>>> jbd2_journal_commit_transaction
>>>> **get jh->b_state_lock**
>>>> jbd2_journal_refile_buffer
>>>>  mark_buffer_dirty
>>>>   __mark_inode_dirty
>>>>    block_dump___mark_inode_dirty
>>>>     d_find_alias
>>>>                                      d_delete
>>>>                                       unhash
>>>>     dput  //put the last refcount
>>>>      evict
>>>>       journal_unmap_buffer
>>>>        **get jh->b_state_lock again**
>>>>
>>>> In most cases of where invoking mark_inode_dirty() will get inode's
>>>> refcount and the last iput may not happen, but it's not safe. After
>>>> checking the block_dump code, it only want to dump the file name of the
>>>> dirty inode, so there is no need to get and put denrty, and dump an
>>>> unhashed dentry is also fine. This patch remove the dget() && dput(),
>>>> print the dentry name directly.
>>>>
>>>> Signed-off-by: zhangyi (F) <yi.zhang@huawei.com>
>>>> Signed-off-by: yebin (H) <yebin10@huawei.com>
>>>
>>> Hrm, ok. Honestly, I wanted to just delete that code for a long time. IMO
>>> tracepoints (and we have one in __mark_inode_dirty) are much more useful
>>> for tracing anyway. This code exists only because it was there much before
>>> tracepoints existed... Do you have a strong reason why are you using
>>> block_dump instead of tracepoint trace_writeback_mark_inode_dirty() for
>>> your monitoring?
>>>
>>
>> Hi, Jan. We just do some stress tests and find this issue, I'm not sure who
>> are still using this old debug interface and gather it may need time. Could
>> we firstly fix this issue, and then delete this code if no opposed?
> 
> I'd do it the other way around :) Delete the code and only fix it if
> someone complains that the feature is still used and so we should not
> delete it. Will you send a patch or should I do it?
> 

OK, I will send a RFC patch to delete this feature.

Thanks,
Yi.
Christoph Hellwig March 5, 2021, 1:24 p.m. UTC | #5
On Mon, Mar 01, 2021 at 12:21:02PM +0100, Jan Kara wrote:
> Hrm, ok. Honestly, I wanted to just delete that code for a long time. IMO
> tracepoints (and we have one in __mark_inode_dirty) are much more useful
> for tracing anyway. This code exists only because it was there much before
> tracepoints existed... Do you have a strong reason why are you using
> block_dump instead of tracepoint trace_writeback_mark_inode_dirty() for
> your monitoring?

Let me play devils advocate here, the downside of the writeback
tracepoints is that they only trace the inode number and not a file name
(component).  Which is also the reason they avoid this problem.

That being said block_dump is a horrible hack, and trace points are the
proper replacement.
diff mbox series

Patch

diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index c41cb887eb7d..e9b0952fe236 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -2199,21 +2199,29 @@  int dirtytime_interval_handler(struct ctl_table *table, int write,
 static noinline void block_dump___mark_inode_dirty(struct inode *inode)
 {
 	if (inode->i_ino || strcmp(inode->i_sb->s_id, "bdev")) {
-		struct dentry *dentry;
+		struct dentry *dentry = NULL;
 		const char *name = "?";
 
-		dentry = d_find_alias(inode);
-		if (dentry) {
-			spin_lock(&dentry->d_lock);
-			name = (const char *) dentry->d_name.name;
+		if (!hlist_empty(&inode->i_dentry)) {
+			spin_lock(&inode->i_lock);
+			if (!hlist_empty(&inode->i_dentry)) {
+				dentry = hlist_entry(inode->i_dentry.first,
+						     struct dentry, d_u.d_alias);
+				spin_lock(&dentry->d_lock);
+				name = (const char *) dentry->d_name.name;
+			} else {
+				spin_unlock(&inode->i_lock);
+			}
 		}
+
 		printk(KERN_DEBUG
 		       "%s(%d): dirtied inode %lu (%s) on %s\n",
 		       current->comm, task_pid_nr(current), inode->i_ino,
 		       name, inode->i_sb->s_id);
+
 		if (dentry) {
 			spin_unlock(&dentry->d_lock);
-			dput(dentry);
+			spin_unlock(&inode->i_lock);
 		}
 	}
 }