Re: Possible buffer cache race?

[Jaromír Doleček <jaromir.dolecek%gmail.com@localhost>]

2016-10-24 19:34 GMT+02:00 David Holland <dholland-tech%netbsd.org@localhost>:
> Is this correlated with the syncer running? I have been seeing a
> problem where every time the syncer runs it locks out everything else,
> and once that happens some things take several seconds to complete
> afterwards.

Doesn't seem to me just syncer slow - it behaves as regular deadlock.
If I just wait, nothing happens - it will not recover itself.
Actually, when I waited too long (couple minutes), the sync command
itself blocked and system didn't recover.

> The tstile ones are unlikely to be interesting (if you have a bunch of
> tstiles, pick one that isn't, which'll be what they're waiting behind)
> but the others might be. Knowing where it gets stuck will help a lot;
> or if it doesn't get stuck in any one place that too.

Got these example tracebacks:

#1
trace: pid 540 lid 1 at 0xfffffe90f090fb10
sleepq_block() at sleepq_block+0x97
cv_timedwait() at cv_timedwait+0x123
bbusy() at bbusy+0xad
getblk() at getblk+0x5a
bio_doread() at bio_doread+0x1d
bread() at bread+0x1a
ffs_update.part.3() at ffs_update.part.3+0x112
ufs_inactive() at ufs_inactive+0x18e
VOP_INACTIVE() at VOP_INACTIVE+0x33
vrelel() at vrelel+0x259
vn_close() at vn_close+0x41
closef() at closef+0x54
fd_close() at fd_close+0x2da
sys_close() at sys_close+0x20
syscall() at syscall+0x164

#2
trace: pid 222 lid 1 at 0xfffffe90f0927c20
sleepq_block() at sleepq_block+0x97
turnstile_block() at turnstile_block+0x3a9
mutex_enter() at mutex_enter+0x36c
genfs_renamelock_enter() at genfs_renamelock_enter+0xd
do_sys_renameat() at do_sys_renameat+0x478
sys_rename() at sys_rename+0x25
syscall() at syscall+0x164

#3
trace: pid 697 lid 1 at 0xfffffe90f089f850
sleepq_block() at sleepq_block+0x97
cv_timedwait() at cv_timedwait+0x123
bbusy() at bbusy+0xad
getblk() at getblk+0x5a
bio_doread() at bio_doread+0x1d
bread() at bread+0x1a
ffs_update.part.3() at ffs_update.part.3+0x112
ufs_inactive() at ufs_inactive+0x18e
VOP_INACTIVE() at VOP_INACTIVE+0x33
vrelel() at vrelel+0x259
genfs_rename_exit() at genfs_rename_exit+0x10a
genfs_sane_rename() at genfs_sane_rename+0x7a3
ufs_sane_rename() at ufs_sane_rename+0x3a
genfs_insane_rename() at genfs_insane_rename+0x15d
VOP_RENAME() at VOP_RENAME+0x43
do_sys_renameat() at do_sys_renameat+0x77f
sys_rename() at sys_rename+0x25
syscall() at syscall+0x164

Those seem to be then for inode updates. I've spent some time trying
to trigger this locally, so far without success.

Once I'll get the remote machine reset again, I'll try to trigger the
condition using ATA disk - I want to rule out driver bug.

> The most common cause of missed wakeups is not going to sleep
> atomically, so it's usually a property of a particular sleep site.
> Next most common is races between changing things affecting the sleep
> condition and posting a wakeup; in particular, unlocked wakeup before
> change (or unlocked wakeup after change without a memory barrier to
> enforce the ordering) leads to problems.

Seems this more likely an async mount issue, not so much concurrency -
similar symptoms are described in PR kern/47030 for sysinst stall.
Sysinst also mounts the new filesystem async, and the condition there
is observed on VM with 1 CPU. I didn't manage to repeat this with qemu
2.7.0, but I'll check later with the qemu0 package.

The traceback in that PR is slightly different thought (it stalls
waiting for new buf), so that can actually be different issue.

Jaromir