metaslab_load/spa_load errors at startup on all my pools

S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
Hello,

I noticed I am getting a set of metaslab_load message + other related to it.
I found a couple of things related to these messages, but they are always associated with failures or error messages.

For two drives, I haven't done anything beyond creating empty pools. For the last one, it's picked up by the OS and I didn't manage it after creating the pool.
All drives are new, all from different brands.

I have three drives for which I created pools through the GUI: 1 SSD that I currently use for logs + swap (LOG_SWAP_POOL) and 2 8TB (1 WD, 1ST) that I want to mirror in a separate pool (ARCHIVE_POOL).
To see if the issue was related to the pool, I did a version with 3 pools (LOG_SWAP_POOL (unchanged), POOL_0, POOL_D1)
I got the issue on both configurations (the LOG_SWAP_POOL is the same on each run).

I tried to reproduce the issue in a VM with two files acting as drives and I cannot see the errors, which makes me wonder (and worry...).
I will try tomorrow with the current drives on SATA on my VM (so I can check if that's the drives or the hardware surrounding it).

Any idea? And should I worry?
I will follow up tomorrow with my actual drives on SATA in a VM.

Log for LOG_SWAP_POOL + ARCHIVE_POOL
Code:
Mar 28 01:05:20 bob Beginning pools import
Mar 28 01:05:20 bob Importing LOG_SWAP_POOL
Mar 28 01:05:20 bob Importing ARCHIVE_POOL
Mar 28 01:05:20 bob mmp.c:241:mmp_thread_start(): MMP thread started pool 'LOG_SWAP_POOL' gethrtime 37403720605
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 12, smp_length 4392, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 0, unloaded time 37403 ms, loading_time 0 ms, ms_max_size 536870912, max si
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 14, smp_length 2904, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37404 ms, loading_time 0 ms, ms_max_size 536870912, max size
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 16, smp_length 3096, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37404 ms, loading_time 0 ms, ms_max_size 536870912, max size
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 20, smp_length 2056, unflushed_allocs 0, unflushed_frees 12288, freed 0, defer 0 + 0, unloaded time 37404 ms, loading_time 0 ms, ms_max_size 536870912, max s
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 21, smp_length 1632, unflushed_allocs 0, unflushed_frees 12288, freed 0, defer 0 + 0, unloaded time 37405 ms, loading_time 0 ms, ms_max_size 536870912, max s
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 36, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37405 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 37, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37405 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 38, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37406 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1325, spa LOG_SWAP_POOL, vdev_id 0, ms_id 39, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37406 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=LOG_SWAP_POOL async request task=1
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=LOG_SWAP_POOL async request task=2048
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load(LOG_SWAP_POOL, config trusted): LOADED
Mar 28 01:05:20 bob spa_history.c:309:spa_history_log_sync(): txg 1326 open pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1326, spa LOG_SWAP_POOL, vdev_id 0, ms_id 40, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1326, spa LOG_SWAP_POOL, vdev_id 0, ms_id 41, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1326, spa LOG_SWAP_POOL, vdev_id 0, ms_id 42, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1326, spa LOG_SWAP_POOL, vdev_id 0, ms_id 43, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1326, spa LOG_SWAP_POOL, vdev_id 0, ms_id 44, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1327, spa LOG_SWAP_POOL, vdev_id 0, ms_id 45, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1327, spa LOG_SWAP_POOL, vdev_id 0, ms_id 46, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1327, spa LOG_SWAP_POOL, vdev_id 0, ms_id 47, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 1327, spa LOG_SWAP_POOL, vdev_id 0, ms_id 48, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37434 ms, loading_time 0 ms, ms_max_size 536870912, max size err
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=LOG_SWAP_POOL async request task=32
Mar 28 01:05:20 bob spa_history.c:309:spa_history_log_sync(): txg 1328 import pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 01:05:20 bob spa.c:6138:spa_tryimport(): spa_tryimport: importing ARCHIVE_POOL
Mar 28 01:05:20 bob spa.c:6143:spa_tryimport(): spa_tryimport: using cachefile '/data/zfs/zpool.cache.saved'
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADING
Mar 28 01:05:20 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/d58b9551-8f58-11eb-80ce-00fd45fc0de0': best uberblock found for spa $import. txg 8
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=8
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=$import async request task=2048
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADED
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): UNLOADING
Mar 28 01:05:20 bob spa.c:5990:spa_import(): spa_import: importing ARCHIVE_POOL
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load(ARCHIVE_POOL, config trusted): LOADING
Mar 28 01:05:20 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/d58b9551-8f58-11eb-80ce-00fd45fc0de0': best uberblock found for spa ARCHIVE_POOL. txg 8
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load(ARCHIVE_POOL, config untrusted): using uberblock with txg=8
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load(ARCHIVE_POOL, config trusted): read 4 log space maps (4 total blocks - blksz = 131072 bytes) in 0 ms
Mar 28 01:05:20 bob mmp.c:241:mmp_thread_start(): MMP thread started pool 'ARCHIVE_POOL' gethrtime 38396908783
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=ARCHIVE_POOL async request task=1
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=ARCHIVE_POOL async request task=2048
Mar 28 01:05:20 bob spa_misc.c:411:spa_load_note(): spa_load(ARCHIVE_POOL, config trusted): LOADED
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 9, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size error
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 10, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 11, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 12, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 13, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 14, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 15, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 16, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 17, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38397 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob spa_history.c:309:spa_history_log_sync(): txg 10 open pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 18, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38583 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 19, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38583 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 20, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38583 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 21, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38583 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 22, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38584 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 23, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38584 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 24, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38584 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa ARCHIVE_POOL, vdev_id 0, ms_id 25, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38584 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa ARCHIVE_POOL, vdev_id 0, ms_id 26, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38584 ms, loading_time 0 ms, ms_max_size 17179869184, max size erro
Mar 28 01:05:20 bob spa.c:8187:spa_async_request(): spa=ARCHIVE_POOL async request task=32
Mar 28 01:05:20 bob spa_history.c:309:spa_history_log_sync(): txg 12 import pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 01:05:20 bob Pools import completed
 
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
Logs made me go over the max character per post o_O

