Date: Sun, 23 Dec 2012 11:55:15 -0700 From: Ian Lepore <freebsd@damnhippie.dyndns.org> To: freebsd-current@freebsd.org Subject: Why does sleep(1) end up blocked in bwillwrite()? Message-ID: <1356288915.1129.68.camel@revolution.hippie.lan>
next in thread | raw e-mail | index | archive | help
Background: I'm trying to get nandfs working on a low-end small-memory
embedded system. I'm debugging performance problems that manifest as
the system (or large portions of it) becoming unresponsive for many
seconds at a time. It appears that sometimes the nandfs background
garbage collector does things that lead to dirtying lots of buffers way
faster than they can be written. When that happens it seems to take too
long (many seconds) for the problem to clear. That's the basic
situation I'm investigating, but NOT what this mail is about, that's
just the background.
When this situation happens, some of the threads in my application keep
running fine. Others get blocked unexpectedly even though they do no
disk IO at all, they're working with sockets and serial (uart) devices.
I discovered by accident that I can see a form of the problem happening
just using sleep(1) and hitting ^T while the buffer starvation is in
progress...
guava# sleep 999999
[ hit ^T]
load: 1.03 cmd: sleep 472 [nanslp] 2.03r 0.01u 0.02s 0% 1372k
sleep: about 999997 second(s) left out of the original 999999
[ hit ^T]
load: 1.27 cmd: sleep 472 [nanslp] 9.32r 0.01u 0.02s 0% 1376k
sleep: about 999989 second(s) left out of the original 999999
[ hit ^T]
load: 1.49 cmd: sleep 472 [nanslp] 11.53r 0.01u 0.02s 0% 1376k
[ note no output from sleep(1) here, repeated ^T now gives...]
load: 1.49 cmd: sleep 472 [flswai] 12.01r 0.01u 0.03s 0% 1376k
load: 1.49 cmd: sleep 472 [flswai] 12.27r 0.01u 0.03s 0% 1376k
load: 1.49 cmd: sleep 472 [flswai] 12.76r 0.01u 0.03s 0% 1376k
load: 1.49 cmd: sleep 472 [flswai] 13.06r 0.01u 0.03s 0% 1376k
load: 1.49 cmd: sleep 472 [flswai] 13.26r 0.01u 0.03s 0% 1376k
load: 1.61 cmd: sleep 472 [flswai] 20.03r 0.02u 0.07s 0% 1376k
load: 1.64 cmd: sleep 472 [flswai] 20.49r 0.02u 0.07s 0% 1376k
load: 1.64 cmd: sleep 472 [flswai] 20.68r 0.02u 0.08s 0% 1376k
sleep: about 999987 second(s) left out of the original 999999
So here sleep(1) was blocked in bwillwrite() for about 9 seconds on a
write to stderr (which is an ssh xterm connection).
The call to bwillwrite() is in kern/sys_generic.c in dofilewrite():
if (fp->f_type == DTYPE_VNODE)
bwillwrite();
I just noticed the checkin message that added the DTYPE_VNODE check
specifically mentions not penalizing devices and pipes and such. I
think maybe things have evolved since then (Dec 2000) and this check is
no longer sufficient. Maybe it needs to be something more like
if (fp->f_type == DTYPE_VNODE && fp->f_vnode->v_type == VREG)
but I have a gut feeling it needs to be more complex than that (can
f_vnode be NULL, what sort of locking is required to peek into f_vnode
at this point, etc), so I can't really propose a patch for this. In
fact, I can't even say for sure it's a bug, but it sure feels like one
to the application-developer part of me.
-- Ian
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1356288915.1129.68.camel>