Open
Description
System information
N/A
Describe the problem you're observing
zfs-tests-functional occasionally hangs hitting the job time limit.
Describe how to reproduce the problem
take a look at CI runs that hit the time limit
Include any warning/errors/backtraces from the system logs
Test (Linux): /usr/share/zfs/zfs-tests/tests/functional/mmp/mmp_interval (run as root) [00:00] [PASS]
06:09:50.43 ASSERTION: MULTIHOST_INTERVAL cannot be set to an invalid value
06:09:50.43 SUCCESS: set_tunable64 MULTIHOST_INTERVAL -1 exited 1
06:09:50.43 SUCCESS: set_tunable64 MULTIHOST_INTERVAL 100
06:09:50.44 SUCCESS: set_tunable64 MULTIHOST_INTERVAL 1000
06:09:50.44 MULTIHOST_INTERVAL cannot be set to an invalid value
06:09:50.44 NOTE: Performing local cleanup via log_onexit (cleanup)
06:09:50.44 SUCCESS: set_tunable64 MULTIHOST_INTERVAL 1000
Test (Linux): /usr/share/zfs/zfs-tests/callbacks/zfs_failsafe (run as root) [00:00] [PASS]
07:37:32.20 removed all registered handlers
Test (Linux): /usr/share/zfs/zfs-tests/tests/functional/mmp/mmp_active_import (run as root) [87:41] [KILLED]
06:09:50.50 ASSERTION: multihost=on|off active pool activity checks
06:09:50.53 SUCCESS: rm -f /var/tmp/mmp/*
06:09:50.54 SUCCESS: mkdir -p /var/tmp/mmp
06:09:50.54 SUCCESS: rm -f /var/tmp/mmp/*
06:09:50.55 SUCCESS: truncate -s 268435456 /var/tmp/mmp/vdev1 /var/tmp/mmp/vdev2
06:09:50.55 SUCCESS: mmp_clear_hostid
06:09:50.57 SUCCESS: mmp_set_hostid 01234567
06:09:50.66 SUCCESS: zpool create -f -o cachefile=/var/tmp/mmp/zpool.cache mmppool mirror /var/tmp/mmp/vdev1 /var/tmp/mmp/vdev2
06:09:50.71 SUCCESS: zpool set multihost=on mmppool
06:09:50.71 SUCCESS: mv /var/tmp/mmp/zpool.cache /var/tmp/mmp/zpool.cache.stale
06:09:50.78 SUCCESS: zpool export mmppool
06:09:50.79 SUCCESS: mmp_clear_hostid
06:09:50.80 SUCCESS: mmp_set_hostid 89abcdef
06:09:50.80 NOTE: Starting ztest in the background as hostid 01234567
06:09:50.80 SUCCESS: eval ZFS_HOSTID=01234567 ztest -VVVVV -T120 -M -k0 -f /var/tmp/mmp -E -p mmppool >/var/tmp/mmp/ztest.log 2>&1 &
06:09:50.91 1260042
06:09:50.91 1260050
06:09:50.91 SUCCESS: pgrep ztest
06:09:55.92 SUCCESS: sleep 5
06:09:56.06 SUCCESS: mmp_set_hostid 89abcdef
06:09:57.21 SUCCESS: is_pool_imported mmppool -d /var/tmp/mmp
06:09:58.35 cannot import 'mmppool': pool is imported on fv-az573-131 (hostid: 0x53977)
06:09:58.36 SUCCESS: try_pool_import mmppool -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:09:59.71 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:09:59.72 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:01.04 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:01.04 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:02.35 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:02.36 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:03.73 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:03.73 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:04.96 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:04.97 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:06.30 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:06.30 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:07.64 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:07.64 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:09.02 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:09.03 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:10.37 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:10.37 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:11.70 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:11.70 SUCCESS: try_pool_import mmppool -f -d /var/tmp/mmp Cannot import 'mmppool': pool is imported
06:10:13.88 cannot import 'mmppool': pool is imported on fv-az573-131 (hostid: 0x53977)
06:10:13.88 cannot import 'mmppool': pool is imported on fv-az573-131 (hostid: 0x53977)
06:10:13.88 SUCCESS: try_pool_import mmppool -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:15.48 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:15.48 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:15.49 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:18.05 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:18.05 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:18.06 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:20.61 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:20.61 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:20.62 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:22.22 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:22.22 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:22.23 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:24.77 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:24.77 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:24.77 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:26.35 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:26.35 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:26.35 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:28.90 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:28.90 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:28.91 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:31.53 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:31.53 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:31.53 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:34.10 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:34.10 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:34.11 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:36.69 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:36.69 cannot import 'mmppool': pool is imported on host 'fv-az573-131' (hostid=53977).
06:10:36.70 SUCCESS: try_pool_import mmppool -f -c /var/tmp/mmp/zpool.cache.stale Cannot import 'mmppool': pool is imported
06:10:36.73 SUCCESS: kill -9 1260042 1260360
06:10:59.38 SUCCESS: wait_pool_imported mmppool -d /var/tmp/mmp
06:10:59.38 SUCCESS: rm /var/tmp/mmp/ztest.log
06:10:59.39 SUCCESS: mmp_clear_hostid
06:10:59.44 SUCCESS: check_pool_import mmppool -d /var/tmp/mmp action Set a unique system hostid
06:10:59.45 SUCCESS: mmp_set_hostid 01234567
06:11:22.03 SUCCESS: check_pool_import mmppool -d /var/tmp/mmp action The pool can be imported
06:11:22.04 SUCCESS: mmp_clear_hostid
06:11:22.05 SUCCESS: mmp_set_hostid 89abcdef
06:11:45.68 SUCCESS: check_pool_import mmppool -d /var/tmp/mmp status The pool was last accessed by another system.
06:12:07.26 cannot import 'mmppool': pool was previously in use from another system.
06:12:07.26 SUCCESS: try_pool_import mmppool -d /var/tmp/mmp pool was previously in use from another system.
06:12:55.86 SUCCESS: import_activity_check mmppool -f -d /var/tmp/mmp
07:37:31.52 SUCCESS: zpool export mmppool
07:37:31.91 SUCCESS: import_no_activity_check mmppool -d /var/tmp/mmp
07:37:31.92 multihost=on|off active pool activity checks passed
07:37:31.92 NOTE: Performing local cleanup via log_onexit (cleanup)
07:37:32.05 SUCCESS: zpool destroy -f mmppool
07:37:32.14 SUCCESS: rm -f /var/tmp/mmp/vdev1 /var/tmp/mmp/vdev2 /var/tmp/mmp/zpool.cache /var/tmp/mmp/zpool.cache.stale
07:37:32.15 SUCCESS: mmp_clear_hostid
Test (Linux): /usr/share/zfs/zfs-tests/tests/functional/mmp/mmp_inactive_import (run as root) [00:31] [FAIL]
07:37:32.24 ASSERTION: multihost=on|off inactive pool activity checks
07:37:32.25 SUCCESS: mmp_set_hostid 01234567
07:37:32.25 NOTE: begin default_setup_noexit
07:37:32.32 invalid vdev specification
07:37:32.32 the following errors must be manually repaired:
07:37:32.32 /dev/loop3 is part of active pool 'testpool2'
07:37:32.32 ERROR: zpool create -f testpool loop3 exited 1
07:37:32.33 NOTE: Performing test-fail callback (/usr/share/zfs/zfs-tests/callbacks/zfs_dbgmsg.ksh)
07:37:32.33 =================================================================
07:37:32.33 Tailing last 200 lines of zfs_dbgmsg log
07:37:32.33 =================================================================
07:37:32.35 1669788710 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788711 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788712 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788713 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788714 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788715 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788716 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788718 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788719 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788720 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788721 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788722 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788723 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788724 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788725 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788726 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788727 spa.c:8407:spa_async_request(): spa=$import async request task=2048
07:37:32.35 1669788727 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADED
07:37:32.35 1669788727 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): UNLOADING
07:37:32.35 1669788727 spa.c:6289:spa_tryimport(): spa_tryimport: importing mmppool
07:37:32.35 1669788727 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADING
07:37:32.35 1669788727 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788727 spa_misc.c:416:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=540
07:37:32.35 1669788727 spa.c:3159:spa_activity_check_duration(): fail_intvals>0 import_delay=20000000000 ub_mmp mmp_fails=10 ub_mmp mmp_interval=1000 import_intervals=20
07:37:32.35 1669788727 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788728 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788729 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788730 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788731 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788732 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788733 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788734 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788735 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788736 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788737 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788738 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788739 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788740 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788741 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788742 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788743 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788744 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788745 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788746 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788747 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788748 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788749 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 540
07:37:32.35 1669788750 spa.c:8407:spa_async_request(): spa=$import async request task=2048
07:37:32.35 1669788750 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADED
07:37:32.35 1669788750 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): UNLOADING
07:37:32.35 1669788750 spa.c:6141:spa_import(): spa_import: importing mmppool
07:37:32.35 1669788750 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): LOADING
07:37:32.35 1669788750 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788750 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config untrusted): using uberblock with txg=540
07:37:32.35 1669788750 spa.c:3159:spa_activity_check_duration(): fail_intvals>0 import_delay=20000000000 ub_mmp mmp_fails=10 ub_mmp mmp_interval=1000 import_intervals=20
07:37:32.35 1669788750 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788751 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788752 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788753 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788755 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788756 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788757 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788758 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788759 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788760 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788761 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788762 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788763 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788764 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788765 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788766 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788767 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788768 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788769 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788770 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788771 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788772 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788773 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788774 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 540
07:37:32.35 1669788775 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): read 15 log space maps (15 total blocks - blksz = 131072 bytes) in 3 ms
07:37:32.35 1669788775 mmp.c:239:mmp_thread_start(): MMP thread started pool 'mmppool' gethrtime 9904029300100
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 9, smp_length 10944, unflushed_allocs 183296, unflushed_frees 133120, freed 0, defer 0 + 0, unloaded time 9904029 ms, loading_time 0 ms, ms_max_size 8971264, max size error 8938496, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 10, smp_length 10768, unflushed_allocs 174592, unflushed_frees 84480, freed 0, defer 0 + 0, unloaded time 9904030 ms, loading_time 0 ms, ms_max_size 10743296, max size error 10722816, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 13, smp_length 12416, unflushed_allocs 92672, unflushed_frees 227840, freed 0, defer 0 + 0, unloaded time 9904031 ms, loading_time 0 ms, ms_max_size 8746496, max size error 8730112, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 14, smp_length 5640, unflushed_allocs 132096, unflushed_frees 30208, freed 0, defer 0 + 0, unloaded time 9904032 ms, loading_time 0 ms, ms_max_size 12763648, max size error 12756992, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 1, smp_length 18640, unflushed_allocs 85504, unflushed_frees 80896, freed 0, defer 0 + 0, unloaded time 9904032 ms, loading_time 1 ms, ms_max_size 7407616, max size error 7395328, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 4, smp_length 10360, unflushed_allocs 38912, unflushed_frees 41472, freed 0, defer 0 + 0, unloaded time 9904034 ms, loading_time 0 ms, ms_max_size 4765184, max size error 4757504, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 5, smp_length 13096, unflushed_allocs 82432, unflushed_frees 82432, freed 0, defer 0 + 0, unloaded time 9904034 ms, loading_time 1 ms, ms_max_size 6949376, max size error 6932992, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 6, smp_length 14704, unflushed_allocs 152576, unflushed_frees 176640, freed 0, defer 0 + 0, unloaded time 9904036 ms, loading_time 1 ms, ms_max_size 6121472, max size error 6080512, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 541, spa mmppool, vdev_id 0, ms_id 7, smp_length 20608, unflushed_allocs 176640, unflushed_frees 6144, freed 0, defer 0 + 0, unloaded time 9904037 ms, loading_time 1 ms, ms_max_size 7593472, max size error 7589376, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:3917:metaslab_flush(): flushing: txg 541, spa mmppool, vdev_id 0, ms_id 13, unflushed_allocs 92672, unflushed_frees 227840, appended 632 bytes
07:37:32.35 1669788775 spa.c:8407:spa_async_request(): spa=mmppool async request task=1
07:37:32.35 1669788775 spa.c:8407:spa_async_request(): spa=mmppool async request task=2048
07:37:32.35 1669788775 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): LOADED
07:37:32.35 1669788775 spa_history.c:306:spa_history_log_sync(): txg 542 open pool version 5000; software version 1f1b3da-dist; uts fv-az573-131 5.15.0-1023-azure #29~20.04.1-Ubuntu SMP Wed Oct 26 19:18:25 UTC 2022 x86_64
07:37:32.35 1669788775 metaslab.c:3917:metaslab_flush(): flushing: txg 542, spa mmppool, vdev_id 0, ms_id 9, unflushed_allocs 176128, unflushed_frees 136192, appended 528 bytes
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 542, spa mmppool, vdev_id 0, ms_id 8, smp_length 14304, unflushed_allocs 0, unflushed_frees 512, freed 0, defer 0 + 512, unloaded time 9904111 ms, loading_time 1 ms, ms_max_size 7515648, max size error 7515648, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 542, spa mmppool, vdev_id 0, ms_id 11, smp_length 12880, unflushed_allocs 0, unflushed_frees 5120, freed 0, defer 0 + 2048, unloaded time 9904112 ms, loading_time 1 ms, ms_max_size 8193024, max size error 8190976, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 542, spa mmppool, vdev_id 0, ms_id 12, smp_length 13072, unflushed_allocs 0, unflushed_frees 4096, freed 0, defer 0 + 4096, unloaded time 9904114 ms, loading_time 1 ms, ms_max_size 7993856, max size error 7993856, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 543, spa mmppool, vdev_id 0, ms_id 0, smp_length 14592, unflushed_allocs 81920, unflushed_frees 204800, freed 0, defer 0 + 8192, unloaded time 9904115 ms, loading_time 1 ms, ms_max_size 4077056, max size error 4048896, old_weight 540000000000001, new_weight 540000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 543, spa mmppool, vdev_id 0, ms_id 2, smp_length 10288, unflushed_allocs 82432, unflushed_frees 6144, freed 0, defer 1024 + 0, unloaded time 9904116 ms, loading_time 0 ms, ms_max_size 3926016, max size error 3921920, old_weight 540000000000001, new_weight 540000000000001
07:37:32.35 1669788775 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 543, spa mmppool, vdev_id 0, ms_id 3, smp_length 13920, unflushed_allocs 0, unflushed_frees 2048, freed 0, defer 0 + 2048, unloaded time 9904116 ms, loading_time 1 ms, ms_max_size 3359232, max size error 3359232, old_weight 540000000000001, new_weight 540000000000001
07:37:32.35 1669788775 spa.c:8407:spa_async_request(): spa=mmppool async request task=32
07:37:32.35 1669788775 spa_history.c:306:spa_history_log_sync(): txg 544 import pool version 5000; software version 1f1b3da-dist; uts fv-az573-131 5.15.0-1023-azure #29~20.04.1-Ubuntu SMP Wed Oct 26 19:18:25 UTC 2022 x86_64
07:37:32.35 1669788775 metaslab.c:3917:metaslab_flush(): flushing: txg 544, spa mmppool, vdev_id 0, ms_id 0, unflushed_allocs 81920, unflushed_frees 204800, appended 424 bytes
07:37:32.35 1669788775 spa_history.c:293:spa_history_log_sync(): command: zpool import -f -d /var/tmp/mmp mmppool
07:37:32.35 1669788775 metaslab.c:3917:metaslab_flush(): flushing: txg 593, spa mmppool, vdev_id 0, ms_id 7, unflushed_allocs 211456, unflushed_frees 11776, appended 344 bytes
07:37:32.35 1669788775 spa_history.c:293:spa_history_log_sync(): command: zpool export mmppool
07:37:32.35 1669788775 metaslab.c:3917:metaslab_flush(): flushing: txg 594, spa mmppool, vdev_id 0, ms_id 10, unflushed_allocs 168448, unflushed_frees 88064, appended 456 bytes
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 4, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 8, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 4, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 8, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 4, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 8, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 1, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 5, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 9, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 1, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 5, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 9, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 1, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 5, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 9, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 2, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 6, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 10, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 2, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 6, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 10, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 2, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 6, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 10, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 3, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 0, ms_id 7, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 3, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 1, ms_id 7, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 3, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793589 metaslab.c:2544:metaslab_unload(): metaslab_unload: txg 172, spa testpool2, vdev_id 2, ms_id 7, weight 700000000000001, selected txg 21 (5305775 ms ago), alloc_txg 0, loaded 5327092 ms ago, max_size 268435456
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 1, unflushed_allocs 112128, unflushed_frees 106496, appended 400 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 5, unflushed_allocs 116736, unflushed_frees 100352, appended 400 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 2, unflushed_allocs 82432, unflushed_frees 6144, appended 184 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 6, unflushed_allocs 178688, unflushed_frees 222208, appended 504 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 14, unflushed_allocs 147456, unflushed_frees 64000, appended 256 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 4, unflushed_allocs 89088, unflushed_frees 59392, appended 296 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 11, unflushed_allocs 0, unflushed_frees 5120, appended 32 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 3, unflushed_allocs 0, unflushed_frees 2048, appended 16 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 8, unflushed_allocs 0, unflushed_frees 512, appended 16 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 12, unflushed_allocs 0, unflushed_frees 4096, appended 40 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 13, unflushed_allocs 15360, unflushed_frees 28160, appended 96 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 9, unflushed_allocs 1024, unflushed_frees 10240, appended 48 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 0, unflushed_allocs 0, unflushed_frees 2560, appended 16 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 7, unflushed_allocs 49664, unflushed_frees 35840, appended 128 bytes
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 603, spa mmppool, vdev_id 0, ms_id 10, unflushed_allocs 0, unflushed_frees 7680, appended 16 bytes
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): UNLOADING
07:37:32.35 1669793851 mmp.c:259:mmp_thread_stop(): MMP thread stopped pool 'mmppool' gethrtime 14979860407800
07:37:32.35 1669793851 spa.c:6289:spa_tryimport(): spa_tryimport: importing mmppool
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADING
07:37:32.35 1669793851 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa $import. txg 603
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=603
07:37:32.35 1669793851 spa.c:8407:spa_async_request(): spa=$import async request task=2048
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADED
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): UNLOADING
07:37:32.35 1669793851 spa.c:6141:spa_import(): spa_import: importing mmppool
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): LOADING
07:37:32.35 1669793851 vdev.c:161:vdev_dbgmsg(): file vdev '/var/tmp/mmp/vdev1': best uberblock found for spa mmppool. txg 603
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config untrusted): using uberblock with txg=603
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): read 1 log space maps (1 total blocks - blksz = 131072 bytes) in 0 ms
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): spa_load_verify found 0 metadata errors and 2 data errors
07:37:32.35 1669793851 mmp.c:239:mmp_thread_start(): MMP thread started pool 'mmppool' gethrtime 14980012802200
07:37:32.35 1669793851 spa.c:8407:spa_async_request(): spa=mmppool async request task=1
07:37:32.35 1669793851 spa.c:8407:spa_async_request(): spa=mmppool async request task=2048
07:37:32.35 1669793851 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): LOADED
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 9, smp_length 11520, unflushed_allocs 30720, unflushed_frees 35328, freed 0, defer 0 + 0, unloaded time 14980046 ms, loading_time 0 ms, ms_max_size 8976896, max size error 8966656, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 10, smp_length 11240, unflushed_allocs 30720, unflushed_frees 35328, freed 0, defer 0 + 0, unloaded time 14980047 ms, loading_time 0 ms, ms_max_size 10748928, max size error 10738688, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 13, smp_length 13144, unflushed_allocs 35328, unflushed_frees 29696, freed 0, defer 0 + 0, unloaded time 14980048 ms, loading_time 0 ms, ms_max_size 8747520, max size error 8736768, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 14, smp_length 5896, unflushed_allocs 35328, unflushed_frees 23552, freed 0, defer 0 + 0, unloaded time 14980049 ms, loading_time 0 ms, ms_max_size 12772864, max size error 12762112, old_weight 5c0000000000001, new_weight 5c0000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 1, smp_length 19040, unflushed_allocs 47104, unflushed_frees 51200, freed 0, defer 0 + 0, unloaded time 14980050 ms, loading_time 1 ms, ms_max_size 7408640, max size error 7390208, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 4, smp_length 10656, unflushed_allocs 47104, unflushed_frees 61440, freed 0, defer 0 + 0, unloaded time 14980051 ms, loading_time 0 ms, ms_max_size 4768768, max size error 4751360, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 5, smp_length 13496, unflushed_allocs 46080, unflushed_frees 47616, freed 0, defer 0 + 0, unloaded time 14980052 ms, loading_time 0 ms, ms_max_size 6952960, max size error 6939648, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 6, smp_length 15208, unflushed_allocs 46080, unflushed_frees 57344, freed 0, defer 0 + 0, unloaded time 14980053 ms, loading_time 1 ms, ms_max_size 6130688, max size error 6120448, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 7, smp_length 21080, unflushed_allocs 159232, unflushed_frees 143360, freed 0, defer 0 + 0, unloaded time 14980054 ms, loading_time 1 ms, ms_max_size 7615488, max size error 7600640, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 spa_history.c:306:spa_history_log_sync(): txg 605 open pool version 5000; software version 1f1b3da-dist; uts fv-az573-131 5.15.0-1023-azure #29~20.04.1-Ubuntu SMP Wed Oct 26 19:18:25 UTC 2022 x86_64
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 605, spa mmppool, vdev_id 0, ms_id 0, unflushed_allocs 0, unflushed_frees 26112, appended 48 bytes
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 8, smp_length 14320, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 14980074 ms, loading_time 1 ms, ms_max_size 7515648, max size error 7515648, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 605, spa mmppool, vdev_id 0, ms_id 11, smp_length 12912, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 14980076 ms, loading_time 0 ms, ms_max_size 8193024, max size error 8193024, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 606, spa mmppool, vdev_id 0, ms_id 12, smp_length 13112, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 14980077 ms, loading_time 0 ms, ms_max_size 7993856, max size error 7993856, old_weight 580000000000001, new_weight 580000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 606, spa mmppool, vdev_id 0, ms_id 0, smp_length 15080, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 14980078 ms, loading_time 0 ms, ms_max_size 4077056, max size error 4066816, old_weight 540000000000001, new_weight 540000000000001
07:37:32.35 1669793851 spa.c:8407:spa_async_request(): spa=mmppool async request task=32
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 606, spa mmppool, vdev_id 0, ms_id 2, smp_length 10472, unflushed_allocs 0, unflushed_frees 40448, freed 0, defer 0 + 0, unloaded time 14980078 ms, loading_time 0 ms, ms_max_size 3935744, max size error 3925504, old_weight 540000000000001, new_weight 540000000000001
07:37:32.35 1669793851 metaslab.c:2431:metaslab_load_impl(): metaslab_load: txg 607, spa mmppool, vdev_id 0, ms_id 3, smp_length 13936, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 14980079 ms, loading_time 1 ms, ms_max_size 3359232, max size error 3359232, old_weight 540000000000001, new_weight 540000000000001
07:37:32.35 1669793851 spa_history.c:306:spa_history_log_sync(): txg 607 import pool version 5000; software version 1f1b3da-dist; uts fv-az573-131 5.15.0-1023-azure #29~20.04.1-Ubuntu SMP Wed Oct 26 19:18:25 UTC 2022 x86_64
07:37:32.35 1669793851 metaslab.c:3917:metaslab_flush(): flushing: txg 607, spa mmppool, vdev_id 0, ms_id 1, unflushed_allocs 52224, unflushed_frees 50688, appended 112 bytes
07:37:32.35 1669793852 spa_history.c:293:spa_history_log_sync(): command: zpool import -d /var/tmp/mmp mmppool
07:37:32.35 1669793852 metaslab.c:3917:metaslab_flush(): flushing: txg 625, spa mmppool, vdev_id 0, ms_id 2, unflushed_allocs 0, unflushed_frees 40448, appended 72 bytes
07:37:32.35 1669793852 spa_history.c:293:spa_history_log_sync(): command: zpool destroy -f mmppool
07:37:32.35 1669793852 metaslab.c:3917:metaslab_flush(): flushing: txg 634, spa mmppool, vdev_id 0, ms_id 4, unflushed_allocs 52224, unflushed_frees 57344, appended 128 bytes
07:37:32.35 1669793852 spa_misc.c:416:spa_load_note(): spa_load(mmppool, config trusted): UNLOADING
07:37:32.35 1669793852 metaslab.c:3917:metaslab_flush(): flushing: txg 643, spa mmppool, vdev_id 0, ms_id 5, unflushed_allocs 50688, unflushed_frees 38400, appended 136 bytes
07:37:32.35 1669793852 mmp.c:259:mmp_thread_stop(): MMP thread stopped pool 'mmppool' gethrtime 14980385035000
07:37:32.35 =================================================================
07:37:32.35 End of zfs_dbgmsg log
07:37:32.35 =================================================================
07:37:32.35 NOTE: Performing test-fail callback (/usr/share/zfs/zfs-tests/callbacks/zfs_dmesg.ksh)
07:37:32.35 =================================================================
07:37:32.35 Tailing last 200 lines of dmesg log
07:37:32.35 =================================================================
07:37:32.37 [10514.072448] __schedule+0x2c2/0x8e0
07:37:32.37 [10514.072454] schedule+0x69/0x110
07:37:32.37 [10514.072459] cv_wait_common+0x157/0x260 [spl]
07:37:32.37 [10514.072472] ? wait_woken+0x60/0x60
07:37:32.37 [10514.072476] __cv_wait+0x15/0x20 [spl]
07:37:32.37 [10514.072483] vdev_autotrim_stop_wait+0x67/0xe0 [zfs]
07:37:32.37 [10514.072680] vdev_autotrim_stop_all+0x35/0x50 [zfs]
07:37:32.37 [10514.072839] spa_export_common+0x327/0x5a0 [zfs]
07:37:32.37 [10514.072994] spa_export+0x1b/0x30 [zfs]
07:37:32.37 [10514.073171] zfs_ioc_pool_export+0x33/0x40 [zfs]
07:37:32.37 [10514.073335] zfsdev_ioctl_common+0x6be/0x7a0 [zfs]
07:37:32.37 [10514.073496] ? __check_object_size+0x61/0x160
07:37:32.37 [10514.073499] zfsdev_ioctl+0x57/0xf0 [zfs]
07:37:32.37 [10514.073668] __x64_sys_ioctl+0x95/0xd0
07:37:32.37 [10514.073672] do_syscall_64+0x5c/0xc0
07:37:32.37 [10514.073675] ? do_user_addr_fault+0x1d3/0x640
07:37:32.37 [10514.073680] ? irqentry_exit_to_user_mode+0x9/0x30
07:37:32.37 [10514.073684] ? irqentry_exit+0x1d/0x30
07:37:32.37 [10514.073686] ? exc_page_fault+0x7d/0x160
07:37:32.37 [10514.073689] entry_SYSCALL_64_after_hwframe+0x61/0xcb
07:37:32.37 [10514.073693] RIP: 0033:0x7fed338953ab
07:37:32.37 [10514.073695] RSP: 002b:00007ffe69ee5a08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
07:37:32.37 [10514.073698] RAX: ffffffffffffffda RBX: 00006120000001c0 RCX: 00007fed338953ab
07:37:32.37 [10514.073700] RDX: 00007fed3041a030 RSI: 0000000000005a03 RDI: 0000000000000004
07:37:32.37 [10514.073701] RBP: 00007ffe69ee5ac0 R08: 00000ffe2607babc R09: 0000000000000000
07:37:32.37 [10514.073702] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000005a03
07:37:32.37 [10514.073703] R13: 0000000000000004 R14: 00007fed3041a030 R15: 00000ffda6083400
07:37:32.37 [10514.073706] </TASK>
07:37:32.37 [10634.880320] INFO: task zpool:1268006 blocked for more than 724 seconds.
07:37:32.37 [10634.888337] Tainted: P OE 5.15.0-1023-azure #29~20.04.1-Ubuntu
07:37:32.37 [10634.899512] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
07:37:32.37 [10634.911117] task:zpool state:D stack: 0 pid:1268006 ppid:1259863 flags:0x00004000
07:37:32.37 [10634.911123] Call Trace:
07:37:32.37 [10634.911126] <TASK>
07:37:32.37 [10634.911129] __schedule+0x2c2/0x8e0
07:37:32.37 [10634.911135] schedule+0x69/0x110
07:37:32.37 [10634.911140] cv_wait_common+0x157/0x260 [spl]
07:37:32.37 [10634.911154] ? wait_woken+0x60/0x60
07:37:32.37 [10634.911159] __cv_wait+0x15/0x20 [spl]
07:37:32.37 [10634.911166] vdev_autotrim_stop_wait+0x67/0xe0 [zfs]
07:37:32.37 [10634.911397] vdev_autotrim_stop_all+0x35/0x50 [zfs]
07:37:32.37 [10634.911613] spa_export_common+0x327/0x5a0 [zfs]
07:37:32.37 [10634.911785] spa_export+0x1b/0x30 [zfs]
07:37:32.37 [10634.911980] zfs_ioc_pool_export+0x33/0x40 [zfs]
07:37:32.37 [10634.912180] zfsdev_ioctl_common+0x6be/0x7a0 [zfs]
07:37:32.37 [10634.912432] ? __check_object_size+0x61/0x160
07:37:32.37 [10634.912437] zfsdev_ioctl+0x57/0xf0 [zfs]
07:37:32.37 [10634.912613] __x64_sys_ioctl+0x95/0xd0
07:37:32.37 [10634.912617] do_syscall_64+0x5c/0xc0
07:37:32.37 [10634.912621] ? do_user_addr_fault+0x1d3/0x640
07:37:32.37 [10634.912627] ? irqentry_exit_to_user_mode+0x9/0x30
07:37:32.37 [10634.912631] ? irqentry_exit+0x1d/0x30
07:37:32.37 [10634.912633] ? exc_page_fault+0x7d/0x160
07:37:32.37 [10634.912636] entry_SYSCALL_64_after_hwframe+0x61/0xcb
07:37:32.37 [10634.912641] RIP: 0033:0x7fed338953ab
07:37:32.37 [10634.912644] RSP: 002b:00007ffe69ee5a08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
07:37:32.37 [10634.912647] RAX: ffffffffffffffda RBX: 00006120000001c0 RCX: 00007fed338953ab
07:37:32.37 [10634.912649] RDX: 00007fed3041a030 RSI: 0000000000005a03 RDI: 0000000000000004
07:37:32.37 [10634.912650] RBP: 00007ffe69ee5ac0 R08: 00000ffe2607babc R09: 0000000000000000
07:37:32.37 [10634.912652] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000005a03
07:37:32.37 [10634.912653] R13: 0000000000000004 R14: 00007fed3041a030 R15: 00000ffda6083400
07:37:32.37 [10634.912655] </TASK>
07:37:32.37 [10755.710531] INFO: task zpool:1268006 blocked for more than 845 seconds.
07:37:32.37 [10755.718120] Tainted: P OE 5.15.0-1023-azure #29~20.04.1-Ubuntu
07:37:32.37 [10755.725734] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
07:37:32.37 [10755.733844] task:zpool state:D stack: 0 pid:1268006 ppid:1259863 flags:0x00004000
07:37:32.37 [10755.733851] Call Trace:
07:37:32.37 [10755.733853] <TASK>
07:37:32.37 [10755.733857] __schedule+0x2c2/0x8e0
07:37:32.37 [10755.733863] schedule+0x69/0x110
07:37:32.37 [10755.733868] cv_wait_common+0x157/0x260 [spl]
07:37:32.37 [10755.733882] ? wait_woken+0x60/0x60
07:37:32.37 [10755.733888] __cv_wait+0x15/0x20 [spl]
07:37:32.37 [10755.733895] vdev_autotrim_stop_wait+0x67/0xe0 [zfs]
07:37:32.37 [10755.734086] vdev_autotrim_stop_all+0x35/0x50 [zfs]
07:37:32.37 [10755.734244] spa_export_common+0x327/0x5a0 [zfs]
07:37:32.37 [10755.734410] spa_export+0x1b/0x30 [zfs]
07:37:32.37 [10755.734564] zfs_ioc_pool_export+0x33/0x40 [zfs]
07:37:32.37 [10755.734725] zfsdev_ioctl_common+0x6be/0x7a0 [zfs]
07:37:32.37 [10755.734886] ? __check_object_size+0x61/0x160
07:37:32.37 [10755.734890] zfsdev_ioctl+0x57/0xf0 [zfs]
07:37:32.37 [10755.735056] __x64_sys_ioctl+0x95/0xd0
07:37:32.37 [10755.735061] do_syscall_64+0x5c/0xc0
07:37:32.37 [10755.735064] ? do_user_addr_fault+0x1d3/0x640
07:37:32.37 [10755.735070] ? irqentry_exit_to_user_mode+0x9/0x30
07:37:32.37 [10755.735073] ? irqentry_exit+0x1d/0x30
07:37:32.37 [10755.735076] ? exc_page_fault+0x7d/0x160
07:37:32.37 [10755.735079] entry_SYSCALL_64_after_hwframe+0x61/0xcb
07:37:32.37 [10755.735083] RIP: 0033:0x7fed338953ab
07:37:32.37 [10755.735085] RSP: 002b:00007ffe69ee5a08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
07:37:32.37 [10755.735088] RAX: ffffffffffffffda RBX: 00006120000001c0 RCX: 00007fed338953ab
07:37:32.37 [10755.735090] RDX: 00007fed3041a030 RSI: 0000000000005a03 RDI: 0000000000000004
07:37:32.37 [10755.735091] RBP: 00007ffe69ee5ac0 R08: 00000ffe2607babc R09: 0000000000000000
07:37:32.37 [10755.735093] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000005a03
07:37:32.37 [10755.735094] R13: 0000000000000004 R14: 00007fed3041a030 R15: 00000ffda6083400
07:37:32.37 [10755.735096] </TASK>
07:37:32.37 [10876.540633] INFO: task zpool:1268006 blocked for more than 966 seconds.
07:37:32.37 [10876.548125] Tainted: P OE 5.15.0-1023-azure #29~20.04.1-Ubuntu
07:37:32.37 [10876.556281] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
07:37:32.37 [10876.564420] task:zpool state:D stack: 0 pid:1268006 ppid:1259863 flags:0x00004000
07:37:32.37 [10876.564428] Call Trace:
07:37:32.37 [10876.564431] <TASK>
07:37:32.37 [10876.564434] __schedule+0x2c2/0x8e0
07:37:32.37 [10876.564441] schedule+0x69/0x110
07:37:32.37 [10876.564446] cv_wait_common+0x157/0x260 [spl]
07:37:32.37 [10876.564460] ? wait_woken+0x60/0x60
07:37:32.37 [10876.564466] __cv_wait+0x15/0x20 [spl]
07:37:32.37 [10876.564473] vdev_autotrim_stop_wait+0x67/0xe0 [zfs]
07:37:32.37 [10876.564695] vdev_autotrim_stop_all+0x35/0x50 [zfs]
07:37:32.37 [10876.564868] spa_export_common+0x327/0x5a0 [zfs]
07:37:32.37 [10876.565024] spa_export+0x1b/0x30 [zfs]
07:37:32.37 [10876.565178] zfs_ioc_pool_export+0x33/0x40 [zfs]
07:37:32.37 [10876.565340] zfsdev_ioctl_common+0x6be/0x7a0 [zfs]
07:37:32.37 [10876.565502] ? __check_object_size+0x61/0x160
07:37:32.37 [10876.565506] zfsdev_ioctl+0x57/0xf0 [zfs]
07:37:32.37 [10876.565664] __x64_sys_ioctl+0x95/0xd0
07:37:32.37 [10876.565669] do_syscall_64+0x5c/0xc0
07:37:32.37 [10876.565672] ? do_user_addr_fault+0x1d3/0x640
07:37:32.37 [10876.565678] ? irqentry_exit_to_user_mode+0x9/0x30
07:37:32.37 [10876.565682] ? irqentry_exit+0x1d/0x30
07:37:32.37 [10876.565684] ? exc_page_fault+0x7d/0x160
07:37:32.37 [10876.565687] entry_SYSCALL_64_after_hwframe+0x61/0xcb
07:37:32.37 [10876.565691] RIP: 0033:0x7fed338953ab
07:37:32.37 [10876.565694] RSP: 002b:00007ffe69ee5a08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
07:37:32.37 [10876.565697] RAX: ffffffffffffffda RBX: 00006120000001c0 RCX: 00007fed338953ab
07:37:32.37 [10876.565698] RDX: 00007fed3041a030 RSI: 0000000000005a03 RDI: 0000000000000004
07:37:32.37 [10876.565700] RBP: 00007ffe69ee5ac0 R08: 00000ffe2607babc R09: 0000000000000000
07:37:32.37 [10876.565701] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000005a03
07:37:32.37 [10876.565702] R13: 0000000000000004 R14: 00007fed3041a030 R15: 00000ffda6083400
07:37:32.37 [10876.565704] </TASK>
07:37:32.37 [10997.370819] INFO: task zpool:1268006 blocked for more than 1087 seconds.
07:37:32.37 [10997.378165] Tainted: P OE 5.15.0-1023-azure #29~20.04.1-Ubuntu
07:37:32.37 [10997.386112] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
07:37:32.37 [10997.393677] task:zpool state:D stack: 0 pid:1268006 ppid:1259863 flags:0x00004000
07:37:32.37 [10997.393683] Call Trace:
07:37:32.37 [10997.393686] <TASK>
07:37:32.37 [10997.393690] __schedule+0x2c2/0x8e0
07:37:32.37 [10997.393696] schedule+0x69/0x110
07:37:32.37 [10997.393701] cv_wait_common+0x157/0x260 [spl]
07:37:32.37 [10997.393714] ? wait_woken+0x60/0x60
07:37:32.37 [10997.393720] __cv_wait+0x15/0x20 [spl]
07:37:32.37 [10997.393727] vdev_autotrim_stop_wait+0x67/0xe0 [zfs]
07:37:32.37 [10997.393917] vdev_autotrim_stop_all+0x35/0x50 [zfs]
07:37:32.37 [10997.394078] spa_export_common+0x327/0x5a0 [zfs]
07:37:32.37 [10997.394239] spa_export+0x1b/0x30 [zfs]
07:37:32.37 [10997.394400] zfs_ioc_pool_export+0x33/0x40 [zfs]
07:37:32.37 [10997.394568] zfsdev_ioctl_common+0x6be/0x7a0 [zfs]
07:37:32.37 [10997.394755] ? __check_object_size+0x61/0x160
07:37:32.37 [10997.394760] zfsdev_ioctl+0x57/0xf0 [zfs]
07:37:32.37 [10997.394923] __x64_sys_ioctl+0x95/0xd0
07:37:32.37 [10997.394929] do_syscall_64+0x5c/0xc0
07:37:32.37 [10997.394932] ? do_user_addr_fault+0x1d3/0x640
07:37:32.37 [10997.394938] ? irqentry_exit_to_user_mode+0x9/0x30
07:37:32.37 [10997.394941] ? irqentry_exit+0x1d/0x30
07:37:32.37 [10997.394944] ? exc_page_fault+0x7d/0x160
07:37:32.37 [10997.394947] entry_SYSCALL_64_after_hwframe+0x61/0xcb
07:37:32.37 [10997.394951] RIP: 0033:0x7fed338953ab
07:37:32.37 [10997.394953] RSP: 002b:00007ffe69ee5a08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
07:37:32.37 [10997.394956] RAX: ffffffffffffffda RBX: 00006120000001c0 RCX: 00007fed338953ab
07:37:32.37 [10997.394958] RDX: 00007fed3041a030 RSI: 0000000000005a03 RDI: 0000000000000004
07:37:32.37 [10997.394959] RBP: 00007ffe69ee5ac0 R08: 00000ffe2607babc R09: 0000000000000000
07:37:32.37 [10997.394960] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000005a03
07:37:32.37 [10997.394962] R13: 0000000000000004 R14: 00007fed3041a030 R15: 00000ffda6083400
07:37:32.37 [10997.394964] </TASK>
07:37:32.37 [11118.200978] INFO: task zpool:1268006 blocked for more than 1208 seconds.
07:37:32.37 [11118.207154] Tainted: P OE 5.15.0-1023-azure #29~20.04.1-Ubuntu
07:37:32.37 [11118.213745] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
07:37:32.37 [11118.221111] task:zpool state:D stack: 0 pid:1268006 ppid:1259863 flags:0x00004000
07:37:32.37 [11118.221117] Call Trace:
07:37:32.37 [11118.221120] <TASK>
07:37:32.37 [11118.221124] __schedule+0x2c2/0x8e0
07:37:32.37 [11118.221130] schedule+0x69/0x110
07:37:32.37 [11118.221135] cv_wait_common+0x157/0x260 [spl]
07:37:32.37 [11118.221148] ? wait_woken+0x60/0x60
07:37:32.37 [11118.221153] __cv_wait+0x15/0x20 [spl]
07:37:32.37 [11118.221160] vdev_autotrim_stop_wait+0x67/0xe0 [zfs]
07:37:32.37 [11118.221349] vdev_autotrim_stop_all+0x35/0x50 [zfs]
07:37:32.37 [11118.221519] spa_export_common+0x327/0x5a0 [zfs]
07:37:32.37 [11118.221682] spa_export+0x1b/0x30 [zfs]
07:37:32.37 [11118.221836] zfs_ioc_pool_export+0x33/0x40 [zfs]
07:37:32.37 [11118.221996] zfsdev_ioctl_common+0x6be/0x7a0 [zfs]
07:37:32.37 [11118.222157] ? __check_object_size+0x61/0x160
07:37:32.37 [11118.222161] zfsdev_ioctl+0x57/0xf0 [zfs]
07:37:32.37 [11118.222323] __x64_sys_ioctl+0x95/0xd0
07:37:32.37 [11118.222326] do_syscall_64+0x5c/0xc0
07:37:32.37 [11118.222329] ? do_user_addr_fault+0x1d3/0x640
07:37:32.37 [11118.222335] ? irqentry_exit_to_user_mode+0x9/0x30
07:37:32.37 [11118.222338] ? irqentry_exit+0x1d/0x30
07:37:32.37 [11118.222340] ? exc_page_fault+0x7d/0x160
07:37:32.37 [11118.222343] entry_SYSCALL_64_after_hwframe+0x61/0xcb
07:37:32.37 [11118.222347] RIP: 0033:0x7fed338953ab
07:37:32.37 [11118.222350] RSP: 002b:00007ffe69ee5a08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
07:37:32.37 [11118.222353] RAX: ffffffffffffffda RBX: 00006120000001c0 RCX: 00007fed338953ab
07:37:32.37 [11118.222354] RDX: 00007fed3041a030 RSI: 0000000000005a03 RDI: 0000000000000004
07:37:32.37 [11118.222356] RBP: 00007ffe69ee5ac0 R08: 00000ffe2607babc R09: 0000000000000000
07:37:32.37 [11118.222357] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000005a03
07:37:32.37 [11118.222358] R13: 0000000000000004 R14: 00007fed3041a030 R15: 00000ffda6083400
07:37:32.37 [11118.222360] </TASK>
07:37:32.37 [14981.361215] ZTS run /usr/share/zfs/zfs-tests/callbacks/zfs_failsafe
07:37:32.37 [14981.394679] ZTS run /usr/share/zfs/zfs-tests/tests/functional/mmp/mmp_inactive_import
07:37:32.37 =================================================================
07:37:32.37 End of dmesg log
07:37:32.37 =================================================================