LOG_SWAP_POOL + POOL_0 + POOL_D1
Code:
Mar 28 00:21:49 bob Beginning pools import
Mar 28 00:21:49 bob Importing LOG_SWAP_POOL
Mar 28 00:21:49 bob Importing POOL_0
Mar 28 00:21:49 bob mmp.c:241:mmp_thread_start(): MMP thread started pool 'LOG_SWAP_POOL' gethrtime 37466305750
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 27, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 28, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 29, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 30, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 31, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 32, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 33, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37466 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 34, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37467 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 834, spa LOG_SWAP_POOL, vdev_id 0, ms_id 35, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37467 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=LOG_SWAP_POOL async request task=1
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=LOG_SWAP_POOL async request task=2048
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(LOG_SWAP_POOL, config trusted): LOADED
Mar 28 00:21:49 bob spa_history.c:309:spa_history_log_sync(): txg 835 open pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 835, spa LOG_SWAP_POOL, vdev_id 0, ms_id 36, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 835, spa LOG_SWAP_POOL, vdev_id 0, ms_id 37, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 835, spa LOG_SWAP_POOL, vdev_id 0, ms_id 38, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 835, spa LOG_SWAP_POOL, vdev_id 0, ms_id 39, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 835, spa LOG_SWAP_POOL, vdev_id 0, ms_id 40, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 836, spa LOG_SWAP_POOL, vdev_id 0, ms_id 41, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 836, spa LOG_SWAP_POOL, vdev_id 0, ms_id 42, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 836, spa LOG_SWAP_POOL, vdev_id 0, ms_id 43, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 836, spa LOG_SWAP_POOL, vdev_id 0, ms_id 44, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 37494 ms, loading_time 0 ms, ms_max_size 536870912, max size erro
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=LOG_SWAP_POOL async request task=32
Mar 28 00:21:49 bob spa_history.c:309:spa_history_log_sync(): txg 837 import pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 00:21:49 bob spa.c:6138:spa_tryimport(): spa_tryimport: importing POOL_0
Mar 28 00:21:49 bob spa.c:6143:spa_tryimport(): spa_tryimport: using cachefile '/data/zfs/zpool.cache.saved'
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADING
Mar 28 00:21:49 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/89a74a9a-8f52-11eb-92cb-00fd45fc0de0': best uberblock found for spa $import. txg 8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=8
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=$import async request task=2048
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADED
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): UNLOADING
Mar 28 00:21:49 bob spa.c:6138:spa_tryimport(): spa_tryimport: importing POOL_D1
Mar 28 00:21:49 bob spa.c:6143:spa_tryimport(): spa_tryimport: using cachefile '/data/zfs/zpool.cache.saved'
Mar 28 00:21:49 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/9547f89a-8f52-11eb-92cb-00fd45fc0de0': best uberblock found for spa $import. txg 8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADING
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=$import async request task=2048
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADED
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): UNLOADING
Mar 28 00:21:49 bob spa.c:5990:spa_import(): spa_import: importing POOL_0
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_0, config trusted): LOADING
Mar 28 00:21:49 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/89a74a9a-8f52-11eb-92cb-00fd45fc0de0': best uberblock found for spa POOL_0. txg 8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_0, config untrusted): using uberblock with txg=8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_0, config trusted): read 4 log space maps (4 total blocks - blksz = 131072 bytes) in 25 ms
Mar 28 00:21:49 bob mmp.c:241:mmp_thread_start(): MMP thread started pool 'POOL_0' gethrtime 38493785876
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=POOL_0 async request task=1
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=POOL_0 async request task=2048
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_0, config trusted): LOADED
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 9, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 17179
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 10, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 11, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 12, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 13, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 14, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 15, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 16, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 17, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38494 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob spa_history.c:309:spa_history_log_sync(): txg 10 open pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 18, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 19, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 20, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_0, vdev_id 0, ms_id 21, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_0, vdev_id 0, ms_id 22, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_0, vdev_id 0, ms_id 23, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_0, vdev_id 0, ms_id 24, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_0, vdev_id 0, ms_id 25, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_0, vdev_id 0, ms_id 26, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 38683 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=POOL_0 async request task=32
Mar 28 00:21:49 bob spa_history.c:309:spa_history_log_sync(): txg 12 import pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 00:21:49 bob Importing POOL_D1
Mar 28 00:21:49 bob spa.c:6138:spa_tryimport(): spa_tryimport: importing POOL_D1
Mar 28 00:21:49 bob spa.c:6143:spa_tryimport(): spa_tryimport: using cachefile '/data/zfs/zpool.cache.saved'
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADING
Mar 28 00:21:49 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/9547f89a-8f52-11eb-92cb-00fd45fc0de0': best uberblock found for spa $import. txg 8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=8
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=$import async request task=2048
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): LOADED
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load($import, config trusted): UNLOADING
Mar 28 00:21:49 bob spa.c:5990:spa_import(): spa_import: importing POOL_D1
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_D1, config trusted): LOADING
Mar 28 00:21:49 bob vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/9547f89a-8f52-11eb-92cb-00fd45fc0de0': best uberblock found for spa POOL_D1. txg 8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_D1, config untrusted): using uberblock with txg=8
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_D1, config trusted): read 4 log space maps (4 total blocks - blksz = 131072 bytes) in 23 ms
Mar 28 00:21:49 bob mmp.c:241:mmp_thread_start(): MMP thread started pool 'POOL_D1' gethrtime 39801850585
Mar 28 00:21:49 bob spa_history.c:309:spa_history_log_sync(): txg 10 open pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=POOL_D1 async request task=2048
Mar 28 00:21:49 bob spa_misc.c:411:spa_load_note(): spa_load(POOL_D1, config trusted): LOADED
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 9, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 1717
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 10, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 11, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 12, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 13, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 14, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 15, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 16, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 17, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39802 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=POOL_D1 async request task=1
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 18, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 19, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 20, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 10, spa POOL_D1, vdev_id 0, ms_id 21, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_D1, vdev_id 0, ms_id 22, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_D1, vdev_id 0, ms_id 23, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_D1, vdev_id 0, ms_id 24, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_D1, vdev_id 0, ms_id 25, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 11, spa POOL_D1, vdev_id 0, ms_id 26, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 39845 ms, loading_time 0 ms, ms_max_size 17179869184, max size error 171
Mar 28 00:21:49 bob spa.c:8187:spa_async_request(): spa=POOL_D1 async request task=32
Mar 28 00:21:49 bob spa_history.c:309:spa_history_log_sync(): txg 12 import pool version 5000; software version unknown; uts  12.2-RELEASE-p3 1202000 amd64
Mar 28 00:21:49 bob Pools import completed
 
