Page 2 of 3

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Sun May 02, 2021 1:54 am
by 23degrees
I can confirm I have the same log output from trying the test lundman created, using Big Sur 11.3(20E232).
After 45 minutes of up-time, without any heavy disk activity I ran two terminals.

Terminal One
Code: Select all
 zpool status
  pool: mediapool
 state: ONLINE
status: Some supported and requested features are not enabled on the pool.
   The pool can still be used, but some features are unavailable.
action: Enable all features using 'zpool upgrade'. Once this is done,
   the pool may no longer be accessible by software that does not support
   the features. See zpool-features(5) for details.
  scan: resilvered 24K in 00:00:05 with 0 errors on Fri Apr 16 08:40:29 2021
config:

   NAME                                            STATE     READ WRITE CKSUM
   mediapool                                       ONLINE       0     0     0
     raidz2-0                                      ONLINE       0     0     0
       media-0653279B-BB0B-CB45-BEE5-5520B0A1C8CB  ONLINE       0     0     0
       media-5EA82AA8-C6F8-3040-BB95-1CE92B577A42  ONLINE       0     0     0
       media-19124661-4686-2943-A70C-414B9EA6E308  ONLINE       0     0     0
       media-5FEA9EAB-25E7-494A-9A46-382D46E7693B  ONLINE       0     0     0
       media-12A906DF-9424-E94D-BFA7-884DB06CDC19  ONLINE       0     0     0
       media-C89B78EC-2A1D-DF4A-A6AD-0F052B4BBC89  ONLINE       0     0     0

errors: No known data errors

Code: Select all
zpool list
NAME        SIZE  ALLOC   FREE  CKPOINT  EXPANDSZ   FRAG    CAP  DEDUP    HEALTH  ALTROOT
mediapool  43.5T  24.0T  19.5T        -         -    15%    55%  1.00x    ONLINE  -


Code: Select all
ls -lh  /etc/zfs/
total 88
-rw-r--r--   1 root  wheel   165B  4 29 18:37 vdev_id.conf.alias.example
-rw-r--r--   1 root  wheel   166B  4 29 18:37 vdev_id.conf.multipath.example
-rw-r--r--   1 root  wheel   616B  4 29 18:37 vdev_id.conf.sas_direct.example
-rw-r--r--   1 root  wheel   152B  4 29 18:37 vdev_id.conf.sas_switch.example
-rw-r--r--   1 root  wheel   254B  4 29 18:37 vdev_id.conf.scsi.example
drwxr-xr-x  19 root  wheel   608B  4 29 20:28 zed.d
-rwxr-xr-x   1 root  wheel   9.6K  4 29 18:37 zfs-functions
-rw-r--r--   1 root  wheel   5.0K  5  2 17:49 zpool.cache
-rw-r--r--   1 root  wheel   1.1K  7  6  2015 zpool.cache.bak
drwxr-xr-x  44 root  wheel   1.4K  4 29 20:28 zpool.d


Code: Select all
 sysctl kstat.vmem.vmem | grep -E "bucket_[1-9]" | grep inuse
kstat.vmem.vmem.bucket_4096.mem_inuse: 0
kstat.vmem.vmem.bucket_8192.mem_inuse: 0
kstat.vmem.vmem.bucket_16384.mem_inuse: 0
kstat.vmem.vmem.bucket_32768.mem_inuse: 0
kstat.vmem.vmem.bucket_65536.mem_inuse: 0
kstat.vmem.vmem.bucket_131072.mem_inuse: 0
kstat.vmem.vmem.bucket_262144.mem_inuse: 0
kstat.vmem.vmem.bucket_524288.mem_inuse: 0
kstat.vmem.vmem.bucket_1048576.mem_inuse: 0
kstat.vmem.vmem.bucket_2097152.mem_inuse: 0
kstat.vmem.vmem.bucket_4194304.mem_inuse: 0
kstat.vmem.vmem.bucket_8388608.mem_inuse: 0
kstat.vmem.vmem.bucket_16777216.mem_inuse: 0


