Slow reboots due to ZFS cleanup in kern_shutdown() .. zio_fini()

[Peter Eriksson]

Sigh.

Slight correction, the output below should have said uma_zdestroy() and not uma_zfree_arg() (wrong printf text, but the right times).

After an uptime of 7 hours, a reboot have these times (I removed the “uma” printf in this run):

kmem_cache_destroy(zio_data_buf_cache[8]) took 2 seconds
kmem_cache_destroy(zio_buf_cache[10]) took 6 seconds
kmem_cache_destroy(zio_buf_cache[14]) took 2 seconds
kmem_cache_destroy(zio_buf_cache[16]) took 136 seconds
kmem_cache_destroy(zio_buf_cache[20]) took 31 seconds
kmem_cache_destroy(zio_buf_cache[28]) took 303 seconds
kmem_cache_destroy(zio_buf_cache[224]) took 89 seconds
kmem_cache_destroy(zio_data_buf_cache[224]) took 31 seconds

This is on a mostly idle server (well, apart from compiling the kernel code :-) and some snapshots being taken of all filesystems (once per hour).


So now on to finding out why uma_destroy() is taking so long… :-).

- Peter


> On 2 Dec 2019, at 15:32, Peter Eriksson <pen at lysator.liu.se> wrote:
> 
> I’ve been looking at trying to figure out why our servers take so long to reboot, where the most time is spent doing a “shutdown”. We’ve seen examples where it has taken 10-20 minutes (or more).
> 
> This is Dell PowerEdge R730xd servers with 256GB RAM and ~140TB of disks. FreeBSD 11.3. With ~24000 filsystems per server.
> We normally cap ARC to 128GB RAM.
> 
> Adding a lot of debugging printf() calls to relevant parts of the code points to:
> 
> kern_shutdown() ->
>  EVENTHANDLER_INVOKE(shutdown_post_sync) ->
>  zfsshutdown() -> 
>  zfs__fini() -> 
>  spa_fini() -> 
>  zio_fini():
> 
> Debug output from a test run:
> zio_fini: kmem_cache_destroy(zio_buf_cache & zio_data_buf_cache):
> 
> kmem_cache_destroy: uma_zfree_arg(0xfffff803465eec00) [zio_buf_12288] took 16 seconds
> kmem_cache_destroy(zio_buf_cache[20]) took 16 seconds
> 
> kmem_cache_destroy: uma_zfree_arg(0xfffff803465eeb00) [zio_buf_16384] took 61 seconds
> kmem_cache_destroy(zio_buf_cache[28]) took 61 seconds
> 
> kmem_cache_destroy: uma_zfree_arg(0xfffff8034c9018c0) [zio_buf_131072] took 87 seconds
> kmem_cache_destroy(zio_buf_cache[224]) took 87 seconds
> 
> kmem_cache_destroy: uma_zfree_arg(0xfffff8034c901880) [zio_data_buf_131072] took 5 seconds
> kmem_cache_destroy(zio_data_buf_cache[224]) took 5 seconds
> 
> (I modified the code here to print the time spent if it took 2 seconds or more)
> 
> This is on a newly rebooted server (with all filesystems mounted). Seems like uma_zfree_arg() is taking really long to execute. Now that code isn’t exactly easy to read (for me atleast)… Lot’s of barrier/locks and stuff.
> 
> I wonder why this code should take so long? There shouldn’t be any disk I/O involved and it’s just a cache so I wonder if there might be some way to get rid of it quicker? Any UMA experts online? :-)
> 
> Reason for this is that I’d like to be able to make sure a server reboots more quickly in case of problems. Now with the parallell ZFS mount stuff being done at boot time that part is much quicker :-).
> 
> - Peter
> 
> _______________________________________________
> freebsd-fs at freebsd.org mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-fs
> To unsubscribe, send any mail to "freebsd-fs-unsubscribe at freebsd.org"