Last edited:
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
My boot-pool SSD is on an SSD, connected to USB through a USB<>SATA adapter.
All other drives are on SATA.
- the 2x8TB are through the pre-cabled SATA, so I just put them in the bay and that's it,
- the LOG_SWAP_POOL SSD in on a SATA port that I cabled myself.
All these drives are new.

I noticed that my boot-pool appeared in the log earlier this evening, in a configuration that doesn't exist at the moment (boot SSD + 2x8TB only) -- the LOG_SWAP_POOL SSD wasn't plugged in at that time.
 
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
Some more news this morning.
I am running TrueNAS 12.0 U2.1 (same as in my server hardware) in VirtualBox from macOS:
- I have attached through SATA (directly on the motherboard) the 2x 8TB drives.
- they don't have swap
- I have two virtual drives of 2 GB to create a pool that is unrelated to physical devices (the files are on a SSD)
- they are used only for swap

Here's how it looks for TrueNAS:
Code:
root@truenas[~]# gpart show
=>      40  33554352  ada0  GPT  (16G)
        40      1024     1  freebsd-boot  (512K)
      1064  33521664     2  freebsd-zfs  (16G)
  33522728     31664        - free -  (15M)

=>     40  8388528  ada1  GPT  (4.0G)
       40       88        - free -  (44K)
      128  4194304     1  freebsd-swap  (2.0G)
  4194432  4194136     2  freebsd-zfs  (2.0G)

