linux-mm.kvack.org archive mirror
 help / color / mirror / Atom feed
* [REPORT] ext4 deadlock possibilities by DEPT
@ 2022-02-16  4:11 Byungchul Park
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
  2022-02-16  6:51 ` [REPORT] ext4 deadlock possibilities by DEPT Byungchul Park
  0 siblings, 2 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:11 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

Hi Theodore, Andreas and ext4 folks,

I've been developing a tool for detecting deadlock possibilities by
tracking wait/event rather than lock(?) acquisition order to try to
cover all synchonization machanisms. It's done on v5.17-rc1 tag.

https://github.com/lgebyungchulpark/linux-dept/commits/dept1.11_on_v5.17-rc1

Benifit:

	0. Works with all lock primitives.
	1. Works with wait_for_completion()/complete().
	2. Works with 'wait' on PG_locked.
	3. Works with 'wait' on PG_writeback.
	4. Works with swait/wakeup.
	5. Works with waitqueue.
	6. Multiple reports are allowed.
	7. Deduplication control on multiple reports.
	8. Withstand false positives thanks to 6.
	9. Easy to tag any wait/event.

Future work:

	0. To make it more stable.
	1. To separates Dept from Lockdep.
	2. To improves performance in terms of time and space.
	3. To use Dept as a dependency engine for Lockdep.
	4. To add any missing tags of wait/event in the kernel.
	5. To deduplicate stack trace.

I've got several reports from the tool. Some of them look like false
alarms caused by Lockdep's fake annotations added for better detection.
However, some others look like real deadlock possibility. Because of my
unfamiliarity of the domain, it's hard to confirm if it's a real one.
I'd like to ask for your opinion on it and it'd be appreciated.

How to interpret the report is:

	1. E(event) in each context cannot be triggered because of the
	   W(wait) that cannot be woken.
	2. The stack trace helping find the problematic code is located
	   in each conext's detail.

Let me add the reports on this email thread.

---
Thanks,
Byungchul



^ permalink raw reply	[flat|nested] 8+ messages in thread

* Report in ext4_buffered_write_iter()
  2022-02-16  4:11 [REPORT] ext4 deadlock possibilities by DEPT Byungchul Park
@ 2022-02-16  4:15 ` Byungchul Park
  2022-02-16  4:15   ` Report in ext4_da_write_begin() Byungchul Park
                     ` (4 more replies)
  2022-02-16  6:51 ` [REPORT] ext4 deadlock possibilities by DEPT Byungchul Park
  1 sibling, 5 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:15 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

[    7.083356] ===================================================
[    7.083360] DEPT: Circular dependency has been detected.
[    7.083361] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    7.083363] ---------------------------------------------------
[    7.083364] summary
[    7.083364] ---------------------------------------------------
[    7.083365] *** DEADLOCK ***
[    7.083365] 
[    7.083366] context A
[    7.083366]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    7.083368]     [W] down_write(&sb->s_type->i_mutex_key:0)
[    7.083370]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    7.083371] 
[    7.083371] context B
[    7.083372]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    7.083373]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    7.083374]     [E] write_unlock(&journal->j_state_lock:8)
[    7.083375] 
[    7.083376] context C
[    7.083377]     [S] down_write(&sb->s_type->i_mutex_key:0)
[    7.083378]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    7.083379]     [E] up_write(&sb->s_type->i_mutex_key:0)
[    7.083380] 
[    7.083380] [S]: start of the event context
[    7.083381] [W]: the wait blocked
[    7.083382] [E]: the event not reachable
[    7.083382] ---------------------------------------------------
[    7.083383] context A's detail
[    7.083384] ---------------------------------------------------
[    7.083384] context A
[    7.083385]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    7.083386]     [W] down_write(&sb->s_type->i_mutex_key:0)
[    7.083387]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    7.083388] 
[    7.083388] [S] (unknown)(&(&journal->j_wait_commit)->dmap:0):
[    7.083389] (N/A)
[    7.083390] 
[    7.083391] [W] down_write(&sb->s_type->i_mutex_key:0):
[    7.083391] [<ffffffff812e39d7>] ext4_buffered_write_iter+0x37/0x100
[    7.083398] stacktrace:
[    7.083399]       down_write+0x68/0x580
[    7.083402]       ext4_buffered_write_iter+0x37/0x100
[    7.083404]       ext4_file_write_iter+0x4a/0x7f0
[    7.083406]       new_sync_write+0x100/0x190
[    7.083409]       vfs_write+0x134/0x360
[    7.083411]       ksys_write+0x4d/0xc0
[    7.083413]       do_syscall_64+0x3a/0x90
[    7.083415]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.083417] 
[    7.083418] [E] event(&(&journal->j_wait_commit)->dmap:0):
[    7.083419] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    7.083421] stacktrace:
[    7.083422]       dept_event+0x12b/0x1f0
[    7.083424]       __wake_up_common+0xb0/0x1a0
[    7.083426]       __wake_up_common_lock+0x65/0x90
[    7.083427]       __jbd2_log_start_commit+0x8a/0xa0
[    7.083430]       jbd2_log_start_commit+0x24/0x40
[    7.083431]       __jbd2_journal_force_commit+0x91/0xb0
[    7.083433]       jbd2_journal_force_commit_nested+0x5/0x10
[    7.083434]       ext4_should_retry_alloc+0x5b/0xb0
[    7.083436]       ext4_da_write_begin+0xf2/0x2a0
[    7.083439]       generic_perform_write+0xa6/0x1c0
[    7.083440]       ext4_buffered_write_iter+0x89/0x100
[    7.083442]       ext4_file_write_iter+0x4a/0x7f0
[    7.083444]       new_sync_write+0x100/0x190
[    7.083446]       vfs_write+0x134/0x360
[    7.083448]       ksys_write+0x4d/0xc0
[    7.083449]       do_syscall_64+0x3a/0x90
[    7.083451] ---------------------------------------------------
[    7.083452] context B's detail
[    7.083452] ---------------------------------------------------
[    7.083453] context B
[    7.083453]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    7.083454]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    7.083455]     [E] write_unlock(&journal->j_state_lock:8)
[    7.083457] 
[    7.083457] [S] __raw_write_lock(&journal->j_state_lock:8):
[    7.083458] [<ffffffff81346e9e>] kjournald2+0x7e/0x260
[    7.083460] stacktrace:
[    7.083460]       _raw_write_lock+0x6e/0x90
[    7.083462]       kjournald2+0x7e/0x260
[    7.083463]       kthread+0xe3/0x110
[    7.083466]       ret_from_fork+0x22/0x30
[    7.083469] 
[    7.083469] [W] wait(&(&journal->j_wait_commit)->dmap:0):
[    7.083470] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    7.083472] stacktrace:
[    7.083473]       kjournald2+0x164/0x260
[    7.083474]       kthread+0xe3/0x110
[    7.083476]       ret_from_fork+0x22/0x30
[    7.083477] 
[    7.083478] [E] write_unlock(&journal->j_state_lock:8):
[    7.083479] [<ffffffff8134700b>] kjournald2+0x1eb/0x260
[    7.083480] stacktrace:
[    7.083481]       _raw_write_unlock+0x30/0x70
[    7.083483]       kjournald2+0x1eb/0x260
[    7.083484]       kthread+0xe3/0x110
[    7.083486]       ret_from_fork+0x22/0x30
[    7.083487] ---------------------------------------------------
[    7.083488] context C's detail
[    7.083488] ---------------------------------------------------
[    7.083489] context C
[    7.083490]     [S] down_write(&sb->s_type->i_mutex_key:0)
[    7.083491]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    7.083492]     [E] up_write(&sb->s_type->i_mutex_key:0)
[    7.083493] 
[    7.083493] [S] down_write(&sb->s_type->i_mutex_key:0):
[    7.083494] [<ffffffff81228358>] do_truncate+0x58/0xa0
[    7.083496] stacktrace:
[    7.083497]       down_write+0x8a/0x580
[    7.083498]       do_truncate+0x58/0xa0
[    7.083500]       path_openat+0x646/0x9c0
[    7.083502]       do_filp_open+0xaf/0x110
[    7.083504]       do_sys_openat2+0x1ff/0x300
[    7.083505]       do_sys_open+0x51/0x60
[    7.083507]       do_syscall_64+0x3a/0x90
[    7.083509]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.083511] 
[    7.083511] [W] __raw_read_lock(&journal->j_state_lock:8):
[    7.083512] [<ffffffff8133cd87>] start_this_handle+0xa7/0x5e0
[    7.083515] stacktrace:
[    7.083516]       _raw_read_lock+0x57/0xd0
[    7.083518]       start_this_handle+0xa7/0x5e0
[    7.083519]       jbd2__journal_start+0xe6/0x220
[    7.083521]       __ext4_journal_start_sb+0x11c/0x150
[    7.083523]       ext4_setattr+0x436/0x8f0
[    7.083524]       notify_change+0x352/0x4c0
[    7.083527]       do_truncate+0x6a/0xa0
[    7.083528]       path_openat+0x646/0x9c0
[    7.083530]       do_filp_open+0xaf/0x110
[    7.083531]       do_sys_openat2+0x1ff/0x300
[    7.083533]       do_sys_open+0x51/0x60
[    7.083535]       do_syscall_64+0x3a/0x90
[    7.083536]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.083538] 
[    7.083539] [E] up_write(&sb->s_type->i_mutex_key:0):
[    7.083540] [<ffffffff81228381>] do_truncate+0x81/0xa0
[    7.083541] stacktrace:
[    7.083542]       up_write+0x36/0x170
[    7.083545]       do_truncate+0x81/0xa0
[    7.083547]       path_openat+0x646/0x9c0
[    7.083548]       do_filp_open+0xaf/0x110
[    7.083550]       do_sys_openat2+0x1ff/0x300
[    7.083552]       do_sys_open+0x51/0x60
[    7.083553]       do_syscall_64+0x3a/0x90
[    7.083555]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.083557] ---------------------------------------------------
[    7.083557] information that might be helpful
[    7.083558] ---------------------------------------------------
[    7.083559] CPU: 2 PID: 628 Comm: rs:main Q:Reg Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    7.083561] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    7.083563] Call Trace:
[    7.083564]  <TASK>
[    7.083565]  dump_stack_lvl+0x44/0x57
[    7.083568]  print_circle+0x384/0x510
[    7.083570]  ? __kernel_text_address+0x9/0x30
[    7.083572]  ? print_circle+0x510/0x510
[    7.083574]  cb_check_dl+0x58/0x60
[    7.083575]  bfs+0xdc/0x1b0
[    7.083578]  add_dep+0x94/0x120
[    7.083580]  do_event.isra.22+0x284/0x300
[    7.083582]  ? __wake_up_common+0x93/0x1a0
[    7.083583]  dept_event+0x12b/0x1f0
[    7.083586]  __wake_up_common+0xb0/0x1a0
[    7.083588]  __wake_up_common_lock+0x65/0x90
[    7.083590]  __jbd2_log_start_commit+0x8a/0xa0
[    7.083591]  jbd2_log_start_commit+0x24/0x40
[    7.083593]  __jbd2_journal_force_commit+0x91/0xb0
[    7.083595]  jbd2_journal_force_commit_nested+0x5/0x10
[    7.083597]  ext4_should_retry_alloc+0x5b/0xb0
[    7.083598]  ext4_da_write_begin+0xf2/0x2a0
[    7.083601]  generic_perform_write+0xa6/0x1c0
[    7.083604]  ext4_buffered_write_iter+0x89/0x100
[    7.083606]  ext4_file_write_iter+0x4a/0x7f0
[    7.083609]  new_sync_write+0x100/0x190
[    7.083612]  vfs_write+0x134/0x360
[    7.083615]  ksys_write+0x4d/0xc0
[    7.083616]  ? trace_hardirqs_on+0x38/0xe0
[    7.083619]  do_syscall_64+0x3a/0x90
[    7.083621]  entry_SYSCALL_64_after_hwframe+0x44/0xae


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Report in ext4_da_write_begin()
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
@ 2022-02-16  4:15   ` Byungchul Park
  2022-02-16  4:15   ` Report in ext4_file_write_iter() Byungchul Park
                     ` (3 subsequent siblings)
  4 siblings, 0 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:15 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

