Date: Wed, 18 Mar 2009 15:04:29 -0400 From: Ben Kelly <ben@wanderview.com> To: freebsd-current@freebsd.org Subject: [patch] zfs livelock and thread priorities Message-ID: <DC9F2088-A0AF-467D-8574-F24A045ABD81@wanderview.com>
next in thread | raw e-mail | index | archive | help
--Apple-Mail-46--749651897
Content-Type: text/plain;
charset=US-ASCII;
format=flowed;
delsp=yes
Content-Transfer-Encoding: 7bit
Hello all,
Recently my home server has been going into a livelock state during my
nightly backups. The server has two zfs pools that look like this:
NAME STATE READ WRITE CKSUM
backup ONLINE 0 0 0
mirror ONLINE 0 0 0
label/backup0.eli ONLINE 0 0 0
label/backup1.eli ONLINE 0 0 0
label/backup2.eli ONLINE 0 0 0
NAME STATE READ WRITE CKSUM
tank ONLINE 0 0 0
ad0s3 ONLINE 0 0 0
I've had the tank pool for quite a while, but just recently added the
backup pool. Previously I had been backing up to a smaller disk using
UFS+geli. The server is running a very recent CURRENT.
With this configuration I could get the server into a bad state within
15 minutes by running my rsync backup script. I call it a livelock,
but I'm not really sure if thats the right term. Existing shell
sessions would work for a while, but eventually get wedged. Sometimes
the serial console would stay responsive for a while, but it also
eventually stopped responding to input. The server would continue to
respond to pings and other network traffic. I was not able to log
into new shells.
To try to figure out what was going on I left top running while I
triggered the problem. The following processes were using all the CPU:
PID USERNAME PRI NICE SIZE RES STATE TIME CPU COMMAND
210 root 46 - 0K 20K RUN 0:06 16.70%
txg_thread_enter
1207 root 44 0 3280K 1296K RUN 0:05 13.87% syslogd
889 root 44 0 5436K 2852K RUN 0:04 13.09% apcupsd
33 root 44 - 0K 8K RUN 0:05 12.99% syncer
1696 root 44 0 3280K 1344K RUN 0:01 12.79% syslogd
727 root 44 0 3280K 1496K RUN 0:01 12.60% syslogd
2065 root 44 0 3280K 1344K RUN 0:01 12.60% syslogd
209 root 46 - 0K 8K tx->tx 0:02 4.79%
txg_thread_enter
2485 root 44 0 4636K 2664K RUN 0:00 0.10% top
11 root 171 ki31 0K 8K RUN 0:15 0.00% idle
The exact processes varied, but txg_thread_enter was always in the
mix. The syncer was not always present. I also noticed that lower in
the list was a spa_zio process set to RUN:
2458 root 49 - 0K 8K RUN 0:00 0.00% spa_zio
Using the serial console I broke to the debugger and got some stack
traces. All of the spinning processes were in some form of
txg_wait_open() or txg_thread_wait(). For example:
Tracing command syslogd pid 2065 tid 100174 td 0xa3a568c0
sched_switch(a3a568c0,0,104,f744824c,17e,...) at sched_switch+0x1fc
mi_switch(104,0,a3a568c0,a3a568c0,dfc729a0,...) at mi_switch+0x12a
sleepq_switch(a3a568c0,0,9e88745b,247,0,...) at sleepq_switch+0xcb
sleepq_wait(a35181f0,0,a321b2ab,1,0,...) at sleepq_wait+0x39
_cv_wait(a35181f0,a3518180,a321b186,1d3,a35181f0,...) at _cv_wait+0x188
txg_wait_open(a3518000,2542a87,0,0,cc00,...) at txg_wait_open+0xb5
dmu_tx_wait(ab4d7a00,2,0,cbb5,0,...) at dmu_tx_wait+0x138
zfs_freebsd_write(dfc72be0,0,9e88c07e,0,a62f5df4,...) at
zfs_freebsd_write+0x3e0
VOP_WRITE_APV(a3221580,dfc72be0,9e88c07e,25a,dfc72c70,...) at
VOP_WRITE_APV+0xa6
vn_write(a5689690,bcf74780,a3ec7700,0,a3a568c0,...) at vn_write+0x1b4
dofilewrite(bcf74780,ffffffff,ffffffff,0,a5689690,...) at dofilewrite
+0x97
kern_writev(a3a568c0,e,bcf74780,bcf74780,0,...) at kern_writev+0x58
writev(a3a568c0,dfc72cf8,c,9e5f0500,a3a568c0,...) at writev+0x46
syscall(dfc72d38) at syscall+0x325
Xint0x80_syscall() at Xint0x80_syscall+0x20
The one exception was a single txg_thread_enter process that appeared
to be waiting on zio:
Tracing command txg_thread_enter pid 2469 tid 100252 td 0xa48f4690
sched_switch(a48f4690,0,104,9cb79a82,139,...) at sched_switch+0x1fc
mi_switch(104,0,a48f4690,a48f4690,dfd7ba80,...) at mi_switch+0x12a
sleepq_switch(a48f4690,0,9e88745b,247,0,...) at sleepq_switch+0xcb
sleepq_wait(adff56ec,0,a321cffb,1,0,...) at sleepq_wait+0x39
_cv_wait(adff56ec,adff56d8,a321cf9b,3fe,3b9aca00,...) at _cv_wait+0x188
zio_wait(adff54a8,3ec8,0,0,9f055a60,...) at zio_wait+0x62
dsl_pool_sync(a2d0a400,3ec8,0,0,0,...) at dsl_pool_sync+0x112
--More-- spa_sync(a2ff5000,3ec8,0,0,3e8,...) at spa_sync+0x3b5
txg_sync_thread(a2d0a400,dfd7bd38,0,0,0,...) at txg_sync_thread+0x3b4
fork_exit(a3182790,a2d0a400,dfd7bd38) at fork_exit+0x90
fork_trampoline() at fork_trampoline+0x8
All of the spa_zio processes were blocked waiting on task queues
except for the one spa_zio process marked RUN. It appeared to have
been interrupted:
Tracing command spa_zio pid 2458 tid 100245 td 0xa48d1d20
sched_switch(a48d1d20,0,602,d1125c99,17e,...) at sched_switch+0x1fc
mi_switch(602,0,9e884bce,bc,0,...) at mi_switch+0x12a
--More--
critical_exit(9e8f29a8,a48d1d20,9e8f29a8,a2c33580,e,...) at
critical_exit+0x92
intr_event_handle(a2c33580,dfd62b54,dfd62b48,c3c85000,e,...) at
intr_event_handle+0xaa
intr_execute_handlers
(9e8f29a8,dfd62b54,c3c85000,c381b284,dfd62c10,...) at
intr_execute_handlers+0x>
atpic_handle_intr(e,dfd62b54) at atpic_handle_intr+0x67
Xatpic_intr14() at Xatpic_intr14+0x21
--- interrupt, eip = 0x9e821e7e, esp = 0xdfd62b94, ebp = 0xdfd62c10 ---
generic_bcopy(a4c4ab68,c1757254,a321c015,134,a4c4ab2c,...) at
generic_bcopy+0x1a
vdev_queue_io_done(c1757254,0,a324aad8,a9d0c4c0,a9d0c4c0,...) at
vdev_queue_io_done+0xb2
zio_vdev_io_done(c1757254,a31316e2,a324aad8,0,a3214fd8,...) at
zio_vdev_io_done+0x72
zio_execute(c1757254,0,a3214fd8,352,6a7334a1,...) at zio_execute+0x62
taskq_thread(a324aab8,dfd62d38,0,0,0,...) at taskq_thread+0x1a0
fork_exit(a3132030,a324aab8,dfd62d38) at fork_exit+0x90
fork_trampoline() at fork_trampoline+0x8
Across all the livelocks I triggered the spa_zio process was always
marked to RUN and appeared to have been interrupted. Also, if you
look at the top output it is running at a lower priority than the
other spinning threads.
Its not clear to me why the top threads were spinning in the txg
calls. The zfs code, however, does spawn the txg threads at
minclsyspri and the zio threads at maxclsyspri. It seems that their
intention was that the zio threads should preempt the txg processing.
Currently in FreeBSD, however, these priority values are ignored. In
this case, at least, it looks like the priorities may be required by
the zfs design.
To test this theory I applied the attached patch to sets the zfs
thread priorities. I chose the priority values to be similar to
PRIBIO but so that minclsyspri is still lower priority than
maxclsyspri. The exact values are somewhat arbitrary. With these
changes I have not been able to trigger the livelock condition again.
(Also, it occurred to me that this might make the arc_reclaim_thread
more responsive to system memory pressure.)
I should note, however, that the livelock failure is somewhat timing
dependent. When I enabled WITNESS at one point it changed the timing
to the point where the livelock would only occur after running the
backup for hours instead of minutes. Its possible the thread priority
change has only changed the timing, but not really fixed the problem.
Also, this patch might affect dtrace, but I have not tested that.
Does my analysis look reasonable? Should the spa_zio thread have been
rescheduled even without the priority change? Is there a better way
to attack this problem? Any input would be greatly appreciated.
Thank you.
- Ben
--Apple-Mail-46--749651897
Content-Disposition: attachment;
filename=zfs_thread_priority.diff
Content-Type: application/octet-stream; x-unix-mode=0644;
name="zfs_thread_priority.diff"
Content-Transfer-Encoding: 7bit
Index: sys/cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c
===================================================================
--- sys/cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c (revision 187)
+++ sys/cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c (working copy)
@@ -32,6 +32,7 @@
#include <sys/vdev_impl.h>
#include <sys/fs/zfs.h>
#include <sys/zio.h>
+#include <sys/sched.h>
#include <geom/geom.h>
#include <geom/geom_int.h>
@@ -194,6 +195,8 @@
zio_t *zio;
struct bio *bp;
+ sched_prio(curthread, PRIBIO);
+
ctx = arg;
for (;;) {
mtx_lock(&ctx->gc_queue_mtx);
Index: sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zvol.c
===================================================================
--- sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zvol.c (revision 187)
+++ sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zvol.c (working copy)
@@ -72,6 +72,7 @@
#include <sys/zfs_rlock.h>
#include <sys/vdev_impl.h>
#include <sys/zvol.h>
+#include <sys/sched.h>
#include <geom/geom.h>
#include "zfs_namecheck.h"
@@ -402,6 +403,8 @@
zvol_state_t *zv;
struct bio *bp;
+ sched_prio(curthread, PRIBIO);
+
zv = arg;
for (;;) {
mtx_lock(&zv->zv_queue_mtx);
Index: sys/cddl/compat/opensolaris/sys/proc.h
===================================================================
--- sys/cddl/compat/opensolaris/sys/proc.h (revision 187)
+++ sys/cddl/compat/opensolaris/sys/proc.h (working copy)
@@ -35,12 +35,14 @@
#include <sys/stdint.h>
#include <sys/smp.h>
#include <sys/debug.h>
+#include <sys/sched.h>
+#include <sys/priority.h>
#ifdef _KERNEL
#define CPU curcpu
-#define minclsyspri 0
-#define maxclsyspri 0
+#define minclsyspri (PRIBIO + 2)
+#define maxclsyspri (PRIBIO + 1)
#define max_ncpus mp_ncpus
#define boot_max_ncpus mp_ncpus
@@ -60,6 +62,7 @@
{
proc_t *p;
int error;
+ kthread_t *t;
/*
* Be sure there are no surprises.
@@ -70,7 +73,13 @@
error = kproc_create(proc, arg, &p, 0, stksize / PAGE_SIZE,
"solthread %p", proc);
- return (error == 0 ? FIRST_THREAD_IN_PROC(p) : NULL);
+ if (error == 0) {
+ t = FIRST_THREAD_IN_PROC(p);
+ sched_prio(t, pri);
+ return t;
+ } else {
+ return NULL;
+ }
}
#define thread_exit() kproc_exit(0)
--Apple-Mail-46--749651897
Content-Type: text/plain;
charset=US-ASCII;
format=flowed
Content-Transfer-Encoding: 7bit
--Apple-Mail-46--749651897--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?DC9F2088-A0AF-467D-8574-F24A045ABD81>