=>     40  8388528  ada2  GPT  (4.0G)
       40       88        - free -  (44K)
      128  4194304     1  freebsd-swap  (2.0G)
  4194432  4194136     2  freebsd-zfs  (2.0G)

=>         40  15628053088  ada3  GPT  (7.3T)
           40           88        - free -  (44K)
          128  15628053000     1  freebsd-zfs  (7.3T)

=>         40  15628053088  ada4  GPT  (7.3T)
           40           88        - free -  (44K)
          128  15628053000     1  freebsd-zfs  (7.3T)


In one boot, I created a TEST_POOL with the virtual drives.
In another booth, I created a ARCHIVE_POOL_PA with the 2x 8TB drives.

Code:
root@truenas[~]# zpool status
  pool: ARCHIVE_POOL_VM
 state: ONLINE
config:

    NAME                                            STATE     READ WRITE CKSUM
    ARCHIVE_POOL_VM                                 ONLINE       0     0     0
      mirror-0                                      ONLINE       0     0     0
        gptid/82e35529-8fb8-11eb-af3f-0800279e1322  ONLINE       0     0     0
        gptid/82fad297-8fb8-11eb-af3f-0800279e1322  ONLINE       0     0     0

errors: No known data errors

  pool: TEST_POOL
 state: ONLINE
