linux-mm.kvack.org archive mirror
 help / color / mirror / Atom feed
* [REPORT] net deadlock possibilities by DEPT
@ 2022-02-16  4:12 Byungchul Park
  2022-02-16  4:17 ` Report in unix_stream_read_generic() Byungchul Park
  2022-02-16  6:53 ` [REPORT] net deadlock possibilities by DEPT Byungchul Park
  0 siblings, 2 replies; 6+ messages in thread
From: Byungchul Park @ 2022-02-16  4:12 UTC (permalink / raw)
  To: davem, kuba, netdev
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, tytso,
	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 David, Jakub and net 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] 6+ messages in thread

* Report in unix_stream_read_generic()
  2022-02-16  4:12 [REPORT] net deadlock possibilities by DEPT Byungchul Park
@ 2022-02-16  4:17 ` Byungchul Park
  2022-02-16  4:17   ` Report in unix_stream_sendmsg() Byungchul Park
  2022-02-16  4:33   ` Report in unix_stream_read_generic() Matthew Wilcox
  2022-02-16  6:53 ` [REPORT] net deadlock possibilities by DEPT Byungchul Park
  1 sibling, 2 replies; 6+ messages in thread
From: Byungchul Park @ 2022-02-16  4:17 UTC (permalink / raw)
  To: davem, kuba, netdev
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, tytso,
	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.013330] ===================================================