[    6.881473] ===================================================
[    6.881474] DEPT: Circular dependency has been detected.
[    6.881475] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    6.881476] ---------------------------------------------------
[    6.881476] summary
[    6.881477] ---------------------------------------------------
[    6.881478] *** DEADLOCK ***
[    6.881478] 
[    6.881478] context A
[    6.881479]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    6.881480]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    6.881481]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    6.881482] 
[    6.881483] context B
[    6.881483]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    6.881484]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    6.881485]     [E] write_unlock(&journal->j_state_lock:8)
[    6.881486] 
[    6.881487] [S]: start of the event context
[    6.881487] [W]: the wait blocked
[    6.881488] [E]: the event not reachable
[    6.881489] ---------------------------------------------------
[    6.881489] context A's detail
[    6.881490] ---------------------------------------------------
[    6.881490] context A
[    6.881491]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    6.881492]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    6.881493]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    6.881494] 
[    6.881495] [S] (unknown)(&(&journal->j_wait_commit)->dmap:0):
[    6.881496] (N/A)
[    6.881496] 
[    6.881497] [W] __raw_read_lock(&journal->j_state_lock:8):
[    6.881498] [<ffffffff8133cd87>] start_this_handle+0xa7/0x5e0
[    6.881500] stacktrace:
[    6.881500]       _raw_read_lock+0x57/0xd0
[    6.881502]       start_this_handle+0xa7/0x5e0
[    6.881504]       jbd2__journal_start+0xe6/0x220
[    6.881506]       __ext4_journal_start_sb+0x11c/0x150
[    6.881508]       ext4_truncate+0x167/0x4b0
[    6.881509]       ext4_da_write_begin+0x19c/0x2a0
[    6.881511]       generic_perform_write+0xa6/0x1c0
[    6.881512]       ext4_buffered_write_iter+0x89/0x100
[    6.881515]       ext4_file_write_iter+0x4a/0x7f0
[    6.881516]       new_sync_write+0x100/0x190
[    6.881518]       vfs_write+0x134/0x360
[    6.881521]       ksys_write+0x4d/0xc0
[    6.881522]       do_syscall_64+0x3a/0x90
[    6.881523]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    6.881525] 
[    6.881526] [E] event(&(&journal->j_wait_commit)->dmap:0):
[    6.881527] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    6.881529] stacktrace:
[    6.881529]       dept_event+0x12b/0x1f0
[    6.881531]       __wake_up_common+0xb0/0x1a0
[    6.881532]       __wake_up_common_lock+0x65/0x90
[    6.881533]       __jbd2_log_start_commit+0x8a/0xa0
[    6.881535]       jbd2_log_start_commit+0x24/0x40
[    6.881536]       __jbd2_journal_force_commit+0x91/0xb0
[    6.881538]       jbd2_journal_force_commit_nested+0x5/0x10
[    6.881540]       ext4_should_retry_alloc+0x5b/0xb0
[    6.881541]       ext4_da_write_begin+0xf2/0x2a0
[    6.881543]       generic_perform_write+0xa6/0x1c0
[    6.881544]       ext4_buffered_write_iter+0x89/0x100
[    6.881546]       ext4_file_write_iter+0x4a/0x7f0
[    6.881548]       new_sync_write+0x100/0x190
[    6.881550]       vfs_write+0x134/0x360
[    6.881552]       ksys_write+0x4d/0xc0
[    6.881553]       do_syscall_64+0x3a/0x90
[    6.881555] ---------------------------------------------------
[    6.881556] context B's detail
[    6.881556] ---------------------------------------------------
[    6.881557] context B
[    6.881558]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    6.881559]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    6.881560]     [E] write_unlock(&journal->j_state_lock:8)
[    6.881561] 
[    6.881561] [S] __raw_write_lock(&journal->j_state_lock:8):
[    6.881562] [<ffffffff81346e9e>] kjournald2+0x7e/0x260
[    6.881564] stacktrace:
[    6.881564]       _raw_write_lock+0x6e/0x90
[    6.881566]       kjournald2+0x7e/0x260
[    6.881567]       kthread+0xe3/0x110
[    6.881569]       ret_from_fork+0x22/0x30
[    6.881571] 
[    6.881572] [W] wait(&(&journal->j_wait_commit)->dmap:0):
[    6.881573] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    6.881574] stacktrace:
[    6.881575]       kjournald2+0x164/0x260
[    6.881576]       kthread+0xe3/0x110
[    6.881578]       ret_from_fork+0x22/0x30
[    6.881579] 
[    6.881580] [E] write_unlock(&journal->j_state_lock:8):
[    6.881581] [<ffffffff8134700b>] kjournald2+0x1eb/0x260
[    6.881582] stacktrace:
[    6.881583]       _raw_write_unlock+0x30/0x70
[    6.881585]       kjournald2+0x1eb/0x260
[    6.881586]       kthread+0xe3/0x110
[    6.881588]       ret_from_fork+0x22/0x30
[    6.881589] ---------------------------------------------------
[    6.881590] information that might be helpful
[    6.881590] ---------------------------------------------------
[    6.881591] CPU: 2 PID: 628 Comm: rs:main Q:Reg Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    6.881593] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    6.881594] Call Trace:
[    6.881595]  <TASK>
[    6.881596]  dump_stack_lvl+0x44/0x57
[    6.881597]  print_circle+0x384/0x510
[    6.881599]  ? __kernel_text_address+0x9/0x30
[    6.881601]  ? print_circle+0x510/0x510
[    6.881603]  cb_check_dl+0x58/0x60
[    6.881605]  bfs+0xdc/0x1b0
[    6.881607]  add_dep+0x94/0x120
[    6.881609]  do_event.isra.22+0x284/0x300
[    6.881611]  ? __wake_up_common+0x93/0x1a0
[    6.881612]  dept_event+0x12b/0x1f0
[    6.881615]  __wake_up_common+0xb0/0x1a0
[    6.881617]  __wake_up_common_lock+0x65/0x90
[    6.881619]  __jbd2_log_start_commit+0x8a/0xa0
[    6.881621]  jbd2_log_start_commit+0x24/0x40
[    6.881622]  __jbd2_journal_force_commit+0x91/0xb0
[    6.881624]  jbd2_journal_force_commit_nested+0x5/0x10
[    6.881626]  ext4_should_retry_alloc+0x5b/0xb0
[    6.881628]  ext4_da_write_begin+0xf2/0x2a0
[    6.881630]  generic_perform_write+0xa6/0x1c0
[    6.881633]  ext4_buffered_write_iter+0x89/0x100
[    6.881636]  ext4_file_write_iter+0x4a/0x7f0
[    6.881638]  new_sync_write+0x100/0x190
[    6.881642]  vfs_write+0x134/0x360
[    6.881644]  ksys_write+0x4d/0xc0
[    6.881645]  ? trace_hardirqs_on+0x38/0xe0
[    6.881648]  do_syscall_64+0x3a/0x90
[    6.881650]  entry_SYSCALL_64_after_hwframe+0x44/0xae


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Report in ext4_file_write_iter()
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
  2022-02-16  4:15   ` Report in ext4_da_write_begin() Byungchul Park
@ 2022-02-16  4:15   ` Byungchul Park
  2022-02-16  4:15   ` Report in ext4_sync_file() Byungchul Park
                     ` (2 subsequent siblings)
  4 siblings, 0 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:15 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

