Re: Report in unix_stream_read_generic()

Byungchul Park
2022-02-17T23:50:56Z

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