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