[    6.881168] ===================================================
[    6.881170] DEPT: Circular dependency has been detected.
[    6.881172] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    6.881173] ---------------------------------------------------
[    6.881174] summary
[    6.881174] ---------------------------------------------------
[    6.881175] *** DEADLOCK ***
[    6.881175] 
[    6.881176] context A
[    6.881176]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    6.881178]     [W] down_write(mapping.invalidate_lock:0)
[    6.881179]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    6.881180] 
[    6.881181] context B
[    6.881182]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    6.881183]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    6.881184]     [E] write_unlock(&journal->j_state_lock:8)
[    6.881185] 
[    6.881185] context C
[    6.881186]     [S] down_write(mapping.invalidate_lock:0)
[    6.881187]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    6.881188]     [E] up_write(mapping.invalidate_lock:0)
[    6.881189] 
[    6.881190] [S]: start of the event context
[    6.881190] [W]: the wait blocked
[    6.881191] [E]: the event not reachable
[    6.881191] ---------------------------------------------------
[    6.881192] context A's detail
[    6.881193] ---------------------------------------------------
[    6.881193] context A
[    6.881194]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    6.881195]     [W] down_write(mapping.invalidate_lock:0)
[    6.881196]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    6.881197] 
[    6.881198] [S] (unknown)(&(&journal->j_wait_commit)->dmap:0):
[    6.881199] (N/A)
[    6.881199] 
[    6.881200] [W] down_write(mapping.invalidate_lock:0):
[    6.881201] [<ffffffff812f7cc3>] ext4_da_write_begin+0x183/0x2a0
[    6.881207] stacktrace:
[    6.881207]       down_write+0x68/0x580
[    6.881210]       ext4_da_write_begin+0x183/0x2a0
[    6.881213]       generic_perform_write+0xa6/0x1c0
[    6.881215]       ext4_buffered_write_iter+0x89/0x100
[    6.881219]       ext4_file_write_iter+0x4a/0x7f0
[    6.881222]       new_sync_write+0x100/0x190
[    6.881225]       vfs_write+0x134/0x360
[    6.881228]       ksys_write+0x4d/0xc0
[    6.881230]       do_syscall_64+0x3a/0x90
[    6.881233]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    6.881236] 
[    6.881237] [E] event(&(&journal->j_wait_commit)->dmap:0):
[    6.881238] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    6.881240] stacktrace:
[    6.881240]       dept_event+0x12b/0x1f0
[    6.881243]       __wake_up_common+0xb0/0x1a0
[    6.881244]       __wake_up_common_lock+0x65/0x90
[    6.881246]       __jbd2_log_start_commit+0x8a/0xa0
[    6.881248]       jbd2_log_start_commit+0x24/0x40
[    6.881250]       __jbd2_journal_force_commit+0x91/0xb0
[    6.881251]       jbd2_journal_force_commit_nested+0x5/0x10
[    6.881253]       ext4_should_retry_alloc+0x5b/0xb0
[    6.881254]       ext4_da_write_begin+0xf2/0x2a0
[    6.881256]       generic_perform_write+0xa6/0x1c0
[    6.881258]       ext4_buffered_write_iter+0x89/0x100
[    6.881260]       ext4_file_write_iter+0x4a/0x7f0
[    6.881262]       new_sync_write+0x100/0x190
[    6.881264]       vfs_write+0x134/0x360
[    6.881265]       ksys_write+0x4d/0xc0
[    6.881267]       do_syscall_64+0x3a/0x90
[    6.881268] ---------------------------------------------------
[    6.881269] context B's detail
[    6.881270] ---------------------------------------------------
[    6.881270] context B
[    6.881271]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    6.881272]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    6.881273]     [E] write_unlock(&journal->j_state_lock:8)
[    6.881274] 
[    6.881275] [S] __raw_write_lock(&journal->j_state_lock:8):
[    6.881276] [<ffffffff81346e9e>] kjournald2+0x7e/0x260
[    6.881277] stacktrace:
[    6.881278]       _raw_write_lock+0x6e/0x90
[    6.881280]       kjournald2+0x7e/0x260
[    6.881281]       kthread+0xe3/0x110
[    6.881287]       ret_from_fork+0x22/0x30
[    6.881290] 
[    6.881290] [W] wait(&(&journal->j_wait_commit)->dmap:0):
[    6.881291] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    6.881293] stacktrace:
[    6.881294]       kjournald2+0x164/0x260
[    6.881295]       kthread+0xe3/0x110
[    6.881297]       ret_from_fork+0x22/0x30
[    6.881298] 
[    6.881299] [E] write_unlock(&journal->j_state_lock:8):
[    6.881300] [<ffffffff8134700b>] kjournald2+0x1eb/0x260
[    6.881301] stacktrace:
[    6.881302]       _raw_write_unlock+0x30/0x70
[    6.881304]       kjournald2+0x1eb/0x260
[    6.881305]       kthread+0xe3/0x110
[    6.881307]       ret_from_fork+0x22/0x30
[    6.881308] ---------------------------------------------------
[    6.881309] context C's detail
[    6.881309] ---------------------------------------------------
[    6.881310] context C
[    6.881311]     [S] down_write(mapping.invalidate_lock:0)
[    6.881312]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    6.881313]     [E] up_write(mapping.invalidate_lock:0)
[    6.881314] 
[    6.881314] [S] down_write(mapping.invalidate_lock:0):
[    6.881315] [<ffffffff812f94db>] ext4_setattr+0x3eb/0x8f0
[    6.881317] stacktrace:
[    6.881318]       down_write+0x8a/0x580
[    6.881319]       ext4_setattr+0x3eb/0x8f0
[    6.881321]       notify_change+0x352/0x4c0
[    6.881323]       do_truncate+0x6a/0xa0
[    6.881325]       path_openat+0x646/0x9c0
[    6.881327]       do_filp_open+0xaf/0x110
[    6.881329]       do_sys_openat2+0x1ff/0x300
[    6.881330]       do_sys_open+0x51/0x60
[    6.881332]       do_syscall_64+0x3a/0x90
[    6.881333]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    6.881335] 
[    6.881336] [W] __raw_read_lock(&journal->j_state_lock:8):
[    6.881337] [<ffffffff8133cd87>] start_this_handle+0xa7/0x5e0
[    6.881340] stacktrace:
[    6.881340]       _raw_read_lock+0x57/0xd0
[    6.881342]       start_this_handle+0xa7/0x5e0
[    6.881344]       jbd2__journal_start+0xe6/0x220
[    6.881345]       __ext4_journal_start_sb+0x11c/0x150
[    6.881347]       ext4_setattr+0x436/0x8f0
[    6.881349]       notify_change+0x352/0x4c0
[    6.881350]       do_truncate+0x6a/0xa0
[    6.881352]       path_openat+0x646/0x9c0
[    6.881353]       do_filp_open+0xaf/0x110
[    6.881355]       do_sys_openat2+0x1ff/0x300
[    6.881356]       do_sys_open+0x51/0x60
[    6.881358]       do_syscall_64+0x3a/0x90
[    6.881360]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    6.881362] 
[    6.881362] [E] up_write(mapping.invalidate_lock:0):
[    6.881363] [<ffffffff812f982f>] ext4_setattr+0x73f/0x8f0
[    6.881365] stacktrace:
[    6.881365]       up_write+0x36/0x170
[    6.881369]       ext4_setattr+0x73f/0x8f0
[    6.881370]       notify_change+0x352/0x4c0
[    6.881372]       do_truncate+0x6a/0xa0
[    6.881373]       path_openat+0x646/0x9c0
[    6.881375]       do_filp_open+0xaf/0x110
[    6.881376]       do_sys_openat2+0x1ff/0x300
[    6.881378]       do_sys_open+0x51/0x60
[    6.881379]       do_syscall_64+0x3a/0x90
[    6.881381]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    6.881383] ---------------------------------------------------
[    6.881383] information that might be helpful
[    6.881384] ---------------------------------------------------
[    6.881385] CPU: 2 PID: 628 Comm: rs:main Q:Reg Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    6.881387] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    6.881389] Call Trace:
[    6.881390]  <TASK>
[    6.881391]  dump_stack_lvl+0x44/0x57
[    6.881394]  print_circle+0x384/0x510
[    6.881396]  ? __kernel_text_address+0x9/0x30
[    6.881398]  ? print_circle+0x510/0x510
[    6.881400]  cb_check_dl+0x58/0x60
[    6.881401]  bfs+0xdc/0x1b0
[    6.881404]  add_dep+0x94/0x120
[    6.881406]  do_event.isra.22+0x284/0x300
[    6.881408]  ? __wake_up_common+0x93/0x1a0
[    6.881409]  dept_event+0x12b/0x1f0
[    6.881411]  __wake_up_common+0xb0/0x1a0
[    6.881413]  __wake_up_common_lock+0x65/0x90
[    6.881415]  __jbd2_log_start_commit+0x8a/0xa0
[    6.881417]  jbd2_log_start_commit+0x24/0x40
[    6.881419]  __jbd2_journal_force_commit+0x91/0xb0
[    6.881421]  jbd2_journal_force_commit_nested+0x5/0x10
[    6.881422]  ext4_should_retry_alloc+0x5b/0xb0
[    6.881424]  ext4_da_write_begin+0xf2/0x2a0
[    6.881427]  generic_perform_write+0xa6/0x1c0
[    6.881429]  ext4_buffered_write_iter+0x89/0x100
[    6.881432]  ext4_file_write_iter+0x4a/0x7f0
[    6.881435]  new_sync_write+0x100/0x190
[    6.881438]  vfs_write+0x134/0x360
[    6.881441]  ksys_write+0x4d/0xc0
[    6.881442]  ? trace_hardirqs_on+0x38/0xe0
[    6.881445]  do_syscall_64+0x3a/0x90
[    6.881447]  entry_SYSCALL_64_after_hwframe+0x44/0xae


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Report in ext4_sync_file()
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
  2022-02-16  4:15   ` Report in ext4_da_write_begin() Byungchul Park
  2022-02-16  4:15   ` Report in ext4_file_write_iter() Byungchul Park
