I had the following message written and was previewing itwhen your lock collision post came in. I'll post this anyway, but without a doubt the lock collision makes sense. The threads are racing each other. In my examples below I can see that behavior. If I create volumes "slowly" all works well. It's only when volumes are created too fast via zfs create, or when a pool is imported, that things go wrong.
Original post was:
On Big Sur, doing an import of the 10G pool backed by the test file gives me a sysctl kstat.zfs.misc.dbgmsg.dbgmsg output of:
- Code: Select all
1605746859 spa.c:6157:spa_tryimport(): spa_tryimport: importing testPool
1605746859 spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADING
1605746859 vdev.c:129:vdev_dbgmsg(): file vdev '/Users/david/Desktop/testFile': best uberblock found for spa $import. txg 220
1605746859 spa_misc.c:411:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=220
1605746859 spa.c:8207:spa_async_request(): spa=$import async request task=2048
1605746859 spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADED
1605746859 spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): UNLOADING
1605746859 spa.c:6005:spa_import(): spa_import: importing testPool
1605746859 spa_misc.c:411:spa_load_note(): spa_load(testPool, config trusted): LOADING
1605746859 vdev.c:129:vdev_dbgmsg(): file vdev '/Users/david/Desktop/testFile': best uberblock found for spa testPool. txg 220
1605746859 spa_misc.c:411:spa_load_note(): spa_load(testPool, config untrusted): using uberblock with txg=220
1605746859 spa_misc.c:411:spa_load_note(): spa_load(testPool, config trusted): read 0 log space maps (0 total blocks - blksz = 131072 bytes) in 0 ms
1605746859 mmp.c:241:mmp_thread_start(): MMP thread started pool 'testPool' gethrtime 28761154305876
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 8, smp_length 1328, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761154 ms, loading_time 0 ms, ms_max_size 536870912, max size error 536870912, old_weight 740000000000001, new_weight 740000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 9, smp_length 600, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761154 ms, loading_time 0 ms, ms_max_size 536870912, max size error 536870912, old_weight 740000000000001, new_weight 740000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 10, smp_length 1000, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761155 ms, loading_time 0 ms, ms_max_size 536870912, max size error 536870912, old_weight 740000000000001, new_weight 740000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 11, smp_length 1000, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761155 ms, loading_time 0 ms, ms_max_size 536870912, max size error 536870912, old_weight 740000000000001, new_weight 740000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 0, smp_length 6336, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761155 ms, loading_time 0 ms, ms_max_size 535205376, max size error 535205376, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 1, smp_length 6464, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761155 ms, loading_time 0 ms, ms_max_size 482712064, max size error 482712064, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 221, spa testPool, vdev_id 0, ms_id 2, smp_length 4656, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761155 ms, loading_time 0 ms, ms_max_size 536675840, max size error 536675840, old_weight 700000000000001, new_weight 700000000000001
1605746859 spa.c:8207:spa_async_request(): spa=testPool async request task=1
1605746859 spa.c:8207:spa_async_request(): spa=testPool async request task=2048
1605746859 spa_misc.c:411:spa_load_note(): spa_load(testPool, config trusted): LOADED
1605746859 spa_history.c:309:spa_history_log_sync(): txg 222 open pool version 5000; software version zfs-2.0.0-rc1-250-g4cf230eb65-dirty; uts Davids-MacBook-Pro-2019.local 20.1.0 Darwin Kernel Version 20.1.0: Sat Oct 31 00:07:11 PDT 2020; root:xnu-7195.50.7~2/RELEASE_X86_64
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 5, smp_length 3488, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 512, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 536602112, max size error 536602112, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 13, smp_length 1984, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 6656 + 4608, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 533750784, max size error 533750784, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 15, smp_length 1864, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 6656 + 4608, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 536765952, max size error 536765952, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 14, smp_length 896, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 533125632, max size error 533125632, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 12, smp_length 928, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 534445568, max size error 534445568, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 7, smp_length 2512, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 536822784, max size error 536822784, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 4, smp_length 4360, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 512, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 529208832, max size error 529208832, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 3, smp_length 5344, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 6144 + 8192, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 536177152, max size error 536177152, old_weight 700000000000001, new_weight 700000000000001
1605746859 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 222, spa testPool, vdev_id 0, ms_id 6, smp_length 5024, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 23552 + 22528, unloaded time 28761173 ms, loading_time 0 ms, ms_max_size 432152576, max size error 432152576, old_weight 700000000000001, new_weight 700000000000001
1605746859 spa.c:8207:spa_async_request(): spa=testPool async request task=32
1605746859 spa_history.c:309:spa_history_log_sync(): txg 224 import pool version 5000; software version zfs-2.0.0-rc1-250-g4cf230eb65-dirty; uts Davids-MacBook-Pro-2019.local 20.1.0 Darwin Kernel Version 20.1.0: Sat Oct 31 00:07:11 PDT 2020; root:xnu-7195.50.7~2/RELEASE_X86_64
1605746874 spa_history.c:296:spa_history_log_sync(): command: zpool import -d /Users/david/Desktop testPool
1605746874 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 228, spa testPool, vdev_id 0, ms_id 16, smp_length 1064, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28776106 ms, loading_time 0 ms, ms_max_size 532796416, max size error 532796416, old_weight 700000000000001, new_weight 700000000000001
1605746874 metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 228, spa testPool, vdev_id 0, ms_id 17, smp_length 928, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 28776106 ms, loading_time 0 ms, ms_max_size 536758272, max size error 536758272, old_weight 700000000000001, new_weight 700000000000001
Grabbing the the one disk showing without a partition table has a blank "Content" key section and lacks any children entries for partitions vs. the disk that shows the partition table which has "GUID_partition_scheme" and shows a chunk of content related to disk4s1.
Okay, here's what's really weird. On Big Sur if I create the 10G file and pool backed by that file from scratch and then create one volume and
wait several seconds for it to appear in diskutil's output, I can format it. I can then repeat that create, wait, format cycle and all is well. So I end up with:
- Code: Select all
/dev/disk2 (internal, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +10.2 GB disk2
1: ZFS Dataset testPool-ALT2 10.2 GB disk2s1
/dev/disk3 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +1.1 GB disk3
1: Apple_HFS Alt-Vol1 1.1 GB disk3s1
/dev/disk4 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +1.1 GB disk4
1: Apple_HFS Alt-Vol2 1.1 GB disk4s1
/dev/disk5 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +1.1 GB disk5
1: Apple_HFS Alt-Vol3 1.1 GB disk5s1
Great.
But now for what's really odd.
If I export the pool and re-import it I get:- Code: Select all
/dev/disk2 (internal, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +10.2 GB disk2
1: ZFS Dataset testPool-ALT2 10.2 GB disk2s1
/dev/disk3 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk3
/dev/disk4 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +1.1 GB disk4
1: Apple_HFS Alt-Vol1 1.1 GB disk4s1
And even more strange... if I wipe the file and start again but this time "quickly" create the 3 volumes in a row (zfs create -V 1G testPool-ALT2/vol1, hit enter, up arrow, replace the 1 with a 2, hit enter, and do the same for vol3) - basically creating them as fast as the command line lets me do it I end up with the 3rd one never showing up. It exists in zfs list, but never attaches as a /dev/disk entry.
- Code: Select all
bash-3.2# diskutil list
/dev/disk2 (internal, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +10.2 GB disk2
1: ZFS Dataset testPool-ALT2 10.2 GB disk2s1
/dev/disk3 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk3
/dev/disk4 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk4
I can do a "diskutil partitionDisk disk4 GPT jhfs+ Alt-VolB 0" on the two disks that show up and it works great for those two disks (volumes.)
- Code: Select all
bash-3.2# diskutil list
/dev/disk2 (internal, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +10.2 GB disk2
1: ZFS Dataset testPool-ALT2 10.2 GB disk2s1
/dev/disk3 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +1.1 GB disk3
1: Apple_HFS Alt-Vol3 1.1 GB disk3s1
/dev/disk4 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +1.1 GB disk4
1: Apple_HFS Alt-Vol3 1.1 GB disk4s1
But, it all falls apart when I export and re-import... and I get *all three* disks (volumes) showing, but none have partition tables.
- Code: Select all
/dev/disk2 (internal, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +10.2 GB disk2
1: ZFS Dataset testPool-ALT2 10.2 GB disk2s1
/dev/disk3 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk3
/dev/disk4 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk4
/dev/disk5 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk5
Two other interesting tidbits:
- When I'm creating the zfs volumes "as fast as I can" the first "zfs create" returns "instantly"... the subsequent ones all take a few seconds before the command prompt comes back
- If I pause and wait a minute after quickly creating 3 volumes I can create a 4th volume... and that 4th one will show in the diskutil list output. (I know it's the 4th because I changed the size of the volume from 1G to 1.2G)
Note how one volume is still missing. (The last of the "quickly created" ones)
- Code: Select all
bash-3.2# diskutil list
/dev/disk2 (internal, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: GUID_partition_scheme +10.2 GB disk2
1: ZFS Dataset testPool-ALT2 10.2 GB disk2s1
/dev/disk3 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk3
/dev/disk4 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.1 GB disk4
/dev/disk5 (external, virtual):
#: TYPE NAME SIZE IDENTIFIER
0: +1.3 GB disk5