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
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