[    7.013331] DEPT: Circular dependency has been detected.
[    7.013332] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    7.013333] ---------------------------------------------------
[    7.013334] summary
[    7.013334] ---------------------------------------------------
[    7.013335] *** DEADLOCK ***
[    7.013335] 
[    7.013335] context A
[    7.013336]     [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
[    7.013337]     [W] __mutex_lock_common(&u->iolock:0)
[    7.013338]     [E] event(&(&ei->socket.wq.wait)->dmap:0)
[    7.013340] 
[    7.013340] context B
[    7.013341]     [S] __raw_spin_lock(&u->lock:0)
[    7.013342]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
[    7.013343]     [E] spin_unlock(&u->lock:0)
[    7.013344] 
[    7.013344] context C
[    7.013345]     [S] __mutex_lock_common(&u->iolock:0)
[    7.013346]     [W] __raw_spin_lock(&u->lock:0)
[    7.013347]     [E] mutex_unlock(&u->iolock:0)
[    7.013348] 
[    7.013348] [S]: start of the event context
[    7.013349] [W]: the wait blocked
[    7.013349] [E]: the event not reachable
[    7.013350] ---------------------------------------------------
[    7.013351] context A's detail
[    7.013351] ---------------------------------------------------
[    7.013352] context A
[    7.013352]     [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
[    7.013353]     [W] __mutex_lock_common(&u->iolock:0)
[    7.013354]     [E] event(&(&ei->socket.wq.wait)->dmap:0)
[    7.013355] 
[    7.013356] [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0):
[    7.013357] (N/A)
[    7.013357] 
[    7.013358] [W] __mutex_lock_common(&u->iolock:0):
[    7.013359] [<ffffffff81aa4918>] unix_stream_read_generic+0xab8/0xb60
[    7.013362] stacktrace:
[    7.013362]       __mutex_lock+0x52c/0x900
[    7.013364]       unix_stream_read_generic+0xab8/0xb60
[    7.013366]       unix_stream_recvmsg+0x40/0x50
[    7.013368]       ____sys_recvmsg+0x85/0x190
[    7.013370]       ___sys_recvmsg+0x78/0xb0
[    7.013371]       __sys_recvmsg+0x4b/0x80
[    7.013373]       do_syscall_64+0x3a/0x90
[    7.013374]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013376] 
[    7.013377] [E] event(&(&ei->socket.wq.wait)->dmap:0):
[    7.013378] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    7.013379] stacktrace:
[    7.013380]       dept_event+0x12b/0x1f0
[    7.013381]       __wake_up_common+0xb0/0x1a0
[    7.013383]       __wake_up_common_lock+0x65/0x90
[    7.013384]       unix_write_space+0x75/0x100
[    7.013386]       sock_wfree+0x68/0xa0
[    7.013387]       unix_destruct_scm+0x66/0x70
[    7.013389]       skb_release_head_state+0x3b/0x90
[    7.013391]       skb_release_all+0x9/0x20
[    7.013393]       consume_skb+0x4c/0xe0
[    7.013394]       unix_stream_read_generic+0xa3c/0xb60
[    7.013397]       unix_stream_recvmsg+0x40/0x50
[    7.013399]       ____sys_recvmsg+0x85/0x190
[    7.013400]       ___sys_recvmsg+0x78/0xb0
[    7.013402]       __sys_recvmsg+0x4b/0x80
[    7.013403]       do_syscall_64+0x3a/0x90
[    7.013405]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013407] ---------------------------------------------------
[    7.013407] context B's detail
[    7.013408] ---------------------------------------------------
[    7.013408] context B
[    7.013409]     [S] __raw_spin_lock(&u->lock:0)
[    7.013410]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
[    7.013411]     [E] spin_unlock(&u->lock:0)
[    7.013412] 
[    7.013412] [S] __raw_spin_lock(&u->lock:0):
[    7.013413] [<ffffffff81aa451f>] unix_stream_read_generic+0x6bf/0xb60
[    7.013416] stacktrace:
[    7.013416]       _raw_spin_lock+0x6e/0x90
[    7.013418]       unix_stream_read_generic+0x6bf/0xb60
[    7.013420]       unix_stream_recvmsg+0x40/0x50
[    7.013422]       sock_read_iter+0x85/0xd0
[    7.013424]       new_sync_read+0x162/0x180
[    7.013426]       vfs_read+0xf3/0x190
[    7.013428]       ksys_read+0xa6/0xc0
[    7.013429]       do_syscall_64+0x3a/0x90
[    7.013431]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013433] 
[    7.013434] [W] wait(&(&ei->socket.wq.wait)->dmap:0):
[    7.013434] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    7.013436] stacktrace:
[    7.013437]       unix_stream_read_generic+0x6fa/0xb60
[    7.013439]       unix_stream_recvmsg+0x40/0x50
[    7.013441]       sock_read_iter+0x85/0xd0
[    7.013443]       new_sync_read+0x162/0x180
[    7.013445]       vfs_read+0xf3/0x190
[    7.013447]       ksys_read+0xa6/0xc0
[    7.013448]       do_syscall_64+0x3a/0x90
[    7.013449]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013451] 
[    7.013452] [E] spin_unlock(&u->lock:0):
[    7.013453] [<ffffffff81aa45df>] unix_stream_read_generic+0x77f/0xb60
[    7.013455] stacktrace:
[    7.013456]       _raw_spin_unlock+0x30/0x70
[    7.013457]       unix_stream_read_generic+0x77f/0xb60
[    7.013460]       unix_stream_recvmsg+0x40/0x50
[    7.013462]       sock_read_iter+0x85/0xd0
[    7.013464]       new_sync_read+0x162/0x180
[    7.013465]       vfs_read+0xf3/0x190
[    7.013467]       ksys_read+0xa6/0xc0
[    7.013468]       do_syscall_64+0x3a/0x90
[    7.013470]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013472] ---------------------------------------------------
[    7.013473] context C's detail
[    7.013473] ---------------------------------------------------
[    7.013474] context C
[    7.013474]     [S] __mutex_lock_common(&u->iolock:0)
[    7.013475]     [W] __raw_spin_lock(&u->lock:0)
[    7.013476]     [E] mutex_unlock(&u->iolock:0)
[    7.013477] 
[    7.013478] [S] __mutex_lock_common(&u->iolock:0):
[    7.013479] [<ffffffff81aa3f40>] unix_stream_read_generic+0xe0/0xb60
[    7.013481] stacktrace:
[    7.013482]       __mutex_lock+0x54d/0x900
[    7.013483]       unix_stream_read_generic+0xe0/0xb60
[    7.013486]       unix_stream_recvmsg+0x40/0x50
[    7.013488]       ____sys_recvmsg+0x85/0x190
[    7.013490]       ___sys_recvmsg+0x78/0xb0
[    7.013491]       __sys_recvmsg+0x4b/0x80
[    7.013492]       do_syscall_64+0x3a/0x90
[    7.013494]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013496] 
[    7.013496] [W] __raw_spin_lock(&u->lock:0):
[    7.013497] [<ffffffff81aa3f92>] unix_stream_read_generic+0x132/0xb60
[    7.013499] stacktrace:
[    7.013500]       _raw_spin_lock+0x4b/0x90
[    7.013502]       unix_stream_read_generic+0x132/0xb60
[    7.013504]       unix_stream_recvmsg+0x40/0x50
[    7.013506]       ____sys_recvmsg+0x85/0x190
[    7.013508]       ___sys_recvmsg+0x78/0xb0
[    7.013509]       __sys_recvmsg+0x4b/0x80
[    7.013510]       do_syscall_64+0x3a/0x90
[    7.013512]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013514] 
[    7.013514] [E] mutex_unlock(&u->iolock:0):
[    7.013515] [<ffffffff81aa4058>] unix_stream_read_generic+0x1f8/0xb60
[    7.013518] stacktrace:
[    7.013518]       __mutex_unlock_slowpath+0x49/0x2a0
[    7.013520]       unix_stream_read_generic+0x1f8/0xb60
[    7.013522]       unix_stream_recvmsg+0x40/0x50
[    7.013524]       ____sys_recvmsg+0x85/0x190
[    7.013526]       ___sys_recvmsg+0x78/0xb0
[    7.013527]       __sys_recvmsg+0x4b/0x80
[    7.013528]       do_syscall_64+0x3a/0x90
[    7.013530]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.013532] ---------------------------------------------------
[    7.013532] information that might be helpful
[    7.013533] ---------------------------------------------------
[    7.013534] CPU: 2 PID: 641 Comm: avahi-daemon Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    7.013535] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    7.013536] Call Trace:
[    7.013537]  <TASK>
[    7.013538]  dump_stack_lvl+0x44/0x57
[    7.013540]  print_circle+0x384/0x510
[    7.013542]  ? print_circle+0x510/0x510
[    7.013544]  cb_check_dl+0x58/0x60
[    7.013545]  bfs+0xdc/0x1b0
[    7.013548]  add_dep+0x94/0x120
[    7.013550]  do_event.isra.22+0x284/0x300
[    7.013552]  ? __wake_up_common+0x93/0x1a0
[    7.013553]  dept_event+0x12b/0x1f0
[    7.013555]  __wake_up_common+0xb0/0x1a0
[    7.013557]  __wake_up_common_lock+0x65/0x90
[    7.013559]  unix_write_space+0x75/0x100
[    7.013562]  sock_wfree+0x68/0xa0
[    7.013564]  unix_destruct_scm+0x66/0x70
[    7.013565]  skb_release_head_state+0x3b/0x90
[    7.013568]  skb_release_all+0x9/0x20
[    7.013570]  consume_skb+0x4c/0xe0
[    7.013572]  unix_stream_read_generic+0xa3c/0xb60
[    7.013575]  ? prepare_to_wait_exclusive+0xa0/0xa0
[    7.013577]  unix_stream_recvmsg+0x40/0x50
[    7.013580]  ? unix_state_double_unlock+0x40/0x40
[    7.013582]  ____sys_recvmsg+0x85/0x190
[    7.013584]  ? __import_iovec+0xd1/0x140
[    7.013587]  ? import_iovec+0x17/0x20
[    7.013589]  ? copy_msghdr_from_user+0x47/0x60
[    7.013591]  ___sys_recvmsg+0x78/0xb0
[    7.013593]  ? trace_hardirqs_on+0x38/0xe0
[    7.013595]  ? finish_task_switch+0xf3/0x2a0
[    7.013598]  ? __sys_recvmsg+0x4b/0x80
[    7.013599]  __sys_recvmsg+0x4b/0x80
[    7.013601]  do_syscall_64+0x3a/0x90
[    7.013603]  entry_SYSCALL_64_after_hwframe+0x44/0xae


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

