Date: Wed, 2 Dec 2009 14:55:23 -0600 From: Kevin <kevin@your.org> To: freebsd-fs@freebsd.org Subject: "zfs receive" lock time Message-ID: <30582AF2-B1E8-4C07-A487-C220845963D2@your.org>
next in thread | raw e-mail | index | archive | help
I have two very very fast systems (12-disk 15krpm raid array, 16 cores, etc). I'm using zfs send/receive to replicate a zfs volume from the "master" box to the "slave" box. Every minute, the master takes a new snapshot, then uses "send -i" to send an incremental snapshot to the slave. Normally, no files are changed during the minute so the operation is very fast (<1 second, and most of that is ssh negotiation time). If the slave is completely idle, "zfs receive" takes a fraction of a second. If the slave has been very busy (lots of read activity, no writes - the slave has everything mounted read only), suddenly "zfs receive" can take 30 seconds or more to complete, the whole time it has the filesystem locked. For example, I'd see: 49345 root 1 76 0 13600K 1956K zio->i 9 0:01 1.37% zfs 48910 www 1 46 0 36700K 21932K rrl->r 3 0:24 0.00% lighttpd 48913 www 1 46 0 41820K 26108K rrl->r 2 0:24 0.00% lighttpd 48912 www 1 46 0 37724K 23484K rrl->r 0 0:24 0.00% lighttpd 48911 www 1 46 0 41820K 26460K rrl->r 10 0:23 0.00% lighttpd 48909 www 1 46 0 39772K 24488K rrl->r 5 0:22 0.00% lighttpd 48908 www 1 46 0 36700K 21460K rrl->r 14 0:19 0.00% lighttpd 48907 www 1 45 0 30556K 16216K rrl->r 13 0:14 0.00% lighttpd 48906 www 1 44 0 26460K 11452K rrl->r 6 0:06 0.00% lighttpd At first, I thought it was possibly cache pressure... when the system was busy, whatever data necessary to create a new snapshot was getting pushed out of the cache so it had to be re-read. I increased arc_max and arc_meta_limit to very high values, and it seemed to have no effect, even when arc_meta_used was far below arc_meta_limit. Disabling cache flushes had no impact. Disabling zil cut the time in half, but it's still too long for this application. ktrace on the "zfs receive" shows: 1062 zfs 0.000024 CALL ioctl(0x3,0xcc285a11 ,0x7fffffffa320) 1062 zfs 0.000081 RET ioctl 0 1062 zfs 0.000058 CALL ioctl(0x3,0xcc285a05 ,0x7fffffffa2f0) 1062 zfs 0.000037 RET ioctl 0 1062 zfs 0.000019 CALL ioctl(0x3,0xcc285a11 ,0x7fffffffa320) 1062 zfs 0.000055 RET ioctl 0 1062 zfs 0.000031 CALL ioctl(0x3,0xcc285a11 ,0x7fffffff9f00) 1062 zfs 0.000053 RET ioctl 0 1062 zfs 0.000020 CALL ioctl(0x3,0xcc285a1c ,0x7fffffffc930) 1062 zfs 24.837084 RET ioctl 0 1062 zfs 0.000028 CALL ioctl(0x3,0xcc285a11 ,0x7fffffff9f00) 1062 zfs 0.000074 RET ioctl 0 1062 zfs 0.000037 CALL close(0x6) 1062 zfs 0.000006 RET close 0 1062 zfs 0.000007 CALL close(0x3) 1062 zfs 0.000005 RET close 0 The 24 second call to 0xcc285a1c is ZFS_IOC_RECV, so whatever is going on is in the kernel, not a delay in getting the kernel any data. "systat" is showing that the drives are 100% busy during the operation, so it's obviously doing something. :) Does anyone know what "zfs receive" is doing while it has everything locked like this, and why a lot of read activity beforehand would drastically effect the performance of doing this? -- Kevin
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?30582AF2-B1E8-4C07-A487-C220845963D2>