Code: Select all
 sudo zpool export -a
sudo kextunload -b org.openzfsonosx.zfs
uptime
18:34  up 46 mins, 9 users, load averages: 1.36 1.24 1.39

Code: Select all
 
top
Processes: 461 total, 2 running, 459 sleeping, 2111 threads                                                                                   18:36:02
Load Avg: 1.36, 1.23, 1.36  CPU usage: 1.36% user, 0.80% sys, 97.82% idle  SharedLibs: 458M resident, 81M data, 46M linkedit.
MemRegions: 116857 total, 4618M resident, 262M private, 2575M shared. PhysMem: 20G used (6047M wired), 44G unused.
VM: 2623G vsize, 2318M framework vsize, 0(0) swapins, 0(0) swapouts. Networks: packets: 611913/809M in, 164710/16M out.
Disks: 542391/14G read, 266366/9043M written.


Terminal Two
Code: Select all
sudo log stream --source --predicate 'sender == "zfs"' --style compact
### Edited to shorten log file ###
2021-05-02 18:31:41.663 Df kernel[0:ba36] (zfs) <zfs`org_openzfsonosx_zfs_zvol::stop(IOService*)> zfs_boot_fini no pool_list to clear
2021-05-02 18:31:41.663 Df kernel[0:ba36] (zfs) <zfs`org_openzfsonosx_zfs_zvol::stop(IOService*)> ZFS: Attempting to unload ...
2021-05-02 18:31:41.893 Df kernel[0:ba36] (zfs) <zfs`spl_tsd_fini> SPL: tsd unloading 0
2021-05-02 18:31:41.908 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_128' (0xffffffc20001a040) not empty
2021-05-02 18:31:41.910 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_160' (0xffffffc20001b040) not empty
2021-05-02 18:31:41.912 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_192' (0xffffffc20001c040) not empty
2021-05-02 18:31:41.913 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_224' (0xffffffc20001d040) not empty
2021-05-02 18:31:41.913 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_256' (0xffffffc20001e040) not empty
2021-05-02 18:31:41.913 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_320' (0xffffffc20001f040) not empty
2021-05-02 18:31:41.913 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_384' (0xffffffc200020040) not empty
2021-05-02 18:31:41.926 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_40960' (0xffffffc200036040) not empty
2021-05-02 18:31:41.955 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_va_4096' (0xffffffc20000c040) not empty
2021-05-02 18:31:42.004 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_bufctl_cache' (0xffffffc20000a040) not empty
2021-05-02 18:31:42.055 Df kernel[0:ba36] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_slab_cache' (0xffffffc200009040) not empty
2021-05-02 18:31:42.056 Df kernel[0:ba36] (zfs) <zfs`spl_kmem_fini> SPL: Released 577 slabs
2021-05-02 18:31:42.056 Df kernel[0:ba36] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_default'): leaked 136093696 bytes
2021-05-02 18:31:42.058 Df kernel[0:ba36] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_va'): leaked 150863872 bytes
2021-05-02 18:31:42.059 Df kernel[0:ba36] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_msb'): leaked 6426624 bytes
2021-05-02 18:31:42.059 Df kernel[0:ba36] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_metadata'): leaked 6426624 bytes
2021-05-02 18:31:42.061 Df kernel[0:ba36] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('heap'): leaked 166428672 bytes
### Edited to shorten log file ###

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Sun May 02, 2021 2:32 am
by lundman
Here is an installer for memleak of size 24 (<32). Can only monitor one size at a time due to how expensive it is.. Don't want to run it for too long :)

OpenZFSonOsX-2.0.0-Big.Sur-11-memleak24.pkg
(14.87 MiB) Downloaded 295 times

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Sun May 02, 2021 5:54 am
by Jimbo
Thanks @lundman. I've grabbed a copy and will try to do some testing between work things tomorrow.

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Sun May 02, 2021 4:11 pm
by Jimbo
Ok, colour me a touch confused.