* Report in unix_stream_sendmsg()
  2022-02-16  4:17 ` Report in unix_stream_read_generic() Byungchul Park
@ 2022-02-16  4:17   ` Byungchul Park
  2022-02-16  4:33   ` Report in unix_stream_read_generic() Matthew Wilcox
  1 sibling, 0 replies; 6+ messages in thread
From: Byungchul Park @ 2022-02-16  4:17 UTC (permalink / raw)
  To: davem, kuba, netdev
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, tytso,
	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.008968] ===================================================
[    7.008973] DEPT: Circular dependency has been detected.
[    7.008974] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
[    7.008975] ---------------------------------------------------
[    7.008976] summary
[    7.008976] ---------------------------------------------------
[    7.008980] *** DEADLOCK ***
[    7.008980] 
[    7.008981] context A
[    7.008982]     [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
[    7.008983]     [W] __raw_spin_lock(&u->lock:0)
[    7.008984]     [E] event(&(&ei->socket.wq.wait)->dmap:0)
[    7.008986] 
[    7.008986] context B
[    7.008987]     [S] __raw_spin_lock(&u->lock:0)
[    7.008988]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
[    7.008989]     [E] spin_unlock(&u->lock:0)
[    7.008990] 
[    7.008991] [S]: start of the event context
[    7.008991] [W]: the wait blocked
[    7.008992] [E]: the event not reachable
[    7.008992] ---------------------------------------------------
[    7.008993] context A's detail
[    7.008994] ---------------------------------------------------
[    7.008994] context A
[    7.008995]     [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
[    7.008996]     [W] __raw_spin_lock(&u->lock:0)
[    7.008997]     [E] event(&(&ei->socket.wq.wait)->dmap:0)
[    7.008998] 
[    7.008999] [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0):
[    7.009000] (N/A)
[    7.009000] 
[    7.009001] [W] __raw_spin_lock(&u->lock:0):
[    7.009002] [<ffffffff81aa5c24>] unix_stream_sendmsg+0x294/0x590
[    7.009006] stacktrace:
[    7.009007]       _raw_spin_lock+0x4b/0x90
[    7.009010]       unix_stream_sendmsg+0x294/0x590
[    7.009011]       sock_sendmsg+0x56/0x60
[    7.009015]       sock_write_iter+0x82/0xe0
[    7.009017]       new_sync_write+0x16d/0x190
[    7.009020]       vfs_write+0x134/0x360
[    7.009022]       ksys_write+0xa6/0xc0
[    7.009023]       do_syscall_64+0x3a/0x90
[    7.009026]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.009028] 
[    7.009028] [E] event(&(&ei->socket.wq.wait)->dmap:0):
[    7.009029] [<ffffffff810baa53>] __wake_up_common+0x93/0x1a0
[    7.009031] stacktrace:
[    7.009032]       dept_event+0x12b/0x1f0
[    7.009035]       __wake_up_common+0xb0/0x1a0
[    7.009036]       __wake_up_common_lock+0x65/0x90
[    7.009037]       sock_def_readable+0x5c/0xe0
[    7.009040]       unix_stream_sendmsg+0x19a/0x590
[    7.009041]       sock_sendmsg+0x56/0x60
[    7.009043]       sock_write_iter+0x82/0xe0
[    7.009045]       new_sync_write+0x16d/0x190
[    7.009047]       vfs_write+0x134/0x360
[    7.009049]       ksys_write+0xa6/0xc0
[    7.009050]       do_syscall_64+0x3a/0x90
[    7.009052]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.009054] ---------------------------------------------------
[    7.009054] context B's detail
[    7.009055] ---------------------------------------------------
[    7.009057] context B
[    7.009057]     [S] __raw_spin_lock(&u->lock:0)
[    7.009059]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
[    7.009060]     [E] spin_unlock(&u->lock:0)
[    7.009061] 
[    7.009061] [S] __raw_spin_lock(&u->lock:0):
[    7.009062] [<ffffffff81aa451f>] unix_stream_read_generic+0x6bf/0xb60
[    7.009066] stacktrace:
[    7.009067]       _raw_spin_lock+0x6e/0x90
[    7.009068]       unix_stream_read_generic+0x6bf/0xb60
[    7.009071]       unix_stream_recvmsg+0x40/0x50
[    7.009073]       sock_read_iter+0x85/0xd0
[    7.009074]       new_sync_read+0x162/0x180
[    7.009076]       vfs_read+0xf3/0x190
[    7.009078]       ksys_read+0xa6/0xc0
[    7.009079]       do_syscall_64+0x3a/0x90
[    7.009081]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.009083] 
[    7.009084] [W] wait(&(&ei->socket.wq.wait)->dmap:0):
[    7.009085] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
[    7.009087] stacktrace:
[    7.009087]       unix_stream_read_generic+0x6fa/0xb60
[    7.009089]       unix_stream_recvmsg+0x40/0x50
[    7.009091]       sock_read_iter+0x85/0xd0
[    7.009093]       new_sync_read+0x162/0x180
[    7.009095]       vfs_read+0xf3/0x190
[    7.009097]       ksys_read+0xa6/0xc0
[    7.009098]       do_syscall_64+0x3a/0x90
[    7.009100]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.009102] 
[    7.009102] [E] spin_unlock(&u->lock:0):
[    7.009103] [<ffffffff81aa45df>] unix_stream_read_generic+0x77f/0xb60
[    7.009106] stacktrace:
[    7.009107]       _raw_spin_unlock+0x30/0x70
[    7.009108]       unix_stream_read_generic+0x77f/0xb60
[    7.009110]       unix_stream_recvmsg+0x40/0x50
[    7.009113]       sock_read_iter+0x85/0xd0
[    7.009114]       new_sync_read+0x162/0x180
[    7.009116]       vfs_read+0xf3/0x190
[    7.009118]       ksys_read+0xa6/0xc0
[    7.009119]       do_syscall_64+0x3a/0x90
[    7.009121]       entry_SYSCALL_64_after_hwframe+0x44/0xae
[    7.009123] ---------------------------------------------------
[    7.009124] information that might be helpful
[    7.009124] ---------------------------------------------------
[    7.009125] CPU: 2 PID: 641 Comm: avahi-daemon Tainted: G        W         5.17.0-rc1-00014-gcf3441bb2012 #2
[    7.009128] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[    7.009129] Call Trace:
[    7.009130]  <TASK>
[    7.009131]  dump_stack_lvl+0x44/0x57
[    7.009134]  print_circle+0x384/0x510
[    7.009136]  ? print_circle+0x510/0x510
[    7.009138]  cb_check_dl+0x58/0x60
[    7.009139]  bfs+0xdc/0x1b0
[    7.009142]  add_dep+0x94/0x120
[    7.009144]  do_event.isra.22+0x284/0x300
[    7.009146]  ? __wake_up_common+0x93/0x1a0
[    7.009147]  dept_event+0x12b/0x1f0
[    7.009149]  __wake_up_common+0xb0/0x1a0
[    7.009151]  __wake_up_common_lock+0x65/0x90
[    7.009153]  sock_def_readable+0x5c/0xe0
[    7.009155]  unix_stream_sendmsg+0x19a/0x590
[    7.009158]  sock_sendmsg+0x56/0x60
[    7.009160]  sock_write_iter+0x82/0xe0
[    7.009163]  new_sync_write+0x16d/0x190
[    7.009166]  vfs_write+0x134/0x360
[    7.009169]  ksys_write+0xa6/0xc0
[    7.009170]  ? trace_hardirqs_on+0x38/0xe0
[    7.009173]  do_syscall_64+0x3a/0x90
[    7.009175]  entry_SYSCALL_64_after_hwframe+0x44/0xae


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

* Re: Report in unix_stream_read_generic()
  2022-02-16  4:17 ` Report in unix_stream_read_generic() Byungchul Park
  2022-02-16  4:17   ` Report in unix_stream_sendmsg() Byungchul Park
@ 2022-02-16  4:33   ` Matthew Wilcox
  2022-02-17 23:50     ` Byungchul Park
  1 sibling, 1 reply; 6+ messages in thread
From: Matthew Wilcox @ 2022-02-16  4:33 UTC (permalink / raw)
  To: Byungchul Park
  Cc: davem, kuba, netdev, torvalds, mingo, linux-kernel, peterz, will,
	tglx, rostedt, joel, sashal, daniel.vetter, chris, duyuyang,
	johannes.berg, tj, tytso, 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

On Wed, Feb 16, 2022 at 01:17:03PM +0900, Byungchul Park wrote:
> [    7.013330] ===================================================
> [    7.013331] DEPT: Circular dependency has been detected.
> [    7.013332] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
> [    7.013333] ---------------------------------------------------
> [    7.013334] summary
> [    7.013334] ---------------------------------------------------
> [    7.013335] *** DEADLOCK ***
> [    7.013335] 
> [    7.013335] context A
> [    7.013336]     [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
> [    7.013337]     [W] __mutex_lock_common(&u->iolock:0)
> [    7.013338]     [E] event(&(&ei->socket.wq.wait)->dmap:0)
> [    7.013340] 
> [    7.013340] context B
> [    7.013341]     [S] __raw_spin_lock(&u->lock:0)
> [    7.013342]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
> [    7.013343]     [E] spin_unlock(&u->lock:0)

This seems unlikely to be real.  We're surely not actually waiting
while holding a spinlock; existing debug checks would catch it.

> [    7.013407] ---------------------------------------------------
> [    7.013407] context B's detail
> [    7.013408] ---------------------------------------------------
> [    7.013408] context B
> [    7.013409]     [S] __raw_spin_lock(&u->lock:0)
> [    7.013410]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
> [    7.013411]     [E] spin_unlock(&u->lock:0)
> [    7.013412] 
> [    7.013412] [S] __raw_spin_lock(&u->lock:0):
> [    7.013413] [<ffffffff81aa451f>] unix_stream_read_generic+0x6bf/0xb60
> [    7.013416] stacktrace:
> [    7.013416]       _raw_spin_lock+0x6e/0x90
> [    7.013418]       unix_stream_read_generic+0x6bf/0xb60

It would be helpful if you'd run this through scripts/decode_stacktrace.sh
so we could see line numbers instead of hex offsets (which arene't much
use without the binary kernel).

> [    7.013420]       unix_stream_recvmsg+0x40/0x50
> [    7.013422]       sock_read_iter+0x85/0xd0
> [    7.013424]       new_sync_read+0x162/0x180
> [    7.013426]       vfs_read+0xf3/0x190
> [    7.013428]       ksys_read+0xa6/0xc0
> [    7.013429]       do_syscall_64+0x3a/0x90
> [    7.013431]       entry_SYSCALL_64_after_hwframe+0x44/0xae
> [    7.013433] 
> [    7.013434] [W] wait(&(&ei->socket.wq.wait)->dmap:0):
> [    7.013434] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0

... this may be the source of confusion.  Just because we prepare to
wait doesn't mean we end up actually waiting.  For example, look at
unix_wait_for_peer():

        prepare_to_wait_exclusive(&u->peer_wait, &wait, TASK_INTERRUPTIBLE);

        sched = !sock_flag(other, SOCK_DEAD) &&
                !(other->sk_shutdown & RCV_SHUTDOWN) &&
                unix_recvq_full(other);

        unix_state_unlock(other);

        if (sched)
                timeo = schedule_timeout(timeo);

        finish_wait(&u->peer_wait, &wait);

We *prepare* to wait, *then* drop the lock, then actually schedule.



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

* RE: [REPORT] net deadlock possibilities by DEPT
  2022-02-16  4:12 [REPORT] net deadlock possibilities by DEPT Byungchul Park
  2022-02-16  4:17 ` Report in unix_stream_read_generic() Byungchul Park