config:

    NAME                                            STATE     READ WRITE CKSUM
    TEST_POOL                                       ONLINE       0     0     0
      mirror-0                                      ONLINE       0     0     0
        gptid/e1b2ec7c-8f5b-11eb-8707-0800279e1322  ONLINE       0     0     0
        gptid/e1bba5bb-8f5b-11eb-8707-0800279e1322  ONLINE       0     0     0

errors: No known data errors

  pool: boot-pool
 state: ONLINE
config:

    NAME        STATE     READ WRITE CKSUM
    boot-pool   ONLINE       0     0     0
      ada0p2    ONLINE       0     0     0

errors: No known data errors


On the next reboot, I have the following in my logs:
Code:
root@truenas[~]# grep _impl /var/log/console.log
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 10, smp_length 240, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19289 ms, loading_time 0 ms, ms_max_size 134217728, max size error
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 11, smp_length 280, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 0, unloaded time 19289 ms, loading_time 0 ms, ms_max_size 134217728, max size err
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 12, smp_length 296, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 0, unloaded time 19290 ms, loading_time 0 ms, ms_max_size 134217728, max size err
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 13, smp_length 384, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19290 ms, loading_time 0 ms, ms_max_size 134217728, max size error
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 14, smp_length 352, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19290 ms, loading_time 0 ms, ms_max_size 134217728, max size error
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 0, smp_length 1256, unflushed_allocs 815104, unflushed_frees 815104, freed 0, defer 0 + 0, unloaded time 19291 ms, loading_time 0 ms, ms_max_size 130957312, max s
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 176, spa TEST_POOL, vdev_id 0, ms_id 1, smp_length 1120, unflushed_allocs 372736, unflushed_frees 376832, freed 0, defer 0 + 0, unloaded time 19291 ms, loading_time 0 ms, ms_max_size 132804608, max s
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 177, spa TEST_POOL, vdev_id 0, ms_id 2, smp_length 1680, unflushed_allocs 688128, unflushed_frees 761856, freed 0, defer 32768 + 0, unloaded time 19297 ms, loading_time 0 ms, ms_max_size 131153920, m
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 177, spa TEST_POOL, vdev_id 0, ms_id 3, smp_length 912, unflushed_allocs 360448, unflushed_frees 393216, freed 0, defer 32768 + 0, unloaded time 19298 ms, loading_time 0 ms, ms_max_size 132186112, ma
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 177, spa TEST_POOL, vdev_id 0, ms_id 4, smp_length 1176, unflushed_allocs 790528, unflushed_frees 770048, freed 0, defer 8192 + 4096, unloaded time 19308 ms, loading_time 0 ms, ms_max_size 131461120,
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 178, spa TEST_POOL, vdev_id 0, ms_id 5, smp_length 1120, unflushed_allocs 311296, unflushed_frees 335872, freed 0, defer 8192 + 4096, unloaded time 19308 ms, loading_time 0 ms, ms_max_size 132706304,
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 178, spa TEST_POOL, vdev_id 0, ms_id 6, smp_length 2048, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 4096, unloaded time 19308 ms, loading_time 0 ms, ms_max_size 113397760, max size
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 178, spa TEST_POOL, vdev_id 0, ms_id 7, smp_length 1296, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 4096, unloaded time 19308 ms, loading_time 0 ms, ms_max_size 132784128, max size
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 178, spa TEST_POOL, vdev_id 0, ms_id 8, smp_length 1304, unflushed_allocs 86016, unflushed_frees 143360, freed 0, defer 0 + 16384, unloaded time 19308 ms, loading_time 0 ms, ms_max_size 132550656, ma
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 178, spa TEST_POOL, vdev_id 0, ms_id 9, smp_length 344, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19309 ms, loading_time 0 ms, ms_max_size 133435392, max size error 1
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 9, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size err
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 10, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 11, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 12, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 13, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 14, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 15, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19885 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 16, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19886 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 17, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19886 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 18, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 19, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 20, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 21, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 22, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 23, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 24, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 25, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
Mar 28 13:31:24 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 9, spa ARCHIVE_POOL_VM, vdev_id 0, ms_id 26, smp_length 0, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 19982 ms, loading_time 0 ms, ms_max_size 17179869184, max size er
 