@ 2022-02-16  4:15   ` Byungchul Park
  2022-02-16  4:15   ` Report in ksys_write() Byungchul Park
  2022-02-16  4:15   ` Report in __mark_inode_dirty() Byungchul Park
  4 siblings, 0 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:15 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

[    7.072624] ===================================================
[    7.072630] DEPT: Circular dependency has been detected.
[    7.072631] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    7.072635] ---------------------------------------------------
[    7.072636] summary
[    7.072636] ---------------------------------------------------
[    7.072637] *** DEADLOCK ***
[    7.072637] 
[    7.072638] context A
[    7.072640]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    7.072643]     [W] folio_wait_bit_common(pgwriteback:0)
[    7.072644]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    7.072646] 
[    7.072647] context B
[    7.072647]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    7.072649]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    7.072654]     [E] write_unlock(&journal->j_state_lock:8)
[    7.072656] 
[    7.072657] context C
[    7.072658]     [S] (unknown)(pgwriteback:0)
[    7.072659]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    7.072661]     [E] folio_wake_bit(pgwriteback:0)
[    7.072663] 
[    7.072663] [S]: start of the event context
[    7.072664] [W]: the wait blocked
[    7.072665] [E]: the event not reachable
[    7.072666] ---------------------------------------------------
[    7.072667] context A's detail
[    7.072668] ---------------------------------------------------
[    7.072669] context A
[    7.072670]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    7.072672]     [W] folio_wait_bit_common(pgwriteback:0)
[    7.072674]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    7.072675] 
[    7.072676] [S] (unknown)(&(&journal->j_wait_commit)->dmap:0):
[    7.072678] (N/A)
[    7.072679] 
[    7.072680] [W] folio_wait_bit_common(pgwriteback:0):
[    7.072681] [<ffffffff811ae2e2>] folio_wait_writeback+0x52/0xb0
[    7.072688] stacktrace:
[    7.072689]       folio_wait_bit+0x1ea/0x2a0
[    7.072692]       folio_wait_writeback+0x52/0xb0
[    7.072695]       __filemap_fdatawait_range+0x6d/0xc0
[    7.072701]       file_write_and_wait_range+0x90/0xc0
[    7.072703]       ext4_sync_file+0x1b5/0x410
[    7.072708]       do_fsync+0x33/0x60
[    7.072712]       __x64_sys_fsync+0xb/0x10
[    7.072715]       do_syscall_64+0x3a/0x90
[    7.072719]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.072723] 
[    7.072724] [E] event(&(&journal->j_wait_commit)->dmap:0):
[    7.072725] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    7.072728] stacktrace:
[    7.072729]       dept_event+0x12b/0x1f0
[    7.072733]       __wake_up_common+0xb0/0x1a0
[    7.072735]       __wake_up_common_lock+0x65/0x90
[    7.072737]       __jbd2_log_start_commit+0x8a/0xa0
[    7.072740]       jbd2_log_start_commit+0x24/0x40
[    7.072742]       jbd2_complete_transaction+0x79/0x90
[    7.072745]       ext4_fc_commit+0x329/0x940
[    7.072748]       ext4_sync_file+0x29f/0x410
[    7.072751]       do_fsync+0x33/0x60
[    7.072754]       __x64_sys_fsync+0xb/0x10
[    7.072757]       do_syscall_64+0x3a/0x90
[    7.072759]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.072762] ---------------------------------------------------
[    7.072763] context B's detail
[    7.072764] ---------------------------------------------------
[    7.072765] context B
[    7.072766]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    7.072768]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    7.072769]     [E] write_unlock(&journal->j_state_lock:8)
[    7.072771] 
[    7.072772] [S] __raw_write_lock(&journal->j_state_lock:8):
[    7.072773] [<ffffffff81346e9e>] kjournald2+0x7e/0x260
[    7.072776] stacktrace:
[    7.072777]       _raw_write_lock+0x6e/0x90
[    7.072779]       kjournald2+0x7e/0x260
[    7.072781]       kthread+0xe3/0x110
[    7.072785]       ret_from_fork+0x22/0x30
[    7.072789] 
[    7.072789] [W] wait(&(&journal->j_wait_commit)->dmap:0):
[    7.072791] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    7.072794] stacktrace:
[    7.072795]       kjournald2+0x164/0x260
[    7.072797]       kthread+0xe3/0x110
[    7.072800]       ret_from_fork+0x22/0x30
[    7.072802] 
[    7.072802] [E] write_unlock(&journal->j_state_lock:8):
[    7.072804] [<ffffffff8134700b>] kjournald2+0x1eb/0x260
[    7.072806] stacktrace:
[    7.072807]       _raw_write_unlock+0x30/0x70
[    7.072810]       kjournald2+0x1eb/0x260
[    7.072812]       kthread+0xe3/0x110
[    7.072814]       ret_from_fork+0x22/0x30
[    7.072816] ---------------------------------------------------
[    7.072817] context C's detail
[    7.072818] ---------------------------------------------------
[    7.072819] context C
[    7.072820]     [S] (unknown)(pgwriteback:0)
[    7.072822]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    7.072823]     [E] folio_wake_bit(pgwriteback:0)
[    7.072825] 
[    7.072825] [S] (unknown)(pgwriteback:0):
[    7.072827] (N/A)
[    7.072828] 
[    7.072828] [W] __raw_read_lock(&journal->j_state_lock:8):
[    7.072830] [<ffffffff8133cd87>] start_this_handle+0xa7/0x5e0
[    7.072834] stacktrace:
[    7.072834]       _raw_read_lock+0x57/0xd0
[    7.072837]       start_this_handle+0xa7/0x5e0
[    7.072839]       jbd2_journal_start_reserved+0x4d/0x170
[    7.072842]       __ext4_journal_start_reserved+0x87/0x160
[    7.072845]       ext4_convert_unwritten_io_end_vec+0x26/0xb0
[    7.072848]       ext4_end_io_rsv_work+0xef/0x140
[    7.072850]       process_one_work+0x317/0x640
[    7.072852]       worker_thread+0x44/0x410
[    7.072854]       kthread+0xe3/0x110
[    7.072857]       ret_from_fork+0x22/0x30
[    7.072859] 
[    7.072860] [E] folio_wake_bit(pgwriteback:0):
[    7.072862] [<ffffffff811a30f2>] folio_end_writeback+0x32/0x80
[    7.072865] stacktrace:
[    7.072866]       folio_wake_bit+0x15e/0x170
[    7.072868]       folio_end_writeback+0x32/0x80
[    7.072870]       ext4_finish_bio+0x15a/0x200
[    7.072872]       ext4_release_io_end+0x41/0xe0
[    7.072874]       ext4_end_io_rsv_work+0xaf/0x140
[    7.072876]       process_one_work+0x317/0x640
[    7.072878]       worker_thread+0x44/0x410
[    7.072880]       kthread+0xe3/0x110
[    7.072883]       ret_from_fork+0x22/0x30
[    7.072885] ---------------------------------------------------
[    7.072886] information that might be helpful
[    7.072887] ---------------------------------------------------
[    7.072889] CPU: 1 PID: 620 Comm: cupsd Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    7.072893] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    7.072894] Call Trace:
[    7.072896]  <TASK>
[    7.072898]  dump_stack_lvl+0x44/0x57
[    7.072902]  print_circle+0x384/0x510
[    7.072905]  ? print_circle+0x510/0x510
[    7.072908]  cb_check_dl+0x58/0x60
[    7.072936]  bfs+0xdc/0x1b0
[    7.072940]  add_dep+0x94/0x120
[    7.072944]  do_event.isra.22+0x284/0x300
[    7.072947]  ? __wake_up_common+0x93/0x1a0
[    7.072949]  dept_event+0x12b/0x1f0
[    7.072953]  __wake_up_common+0xb0/0x1a0
[    7.072956]  __wake_up_common_lock+0x65/0x90
[    7.072960]  __jbd2_log_start_commit+0x8a/0xa0
[    7.072963]  jbd2_log_start_commit+0x24/0x40
[    7.072966]  jbd2_complete_transaction+0x79/0x90
[    7.072969]  ext4_fc_commit+0x329/0x940
[    7.072972]  ? to_pool+0x6d/0xb0
[    7.072975]  ? pop_ecxt+0x104/0x110
[    7.072982]  ? dept_ecxt_exit+0xc0/0x140
[    7.072986]  ? _raw_read_unlock+0x4f/0x70
[    7.072989]  ext4_sync_file+0x29f/0x410
[    7.072994]  do_fsync+0x33/0x60
[    7.072997]  __x64_sys_fsync+0xb/0x10
[    7.073000]  do_syscall_64+0x3a/0x90
[    7.073003]  entry_SYSCALL_64_after_hwframe+0x44/0xae


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Report in ksys_write()
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
                     ` (2 preceding siblings ...)
  2022-02-16  4:15   ` Report in ext4_sync_file() Byungchul Park
@ 2022-02-16  4:15   ` Byungchul Park
  2022-02-16  4:15   ` Report in __mark_inode_dirty() Byungchul Park
  4 siblings, 0 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:15 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

[    7.382619] ===================================================
[    7.382623] DEPT: Circular dependency has been detected.
[    7.382624] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    7.382625] ---------------------------------------------------
[    7.382626] summary
[    7.382627] ---------------------------------------------------
[    7.382627] *** DEADLOCK ***
[    7.382627] 
[    7.382628] context A
[    7.382628]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    7.382630]     [W] __mutex_lock_common(&f->f_pos_lock:0)
[    7.382631]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    7.382633] 
[    7.382633] context B
[    7.382634]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    7.382635]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    7.382636]     [E] write_unlock(&journal->j_state_lock:8)
[    7.382637] 
[    7.382638] context C
[    7.382639]     [S] __mutex_lock_common(&f->f_pos_lock:0)
[    7.382640]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    7.382641]     [E] mutex_unlock(&f->f_pos_lock:0)
[    7.382642] 
[    7.382642] [S]: start of the event context
[    7.382643] [W]: the wait blocked
[    7.382643] [E]: the event not reachable
[    7.382644] ---------------------------------------------------
[    7.382645] context A's detail
[    7.382645] ---------------------------------------------------
[    7.382646] context A
[    7.382647]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[    7.382648]     [W] __mutex_lock_common(&f->f_pos_lock:0)
[    7.382649]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[    7.382650] 
[    7.382650] [S] (unknown)(&(&journal->j_wait_commit)->dmap:0):
[    7.382651] (N/A)
[    7.382652] 
[    7.382652] [W] __mutex_lock_common(&f->f_pos_lock:0):
[    7.382653] [<ffffffff8124ff73>] __fdget_pos+0x43/0x50
[    7.382658] stacktrace:
[    7.382659]       __mutex_lock+0x52c/0x900
[    7.382662]       __fdget_pos+0x43/0x50
[    7.382663]       ksys_write+0x15/0xc0
[    7.382665]       do_syscall_64+0x3a/0x90
[    7.382668]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.382670] 
[    7.382671] [E] event(&(&journal->j_wait_commit)->dmap:0):
[    7.382672] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    7.382674] stacktrace:
[    7.382674]       dept_event+0x12b/0x1f0
[    7.382677]       __wake_up_common+0xb0/0x1a0
[    7.382678]       __wake_up_common_lock+0x65/0x90
[    7.382679]       __jbd2_log_start_commit+0x8a/0xa0
[    7.382682]       jbd2_log_start_commit+0x24/0x40
[    7.382683]       __jbd2_journal_force_commit+0x91/0xb0
[    7.382685]       jbd2_journal_force_commit_nested+0x5/0x10
[    7.382686]       ext4_should_retry_alloc+0x5b/0xb0
[    7.382689]       ext4_da_write_begin+0xf2/0x2a0
[    7.382691]       generic_perform_write+0xa6/0x1c0
[    7.382693]       ext4_buffered_write_iter+0x89/0x100
[    7.382695]       ext4_file_write_iter+0x4a/0x7f0
[    7.382697]       new_sync_write+0x100/0x190
[    7.382700]       vfs_write+0x134/0x360
[    7.382702]       ksys_write+0x4d/0xc0
[    7.382703]       do_syscall_64+0x3a/0x90
[    7.382705] ---------------------------------------------------
[    7.382705] context B's detail
[    7.382706] ---------------------------------------------------
[    7.382706] context B
[    7.382707]     [S] __raw_write_lock(&journal->j_state_lock:8)
[    7.382708]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[    7.382709]     [E] write_unlock(&journal->j_state_lock:8)
[    7.382710] 
[    7.382711] [S] __raw_write_lock(&journal->j_state_lock:8):
[    7.382712] [<ffffffff81346e9e>] kjournald2+0x7e/0x260
[    7.382713] stacktrace:
[    7.382714]       _raw_write_lock+0x6e/0x90
[    7.382716]       kjournald2+0x7e/0x260
[    7.382717]       kthread+0xe3/0x110
[    7.382720]       ret_from_fork+0x22/0x30
[    7.382722] 
[    7.382723] [W] wait(&(&journal->j_wait_commit)->dmap:0):
[    7.382724] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    7.382725] stacktrace:
[    7.382726]       kjournald2+0x164/0x260
[    7.382727]       kthread+0xe3/0x110
[    7.382729]       ret_from_fork+0x22/0x30
[    7.382731] 
[    7.382731] [E] write_unlock(&journal->j_state_lock:8):
[    7.382732] [<ffffffff8134700b>] kjournald2+0x1eb/0x260
[    7.382734] stacktrace:
[    7.382734]       _raw_write_unlock+0x30/0x70
[    7.382736]       kjournald2+0x1eb/0x260
[    7.382737]       kthread+0xe3/0x110
[    7.382739]       ret_from_fork+0x22/0x30
[    7.382740] ---------------------------------------------------
[    7.382741] context C's detail
[    7.382742] ---------------------------------------------------
[    7.382742] context C
[    7.382743]     [S] __mutex_lock_common(&f->f_pos_lock:0)
[    7.382744]     [W] __raw_read_lock(&journal->j_state_lock:8)
[    7.382745]     [E] mutex_unlock(&f->f_pos_lock:0)
[    7.382746] 
[    7.382746] [S] __mutex_lock_common(&f->f_pos_lock:0):
[    7.382747] [<ffffffff8124ff73>] __fdget_pos+0x43/0x50
[    7.382749] stacktrace:
[    7.382750]       __mutex_lock+0x54d/0x900
[    7.382751]       __fdget_pos+0x43/0x50
[    7.382753]       ksys_write+0x15/0xc0
[    7.382754]       do_syscall_64+0x3a/0x90
[    7.382756]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.382758] 
[    7.382758] [W] __raw_read_lock(&journal->j_state_lock:8):
[    7.382759] [<ffffffff8133cd87>] start_this_handle+0xa7/0x5e0
[    7.382762] stacktrace:
[    7.382763]       _raw_read_lock+0x57/0xd0
[    7.382765]       start_this_handle+0xa7/0x5e0
[    7.382766]       jbd2__journal_start+0xe6/0x220
[    7.382768]       __ext4_journal_start_sb+0x11c/0x150
[    7.382770]       ext4_dirty_inode+0x2f/0x70
[    7.382771]       __mark_inode_dirty+0x1ba/0x400
[    7.382774]       generic_update_time+0x99/0xc0
[    7.382775]       file_update_time+0x85/0xe0
[    7.382777]       ext4_buffered_write_iter+0x56/0x100
[    7.382779]       ext4_file_write_iter+0x4a/0x7f0
[    7.382781]       new_sync_write+0x100/0x190
[    7.382783]       vfs_write+0x134/0x360
[    7.382785]       ksys_write+0x4d/0xc0
[    7.382786]       do_syscall_64+0x3a/0x90
[    7.382788]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.382790] 
[    7.382790] [E] mutex_unlock(&f->f_pos_lock:0):
[    7.382791] [<ffffffff8122c800>] ksys_write+0x90/0xc0
[    7.382792] stacktrace:
[    7.382793]       __mutex_unlock_slowpath+0x49/0x2a0
[    7.382795]       ksys_write+0x90/0xc0
[    7.382796]       do_syscall_64+0x3a/0x90
[    7.382797]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.382799] ---------------------------------------------------
[    7.382800] information that might be helpful
[    7.382801] ---------------------------------------------------
[    7.382802] CPU: 1 PID: 628 Comm: rs:main Q:Reg Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    7.382804] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    7.382805] Call Trace:
[    7.382807]  <TASK>
[    7.382808]  dump_stack_lvl+0x44/0x57
[    7.382810]  print_circle+0x384/0x510
[    7.382812]  ? unwind_get_return_address+0x16/0x30
[    7.382816]  ? print_circle+0x510/0x510
[    7.382818]  cb_check_dl+0x58/0x60
[    7.382819]  bfs+0xdc/0x1b0
[    7.382822]  add_dep+0x94/0x120
[    7.382824]  do_event.isra.22+0x284/0x300
[    7.382826]  ? __wake_up_common+0x93/0x1a0
[    7.382827]  dept_event+0x12b/0x1f0
[    7.382829]  __wake_up_common+0xb0/0x1a0
[    7.382831]  __wake_up_common_lock+0x65/0x90
[    7.382833]  __jbd2_log_start_commit+0x8a/0xa0
[    7.382835]  jbd2_log_start_commit+0x24/0x40
[    7.382837]  __jbd2_journal_force_commit+0x91/0xb0
[    7.382839]  jbd2_journal_force_commit_nested+0x5/0x10
[    7.382840]  ext4_should_retry_alloc+0x5b/0xb0
[    7.382842]  ext4_da_write_begin+0xf2/0x2a0
[    7.382845]  generic_perform_write+0xa6/0x1c0
[    7.382847]  ext4_buffered_write_iter+0x89/0x100
[    7.382850]  ext4_file_write_iter+0x4a/0x7f0
[    7.382853]  new_sync_write+0x100/0x190
[    7.382856]  vfs_write+0x134/0x360
[    7.382859]  ksys_write+0x4d/0xc0
[    7.382860]  ? trace_hardirqs_on+0x38/0xe0
[    7.382863]  do_syscall_64+0x3a/0x90
[    7.382865]  entry_SYSCALL_64_after_hwframe+0x44/0xae


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Report in __mark_inode_dirty()
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
                     ` (3 preceding siblings ...)
  2022-02-16  4:15   ` Report in ksys_write() Byungchul Park
@ 2022-02-16  4:15   ` Byungchul Park
  4 siblings, 0 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  4:15 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

