Re: Report in unix_stream_read_generic()

[Byungchul Park]

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