@ 2022-02-16  6:53 ` Byungchul Park
  1 sibling, 0 replies; 6+ messages in thread
From: Byungchul Park @ 2022-02-16  6:53 UTC (permalink / raw)
  To: davem, kuba, netdev
  Cc: torvalds, mingo, linux-kernel, peterz, will, tglx, rostedt, joel,
	sashal, daniel.vetter, chris, duyuyang, johannes.berg, tj, tytso,
	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] 6+ messages in thread

* Re: Report in unix_stream_read_generic()
  2022-02-16  4:33   ` Report in unix_stream_read_generic() Matthew Wilcox
@ 2022-02-17 23:50     ` Byungchul Park
  0 siblings, 0 replies; 6+ messages in thread
From: Byungchul Park @ 2022-02-17 23:50 UTC (permalink / raw)
  To: Matthew Wilcox
  Cc: davem, kuba, netdev, torvalds, mingo, linux-kernel, peterz, will,
	tglx, rostedt, joel, sashal, daniel.vetter, chris, duyuyang,
	johannes.berg, tj, tytso, 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

On Wed, Feb 16, 2022 at 04:33:41AM +0000, Matthew Wilcox wrote:
> On Wed, Feb 16, 2022 at 01:17:03PM +0900, Byungchul Park wrote:
> > [    7.013330] ===================================================
> > [    7.013331] DEPT: Circular dependency has been detected.
> > [    7.013332] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G        W        
> > [    7.013333] ---------------------------------------------------
> > [    7.013334] summary
> > [    7.013334] ---------------------------------------------------
> > [    7.013335] *** DEADLOCK ***
> > [    7.013335] 
> > [    7.013335] context A
> > [    7.013336]     [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
> > [    7.013337]     [W] __mutex_lock_common(&u->iolock:0)
> > [    7.013338]     [E] event(&(&ei->socket.wq.wait)->dmap:0)
> > [    7.013340] 
> > [    7.013340] context B
> > [    7.013341]     [S] __raw_spin_lock(&u->lock:0)
> > [    7.013342]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
> > [    7.013343]     [E] spin_unlock(&u->lock:0)
> 
> This seems unlikely to be real.  We're surely not actually waiting
> while holding a spinlock; existing debug checks would catch it.
> 
> > [    7.013407] ---------------------------------------------------
> > [    7.013407] context B's detail
> > [    7.013408] ---------------------------------------------------
> > [    7.013408] context B
> > [    7.013409]     [S] __raw_spin_lock(&u->lock:0)
> > [    7.013410]     [W] wait(&(&ei->socket.wq.wait)->dmap:0)
> > [    7.013411]     [E] spin_unlock(&u->lock:0)
> > [    7.013412] 
> > [    7.013412] [S] __raw_spin_lock(&u->lock:0):
> > [    7.013413] [<ffffffff81aa451f>] unix_stream_read_generic+0x6bf/0xb60
> > [    7.013416] stacktrace:
> > [    7.013416]       _raw_spin_lock+0x6e/0x90
> > [    7.013418]       unix_stream_read_generic+0x6bf/0xb60
> 
> It would be helpful if you'd run this through scripts/decode_stacktrace.sh

(Sorry for late reply, which was because of my email client issue.)

It was big help. Thank you very much.

> so we could see line numbers instead of hex offsets (which arene't much
> use without the binary kernel).
> 
> > [    7.013420]       unix_stream_recvmsg+0x40/0x50
> > [    7.013422]       sock_read_iter+0x85/0xd0
> > [    7.013424]       new_sync_read+0x162/0x180
> > [    7.013426]       vfs_read+0xf3/0x190
> > [    7.013428]       ksys_read+0xa6/0xc0
> > [    7.013429]       do_syscall_64+0x3a/0x90
> > [    7.013431]       entry_SYSCALL_64_after_hwframe+0x44/0xae
> > [    7.013433] 
> > [    7.013434] [W] wait(&(&ei->socket.wq.wait)->dmap:0):
> > [    7.013434] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0
> 
> ... this may be the source of confusion.  Just because we prepare to
> wait doesn't mean we end up actually waiting.  For example, look at
> unix_wait_for_peer():
> 
>         prepare_to_wait_exclusive(&u->peer_wait, &wait, TASK_INTERRUPTIBLE);
> 
>         sched = !sock_flag(other, SOCK_DEAD) &&
>                 !(other->sk_shutdown & RCV_SHUTDOWN) &&
>                 unix_recvq_full(other);
> 
>         unix_state_unlock(other);
> 
>         if (sched)
>                 timeo = schedule_timeout(timeo);
> 
>         finish_wait(&u->peer_wait, &wait);
> 
> We *prepare* to wait, *then* drop the lock, then actually schedule.

Big help, too. I checked some samples for the usage, but where it's
almost "prepare == wait" :-(. Thanks a lot!

Thanks,
Byungchul


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

end of thread, other threads:[~2022-02-17 23:50 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-02-16  4:12 [REPORT] net deadlock possibilities by DEPT Byungchul Park
2022-02-16  4:17 ` Report in unix_stream_read_generic() Byungchul Park
2022-02-16  4:17   ` Report in unix_stream_sendmsg() Byungchul Park
2022-02-16  4:33   ` Report in unix_stream_read_generic() Matthew Wilcox
2022-02-17 23:50     ` Byungchul Park
2022-02-16  6:53 ` [REPORT] net 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).