[   22.135149] ===================================================
[   22.135154] DEPT: Circular dependency has been detected.
[   22.135156] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[   22.135159] ---------------------------------------------------
[   22.135161] summary
[   22.135162] ---------------------------------------------------
[   22.135163] *** DEADLOCK ***
[   22.135163] 
[   22.135164] context A
[   22.135166]     [S] start_this_handle(jbd2_handle:0)
[   22.135169]     [W] __raw_write_lock(&journal->j_state_lock:8)
[   22.135171]     [E] up_read(jbd2_handle:0)
[   22.135174] 
[   22.135175] context B
[   22.135176]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[   22.135179]     [W] start_this_handle(jbd2_handle:0)
[   22.135181]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[   22.135183] 
[   22.135184] context C
[   22.135185]     [S] __raw_write_lock(&journal->j_state_lock:8)
[   22.135188]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[   22.135190]     [E] write_unlock(&journal->j_state_lock:8)
[   22.135192] 
[   22.135193] [S]: start of the event context
[   22.135194] [W]: the wait blocked
[   22.135195] [E]: the event not reachable
[   22.135197] ---------------------------------------------------
[   22.135198] context A's detail
[   22.135199] ---------------------------------------------------
[   22.135200] context A
[   22.135202]     [S] start_this_handle(jbd2_handle:0)
[   22.135204]     [W] __raw_write_lock(&journal->j_state_lock:8)
[   22.135206]     [E] up_read(jbd2_handle:0)
[   22.135208] 
[   22.135209] [S] start_this_handle(jbd2_handle:0):
[   22.135211] [<ffffffff8133cdfb>] start_this_handle+0x11b/0x5e0
[   22.135220] stacktrace:
[   22.135221]       start_this_handle+0x1d2/0x5e0
[   22.135228]       jbd2__journal_start+0xe6/0x220
[   22.135231]       __ext4_journal_start_sb+0x11c/0x150
[   22.135236]       ext4_dirty_inode+0x2f/0x70
[   22.135240]       __mark_inode_dirty+0x1ba/0x400
[   22.135244]       generic_update_time+0x99/0xc0
[   22.135248]       touch_atime+0x18c/0x1e0
[   22.135251]       filemap_read+0x27a/0x920
[   22.135255]       __kernel_read+0x12e/0x2f0
[   22.135263]       bprm_execve+0x2f0/0x6c0
[   22.135267]       do_execveat_common.isra.49+0x1b5/0x1d0
[   22.135271]       __x64_sys_execve+0x2d/0x40
[   22.135275]       do_syscall_64+0x3a/0x90
[   22.135280]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[   22.135285] 
[   22.135286] [W] __raw_write_lock(&journal->j_state_lock:8):
[   22.135288] [<ffffffff81348c59>] jbd2_log_start_commit+0x19/0x40
[   22.135293] stacktrace:
[   22.135294]       dept_wait+0x125/0x1e0
[   22.135299]       _raw_write_lock+0x4b/0x90
[   22.135303]       jbd2_log_start_commit+0x19/0x40
[   22.135306]       jbd2_journal_stop+0x104/0x310
[   22.135310]       __ext4_journal_stop+0x31/0x90
[   22.135313]       __mark_inode_dirty+0x1ba/0x400
[   22.135316]       generic_update_time+0x99/0xc0
[   22.135319]       touch_atime+0x18c/0x1e0
[   22.135323]       filemap_read+0x27a/0x920
[   22.135326]       __kernel_read+0x12e/0x2f0
[   22.135330]       bprm_execve+0x2f0/0x6c0
[   22.135334]       do_execveat_common.isra.49+0x1b5/0x1d0
[   22.135338]       __x64_sys_execve+0x2d/0x40
[   22.135342]       do_syscall_64+0x3a/0x90
[   22.135345]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[   22.135349] 
[   22.135351] [E] up_read(jbd2_handle:0):
[   22.135352] [<ffffffff8133ce34>] start_this_handle+0x154/0x5e0
[   22.135357] ---------------------------------------------------
[   22.135358] context B's detail
[   22.135359] ---------------------------------------------------
[   22.135360] context B
[   22.135362]     [S] (unknown)(&(&journal->j_wait_commit)->dmap:0)
[   22.135364]     [W] start_this_handle(jbd2_handle:0)
[   22.135366]     [E] event(&(&journal->j_wait_commit)->dmap:0)
[   22.135368] 
[   22.135369] [S] (unknown)(&(&journal->j_wait_commit)->dmap:0):
[   22.135371] (N/A)
[   22.135372] 
[   22.135373] [W] start_this_handle(jbd2_handle:0):
[   22.135375] [<ffffffff8133cdfb>] start_this_handle+0x11b/0x5e0
[   22.135379] stacktrace:
[   22.135380]       start_this_handle+0x1ad/0x5e0
[   22.135383]       jbd2__journal_start+0xe6/0x220
[   22.135387]       __ext4_journal_start_sb+0x11c/0x150
[   22.135391]       ext4_truncate+0x167/0x4b0
[   22.135394]       ext4_da_write_begin+0x19c/0x2a0
[   22.135397]       generic_perform_write+0xa6/0x1c0
[   22.135400]       ext4_buffered_write_iter+0x89/0x100
[   22.135405]       ext4_file_write_iter+0x4a/0x7f0
[   22.135409]       new_sync_write+0x100/0x190
[   22.135413]       vfs_write+0x134/0x360
[   22.135417]       ksys_write+0x4d/0xc0
[   22.135419]       do_syscall_64+0x3a/0x90
[   22.135423]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[   22.135427] 
[   22.135428] [E] event(&(&journal->j_wait_commit)->dmap:0):
[   22.135430] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[   22.135433] stacktrace:
[   22.135434]       dept_event+0x12b/0x1f0
[   22.135438]       __wake_up_common+0xb0/0x1a0
[   22.135440]       __wake_up_common_lock+0x65/0x90
[   22.135443]       __jbd2_log_start_commit+0x8a/0xa0
[   22.135446]       jbd2_log_start_commit+0x24/0x40
[   22.135449]       __jbd2_journal_force_commit+0x91/0xb0
[   22.135452]       jbd2_journal_force_commit_nested+0x5/0x10
[   22.135455]       ext4_should_retry_alloc+0x5b/0xb0
[   22.135459]       ext4_da_write_begin+0xf2/0x2a0
[   22.135462]       generic_perform_write+0xa6/0x1c0
[   22.135465]       ext4_buffered_write_iter+0x89/0x100
[   22.135469]       ext4_file_write_iter+0x4a/0x7f0
[   22.135473]       new_sync_write+0x100/0x190
[   22.135477]       vfs_write+0x134/0x360
[   22.135481]       ksys_write+0x4d/0xc0
[   22.135483]       do_syscall_64+0x3a/0x90
[   22.135487] ---------------------------------------------------
[   22.135488] context C's detail
[   22.135489] ---------------------------------------------------
[   22.135491] context C
[   22.135492]     [S] __raw_write_lock(&journal->j_state_lock:8)
[   22.135494]     [W] wait(&(&journal->j_wait_commit)->dmap:0)
[   22.135496]     [E] write_unlock(&journal->j_state_lock:8)
[   22.135498] 
[   22.135499] [S] __raw_write_lock(&journal->j_state_lock:8):
[   22.135501] [<ffffffff81346e9e>] kjournald2+0x7e/0x260
[   22.135505] stacktrace:
[   22.135506]       _raw_write_lock+0x6e/0x90
[   22.135510]       kjournald2+0x7e/0x260
[   22.135512]       kthread+0xe3/0x110
[   22.135517]       ret_from_fork+0x22/0x30
[   22.135520] 
[   22.135521] [W] wait(&(&journal->j_wait_commit)->dmap:0):
[   22.135523] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[   22.135527] stacktrace:
[   22.135528]       kjournald2+0x164/0x260
[   22.135530]       kthread+0xe3/0x110
[   22.135534]       ret_from_fork+0x22/0x30
[   22.135537] 
[   22.135538] [E] write_unlock(&journal->j_state_lock:8):
[   22.135540] [<ffffffff8134700b>] kjournald2+0x1eb/0x260
[   22.135543] stacktrace:
[   22.135545]       _raw_write_unlock+0x30/0x70
[   22.135548]       kjournald2+0x1eb/0x260
[   22.135551]       kthread+0xe3/0x110
[   22.135554]       ret_from_fork+0x22/0x30
[   22.135557] ---------------------------------------------------
[   22.135559] information that might be helpful
[   22.135560] ---------------------------------------------------
[   22.135562] CPU: 2 PID: 869 Comm: getty Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[   22.135566] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[   22.135569] Call Trace:
[   22.135571]  <TASK>
[   22.135573]  dump_stack_lvl+0x44/0x57
[   22.135577]  print_circle+0x384/0x510
[   22.135582]  ? print_circle+0x510/0x510
[   22.135586]  cb_check_dl+0x58/0x60
[   22.135589]  bfs+0xdc/0x1b0
[   22.135593]  ? jbd2_log_start_commit+0x19/0x40
[   22.135596]  add_dep+0x94/0x120
[   22.135601]  ? jbd2_log_start_commit+0x19/0x40
[   22.135604]  add_wait+0x24e/0x410
[   22.135608]  ? check_new_class+0x44/0x190
[   22.135611]  ? jbd2_log_start_commit+0x19/0x40
[   22.135615]  dept_wait+0x125/0x1e0
[   22.135619]  _raw_write_lock+0x4b/0x90
[   22.135623]  ? jbd2_log_start_commit+0x19/0x40
[   22.135626]  jbd2_log_start_commit+0x19/0x40
[   22.135630]  jbd2_journal_stop+0x104/0x310
[   22.135635]  __ext4_journal_stop+0x31/0x90
[   22.135639]  __mark_inode_dirty+0x1ba/0x400
[   22.135643]  generic_update_time+0x99/0xc0
[   22.135647]  touch_atime+0x18c/0x1e0
[   22.135652]  filemap_read+0x27a/0x920
[   22.135658]  ? avc_has_perm+0xfa/0x1c0
[   22.135662]  ? _raw_spin_unlock_irqrestore+0x58/0x80
[   22.135666]  ? _raw_spin_unlock_irqrestore+0x58/0x80
[   22.135670]  __kernel_read+0x12e/0x2f0
[   22.135677]  bprm_execve+0x2f0/0x6c0
[   22.135683]  do_execveat_common.isra.49+0x1b5/0x1d0
[   22.135688]  __x64_sys_execve+0x2d/0x40
[   22.135693]  do_syscall_64+0x3a/0x90
[   22.135697]  entry_SYSCALL_64_after_hwframe+0x44/0xae