Last edited:
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
I did the same in FreeNAS 11.3 U5, and I don't have any error when using the VM and rebooting.

Code:
Mar 28 07:46:22 freenas Beginning pools import
Mar 28 07:46:22 freenas Importing ARCHIVE_POOL_VM
Mar 28 07:46:22 freenas Importing TEST_POOL
Mar 28 07:46:22 freenas Pools import completed


I will try on the server now. I hope it is the same.
I will then open a ticket against 12.0 U2.1 for these message.
Could it be that something has changed on how the server shuts down?
 
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
On FreeNAS 11.3 U5, I still have it.
It looks like the issue arrises when I have the SSD connected to the ODD SATA port of the motherboard (in my case, I have 4xSATA connected in a signal proprietary cable + 1xSATA with a standard SATA connector that is normally used for the ODD.

Since I also saw some issues on the VM, I am wondering if that's the SSD causing the issue or the 2x 8TB...

Code:
Mar 28 18:45:16 bob Beginning pools import
Mar 28 18:45:16 bob Importing ARCHIVE_POOL
Mar 28 18:45:16 bob disk vdev '/dev/gptid/60fda34c-8fcb-11eb-895c-00fd45fc0de0': best uberblock found for spa ARCHIVE_POOL. txg 38
Mar 28 18:45:16 bob spa_load(ARCHIVE_POOL, config untrusted): using uberblock with txg=38
Mar 28 18:45:16 bob spa=ARCHIVE_POOL async request task=1
Mar 28 18:45:16 bob spa_load(ARCHIVE_POOL, config trusted): LOADED
Mar 28 18:45:16 bob txg 40 open pool version 5000; software version 5000/5; uts  11.3-RELEASE-p14 1103000 amd64
Mar 28 18:45:16 bob spa=ARCHIVE_POOL async request task=32
Mar 28 18:45:16 bob txg 42 import pool version 5000; software version 5000/5; uts  11.3-RELEASE-p14 1103000 amd64
Mar 28 18:45:16 bob Importing SSD_POOL_TEST
Mar 28 18:45:16 bob Pools import completed
 
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
I've added my two drives from Nas4Free/Ximanas and imported them (but they didn't get an upgrade).