Code: Select all
% zfs version
zfs-2.0.0-rc6
zfs-kmod-macos-2.0.0-rc6-3-gbd2d850a38-dirty


However I get no output when running
Code: Select all
% sudo log stream --source --predicate 'sender == "zfs"' --style compact
and I end up with:
Code: Select all
% sudo zpool export -a                   
Volume Tester on disk3s1 unmounted
% sudo kextunload -b org.openzfsonosx.zfs
Executing: /usr/bin/kmutil unload -b org.openzfsonosx.zfs
Error Domain=KMErrorDomain Code=71 "Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)" UserInfo={NSLocalizedDescription=Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)}
% sudo zpool export -a                   
The ZFS modules are not loaded.
Try running '/sbin/kextload zfs.kext' as root to load them.


Am I missing somthing here?

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Sun May 02, 2021 9:35 pm
by lundman
Uh huh that is.. new.. and yet you managed to unload them before..

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Sun May 02, 2021 9:54 pm
by Jimbo
I did indeed manage to unload them before. Despite the error, they still seemed to unload though...

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Mon May 03, 2021 2:37 am
by Jimbo
Ok, this might be more helpful. I was trying to reproduce on my test machine (old MBP BS 11.3, i7, 16Gb and pool of 1 SSD)... that wasn't working.

Installing and running on the Mac Mini with all the pools... export -a and unload produces:

Code: Select all
% sudo log stream --source --predicate 'sender == "zfs"' --style compact                   
Filtering the log data using "sender == "zfs""
Timestamp               Ty Process[PID:TID]
2021-05-03 18:25:49.587 Df kernel[0:a18] (zfs) <zfs`zvolRemoveDeviceTerminate> zvolRemoveDeviceTerminate
2021-05-03 18:25:49.587 Df kernel[0:2430] (zfs) <zfs`__dprintf> spa_history.c:295:spa_history_log_sync(): command: zpool export -a
2021-05-03 18:25:49.893 Df kernel[0:d5fc] (zfs) <zfs`__dprintf> spa_misc.c:413:spa_load_note(): spa_load(Reservoir, config trusted): UNLOADING
2021-05-03 18:25:50.431 Df kernel[0:d5fc] (zfs) <zfs`__dprintf> mmp.c:261:mmp_thread_stop(): MMP thread stopped pool 'Reservoir' gethrtime 8080885106172
2021-05-03 18:25:51.769 Df kernel[0:d72e] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848324, spa Tank, vdev_id 1, ms_id 4, smp_length 1168, unflushed_allocs 0, unflushed_frees 36864, freed 0, defer 0 + 0, unloaded time 7145924 ms, loading_time 7 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:51.843 Df kernel[0:17eb] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 97, smp_length 329568, unflushed_allocs 974848, unflushed_frees 598016, freed 0, defer 0 + 0, unloaded time 7155960 ms, loading_time 47 ms, ms_max_size 143491096576, max size error 0, old_weight 940000000000001, new_weight 940000000000001
2021-05-03 18:25:51.872 Df kernel[0:17eb] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 156, smp_length 356272, unflushed_allocs 819200, unflushed_frees 491520, freed 0, defer 0 + 0, unloaded time 7156007 ms, loading_time 28 ms, ms_max_size 264625053696, max size error 0, old_weight 940000000000001, new_weight 940000000000001
2021-05-03 18:25:51.965 Df kernel[0:17ed] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 34, smp_length 146368, unflushed_allocs 1048576, unflushed_frees 1409024, freed 0, defer 0 + 0, unloaded time 7156035 ms, loading_time 92 ms, ms_max_size 94973902848, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.018 Df kernel[0:17ed] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 73, smp_length 201472, unflushed_allocs 933888, unflushed_frees 1302528, freed 0, defer 0 + 0, unloaded time 7156128 ms, loading_time 53 ms, ms_max_size 89496043520, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.067 Df kernel[0:17e9] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 74, smp_length 253736, unflushed_allocs 450560, unflushed_frees 958464, freed 0, defer 0 + 0, unloaded time 7156182 ms, loading_time 49 ms, ms_max_size 73616801792, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.116 Df kernel[0:17e9] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 129, smp_length 377080, unflushed_allocs 360448, unflushed_frees 786432, freed 0, defer 0 + 0, unloaded time 7156231 ms, loading_time 48 ms, ms_max_size 113743347712, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.158 Df kernel[0:17f2] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 130, smp_length 234168, unflushed_allocs 770048, unflushed_frees 794624, freed 0, defer 0 + 0, unloaded time 7156280 ms, loading_time 41 ms, ms_max_size 100032675840, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.206 Df kernel[0:17f2] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 134, smp_length 295904, unflushed_allocs 753664, unflushed_frees 802816, freed 0, defer 0 + 0, unloaded time 7156322 ms, loading_time 47 ms, ms_max_size 99930693632, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.283 Df kernel[0:17f2] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848325, spa Tank, vdev_id 0, ms_id 137, smp_length 181464, unflushed_allocs 1204224, unflushed_frees 1703936, freed 0, defer 0 + 0, unloaded time 7146389 ms, loading_time 56 ms, ms_max_size 72216068096, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.525 Df kernel[0:d73d] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 15, smp_length 304, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 18 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.532 Df kernel[0:d73c] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 14, smp_length 512, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 24 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.534 Df kernel[0:d73b] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 13, smp_length 1216, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 27 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.558 Df kernel[0:d73e] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 16, smp_length 176, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 50 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.596 Df kernel[0:d738] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 10, smp_length 1008, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 89 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.606 Df kernel[0:d736] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 7, smp_length 8248, unflushed_allocs 0, unflushed_frees 36864, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 99 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.608 Df kernel[0:d739] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 11, smp_length 5704, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 101 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.613 Df kernel[0:d73a] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 12, smp_length 5408, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 106 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.627 Df kernel[0:d744] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 0, ms_id 83, smp_length 103872, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 119 ms, ms_max_size 43039686656, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.628 Df kernel[0:d740] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 0, ms_id 166, smp_length 44624, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 121 ms, ms_max_size 78787289088, max size error 0, old_weight 900000000000001, new_weight 900000000000001
2021-05-03 18:25:52.638 Df kernel[0:d737] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 9, smp_length 5936, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146669 ms, loading_time 131 ms, ms_max_size 1073741824, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.642 Df kernel[0:d735] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848326, spa Tank, vdev_id 1, ms_id 6, smp_length 11544, unflushed_allocs 0, unflushed_frees 114688, freed 0, defer 0 + 4096, unloaded time 8082960 ms, loading_time 135 ms, ms_max_size 1073737728, max size error 1073700864, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:52.676 Df kernel[0:d743] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848327, spa Tank, vdev_id 0, ms_id 80, smp_length 76616, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 168 ms, ms_max_size 58880475136, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.679 Df kernel[0:d746] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848327, spa Tank, vdev_id 0, ms_id 96, smp_length 146408, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 172 ms, ms_max_size 51135430656, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.699 Df kernel[0:d747] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848328, spa Tank, vdev_id 0, ms_id 119, smp_length 103064, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 191 ms, ms_max_size 61893894144, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.701 Df kernel[0:d741] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848328, spa Tank, vdev_id 0, ms_id 27, smp_length 75992, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 193 ms, ms_max_size 34660106240, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.717 Df kernel[0:d742] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848328, spa Tank, vdev_id 0, ms_id 45, smp_length 37472, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 210 ms, ms_max_size 53390467072, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.728 Df kernel[0:d73f] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848328, spa Tank, vdev_id 0, ms_id 69, smp_length 69920, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 220 ms, ms_max_size 48260825088, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:52.739 Df kernel[0:d745] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848328, spa Tank, vdev_id 0, ms_id 111, smp_length 58960, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 7146670 ms, loading_time 231 ms, ms_max_size 65315192832, max size error 0, old_weight 8c0000000000002, new_weight 8c0000000000002
2021-05-03 18:25:53.415 Df kernel[0:d73e] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848329, spa Tank, vdev_id 1, ms_id 17, smp_length 96, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 8083869 ms, loading_time 0 ms, ms_max_size 1073741824, max size error 1073741824, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:54.204 Df kernel[0:d735] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848334, spa Tank, vdev_id 1, ms_id 5, smp_length 14408, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 36864, unloaded time 7213340 ms, loading_time 39 ms, ms_max_size 1073496064, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:54.961 Df kernel[0:d73c] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848338, spa Tank, vdev_id 1, ms_id 0, smp_length 776, unflushed_allocs 0, unflushed_frees 8192, freed 0, defer 0 + 4096, unloaded time 8085393 ms, loading_time 21 ms, ms_max_size 1073733632, max size error 1073729536, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:56.353 Df kernel[0:d736] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848346, spa Tank, vdev_id 1, ms_id 8, smp_length 8968, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 36864, unloaded time 7160453 ms, loading_time 63 ms, ms_max_size 1073496064, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:57.035 Df kernel[0:d77a] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848350, spa Tank, vdev_id 1, ms_id 1, smp_length 3512, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 4096, unloaded time 8087469 ms, loading_time 20 ms, ms_max_size 1073725440, max size error 1073725440, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:57.814 Df kernel[0:d736] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848354, spa Tank, vdev_id 1, ms_id 2, smp_length 9768, unflushed_allocs 0, unflushed_frees 69632, freed 0, defer 0 + 36864, unloaded time 7161953 ms, loading_time 23 ms, ms_max_size 1073496064, max size error 0, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:59.194 Df kernel[0:d73b] (zfs) <zfs`__dprintf> metaslab.c:2466:metaslab_load_impl(): metaslab_load: txg 24848362, spa Tank, vdev_id 1, ms_id 3, smp_length 8608, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 36864, unloaded time 7163318 ms, loading_time 39 ms, ms_max_size 1073491968, max size error 503808, old_weight 780000000000001, new_weight 780000000000001
2021-05-03 18:25:59.612 Df kernel[0:1d18] (zfs) <zfs`__dprintf> spa_history.c:295:spa_history_log_sync(): command: zpool export -a
2021-05-03 18:26:09.858 Df kernel[0:d5fc] (zfs) <zfs`__dprintf> spa_misc.c:413:spa_load_note(): spa_load(Tank, config trusted): UNLOADING
2021-05-03 18:26:10.437 Df kernel[0:d5fc] (zfs) <zfs`__dprintf> mmp.c:261:mmp_thread_stop(): MMP thread stopped pool 'Tank' gethrtime 8100891018153
2021-05-03 18:26:22.282 Df kernel[0:d897] (zfs) <zfs`org_openzfsonosx_zfs_zvol::stop(IOService*)> zfs_boot_fini no pool_list to clear
2021-05-03 18:26:22.282 Df kernel[0:d897] (zfs) <zfs`org_openzfsonosx_zfs_zvol::stop(IOService*)> ZFS: Attempting to unload ...
2021-05-03 18:26:24.764 Df kernel[0:d897] (zfs) <zfs`spl_tsd_fini> SPL: tsd unloading 0
2021-05-03 18:26:24.764 Df kernel[0:d897] (zfs) <zfs`spl_kmem_fini> SPL: Leaks, numnodes 0
2021-05-03 18:26:24.764 Df kernel[0:d897] (zfs) <zfs`spl_kmem_fini> SPL: End of leaks (if any)
2021-05-03 18:26:24.767 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_24' (0xffffffc180011040) not empty
2021-05-03 18:26:25.370 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_128' (0xffffffc18001a040) not empty
2021-05-03 18:26:25.371 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_160' (0xffffffc18001b040) not empty
2021-05-03 18:26:25.374 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_192' (0xffffffc18001c040) not empty
2021-05-03 18:26:25.374 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_224' (0xffffffc18001d040) not empty
2021-05-03 18:26:25.374 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_256' (0xffffffc18001e040) not empty
2021-05-03 18:26:25.376 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_320' (0xffffffc18001f040) not empty
2021-05-03 18:26:25.376 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_384' (0xffffffc180020040) not empty
2021-05-03 18:26:25.403 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_40960' (0xffffffc180036040) not empty
2021-05-03 18:26:26.850 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_va_4096' (0xffffffc18000c040) not empty
2021-05-03 18:26:27.580 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_bufctl_cache' (0xffffffc18000a040) not empty
2021-05-03 18:26:28.268 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_slab_cache' (0xffffffc180009040) not empty
2021-05-03 18:26:28.281 Df kernel[0:d897] (zfs) <zfs`spl_kmem_fini> SPL: Released 2242 slabs
2021-05-03 18:26:28.281 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_default'): leaked 3802112000 bytes
2021-05-03 18:26:28.318 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_va'): leaked 3871948800 bytes
2021-05-03 18:26:28.351 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_msb'): leaked 163495936 bytes
2021-05-03 18:26:28.363 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('kmem_metadata'): leaked 163495936 bytes
2021-05-03 18:26:28.421 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('heap'): leaked 4234330112 bytes
2021-05-03 18:26:28.480 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: vmem_fini: walking spl_heap_arena, aka bucket_heap (pass 2)
2021-05-03 18:26:28.500 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: vmem_fini: walking bucket arenas...
2021-05-03 18:26:28.533 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('bucket_32768'): leaked 391806976 bytes
2021-05-03 18:26:28.538 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('bucket_65536'): leaked 3307847680 bytes
2021-05-03 18:26:28.557 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: vmem_fini: walking vmem metadata-related arenas...
2021-05-03 18:26:28.566 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('bucket_heap'): leaked 4234330112 bytes
2021-05-03 18:26:28.604 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('vmem_seg'): leaked 358727680 bytes
2021-05-03 18:26:28.611 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('vmem_hash'): leaked 196608 bytes
2021-05-03 18:26:28.611 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('vmem_metadata'): leaked 358924288 bytes
2021-05-03 18:26:28.617 Df kernel[0:d897] (zfs) <zfs`vmem_destroy> SPL: vmem_destroy('spl_default_arena'): leaked 358973440 bytes
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_destroy_internal> SPL: vmem_destroy('vmem_vmem'): leaked 7680 bytes
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_destroy_internal> SPL: vmem_destroy('vmem_vmem'): STILL 7680 bytes at kstat_delete() time
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: arenas removed, now try destroying mutexes...
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_xnu_alloc_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_panic_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_pushpage_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_nosleep_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_sleep_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_segfree_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> vmem_list_lock
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini>
SPL: vmem_fini: walking list of live slabs at time of call to vmem_fini
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: WOULD HAVE released 0 bytes (0 spans) from arenas
2021-05-03 18:26:28.619 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: vmem_fini: Brief delay for readability...
2021-05-03 18:26:29.611 Df kernel[0:d897] (zfs) <zfs`vmem_fini> SPL: vmem_fini: done!
2021-05-03 18:26:29.611 Df kernel[0:d897] (zfs) <zfs`spl_mutex_subsystem_fini> Dumping leaked mutex allocations...
2021-05-03 18:26:29.611 Df kernel[0:d897] (zfs) <zfs`spl_mutex_subsystem_fini> Dumped 0 leaked allocations. Wait for watchdog to exit..
2021-05-03 18:26:32.061 Df kernel[0:9b6] (zfs) <zfs`spl_wdlist_check> SPL: watchdog thread exit
2021-05-03 18:26:32.061 Df kernel[0:d897] (zfs) <zfs`org_openzfsonosx_zfs_zvol::stop(IOService*)> ZFS: Unloaded module v2.0.0-rc6


