Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slow import #11034

Closed
stuartthebruce opened this issue Oct 9, 2020 · 18 comments
Closed

Slow import #11034

stuartthebruce opened this issue Oct 9, 2020 · 18 comments
Labels
Type: Feature Feature request or new feature Type: Performance Performance improvement or performance problem

Comments

@stuartthebruce
Copy link

System information

Type Version/Name
Distribution Name Scientific Linux
Distribution Version 7.8
Linux Kernel 3.10.0-1127.18.2.el7
Architecture x86_64
ZFS Version 0.8.5
SPL Version 0.8.5

Describe the problem you're observing

zpool import reproducibly takes nearly 5 minutes for a pool with 60 HDD without any obvious storage or CPU bottlenecks.

Describe how to reproduce the problem

[root@node809 ~]# time zpool import jbod2-backup

real    4m51.419s
user    0m4.110s
sys     0m45.043s

And a similar time was seen during the import at boot.

Include any warning/errors/backtraces from the system logs

[root@node809 ~]# zpool status
  pool: jbod2-backup
 state: ONLINE
  scan: scrub in progress since Thu Oct  8 11:50:15 2020
	67.8T scanned at 3.37G/s, 65.7T issued at 3.27G/s, 331T total
	0B repaired, 19.84% done, 0 days 23:07:06 to go
config:

	NAME                              STATE     READ WRITE CKSUM
	jbod2-backup                      ONLINE       0     0     0
	  raidz3-0                        ONLINE       0     0     0
	    35000cca2531dd934             ONLINE       0     0     0
	    35000cca2531e2a94             ONLINE       0     0     0
	    35000cca2531e3ce8             ONLINE       0     0     0
	    35000cca2531e5f38             ONLINE       0     0     0
	    35000cca2531e5f68             ONLINE       0     0     0
	    35000cca2531e5f6c             ONLINE       0     0     0
	    35000cca2531e6404             ONLINE       0     0     0
	    35000cca2531e84ec             ONLINE       0     0     0
	    35000cca2531e868c             ONLINE       0     0     0
	    35000cca2531e87d8             ONLINE       0     0     0
	  raidz3-1                        ONLINE       0     0     0
	    35000cca2531e9750             ONLINE       0     0     0
	    35000cca2531e9764             ONLINE       0     0     0
	    35000cca2531e9f48             ONLINE       0     0     0
	    35000cca2531eb96c             ONLINE       0     0     0
	    35000cca2531ec858             ONLINE       0     0     0
	    35000cca2530aa110             ONLINE       0     0     0
	    35000cca2530aa424             ONLINE       0     0     0
	    35000cca2530aacb4             ONLINE       0     0     0
	    35000cca2530e297c             ONLINE       0     0     0
	    35000cca2530f661c             ONLINE       0     0     0
	  raidz3-2                        ONLINE       0     0     0
	    35000cca253100b68             ONLINE       0     0     0
	    35000cca253123c08             ONLINE       0     0     0
	    35000cca253158878             ONLINE       0     0     0
	    35000cca253168af4             ONLINE       0     0     0
	    35000cca25316cc20             ONLINE       0     0     0
	    35000cca25316d614             ONLINE       0     0     0
	    35000cca25316e978             ONLINE       0     0     0
	    35000cca253178e50             ONLINE       0     0     0
	    35000cca2531bc948             ONLINE       0     0     0
	    35000cca2531d7500             ONLINE       0     0     0
	  raidz3-3                        ONLINE       0     0     0
	    35000cca2530a4188             ONLINE       0     0     0
	    35000cca2530a461c             ONLINE       0     0     0
	    35000cca2530a4868             ONLINE       0     0     0
	    35000cca2530a4918             ONLINE       0     0     0
	    35000cca2530a4bc4             ONLINE       0     0     0
	    35000cca2530a58a4             ONLINE       0     0     0
	    35000cca2530a63f4             ONLINE       0     0     0
	    35000cca2530a6adc             ONLINE       0     0     0
	    35000cca2530a6f3c             ONLINE       0     0     0
	    35000cca2530a7108             ONLINE       0     0     0
	  raidz3-4                        ONLINE       0     0     0
	    35000cca2530a7130             ONLINE       0     0     0
	    35000cca2530a7288             ONLINE       0     0     0
	    35000cca2530a7408             ONLINE       0     0     0
	    35000cca2530a7428             ONLINE       0     0     0
	    35000cca2530a7494             ONLINE       0     0     0
	    35000cca253032d58             ONLINE       0     0     0
	    35000cca253075af0             ONLINE       0     0     0
	    35000cca253084ee4             ONLINE       0     0     0
	    35000cca253089a64             ONLINE       0     0     0
	    35000cca25308a028             ONLINE       0     0     0
	  raidz3-5                        ONLINE       0     0     0
	    35000cca253090cbc             ONLINE       0     0     0
	    35000cca253091b9c             ONLINE       0     0     0
	    35000cca2530925bc             ONLINE       0     0     0
	    35000cca253093758             ONLINE       0     0     0
	    35000cca25309e6d8             ONLINE       0     0     0
	    35000cca2530a0dd0             ONLINE       0     0     0
	    35000cca2530a0f64             ONLINE       0     0     0
	    35000cca2530a1140             ONLINE       0     0     0
	    35000cca2530a21c4             ONLINE       0     0     0
	    35000cca2530a23b4             ONLINE       0     0     0
	logs
	  mirror-6                        ONLINE       0     0     0
	    wwn-0x55cd2e404c21b856-part3  ONLINE       0     0     0
	    wwn-0x55cd2e414dcf191d-part3  ONLINE       0     0     0