I now get:
Code:
Mar 28 19:18:43 bob Beginning pools import
Mar 28 19:18:43 bob Importing ARCHIVE_POOL
Mar 28 19:18:43 bob spa_load($import, config trusted): LOADED
Mar 28 19:18:43 bob spa_load($import, config trusted): UNLOADING
Mar 28 19:18:43 bob spa_import: importing ARCHIVE_POOL
Mar 28 19:18:43 bob spa_load(ARCHIVE_POOL, config trusted): LOADING
Mar 28 19:18:43 bob disk vdev '/dev/gptid/4a941c7d-8fe8-11eb-999f-00fd45fc0de0': best uberblock found for spa ARCHIVE_POOL. txg 14
Mar 28 19:18:43 bob spa_load(ARCHIVE_POOL, config untrusted): using uberblock with txg=14
Mar 28 19:18:43 bob spa=ARCHIVE_POOL async request task=1
Mar 28 19:18:43 bob spa_load(ARCHIVE_POOL, config trusted): LOADED
Mar 28 19:18:43 bob txg 16 open pool version 5000; software version 5000/5; uts  11.3-RELEASE-p14 1103000 amd64
Mar 28 19:18:43 bob spa=ARCHIVE_POOL async request task=32
Mar 28 19:18:43 bob txg 18 import pool version 5000; software version 5000/5; uts  11.3-RELEASE-p14 1103000 amd64
Mar 28 19:18:43 bob Importing MAIN_POOL
Mar 28 19:18:43 bob spa_tryimport: importing MAIN_POOL
Mar 28 19:18:43 bob spa_tryimport: using cachefile '/data/zfs/zpool.cache.saved'
Mar 28 19:18:43 bob spa_load($import, config trusted): LOADING
Mar 28 19:18:43 bob disk vdev '/dev/ada1': best uberblock found for spa $import. txg 2575211
Mar 28 19:18:43 bob spa_load($import, config untrusted): using uberblock with txg=2575211
Mar 28 19:18:43 bob spa_load($import, config trusted): LOADED
Mar 28 19:18:43 bob spa_load($import, config trusted): UNLOADING
Mar 28 19:18:43 bob spa_import: importing MAIN_POOL
Mar 28 19:18:43 bob spa_load(MAIN_POOL, config trusted): LOADING
Mar 28 19:18:43 bob disk vdev '/dev/ada1': best uberblock found for spa MAIN_POOL. txg 2575211
Mar 28 19:18:43 bob spa_load(MAIN_POOL, config untrusted): using uberblock with txg=2575211
Mar 28 19:18:43 bob spa=MAIN_POOL async request task=1
Mar 28 19:18:43 bob spa_load(MAIN_POOL, config trusted): LOADED
Mar 28 19:18:43 bob txg 2575213 open pool version 5000; software version 5000/5; uts  11.3-RELEASE-p14 1103000 amd64
Mar 28 19:18:43 bob spa=MAIN_POOL async request task=32
Mar 28 19:18:43 bob txg 2575215 import pool version 5000; software version 5000/5; uts  11.3-RELEASE-p14 1103000 amd64
Mar 28 19:18:43 bob Pools import completed


Code:
root@bob[~]# zpool status
  pool: ARCHIVE_POOL
state: ONLINE
  scan: none requested
config:

    NAME                                            STATE     READ WRITE CKSUM
    ARCHIVE_POOL                                    ONLINE       0     0     0
      mirror-0                                      ONLINE       0     0     0
        gptid/4a913f78-8fe8-11eb-999f-00fd45fc0de0  ONLINE       0     0     0
        gptid/4a941c7d-8fe8-11eb-999f-00fd45fc0de0  ONLINE       0     0     0

errors: No known data errors

  pool: MAIN_POOL
state: ONLINE
status: Some supported 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(7) for details.
  scan: scrub repaired 0 in 0 days 04:34:59 with 0 errors on Mon Jan  4 05:53:08 2021
config:

    NAME        STATE     READ WRITE CKSUM
    MAIN_POOL   ONLINE       0     0     0
      mirror-0  ONLINE       0     0     0
        ada2    ONLINE       0     0     0
        ada1    ONLINE       0     0     0

errors: No known data errors

  pool: freenas-boot
state: ONLINE
  scan: none requested
config:

    NAME        STATE     READ WRITE CKSUM
    freenas-boot  ONLINE       0     0     0
      da0p2     ONLINE       0     0     0

errors: No known data errors


I have to say, I don't know what's happening, and it's worrying me.
 
S

seldo

Dabbler
Joined
Jan 4, 2021
Messages
47
Just for completion on this thread, if anyone looks for the same thing in the future:
I opened a Jira issue and got a well commented feedback.

In short: if the pools import properly and the log don't show errors, you are fine.
For more details, check the Jira issue.
 
You must log in or register to reply here.

Similar threads

WB3FFV
Errors in TrueNAS 12.0-U2, and disks not showing info
Replies
0
Views
850
WB3FFV
WB3FFV
P
Unable to import zpool, data is still intact when checked with readonly
Replies
7
Views
2K
pk7909
P
andreaconfa
Scrub Error on all Pools
Replies
8
Views
1K
andreaconfa
andreaconfa
C
Failure to import zpool
Replies
3
Views
1K
ci4ic4
C
D
all disks failing in pool at the same time
Replies
6
Views
1K
digity
D
Top