^ permalink raw reply	[flat|nested] 8+ messages in thread

* RE: [REPORT] ext4 deadlock possibilities by DEPT
  2022-02-16  4:11 [REPORT] ext4 deadlock possibilities by DEPT Byungchul Park
  2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
@ 2022-02-16  6:51 ` Byungchul Park
  1 sibling, 0 replies; 8+ messages in thread
From: Byungchul Park @ 2022-02-16  6:51 UTC (permalink / raw)
  To: tytso, adilger.kernel, linux-ext4
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, willy,
	david, amir73il, bfields, gregkh, kernel-team, linux-mm, akpm,
	mhocko, minchan, hannes, vdavydov.dev, sj, jglisse, dennis, cl,
	penberg, rientjes, vbabka, ngupta, linux-block, axboe,
	paolo.valente, josef, linux-fsdevel, viro, jack, jlayton,
	dan.j.williams, hch, djwong, dri-devel, airlied,
	rodrigosiqueiramelo, melissa.srw, hamohammed.sa

Thanks to Matthew, I found the reports are spurious.. I missed the case
that it's not going to real sleep after preparing a wait.

I'm sorry for bothering you guys. Please ignore the reports.



^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2022-02-16  6:51 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-02-16  4:11 [REPORT] ext4 deadlock possibilities by DEPT Byungchul Park
2022-02-16  4:15 ` Report in ext4_buffered_write_iter() Byungchul Park
2022-02-16  4:15   ` Report in ext4_da_write_begin() Byungchul Park
2022-02-16  4:15   ` Report in ext4_file_write_iter() Byungchul Park
2022-02-16  4:15   ` Report in ext4_sync_file() Byungchul Park
2022-02-16  4:15   ` Report in ksys_write() Byungchul Park
2022-02-16  4:15   ` Report in __mark_inode_dirty() Byungchul Park
2022-02-16  6:51 ` [REPORT] ext4 deadlock possibilities by DEPT Byungchul Park

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).