errors: No known data errors

During initial boot import,

[root@node809 ~]# less /proc/spl/kstat/zfs/dbgmsg
timestamp    message
1602182716   spa.c:5638:spa_tryimport(): spa_tryimport: importing jbod2-backup
1602182716   spa.c:5643:spa_tryimport(): spa_tryimport: using cachefile '/etc/zfs/zpool.cache'
1602182716   spa_misc.c:408:spa_load_note(): spa_load($import, config trusted): LOADING
1602182717   vdev.c:125:vdev_dbgmsg(): disk vdev '/dev/disk/by-id/wwn-0x55cd2e414dcf191d-part3': best uberblock found for spa $import. txg 1179477
1602182717   spa_misc.c:408:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=1179477
1602182800   spa_misc.c:408:spa_load_note(): spa_load($import, config trusted): LOADED
1602182800   spa_misc.c:408:spa_load_note(): spa_load($import, config trusted): UNLOADING
1602182800   spa.c:5638:spa_tryimport(): spa_tryimport: importing jbod2-backup
1602182800   spa.c:5643:spa_tryimport(): spa_tryimport: using cachefile '/etc/zfs/zpool.cache'
1602182800   spa_misc.c:408:spa_load_note(): spa_load($import, config trusted): LOADING
1602182801   vdev.c:125:vdev_dbgmsg(): disk vdev '/dev/disk/by-id/wwn-0x55cd2e414dcf191d-part3': best uberblock found for spa $import. txg 1179477
1602182801   spa_misc.c:408:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=1179477
1602182882   spa_misc.c:408:spa_load_note(): spa_load($import, config trusted): LOADED
1602182882   spa_misc.c:408:spa_load_note(): spa_load($import, config trusted): UNLOADING
1602182883   spa.c:5490:spa_import(): spa_import: importing jbod2-backup
1602182883   spa_misc.c:408:spa_load_note(): spa_load(jbod2-backup, config trusted): LOADING
1602182884   vdev.c:125:vdev_dbgmsg(): disk vdev '/dev/disk/by-id/wwn-0x55cd2e414dcf191d-part3': best uberblock found for spa jbod2-backup. txg 1179477
1602182884   spa_misc.c:408:spa_load_note(): spa_load(jbod2-backup, config untrusted): using uberblock with txg=1179477
1602182966   mmp.c:241:mmp_thread_start(): MMP thread started pool 'jbod2-backup' gethrtime 268807824866
1602182966   spa.c:7592:spa_async_request(): spa=jbod2-backup async request task=1
1602182966   spa_misc.c:408:spa_load_note(): spa_load(jbod2-backup, config trusted): LOADED
1602182967   spa_history.c:319:spa_history_log_sync(): txg 1179479 open pool version 5000; software version unknown; uts node809 3.10.0-1127.18.2.el7.x86_64 #1 SMP Thu Jul 30 10:36:16 CDT 2020 x86_64
1602182967   mmp.c:443:mmp_write_uberblock(): MMP SCL_STATE acquisition pool 'jbod2-backup' took 12848851 ns gethrtime 269845292349
1602182967   spa.c:7592:spa_async_request(): spa=jbod2-backup async request task=32
1602182967   spa_history.c:319:spa_history_log_sync(): txg 1179481 import pool version 5000; software version unknown; uts node809 3.10.0-1127.18.2.el7.x86_64 #1 SMP Thu Jul 30 10:36:16 CDT 2020 x86_64
1602182973   spa_history.c:306:spa_history_log_sync(): command: zpool import -c /etc/zfs/zpool.cache -aN
1602183015   mmp.c:443:mmp_write_uberblock(): MMP SCL_STATE acquisition pool 'jbod2-backup' took 289671932 ns gethrtime 317229543459
1602183015   spa_history.c:319:spa_history_log_sync(): txg 1179492 scan setup func=1 mintxg=0 maxtxg=1179492
1602183015   dsl_scan.c:3581:dsl_scan_sync(): doing scan sync txg 1179492; ddt bm=0/0/0/0
1602183015   dsl_scan.c:2603:dsl_scan_ddt(): scanned 0 ddt entries with class_max = 1; suspending=0
1602183025   dsl_scan.c:3623:dsl_scan_sync(): scan visited 7526 blocks in 10643ms (1 os's, 4364 holes, 0 < mintxg, 0 in ddt, 0 > maxtxg)
1602183026   dsl_scan.c:3589:dsl_scan_sync(): doing scan sync txg 1179493; bm=0/259/0/0
1602183031   dsl_scan.c:3623:dsl_scan_sync(): scan visited 9863846 blocks in 5000ms (1 os's, 8936159 holes, 0 < mintxg, 0 in ddt, 0 > maxtxg)
1602183031   spa_history.c:306:spa_history_log_sync(): command: zpool scrub jbod2-backup
1602183031   dsl_scan.c:3589:dsl_scan_sync(): doing scan sync txg 1179494; bm=0/724899/0/2

During multiuser import,

[root@node809 ~]# iostat -xzm 3
...
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.06    0.00    0.10    4.11    0.00   95.73

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdd               0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02    8.67    8.67    0.00   8.67   1.73
sde               0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01    9.00    9.00    0.00   9.00   0.60
sdf               0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02   12.33   12.33    0.00  12.33   2.47
sdg               0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.02   13.00   13.00    0.00  13.25   1.77
sdi               0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01    8.50    8.50    0.00   8.50   0.57
sdj               0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.02   11.60   11.60    0.00  11.60   1.93
sdk               0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02   11.00   11.00    0.00  11.00   2.20
sdl               0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.02    9.20    9.20    0.00   9.20   1.53
sdm               0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   19.00   19.00    0.00  19.00   0.63
sdn               0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.00    5.50    5.50    0.00   5.50   0.37
sdo               0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01   13.33   13.33    0.00  13.33   1.33
sdp               0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03   13.43   13.43    0.00  13.43   3.13
sdq               0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.01    6.25    6.25    0.00   6.25   0.83
sdr               0.00     0.00    2.67    0.00     0.01     0.00     8.00     0.02    8.00    8.00    0.00   8.00   2.13
sds               0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01    8.67    8.67    0.00   8.67   0.87
sdt               0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    0.00    0.00    0.00   0.00   0.00
sdu               0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01    9.00    9.00    0.00   9.00   0.60
sdv               0.00     0.00    2.67    0.00     0.01     0.00     8.00     0.02    7.75    7.75    0.00   7.75   2.07
sdw               0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    8.00    8.00    0.00   8.00   1.33
sdy               0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   10.00   10.00    0.00  10.00   0.33
sdz               0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   12.00   12.00    0.00  12.00   0.40
sdaa              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.01    9.50    9.50    0.00   9.50   1.27
sdab              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   11.50   11.50    0.00  11.50   0.77
sdac              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.02    9.29    9.29    0.00   9.29   2.17
sdae              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    7.00    7.00    0.00   7.00   0.23
sdaf              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03   11.14   11.14    0.00  11.14   2.60
sdaj              0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01    6.00    6.00    0.00   6.00   0.60
sdak              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   16.00   16.00    0.00  16.00   0.53
sdal              0.00     0.00    1.33    0.00     0.01     0.00    10.00     0.02   11.50   11.50    0.00  11.50   1.53
sdan              0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01   10.33   10.33    0.00  10.33   1.03
sdap              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    4.00    4.00    0.00   4.00   0.67
sdaq              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.01    6.17    6.17    0.00   6.17   1.23
sdas              0.00     0.00    0.67    0.00     0.00     0.00    12.00     0.00    0.00    0.00    0.00   0.00   0.00
sdat              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   11.00   11.00    0.00  11.00   0.73
sdau              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.02   13.00   13.00    0.00  13.00   2.17
sdax              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   18.00   18.00    0.00  18.00   0.60
sdaz              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.01    6.33    6.33    0.00   6.33   1.27
sday              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.01   10.50   10.50    0.00  10.50   1.40
sdba              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    5.40    5.40    0.00   5.40   0.90
sdbb              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.03   15.80   15.80    0.00  15.80   2.63
sdbc              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   14.00   14.00    0.00  14.00   0.47
sdbe              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   12.00   12.00    0.00  12.00   0.40
sdbf              0.00     0.00    1.67    0.00     0.01     0.00     9.60     0.01    4.80    4.80    0.00   4.80   0.80
sdbg              0.00     0.00    1.33    0.00     0.01     0.00    10.00     0.02   12.75   12.75    0.00  12.75   1.70
sdbh              0.00     0.00    2.33    0.00     0.01     0.00    10.29     0.01    4.14    4.14    0.00   4.14   0.97
sdbi              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.02    9.20    9.20    0.00   9.20   1.53
sdbj              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    5.00    5.00    0.00   5.00   0.17
sdbk              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01    8.50    8.50    0.00   8.50   0.57
sdbo              0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01   13.33   13.33    0.00  13.33   1.33
sdbp              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    8.00    8.00    0.00   8.00   0.27
sdbq              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.00    5.00    5.00    0.00   5.00   0.33
sdbt              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.01    7.17    7.17    0.00   7.17   1.43
sdbr              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    6.80    6.80    0.00   6.80   1.13
sdbs              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.02   11.40   11.40    0.00  11.40   1.90
sdbv              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   10.00   10.00    0.00  10.00   0.67
sdbx              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03   11.57   11.57    0.00  11.57   2.70
sdbz              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.02    6.86    6.86    0.00   6.86   1.60
sdby              0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.02    7.00    7.00    0.00  17.00   1.70
sdcc              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   16.00   16.00    0.00  16.00   0.53
sdcf              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    0.00    0.00    0.00   0.00   0.00
sdch              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    0.00    0.00    0.00   0.00   0.00
sdcj              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   11.00   11.00    0.00  11.00   0.37
sdck              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02    9.00    9.00    0.00   9.00   1.80
sdcl              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.00    4.00    4.00    0.00   4.00   0.27
sdcm              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    0.00    0.00    0.00   0.00   0.00
sdcs              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   17.00   17.00    0.00  17.00   0.57
sdct              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.02   15.25   15.25    0.00  15.25   2.03
sdcv              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.02   17.25   17.25    0.00  17.25   2.30
sdcx              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02    9.67    9.67    0.00   9.67   1.93
sdcy              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.01    6.14    6.14    0.00   6.14   1.43
sdbn              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.01    6.43    6.43    0.00   6.14   1.43
sdda              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   16.00   16.00    0.00  16.00   0.53
sddb              0.00     0.00    0.67    0.00     0.00     0.00    12.00     0.01    7.50    7.50    0.00   7.50   0.50
sddc              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02    8.33    8.33    0.00   8.33   1.67
sddd              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    9.00    9.00    0.00   9.00   0.30
sdde              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   14.00   14.00    0.00  14.00   0.47
sddf              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01    7.50    7.50    0.00   7.50   0.50
sddg              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    8.20    8.20    0.00   8.20   1.37
sddi              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02    8.67    8.67    0.00   8.67   1.73
sddk              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    4.00    4.00    0.00   4.00   0.13
sddl              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   19.00   19.00    0.00  19.00   0.63
sddm              0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   10.50   10.50    0.00  10.50   0.70
sddn              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.01    4.75    4.75    0.00   4.75   0.63
sddp              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.02    9.57    9.57    0.00   9.57   2.23
sddq              0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01    9.00    9.00    0.00   9.00   0.90
sdci              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.01    5.67    5.67    0.00   5.67   1.13
sdca              0.00     0.00    0.67    0.00     0.01     0.00    16.00     0.00    5.50    5.50    0.00   5.50   0.37
sdbl              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02    8.17    8.17    0.00   8.17   1.63
sdbw              0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01    9.67    9.67    0.00   9.67   0.97
sdcd              0.00     0.00    2.67    0.00     0.01     0.00     8.00     0.02    8.12    8.12    0.00   8.13   2.17
sdcr              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.02   13.50   13.50    0.00  13.50   1.80
sdce              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.03   17.00   17.00    0.00  17.00   2.83
sddj              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    8.60    8.60    0.00   8.60   1.43
sddh              0.00     0.00    1.67    0.00     0.01     0.00     8.00     0.01    6.00    6.00    0.00   6.00   1.00
sdcn              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03   10.71   10.71    0.00  10.71   2.50
sddo              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.00    3.50    3.50    0.00   3.50   0.47
dm-1              0.00     0.00    3.67    0.00     0.01     0.00     8.00     0.03    8.09    8.09    0.00   8.09   2.97
dm-2              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    5.00    5.00    0.00   5.00   0.17
dm-3              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   19.00   19.00    0.00  19.00   0.63
dm-4              0.00     0.00    4.67    0.00     0.02     0.00     8.00     0.06   12.57   12.57    0.00  12.57   5.87
dm-5              0.00     0.00    1.33    0.00     0.01     0.00     8.00     0.01    8.00    8.00    0.00   8.00   1.07
dm-6              0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03    6.57    6.57    0.00  11.00   2.57
dm-7              0.00     0.00    2.00    0.00     0.01     0.00     8.00     0.02   11.50   11.50    0.00  11.50   2.30
dm-8              0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   16.00   16.00    0.00  16.00   0.53
dm-10             0.00     0.00    1.33    0.00     0.01     0.00    12.00     0.01    9.25    9.25    0.00   9.25   1.23
dm-11             0.00     0.00    4.67    0.00     0.02     0.00     8.00     0.04    8.07    8.07    0.00   8.07   3.77
dm-12             0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01   11.33   11.33    0.00  11.33   1.13
dm-13             0.00     0.00    4.00    0.00     0.02     0.00     8.00     0.03    8.42    8.42    0.00   8.42   3.37
dm-14             0.00     0.00    4.67    0.00     0.02     0.00     8.00     0.04    9.14    9.14    0.00   9.14   4.27
dm-15             0.00     0.00    3.33    0.00     0.01     0.00     8.00     0.04   12.50   12.50    0.00  12.50   4.17
dm-17             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   12.00   12.00    0.00  12.00   0.40
dm-18             0.00     0.00    3.00    0.00     0.01     0.00     8.00     0.02    8.00    8.00    0.00   8.00   2.40
dm-19             0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01   11.33   11.33    0.00  11.33   1.13
dm-20             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   11.00   11.00    0.00  11.00   0.37
dm-21             0.00     0.00    4.00    0.00     0.02     0.00     8.00     0.04   10.00   10.00    0.00  10.00   4.00
dm-22             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    7.00    7.00    0.00   7.00   0.23
dm-23             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   18.00   18.00    0.00  18.00   0.60
dm-24             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    7.00    7.00    0.00   7.00   0.23
dm-26             0.00     0.00    4.33    0.00     0.02     0.00     8.00     0.05   11.85   11.85    0.00  11.85   5.13
dm-29             0.00     0.00    2.67    0.00     0.01     0.00     9.00     0.04   13.38   13.38    0.00  13.38   3.57
dm-30             0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   16.50   16.50    0.00  16.50   1.10
dm-31             0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.02   10.57   10.57    0.00  10.57   2.47
dm-33             0.00     0.00    3.33    0.00     0.01     0.00     8.00     0.03    7.80    7.80    0.00   7.80   2.60
dm-34             0.00     0.00    4.33    0.00     0.02     0.00     8.00     0.03    6.23    6.23    0.00   6.15   2.67
dm-35             0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03   14.29   14.29    0.00  14.29   3.33
dm-36             0.00     0.00    0.67    0.00     0.00     0.00    12.00     0.01    8.00    8.00    0.00   8.00   0.53
dm-38             0.00     0.00    4.33    0.00     0.02     0.00     8.00     0.04    9.15    9.15    0.00   9.00   3.90
dm-40             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   14.00   14.00    0.00  14.00   0.47
dm-41             0.00     0.00    1.33    0.00     0.01     0.00    10.00     0.01    9.25    9.25    0.00   9.25   1.23
dm-42             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00   10.00   10.00    0.00  10.00   0.33
dm-43             0.00     0.00    3.00    0.00     0.01     0.00     8.00     0.03    9.33    9.33    0.00   9.33   2.80
dm-44             0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.03   13.43   13.43    0.00  13.43   3.13
dm-45             0.00     0.00    1.00    0.00     0.00     0.00     8.00     0.01    9.00    9.00    0.00   9.00   0.90
dm-46             0.00     0.00    3.67    0.00     0.01     0.00     8.00     0.02    6.18    6.18    0.00   6.18   2.27
dm-47             0.00     0.00    2.67    0.00     0.01     0.00     8.00     0.03   11.75   11.75    0.00  11.75   3.13
dm-48             0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   16.50   16.50    0.00  16.50   1.10
dm-49             0.00     0.00    3.67    0.00     0.01     0.00     8.00     0.04   10.55   10.55    0.00  10.55   3.87
dm-50             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.00    8.00    8.00    0.00   8.00   0.27
dm-51             0.00     0.00    3.67    0.00     0.01     0.00     8.00     0.04   11.18   11.18    0.00   9.64   3.53
dm-52             0.00     0.00    0.33    0.00     0.00     0.00     8.00     0.01   19.00   19.00    0.00  19.00   0.63
dm-53             0.00     0.00    3.33    0.00     0.01     0.00     8.00     0.02    6.80    6.80    0.00   6.80   2.27
dm-54             0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01    9.00    9.00    0.00   9.00   0.60
dm-55             0.00     0.00    0.67    0.00     0.00     0.00     8.00     0.01   16.50   16.50    0.00  16.50   1.10
dm-56             0.00     0.00    3.00    0.00     0.01     0.00     8.89     0.01    4.78    4.78    0.00   4.78   1.43
dm-57             0.00     0.00    4.67    0.00     0.02     0.00     9.14     0.03    6.93    6.93    0.00   6.93   3.23
dm-58             0.00     0.00    3.33    0.00     0.01     0.00     8.00     0.04   12.30   12.30    0.00  12.30   4.10
dm-59             0.00     0.00    2.33    0.00     0.01     0.00     8.00     0.02   10.57   10.57    0.00  10.57   2.47
dm-60             0.00     0.00    2.67    0.00     0.01     0.00     9.00     0.02    8.12    8.12    0.00   8.13   2.17
ATOP - node809                  2020/10/08  18:21:55                  --------------                   3s elapsed
PRC | sys    0.16s |  user   0.07s | #proc    611 | #tslpi   749  | #tslpu     1 | #zombie    2  | #exit      1 |
CPU | sys	5% |  user	2% | irq       0% | idle   2302%  | wait     98% | ipc     0.65  | curscal   ?% |
CPL | avg1    0.99 |  avg5    4.86 | avg15  19.03 | csw     6749  | intr    3597 |               | numcpu    24 |
MEM | tot   251.7G |  free  246.6G | cache 443.7M | buff   44.9M  | slab  664.1M | vmbal   0.0M  | hptot   0.0M |
SWP | tot     0.0M |  free    0.0M |              |               |              | vmcom   1.8G  | vmlim 125.8G |
LVM | cca253178e50 |  busy	5% | read      16 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 10.2 ms |
LVM | cca2530aacb4 |  busy	5% | read      15 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 9.53 ms |
LVM | cca2530a1140 |  busy	5% | read      17 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 8.35 ms |
LVM | cca2530a7108 |  busy	4% | read      12 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 11.2 ms |
DSK |         sdbi |  busy	3% | read       6 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 13.8 ms |
DSK |         sdcj |  busy	3% | read       9 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 9.00 ms |
DSK |         sdab |  busy	3% | read       8 | write      0  | MBr/s    0.0 | MBw/s    0.0  | avio 9.88 ms |
NET | transport    |  tcpi	17 | tcpo      17 | udpi    5865  | udpo       1 | tcpao      0  | tcppo      0 |
NET | network      |  ipi     6166 | ipo       18 | ipfrw      0  | deliv   6166 | icmpi      0  | icmpo      0 |
NET | em1	0% |  pcki    5425 | pcko      19 | sp   10 Gbps  | si 2110 Kbps | so    7 Kbps  | erro       0 |

  PID SYSCPU  USRCPU  VGROW   RGROW  RDDSK   WRDSK RUID      EUID     ST  EXC  THR  S CPUNR   CPU  CMD        1/1
 3813  0.06s   0.02s     0K      0K	0K      0K root      root     --    -    1  R     4    3%  atop
 9713  0.02s   0.03s     0K      0K	0K      0K ganglia   ganglia  --    -    2  S     6    2%  gmond
 2998  0.05s   0.00s	 0K      0K  1252K      0K root      root     --    -    1  D     0    2%  zpool
 8111  0.00s   0.01s	 0K      0K     0K      0K root      root     --    -    3  S    14    0%  NetworkManager
 8032  0.01s   0.00s	 0K      0K	0K      0K root      root     --    -    1  S    18    0%  rngd
 8059  0.00s   0.01s	 0K      0K	0K      0K avahi     avahi    --    -    1  S     0    0%  avahi-daemon
  101  0.01s   0.00s	 0K      0K     0K      0K root      root     --    -    1  S    18    0%  ksoftirqd/18
 3890  0.01s   0.00s	 0K      0K	0K      0K root      root     --    -    1  S    20    0%  z_rd_int
 3191  0.00s   0.00s	 0K      0K	0K      0K root      root     --    -   46  S     3    0%  fuse_dfs
 1262  0.00s   0.00s	 0K      0K    56K      0K root      root     --    -   66  S    11    0%  multipathd
 9181  0.00s   0.00s	 0K      0K	0K      0K root      root     --    -    8  S    15    0%  automount
22062  0.00s   0.00s	 0K      0K	0K      0K root      root     --    -    1  S    22    0%  sshd
 8086  0.00s   0.00s	 0K      0K	0K      0K chrony    chrony   --    -    1  S    14    0%  chronyd
 1078  0.00s   0.00s	 0K      0K	0K      0K root      root     --    -    1  S    20    0%  xfsaild/dm-0
...
@stuartthebruce stuartthebruce added Status: Triage Needed New issue which needs to be triaged Type: Defect Incorrect behavior (e.g. crash, hang) labels Oct 9, 2020
@stuartthebruce
Copy link
Author

Note, 5 minutes is a lot faster than version 0.8.4 for which import never completed with default kernel module settings (#10828).

As one random guess, I tried disabling multihost, but that did not make a significant difference,

[root@node809 ~]# time zpool import jbod2-backup

real	4m17.592s
user	0m3.719s
sys	0m45.679s

Another guess is the number of snapshots since listing those takes a similar amount of time with similar iostat and top statistics (i.e., neither storage devices nor CPU at anywhere near performance limits),

[root@node809 ~]# time zfs list -t snapshot | wc -l
117961

real	9m34.336s
user	0m6.716s
sys	0m45.748s

which is based on a smaller number of filesystems,

[root@node809 ~]# time zfs list -t filesystem | wc -l
276

real	0m0.107s
user	0m0.025s
sys	0m0.084s

And here are the pool properties

[root@node809 ~]# zpool get all
NAME          PROPERTY                       VALUE                          SOURCE
jbod2-backup  size                           655T                           -
jbod2-backup  capacity                       50%                            -
jbod2-backup  altroot                        -                              default
jbod2-backup  health                         ONLINE                         -
jbod2-backup  guid                           12314841084204185915           -
jbod2-backup  version                        -                              default
jbod2-backup  bootfs                         -                              default
jbod2-backup  delegation                     on                             default
jbod2-backup  autoreplace                    off                            default
jbod2-backup  cachefile                      -                              default
jbod2-backup  failmode                       wait                           default
jbod2-backup  listsnapshots                  off                            default
jbod2-backup  autoexpand                     off                            default
jbod2-backup  dedupditto                     0                              default
jbod2-backup  dedupratio                     1.00x                          -
jbod2-backup  free                           323T                           -
jbod2-backup  allocated                      331T                           -
jbod2-backup  readonly                       off                            -
jbod2-backup  ashift                         0                              default
jbod2-backup  comment                        -                              default
jbod2-backup  expandsize                     -                              -
jbod2-backup  freeing                        0                              -
jbod2-backup  fragmentation                  0%                             -
jbod2-backup  leaked                         0                              -
jbod2-backup  multihost                      off                            default
jbod2-backup  checkpoint                     -                              -
jbod2-backup  load_guid                      2800848285188582640            -
jbod2-backup  autotrim                       off                            default
jbod2-backup  feature@async_destroy          enabled                        local
jbod2-backup  feature@empty_bpobj            active                         local
jbod2-backup  feature@lz4_compress           active                         local
jbod2-backup  feature@multi_vdev_crash_dump  enabled                        local
jbod2-backup  feature@spacemap_histogram     active                         local
jbod2-backup  feature@enabled_txg            active                         local
jbod2-backup  feature@hole_birth             active                         local
jbod2-backup  feature@extensible_dataset     active                         local
jbod2-backup  feature@embedded_data          active                         local
jbod2-backup  feature@bookmarks              enabled                        local
jbod2-backup  feature@filesystem_limits      enabled                        local
jbod2-backup  feature@large_blocks           enabled                        local
jbod2-backup  feature@large_dnode            enabled                        local
jbod2-backup  feature@sha512                 enabled                        local
jbod2-backup  feature@skein                  enabled                        local
jbod2-backup  feature@edonr                  enabled                        local
jbod2-backup  feature@userobj_accounting     active                         local
jbod2-backup  feature@encryption             enabled                        local
jbod2-backup  feature@project_quota          active                         local
jbod2-backup  feature@device_removal         enabled                        local
jbod2-backup  feature@obsolete_counts        enabled                        local
jbod2-backup  feature@zpool_checkpoint       enabled                        local
jbod2-backup  feature@spacemap_v2            active                         local
jbod2-backup  feature@allocation_classes     enabled                        local
jbod2-backup  feature@resilver_defer         enabled                        local
jbod2-backup  feature@bookmark_v2            enabled                        local

@stuartthebruce
Copy link
Author

Removing 80% of the snapshots helped somewhat, but it still takes ~3 min to import,

[root@node809 ~]# time zpool import jbod2-backup

real	2m44.484s
user	0m3.788s
sys	0m44.140s
[root@node809 ~]# time zfs list -t snapshot | wc -l
24393

real	3m50.050s
user	0m1.441s
sys	0m10.679s

@ofaaland
Copy link
Contributor

That's interesting. Good idea to try reducing the number of snapshots. It does seem like the time is being spend loading the config. I'll try creating thousands of snapshots on a local pool and see how that impacts import time.

@stale
Copy link

stale bot commented Oct 21, 2021

This issue has been automatically marked as "stale" because it has not had any activity for a while. It will be closed in 90 days if no further activity occurs. Thank you for your contributions.

@stale stale bot added the Status: Stale No recent activity for issue label Oct 21, 2021
@stuartthebruce
Copy link
Author

In response to stale bot: I am still interested in faster pool import times for pools with a lot of snapshots.

@stale stale bot removed the Status: Stale No recent activity for issue label Oct 21, 2021
@behlendorf behlendorf added Type: Feature Feature request or new feature Type: Performance Performance improvement or performance problem and removed Type: Defect Incorrect behavior (e.g. crash, hang) Status: Triage Needed New issue which needs to be triaged labels Oct 22, 2021
@putnam
Copy link

putnam commented Apr 18, 2022

I don't have a ton of snapshots and my 66-disk pool takes 6 whole minutes to import from cache, every boot. Open to assisting with data any way I can. It's never been any faster than this -- it used to be much worse, as udev was not as well parallelized until recently.

@psaab
Copy link

psaab commented Apr 18, 2022

My 22 drive pool takes 4.5 minutes to import from cache, every boot. No snapshots and the same as @putnam. Always slow on every boot.

4min 35.352s zfs-import-cache.service

@amotin
Copy link
Member

amotin commented Apr 18, 2022

@putnam , @psaab If you have log_spacemap feature active on the pool, you could test thus: #12789 .

@putnam
Copy link

putnam commented Apr 18, 2022

@amotin Would this apply only to unclean exports? I am surprised if the default shutdown behavior in Debian would cause such an export. But I am not sure exactly what plays out when the machine is rebooted normally.

@amotin
Copy link
Member

amotin commented Apr 18, 2022

Shutdown/reboot do not trigger export, only TXG flush. With export I mean literally zpool export.

@putnam
Copy link

putnam commented Apr 18, 2022

Pardon the lack of knowledge on this: so on a typical shutdown/reboot, the pool is left in an unclean state and must do some work during the import to fix itself? It must be an intentional choice by the maintainers to not run export at shutdown -- should they?

@amotin
Copy link
Member

amotin commented Apr 18, 2022

On reboot all the dirty buffers are flushed and transaction group is committed. So technically pool is clean in a sense of possible data loss. On next import ZFS still scrubs last 2 TXGs of metadata just to be sure, but it is not strictly required. But reboot does not flush spacemap logs, that is done only on explicit zpool export. I was probably too aggressive when called reboot an unclean export. Most people consider unclean cases like a power loss, when some ZIL replay is required.

Anyhow, unless you really call zpool export before measuring following zpool import time and you have the log_spacemap feature active -- the patch should help you at some extent.

@putnam
Copy link

putnam commented Apr 18, 2022

log_spacemap is indeed active on my pool.

OK, I understand now that a typical reboot/shutdown qualifies as an 'unclean export' since it doesn't wait to run a full zpool export, which would flush the spacemap logs. So then when imported again on boot, although it's sped up somewhat by the fact that there's no ZIL replay or disk scanning required thanks to the cache, the spacemap flush is what is likely consuming all this time. And your change looks like it's designed to speed this up dramatically!

I'm a little fearful of cowboy-patching on my production system, though I have an offsite backup. Is there any chance of the change corrupting the pool in any way?

@amotin
Copy link
Member

amotin commented Apr 18, 2022

We already use this patch in TrueNAS builds for several months. So far nobody complained. But as you can see I am still trying to get proper review. I hope additional feedback motivate the reviewers.

@putnam
Copy link

putnam commented Apr 19, 2022

Would we be able to test your patch by booting the TrueNAS SCALE install disc and importing the pool temporarily there? Could time it and compare.

@amotin
Copy link
Member

amotin commented Apr 19, 2022

I've never used SCALE installer for that, but may be. Though only one aspect (prefetch) of the patch will affect the first import time. Maximum log length is enforced slowly during normal pool operation.

@amotin
Copy link
Member

amotin commented Apr 28, 2022

The PR was merged.

@amotin amotin closed this as completed Apr 28, 2022
@putnam
Copy link

putnam commented Oct 5, 2022

I just want to provide an update now that 2.1.6 has landed in Debian unstable. With this patch, the wait time to import my 66-disk pool is now less than 15 seconds vs. approximately 7-8 minutes before. Nice work!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Feature Feature request or new feature Type: Performance Performance improvement or performance problem
Projects
None yet
Development

No branches or pull requests

6 participants