Next?

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Mon May 03, 2021 3:23 am
by dereed999
lundman wrote:Did you say your macOS version? BigSur? I'll build a memleak test size == 24 first, run for a bit, then do the unload and it should say where it is leaked from.

BigSur 11.3 (intel). Thank you!

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Tue May 04, 2021 3:46 pm
by lundman
Code: Select all
2021-05-03 18:26:24.764 Df kernel[0:d897] (zfs) <zfs`spl_kmem_fini> SPL: Leaks, numnodes 0
2021-05-03 18:26:24.764 Df kernel[0:d897] (zfs) <zfs`spl_kmem_fini> SPL: End of leaks (if any)
2021-05-03 18:26:24.767 Df kernel[0:d897] (zfs) <zfs`vcmn_err> SPL: Warning: kmem_cache_destroy: 'kmem_alloc_24' (0xffffffc180011040) not empty


Yeah run the memleak24 posted above, and that should print some leak nodes (instead of numnodes 0), and the exact place they were found.

We are also tracking a problem with raidz, which is turning out to be really mischievous.
https://github.com/openzfsonosx/openzfs/issues/48

Re: macos-2.0.0-rc6 Memory Leak?

PostPosted: Tue May 04, 2021 6:09 pm
by dereed999
Oddly enough I can't do the kextunload anymore either. I receive the following error:
Code: Select all
bash-3.2# kextunload -b org.openzfsonosx.zfs
Executing: /usr/bin/kmutil unload -b org.openzfsonosx.zfs
Error Domain=KMErrorDomain Code=71 "Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)" UserInfo={NSLocalizedDescription=Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)}


Looking at a broader set of logs I see the following... I've tried rebooting multiple times and playing with how long the system is up before I export and unload but I consistently get the following error:
Code: Select all
2021-05-04 22:03:11.175 Df kernelmanagerd[92:27b4] <kernelmanagerd> incoming connection from pid 932
2021-05-04 22:03:11.175 Df kernelmanagerd[92:2978] [com.apple.kernelmanagerd.logging:UnloadRequest] <kernelmanagerd> unloadExtensions(withIdentifiers:withClassNames:options:withReply:): Unloading identifiers: ["org.openzfsonosx.zfs"], classNames: []
2021-05-04 22:03:11.178 Df kernel[0:2978] Can't unload kext org.openzfsonosx.zfs; classes have instances:
2021-05-04 22:03:11.178 Df kernel[0:2978]     Kext org.openzfsonosx.zfs class ZFSDataset has 1 instance.
2021-05-04 22:03:11.179 E  kernelmanagerd[92:2978] [com.apple.kernelmanagerd.logging:Kernel] <kernelmanagerd> (kernel): Can't unload kext org.openzfsonosx.zfs; classes have instances:
2021-05-04 22:03:11.179 E  kernelmanagerd[92:2978] [com.apple.kernelmanagerd.logging:Kernel] <kernelmanagerd> (kernel):     Kext org.openzfsonosx.zfs class ZFSDataset has 1 instance.
2021-05-04 22:03:11.179 E  kernelmanagerd[92:2978] <kernelmanagerd> failed to unload extensions: Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)
2021-05-04 22:03:11.179 E  kmutil[932:2975] (KernelManagement) <KernelManagement`__91-[KernelManagementClient unloadExtensionsWithIdentifiers:withClassNames:options:withError:]_block_invoke.22.cold.1> Remote encountered error: Error Domain=KMErrorDomain Code=71 "Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)" UserInfo={NSLocalizedDescription=Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)}
2021-05-04 22:03:11.180 E  kmutil[932:2975] <kmutil> kmutil encountered error (71): Error Domain=KMErrorDomain Code=71 "Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)" UserInfo={NSLocalizedDescription=Kernel request failed: (libkern/kext) kext is in use or retained (cannot unload) (-603946984)}


Yet, there are no ZFS pools imported.