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

Proposed zfs-0.8.4 patchset #10209

Merged
merged 32 commits into from
May 12, 2020

Conversation

tonyhutter
Copy link
Contributor

Motivation and Context

WIP proposed 0.8.4 patchset. This is not a complete list yet, more patches to follow. The target here is to get ZFS building under Fedora 32 w/5.6 kernel and aspirationally the 5.7 kernel.

Description

Mostly build fixes, and a few low-risk fixes/optimizations.

How Has This Been Tested?

Only build tested on F32

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Performance enhancement (non-breaking change which improves efficiency)
  • Code cleanup (non-breaking change which makes code smaller or more readable)
  • Breaking change (fix or feature that would cause existing functionality to change)
  • Documentation (a change to man pages or other documentation)

Checklist:

  • My code follows the ZFS on Linux code style requirements.
  • I have updated the documentation accordingly.
  • I have read the contributing document.
  • I have added tests to cover my changes.
  • I have run the ZFS Test Suite with this change applied.
  • All commit messages are properly formatted and contain Signed-off-by.

@tonyhutter tonyhutter added the Status: Work in Progress Not yet ready for general review label Apr 15, 2020
@ahrens
Copy link
Member

ahrens commented Apr 15, 2020

I think we would like to have the send-dedup deprecation and "zstream dump" command in this release as well.

@gmelikov
Copy link
Member

I propose to backport #10148 too.

@codecov-io
Copy link

Codecov Report

Merging #10209 into zfs-0.8-release will decrease coverage by 11.65%.
The diff coverage is 86.43%.

Impacted file tree graph

@@                 Coverage Diff                  @@
##           zfs-0.8-release   #10209       +/-   ##
====================================================
- Coverage            79.02%   67.37%   -11.66%     
====================================================
  Files                  381      319       -62     
  Lines               117796   101220    -16576     
====================================================
- Hits                 93093    68194    -24899     
- Misses               24703    33026     +8323     
Flag Coverage Δ
#kernel ?
#user 67.37% <86.43%> (-0.53%) ⬇️
Impacted Files Coverage Δ
cmd/mount_zfs/mount_zfs.c 59.04% <0.00%> (ø)
cmd/zed/agents/fmd_api.c 88.61% <ø> (ø)
cmd/zed/agents/fmd_serd.c 78.21% <ø> (ø)
cmd/zed/agents/zfs_mod.c 78.21% <ø> (+0.66%) ⬆️
cmd/zinject/translate.c 50.66% <ø> (ø)
cmd/zinject/zinject.c 35.03% <0.00%> (ø)
include/linux/simd_x86.h 89.13% <ø> (+0.66%) ⬆️
include/sys/dmu.h 100.00% <ø> (ø)
include/sys/vdev_raidz_impl.h 100.00% <ø> (ø)
lib/libnvpair/libnvpair_json.c 19.46% <0.00%> (ø)
... and 263 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9bb3d57...317ac8f. Read the comment docs.

@codecov-io
Copy link

codecov-io commented Apr 16, 2020

Codecov Report

Merging #10209 into zfs-0.8-release will decrease coverage by 0.00%.
The diff coverage is 100.00%.

Impacted file tree graph

@@                 Coverage Diff                 @@
##           zfs-0.8-release   #10209      +/-   ##
===================================================
- Coverage            78.82%   78.82%   -0.01%     
===================================================
  Files                  381      381              
  Lines               118574   118574              
===================================================
- Hits                 93468    93465       -3     
- Misses               25106    25109       +3     
Flag Coverage Δ
#kernel 79.04% <100.00%> (+0.01%) ⬆️
#user 67.45% <100.00%> (+0.10%) ⬆️
Impacted Files Coverage Δ
module/zfs/dsl_crypt.c 87.07% <100.00%> (ø)
module/zfs/vdev_indirect.c 80.66% <0.00%> (-8.50%) ⬇️
cmd/zvol_id/zvol_id_main.c 76.31% <0.00%> (-5.27%) ⬇️
module/zfs/vdev_raidz.c 93.24% <0.00%> (-2.62%) ⬇️
module/zfs/zfs_dir.c 81.58% <0.00%> (-1.87%) ⬇️
module/zfs/bptree.c 92.63% <0.00%> (-1.06%) ⬇️
module/zfs/spa_errlog.c 93.84% <0.00%> (-0.77%) ⬇️
module/zfs/zap_leaf.c 87.76% <0.00%> (-0.71%) ⬇️
module/zfs/dsl_pool.c 94.51% <0.00%> (-0.64%) ⬇️
module/icp/api/kcf_mac.c 40.00% <0.00%> (-0.58%) ⬇️
... and 47 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f5fd31f...f5fd31f. Read the comment docs.

@adamdmoss
Copy link
Contributor

Very nice - good selection of cherrypicks. Only one I'm a little doubtful of is f1646c7 as I'm unsure the risk/reward is worth it for 0.8.

@matveevandrey
Copy link

Any chance to get the following performance related improvements to be included in this patchset?

#10163
#10099
#10067
#10184

@gdevenyi
Copy link
Contributor

Please no. Can we just have a stable no new features patch.

@tonyhutter tonyhutter mentioned this pull request Apr 16, 2020
12 tasks
@ipha
Copy link

ipha commented Apr 19, 2020

Could I suggest bd0d24e: Linux 5.5 compat: blkg_tryget() for support of 5.5+ PREEMPT_RCU kernels

@gdevenyi
Copy link
Contributor

May I request #10216 please.

@ahrens
Copy link
Member

ahrens commented Apr 21, 2020

@gdevenyi Are you experiencing #10216 / #10215 on 0.8? As I noted in the PR, I think the bug only exists on master, not 0.8.

@gdevenyi
Copy link
Contributor

@gdevenyi Are you experiencing #10216 / #10215 on 0.8? As I noted in the PR, I think the bug only exists on master, not 0.8.

Oops, you're right, I confused a bugfix on master with the 0.8.x branch which doesn't have the commit introducing the bug in the first place.

@sempervictus
Copy link
Contributor

@tonyhutter: our patch stack mimics master a bit closer than what's proposed here. I cherry picked the commits in this PR atop our stack and added the recent ZVOL changes (cant cherry pick that cleanly since the whole os-specific thing moves where the diffs apply). This is what we've been building up since 0.8.1. Since we use grsecurity, we reset the stack atop whatever spender's latest patch is, but this setup has worked for us for quite some time (the particular stack listed there just finished 12h of zloop with no issue against 5.4.33-grsec+).
The commits in there are structured to backport supporting features and changes for some of the more impactful stuff. If we do something more along these lines, it'll make future merging a bit more tolerable IMO, plus, more functionaltiy. Far as stability goes, everything except the last few commits has been running for at least a couple months powering a pair of OpenStack clouds and boatload of standalone converged visor/storage setups. Has not been sitting idle on the shelf sort of thing :).

@tonyhutter
Copy link
Contributor Author

All - thanks for the patch suggestions. I'll try to get in as many as I can, provided they are stable and merge relatively cleanly. @behlendorf has also sent me an updated patchlist. Note that progress has been somewhat slow, as our build server got deprecated and it's taking me some extra time to get our new build server up and running.

@satmandu
Copy link
Contributor

Any chance of getting a version of #10187 into 0.8.4 so that 0.8.4 works with kernel 5.7 (assuming no further breaking changes before the final release)? I am using a version of that patch (here: https://launchpadlibrarian.net/474321719/k5.7-rc1-zfs.patch) applied to Ubuntu's zfs-dkms "successfully" with Linux kernel 5.7-rc2 .

I posted that to https://bugs.launchpad.net/ubuntu/+source/zfs-linux/+bug/1872373 but someone with actual expertise should probably figure out if the zvol.c changes are appropriate and not just a working hack.

Also I agree with #10187 (comment) that Linux-Maximum: should stay at 5.6 untl 5.7 is released.

@tonyhutter
Copy link
Contributor Author

@satmandu thanks for that patch! I'll include it in the patchset.

lhuedepohl and others added 6 commits April 22, 2020 14:51
On some systems - openSUSE, for example - there is not yet a writeable
temporary file system available, so bash bails out with an error,

  'cannot create temp file for here-document: Read-only file system',

on the here documents in zfs-mount-generator. The simple fix is to
change these into a multi-line echo statement.

Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Reviewed-By: Richard Laager <rlaager@wiktel.com>
Reviewed-by: George Melikov <mail@gmelikov.ru>
Signed-off-by: Lorenz Hüdepohl <dev@stellardeath.org>
Closes openzfs#9802
If someone is using both multipathd and ZFS, they are probably using
them together.  Ordering the zpool imports after multipathd is ready
fixes import issues for multipath configurations.

Tested-by: Mike Pastore <mike@oobak.org>
Reviewed-by: George Melikov <mail@gmelikov.ru>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Richard Laager <rlaager@wiktel.com>
Closes openzfs#9863
When growing the size of a (VMEM or KVMEM) kmem cache, spl_cache_grow()
always does taskq_dispatch(spl_cache_grow_work), and then waits for the
KMC_BIT_GROWING to be cleared by the taskq thread.

The taskq thread (spl_cache_grow_work()) does:
1. allocate new slab and add to list
2. wake_up_all(skc_waitq)
3. clear_bit(KMC_BIT_GROWING)

Therefore, the waiting thread can wake up before GROWING has been
cleared.  It will see that the growing has not yet completed, and go
back to sleep until it hits the 100ms timeout.

This can have an extreme performance impact on workloads that alloc/free
more than fits in the (statically-sized) magazines.  These workloads
allocate and free slabs with high frequency.

The problem can be observed with `funclatency spl_cache_grow`, which on
some workloads shows that 99.5% of the time it takes <64us to allocate
slabs, but we spend ~70% of our time in outliers, waiting for the 100ms
timeout.

The fix is to do `clear_bit(KMC_BIT_GROWING)` before
`wake_up_all(skc_waitq)`.

A future investigation should evaluate if we still actually need to
taskq_dispatch() at all, and if so on which kernel versions.

Reviewed-by: Paul Dagnelie <pcd@delphix.com>
Reviewed-by: Pavel Zakharov <pavel.zakharov@delphix.com>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Reviewed-by: George Wilson <gwilson@delphix.com>
Signed-off-by: Matthew Ahrens <mahrens@delphix.com>
Closes openzfs#9989
The correct name for the mount unit for / is "-.mount", not ".mount".

Reviewed-by: InsanePrawn <insane.prawny@gmail.com>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Co-authored-by: Antonio Russo <antonio.e.russo@gmail.com>
Signed-off-by: Richard Laager <rlaager@wiktel.com>
Closes openzfs#9970
Commit torvalds/linux@9e8d42a0f accidentally
converted the static inline function blkg_tryget() to GPL-only for
kernels built with CONFIG_PREEMPT_RCU=y and CONFIG_BLK_CGROUP=y.

Resolve the build issue by providing our own equivalent functionality
when needed which uses rcu_read_lock_sched() internally as before.

Reviewed-by: Tony Hutter <hutter2@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#9745
Closes openzfs#10072
When configuring as builtin (--enable-linux-builtin) for kernels
without loadable module support (CONFIG_MODULES=n) only the object
file is created.  Never a loadable kmod.

Update ZFS_LINUX_TRY_COMPILE to handle this in a manor similar to
the ZFS_LINUX_TEST_COMPILE_ALL macro.

Reviewed-by: George Melikov <mail@gmelikov.ru>
Reviewed-by: Tony Hutter <hutter2@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes openzfs#9887
Closes openzfs#10063
@tonyhutter tonyhutter force-pushed the zfs-0.8.4-hutter branch 2 times, most recently from ddf0d44 to 2c18481 Compare April 23, 2020 17:04
@tonyhutter
Copy link
Contributor Author

tonyhutter commented Apr 23, 2020

Looks like I need to update Linux 5.7 compat: blk_alloc_queue() to work on Centos 6:

checking whether follow_down_one() is available... no
checking whether blk_alloc_queue() expects request function... checking whether make_request_fn() returns void... no
checking whether make_request_fn() returns blk_qc_t... configure: error:
	*** None of the expected "make_request_fn" interfaces were detected.
	*** This may be because your kernel version is newer than what is
	*** supported, or you are using a patched custom kernel with
	*** incompatible modifications.
	***
	*** ZFS Version: zfs-0.8.3-1
	*** Compatible Kernels: 2.6.32 - 5.6

@tonyhutter tonyhutter force-pushed the zfs-0.8.4-hutter branch 2 times, most recently from aac5a98 to 39ef9cc Compare April 23, 2020 22:37
@tonyhutter
Copy link
Contributor Author

Looks like Centos 7 and possibly Centos 6 may be panicking early in the test suite. I'm looking into it.

@matveevandrey
Copy link

Recently fixed #10239 Would be extremely useful

@gamanakis
Copy link
Contributor

gamanakis commented Apr 28, 2020

May I suggest #10246 ? It is an one line fix.

@tonyhutter
Copy link
Contributor Author

@gamanakis thanks, I'll pull that one in.

@InsanePrawn
Copy link
Contributor

InsanePrawn commented Apr 28, 2020

I feel obligated to point out that the included systemd mount generator commits are a little more than 'bugfixes' by most standards, but

  • I have a hard time to imagine any backwards-incompatibility in them, although it's been a while since I worked on the generator
  • IIRC there are also some bugfixes squashed into those
  • few people seem to use that generator in the first place, on most distros I know it is still something the user must manually activate. I think I read Ubuntu 20.04 activates it if you install to ZFS? (Purely hearsay, someone better fact check this!)

Overall I think those 'feature' changes are very benign and I think it's much better to include them as a whole than not at all, just wanted to give everyone a heads up.

@tonyhutter
Copy link
Contributor Author

tonyhutter commented Apr 29, 2020

My last push fixed the crashes I was seeing on Centos 6-7 (thanks @behlendorf). It looks like a lot of builders are now failing zfs_rename_004_neg (like http://build.zfsonlinux.org/builders/CentOS%206%20x86_64%20%28TEST%29/builds/9009/steps/shell_9/logs/summary). I'm going to look into that.

@tonyhutter tonyhutter force-pushed the zfs-0.8.4-hutter branch 3 times, most recently from 7658c24 to 7b908e5 Compare April 29, 2020 22:13
gamanakis and others added 2 commits April 30, 2020 08:15
Otherwise when running with reference_tracking_enable=TRUE mounting
and unmounting an encrypted dataset panics with:

Call Trace:
 dump_stack+0x66/0x90
 slab_err+0xcd/0xf2
 ? __kmalloc+0x174/0x260
 ? __kmem_cache_shutdown+0x158/0x240
 __kmem_cache_shutdown.cold+0x1d/0x115
 shutdown_cache+0x11/0x140
 kmem_cache_destroy+0x210/0x230
 spl_kmem_cache_destroy+0x122/0x3e0 [spl]
 zfs_refcount_fini+0x11/0x20 [zfs]
 spa_fini+0x4b/0x120 [zfs]
 zfs_kmod_fini+0x6b/0xa0 [zfs]
 _fini+0xa/0x68c [zfs]
 __x64_sys_delete_module+0x19c/0x2b0
 do_syscall_64+0x5b/0x1a0
 entry_SYSCALL_64_after_hwframe+0x44/0xa9

Reviewed-By: Brian Behlendorf <behlendorf1@llnl.gov>
Reviewed-By: Tom Caputi <tcaputi@datto.com>
Signed-off-by: George Amanakis <gamanakis@gmail.com>
Closes openzfs#10246
META file and changelog updated.

Signed-off-by: Tony Hutter <hutter2@llnl.gov>

TEST_ZIMPORT_SKIP="yes"
@Bronek
Copy link

Bronek commented May 3, 2020

I do not see #10163 and #10184 in this patchset, any chance they could be still included? I recon ZVOL performance is actually an important aspect of basic ZFS functionality, at least for some users (like me). They've been first mentioned in this thread over two weeks ago, and merged in master at least 3 weeks ago.

@Atemu
Copy link

Atemu commented May 8, 2020

I think we would like to have the send-dedup deprecation and "zstream dump" command in this release as well.

I think a feature deprecation would too big of a change for a minor version bump. OpenZFS 2.0 would be a much better target IMO.

Would it block/complicate any of the proposed 0.8.4 changes if it wasn't deprecated?

@aerusso
Copy link
Contributor

aerusso commented May 8, 2020

I'm working on updating the official Debian packaging, and I'm testing this patch set on Debian unstable. I'm consistently getting a test failure for alloc_class_013_pos:

alloc_class_013_pos
Test: /usr/share/zfs/zfs-tests/tests/functional/alloc_class/alloc_class_013_pos (run as root) [00:03] [FAIL]
10:15:44.74 ASSERTION: Removing a dedup device from a pool succeeds.
10:15:44.75 SUCCESS: disk_setup
10:15:44.97 SUCCESS: zpool create testpool /tmp/x/device-0 /tmp/x/device-1 /tmp/x/device-2 dedup /tmp/x/device-3
10:15:47.05 SUCCESS: display_status testpool
10:15:47.71 SUCCESS: zfs create -o dedup=on -V 2G testpool/testvol
10:15:48.28 SUCCESS: zpool sync testpool
10:15:48.29 NAME                SIZE  ALLOC   FREE  CKPOINT  EXPANDSZ   FRAG    CAP  DEDUP    HEALTH  ALTROOT
10:15:48.29 testpool           3.28G  73.2M  3.21G        -         -     0%     2%  45.68x    ONLINE  -
10:15:48.29   /tmp/x/device-0   960M  25.6M   934M        -         -     0%  2.66%      -  ONLINE  
10:15:48.29   /tmp/x/device-1   960M  23.0M   937M        -         -     0%  2.39%      -  ONLINE  
10:15:48.29   /tmp/x/device-2   960M  24.6M   935M        -         -     0%  2.56%      -  ONLINE  
10:15:48.29 dedup                  -      -      -        -         -      -      -      -  -
10:15:48.29   /tmp/x/device-3   480M    45K   480M        -         -     0%  0.00%      -  ONLINE  
10:15:48.30 SUCCESS: zpool list -v testpool
10:15:48.31 cannot remove /tmp/x/device-3: out of space
10:15:48.31 ERROR: zpool remove testpool /tmp/x/device-3 exited 1
10:15:48.31 NOTE: Performing test-fail callback (/usr/share/zfs/zfs-tests/callbacks/zfs_dbgmsg.ksh)

Tailing last 200 lines of zfs_dbgmsg log

10:15:48.39 1588932899   spa.c:5638:spa_tryimport(): spa_tryimport: importing testpool
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load($import, config trusted): LOADING
10:15:48.39 1588932899   vdev.c:124:vdev_dbgmsg(): file vdev '/tmp/x/device-0': best uberblock found for spa $import. txg 17
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=17
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load($import, config trusted): LOADED
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load($import, config trusted): UNLOADING
10:15:48.39 1588932899   spa.c:5490:spa_import(): spa_import: importing testpool
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): LOADING
10:15:48.39 1588932899   vdev.c:124:vdev_dbgmsg(): file vdev '/tmp/x/device-0': best uberblock found for spa testpool. txg 17
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load(testpool, config untrusted): using uberblock with txg=17
10:15:48.39 1588932899   mmp.c:248:mmp_thread_start(): MMP thread started pool 'testpool' gethrtime 992470233349
10:15:48.39 1588932899   spa.c:7592:spa_async_request(): spa=testpool async request task=1
10:15:48.39 1588932899   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): LOADED
10:15:48.39 1588932899   spa_history.c:316:spa_history_log_sync(): txg 19 open pool version 5000; software version unknown; uts vigil.aerusso.net 5.6.0-1-cloud-amd64 #1 SMP Debian 5.6.7-1 (2020-04-29) x86_64
10:15:48.39 1588932899   spa.c:7592:spa_async_request(): spa=testpool async request task=32
10:15:48.39 1588932899   spa_history.c:316:spa_history_log_sync(): txg 21 import pool version 5000; software version unknown; uts vigil.aerusso.net 5.6.0-1-cloud-amd64 #1 SMP Debian 5.6.7-1 (2020-04-29) x86_64
10:15:48.39 1588932901   spa_history.c:305:spa_history_log_sync(): command: zpool import -d /tmp/x -s testpool
10:15:48.39 1588932902   spa_history.c:305:spa_history_log_sync(): command: zpool destroy -f testpool
10:15:48.39 1588932902   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): UNLOADING
10:15:48.39 1588932902   mmp.c:268:mmp_thread_stop(): MMP thread stopped pool 'testpool' gethrtime 995505568062
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts vigil.aerusso.net 5.6.0-1-cloud-amd64 #1 SMP Debian 5.6.7-1 (2020-04-29) x86_64
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
10:15:48.39 1588932902   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
10:15:48.39 1588932902   mmp.c:248:mmp_thread_start(): MMP thread started pool 'testpool' gethrtime 995886481325
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool raidz /tmp/x/device-0 /tmp/x/device-1 /tmp/x/device-2 special mirror /tmp/x/device-3 /tmp/x/device-4
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 6 set testpool (id 54) special_small_blocks=0
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=0 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 8 set testpool (id 54) special_small_blocks=512
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=512 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 9 set testpool (id 54) special_small_blocks=1024
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=1024 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 10 set testpool (id 54) special_small_blocks=2048
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=2048 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 11 set testpool (id 54) special_small_blocks=4096
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=4096 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 12 set testpool (id 54) special_small_blocks=8192
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=8192 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 13 set testpool (id 54) special_small_blocks=16384
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=16384 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 14 set testpool (id 54) special_small_blocks=32768
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=32768 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 15 set testpool (id 54) special_small_blocks=65536
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=65536 testpool
10:15:48.39 1588932903   spa_history.c:309:spa_history_log_sync(): txg 16 set testpool (id 54) special_small_blocks=131072
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zfs set special_small_blocks=131072 testpool
10:15:48.39 1588932903   spa_history.c:305:spa_history_log_sync(): command: zpool destroy -f testpool
10:15:48.39 1588932903   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): UNLOADING
10:15:48.39 1588932904   mmp.c:268:mmp_thread_stop(): MMP thread stopped pool 'testpool' gethrtime 996999639952
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts vigil.aerusso.net 5.6.0-1-cloud-amd64 #1 SMP Debian 5.6.7-1 (2020-04-29) x86_64
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
10:15:48.39 1588932904   mmp.c:248:mmp_thread_start(): MMP thread started pool 'testpool' gethrtime 997160106976
10:15:48.39 1588932904   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool raidz /tmp/x/device-0 /tmp/x/device-1 /tmp/x/device-2 special mirror /tmp/x/device-3 /tmp/x/device-4
10:15:48.39 1588932904   spa_history.c:305:spa_history_log_sync(): command: zpool destroy -f testpool
10:15:48.39 1588932904   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): UNLOADING
10:15:48.39 1588932904   mmp.c:268:mmp_thread_stop(): MMP thread stopped pool 'testpool' gethrtime 997423291275
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts vigil.aerusso.net 5.6.0-1-cloud-amd64 #1 SMP Debian 5.6.7-1 (2020-04-29) x86_64
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
10:15:48.39 1588932904   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
10:15:48.39 1588932904   mmp.c:248:mmp_thread_start(): MMP thread started pool 'testpool' gethrtime 997582606319
10:15:48.39 1588932904   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool /tmp/x/device-0 /tmp/x/device-1 /tmp/x/device-2 special /tmp/x/device-3 special /tmp/x/device-4
10:15:48.39 1588932906   spa_history.c:309:spa_history_log_sync(): txg 8 create testpool/testfs (id 259) 
10:15:48.39 1588932907   spa_history.c:309:spa_history_log_sync(): txg 9 set testpool/testfs (id 259) special_small_blocks=32768
10:15:48.39 1588932907   spa_history.c:309:spa_history_log_sync(): txg 9 set testpool/testfs (id 259) recordsize=32768
10:15:48.39 1588932908   spa_history.c:338:spa_history_log_sync(): ioctl create
10:15:48.39 1588932908   spa_history.c:305:spa_history_log_sync(): command: zfs create -o special_small_blocks=32K -o recordsize=32K testpool/testfs
10:15:48.39 1588932921   vdev_removal.c:346:vdev_remove_initiate_sync(): starting removal thread for vdev 3 (ffff91b91b6c0000) in txg 31 im_obj=279
10:15:48.39 1588932921   spa_history.c:316:spa_history_log_sync(): txg 31 vdev remove started testpool vdev 3 /tmp/x/device-3
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 10 segments for metaslab 0
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 7 segments for metaslab 1
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 4 segments for metaslab 2
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 7 segments for metaslab 3
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 1 segments for metaslab 4
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 2 segments for metaslab 5
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 1 segments for metaslab 6
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 1 segments for metaslab 7
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 2 segments for metaslab 8
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 2 segments for metaslab 9
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 0 segments for metaslab 10
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 0 segments for metaslab 11
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 0 segments for metaslab 12
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 0 segments for metaslab 13
10:15:48.39 1588932921   vdev_removal.c:1479:spa_vdev_remove_thread(): copying 0 segments for metaslab 14
10:15:48.39 1588932928   vdev_indirect_mapping.c:489:vdev_indirect_mapping_add_entries(): txg 32: wrote 16 entries to indirect mapping obj 279; max offset=0x12c5a000
10:15:48.39 1588932928   spa_history.c:305:spa_history_log_sync(): command: zpool remove testpool /tmp/x/device-3
10:15:48.39 1588932928   spa_history.c:338:spa_history_log_sync(): ioctl remap
10:15:48.39 1588932928   spa_history.c:305:spa_history_log_sync(): command: zfs remap testpool/testfs
10:15:48.39 1588932928   vdev_removal.c:1197:vdev_remove_complete(): finishing device removal for vdev 3 in txg 38
10:15:48.39 1588932928   spa_history.c:316:spa_history_log_sync(): txg 38 vdev remove completed testpool vdev 3
10:15:48.39 1588932933   spa_history.c:316:spa_history_log_sync(): txg 40 initialize vdev=/tmp/x/device-3 canceled
10:15:48.39 1588932933   spa_history.c:316:spa_history_log_sync(): txg 40 trim vdev=/tmp/x/device-3 canceled
10:15:48.39 1588932944   spa_history.c:305:spa_history_log_sync(): command: zpool destroy -f testpool
10:15:48.39 1588932944   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): UNLOADING
10:15:48.39 1588932944   mmp.c:268:mmp_thread_stop(): MMP thread stopped pool 'testpool' gethrtime 1037534578668
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts vigil.aerusso.net 5.6.0-1-cloud-amd64 #1 SMP Debian 5.6.7-1 (2020-04-29) x86_64
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
10:15:48.39 1588932944   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
10:15:48.39 1588932944   mmp.c:248:mmp_thread_start(): MMP thread started pool 'testpool' gethrtime 1037822052562
10:15:48.39 1588932944   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool /tmp/x/device-0 /tmp/x/device-1 /tmp/x/device-2 dedup /tmp/x/device-3
10:15:48.39 1588932947   spa_history.c:309:spa_history_log_sync(): txg 8 create testpool/testvol (id 259) 
10:15:48.39 1588932947   spa_history.c:309:spa_history_log_sync(): txg 9 set testpool/testvol (id 259) refreservation=2216689664
10:15:48.39 1588932947   spa_history.c:309:spa_history_log_sync(): txg 10 set testpool/testvol (id 259) dedup=1
10:15:48.39 1588932948   spa_history.c:338:spa_history_log_sync(): ioctl create
10:15:48.39 1588932948   spa_history.c:305:spa_history_log_sync(): command: zfs create -o dedup=on -V 2G testpool/testvol

Tailing last 200 lines of dmesg log

10:15:48.42 [    5.195606] Key type blacklist registered
10:15:48.42 [    5.200620] workingset: timestamp_bits=40 max_order=22 bucket_order=0
10:15:48.42 [    5.214453] zbud: loaded
10:15:48.42 [    5.218884] Key type asymmetric registered
10:15:48.42 [    5.220057] Asymmetric key parser 'x509' registered
10:15:48.42 [    5.221109] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
10:15:48.42 [    5.222852] io scheduler mq-deadline registered
10:15:48.42 [    5.225666] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
10:15:48.42 [    5.235444] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
10:15:48.42 [    5.239019] serio: i8042 KBD port at 0x60,0x64 irq 1
10:15:48.42 [    5.240222] serio: i8042 AUX port at 0x60,0x64 irq 12
10:15:48.42 [    5.241692] rtc_cmos 00:00: RTC can wake from S4
10:15:48.42 [    5.243512] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
10:15:48.42 [    5.246005] rtc_cmos 00:00: registered as rtc0
10:15:48.42 [    5.246979] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
10:15:48.42 [    5.248488] intel_pstate: CPU model not supported
10:15:48.42 [    5.257918] drop_monitor: Initializing network drop monitor service
10:15:48.42 [    5.267706] NET: Registered protocol family 10
10:15:48.42 [    5.328000] Segment Routing with IPv6
10:15:48.42 [    5.329009] mip6: Mobile IPv6
10:15:48.42 [    5.347131] NET: Registered protocol family 17
10:15:48.42 [    5.354495] IPI shorthand broadcast: enabled
10:15:48.42 [    5.356576] sched_clock: Marking stable (5263635815, 92926647)->(5855892709, -499330242)
10:15:48.42 [    5.365044] registered taskstats version 1
10:15:48.42 [    5.366044] Loading compiled-in X.509 certificates
10:15:48.42 [    5.457238] Loaded X.509 cert 'Debian Secure Boot CA: 6ccece7e4c6c0d1f6149f3dd27dfcc5cbb419ea1'
10:15:48.42 [    5.459546] Loaded X.509 cert 'Debian Secure Boot Signer: 00a7468def'
10:15:48.42 [    5.465901] Key type ._fscrypt registered
10:15:48.42 [    5.467211] Key type .fscrypt registered
10:15:48.42 [    5.468378] Key type fscrypt-provisioning registered
10:15:48.42 [    5.469914] AppArmor: AppArmor sha1 policy hashing enabled
10:15:48.42 [    5.474372] rtc_cmos 00:00: setting system clock to 2020-05-08T09:58:32 UTC (1588931912)
10:15:48.42 [    5.500008] Freeing unused kernel image (initmem) memory: 1520K
10:15:48.42 [    5.501945] Write protecting the kernel read-only data: 16384k
10:15:48.42 [    5.506148] Freeing unused kernel image (text/rodata gap) memory: 2044K
10:15:48.42 [    5.508357] Freeing unused kernel image (rodata/data gap) memory: 556K
10:15:48.42 [    5.510351] x86/mm: Checked W+X mappings: passed, no W+X pages found.
10:15:48.42 [    5.511644] x86/mm: Checking user space page tables
10:15:48.42 [    5.512773] x86/mm: Checked W+X mappings: passed, no W+X pages found.
10:15:48.42 [    5.514061] Run /init as init process
10:15:48.42 [    5.514846]   with arguments:
10:15:48.42 [    5.514847]     /init
10:15:48.42 [    5.514847]   with environment:
10:15:48.42 [    5.514848]     HOME=/
10:15:48.42 [    5.514849]     TERM=linux
10:15:48.42 [    5.514849]     BOOT_IMAGE=/boot/vmlinuz-5.6.0-1-cloud-amd64
10:15:48.42 [    5.514850]     biosdevname=0
10:15:48.42 [    5.515044] process '/usr/bin/sh' started with executable stack
10:15:48.42 [    5.563562] systemd-udevd[125]: Starting version 245.5-2
10:15:48.42 [    5.583172] systemd-udevd[126]: Network interface NamePolicy= disabled on kernel command line, ignoring.
10:15:48.42 [    5.597252] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:24 The line takes no effect, ignoring.
10:15:48.42 [    5.600021] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:25 The line takes no effect, ignoring.
10:15:48.42 [    5.602674] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:29 The line takes no effect, ignoring.
10:15:48.42 [    5.604829] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:32 The line takes no effect, ignoring.
10:15:48.42 [    5.606848] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:33 The line takes no effect, ignoring.
10:15:48.42 [    5.608799] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:34 The line takes no effect, ignoring.
10:15:48.42 [    5.610769] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:35 The line takes no effect, ignoring.
10:15:48.42 [    5.612716] systemd-udevd[126]: /usr/lib/udev/rules.d/50-udev-default.rules:36 The line takes no effect, ignoring.
10:15:48.42 [    5.730634] SCSI subsystem initialized
10:15:48.42 [    5.747617] PCI Interrupt Link [LNKC] enabled at IRQ 11
10:15:48.42 [    5.835120] libata version 3.00 loaded.
10:15:48.42 [    5.837715] ata_piix 0000:00:01.1: version 2.13
10:15:48.42 [    5.840835] scsi host0: ata_piix
10:15:48.42 [    5.846267] scsi host1: ata_piix
10:15:48.42 [    5.847629] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0c0 irq 14
10:15:48.42 [    5.850103] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0c8 irq 15
10:15:48.42 [    5.868641] PCI Interrupt Link [LNKD] enabled at IRQ 10
10:15:48.42 [    5.906442] PCI Interrupt Link [LNKB] enabled at IRQ 10
10:15:48.42 [    5.941725] scsi host2: Virtio SCSI HBA
10:15:48.42 [    5.945119] scsi 2:0:0:0: Direct-Access     QEMU     Vz HARDDISK0     2.5+ PQ: 0 ANSI: 5
10:15:48.42 [    6.039081] sd 2:0:0:0: Power-on or device reset occurred
10:15:48.42 [    6.041568] sd 2:0:0:0: [sda] 335544320 512-byte logical blocks: (172 GB/160 GiB)
10:15:48.42 [    6.043936] sd 2:0:0:0: [sda] Write Protect is off
10:15:48.42 [    6.045766] sd 2:0:0:0: [sda] Mode Sense: 63 00 00 08
10:15:48.42 [    6.046050] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
10:15:48.42 [    6.090441]  sda: sda1
10:15:48.42 [    6.106345] sd 2:0:0:0: [sda] Attached SCSI disk
10:15:48.42 [    6.296642] raid6: avx2x4   gen() 22514 MB/s
10:15:48.42 [    6.364631] raid6: avx2x4   xor() 10362 MB/s
10:15:48.42 [    6.432592] raid6: avx2x2   gen() 23228 MB/s
10:15:48.42 [    6.500644] raid6: avx2x2   xor() 12329 MB/s
10:15:48.42 [    6.572845] raid6: avx2x1   gen() 19286 MB/s
10:15:48.42 [    6.640614] raid6: avx2x1   xor()  9128 MB/s
10:15:48.42 [    6.708643] raid6: sse2x4   gen()  9444 MB/s
10:15:48.42 [    6.776644] raid6: sse2x4   xor()  3183 MB/s
10:15:48.42 [    6.844642] raid6: sse2x2   gen()  7979 MB/s
10:15:48.42 [    6.912619] raid6: sse2x2   xor()  6682 MB/s
10:15:48.42 [    6.980594] raid6: sse2x1   gen()  8764 MB/s
10:15:48.42 [    7.048657] raid6: sse2x1   xor()  5085 MB/s
10:15:48.42 [    7.049890] raid6: using algorithm avx2x2 gen() 23228 MB/s
10:15:48.42 [    7.051353] raid6: .... xor() 12329 MB/s, rmw enabled
10:15:48.42 [    7.052830] raid6: using avx2x2 recovery algorithm
10:15:48.42 [    7.056373] xor: automatically using best checksumming function   avx       
10:15:48.42 [    7.199700] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
10:15:48.42 [    7.269341] printk: systemd-udevd: 27 output lines suppressed due to ratelimiting
10:15:48.42 [    7.493357] systemd[1]: Inserted module 'autofs4'
10:15:48.42 [    7.527985] systemd[1]: systemd 245.5-2 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
10:15:48.42 [    7.531970] systemd[1]: Detected virtualization kvm.
10:15:48.42 [    7.533048] systemd[1]: Detected architecture x86-64.
10:15:48.42 [    7.550301] systemd[1]: Set hostname to <vigil.aerusso.net>.
10:15:48.42 [    7.800357] systemd[1]: /lib/systemd/system/rpc-statd.service:16: PIDFile= references a path below legacy directory /var/run/, updating /var/run/rpc.statd.pid \xe2\x86\x92 /run/rpc.statd.pid; please update the unit file accordingly.
10:15:48.42 [    7.818649] systemd[1]: /lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket \xe2\x86\x92 /run/dbus/system_bus_socket; please update the unit file accordingly.
10:15:48.42 [    7.864196] systemd[1]: /lib/systemd/system/docker.socket:6: ListenStream= references a path below legacy directory /var/run/, updating /var/run/docker.sock \xe2\x86\x92 /run/docker.sock; please update the unit file accordingly.
10:15:48.42 [    7.873585] systemd[1]: Created slice system-forward\x2dapt.slice.
10:15:48.42 [    7.875547] systemd[1]: Created slice system-forward\x2dssh.slice.
10:15:48.42 [    7.877658] systemd[1]: Created slice system-getty.slice.
10:15:48.42 [    7.879592] systemd[1]: Created slice system-modprobe.slice.
10:15:48.42 [    7.881978] systemd[1]: Created slice User and Session Slice.
10:15:48.42 [    7.883486] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
10:15:48.42 [    7.885364] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
10:15:48.42 [    7.887289] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
10:15:48.42 [    7.889398] systemd[1]: Reached target Local Encrypted Volumes.
10:15:48.42 [    7.891063] systemd[1]: Reached target Paths.
10:15:48.42 [    7.892375] systemd[1]: Reached target Slices.
10:15:48.42 [    7.893979] systemd[1]: Reached target Swap.
10:15:48.42 [    7.903673] systemd[1]: Listening on RPCbind Server Activation Socket.
10:15:48.42 [    7.906293] systemd[1]: Listening on Syslog Socket.
10:15:48.42 [    7.907976] systemd[1]: Listening on fsck to fsckd communication Socket.
10:15:48.42 [    7.910000] systemd[1]: Listening on initctl Compatibility Named Pipe.
10:15:48.42 [    7.912166] systemd[1]: Listening on Journal Audit Socket.
10:15:48.42 [    7.914178] systemd[1]: Listening on Journal Socket (/dev/log).
10:15:48.42 [    7.916305] systemd[1]: Listening on Journal Socket.
10:15:48.42 [    7.919337] systemd[1]: Listening on udev Control Socket.
10:15:48.42 [    7.920927] systemd[1]: Listening on udev Kernel Socket.
10:15:48.42 [    7.926181] systemd[1]: Mounting Huge Pages File System...
10:15:48.42 [    7.928883] systemd[1]: Mounting POSIX Message Queue File System...
10:15:48.42 [    7.933529] systemd[1]: Mounting NFSD configuration filesystem...
10:15:48.42 [    7.936436] systemd[1]: Mounting RPC Pipe File System...
10:15:48.42 [    7.943456] systemd[1]: Mounting Kernel Debug File System...
10:15:48.42 [    7.947399] systemd[1]: Mounting Kernel Trace File System...
10:15:48.42 [    7.949069] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
10:15:48.42 [    7.953855] systemd[1]: Starting Create list of static device nodes for the current kernel...
10:15:48.42 [    7.962045] systemd[1]: Starting Load Kernel Module drm...
10:15:48.42 [    7.965891] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
10:15:48.42 [    7.968003] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
10:15:48.42 [    7.974926] systemd[1]: Starting Journal Service...
10:15:48.42 [    7.987117] systemd[1]: Starting Load Kernel Modules...
10:15:48.42 [    7.991050] systemd[1]: Starting Remount Root and Kernel File Systems...
10:15:48.42 [    7.993927] systemd[1]: Starting udev Coldplug all Devices...
10:15:48.42 [    7.999527] systemd[1]: Mounted Huge Pages File System.
10:15:48.42 [    8.000924] systemd[1]: Mounted POSIX Message Queue File System.
10:15:48.42 [    8.002772] systemd[1]: Mounted Kernel Debug File System.
10:15:48.42 [    8.004451] systemd[1]: Mounted Kernel Trace File System.
10:15:48.42 [    8.007195] systemd[1]: Finished Create list of static device nodes for the current kernel.
10:15:48.42 [    8.010676] systemd[1]: modprobe@drm.service: Succeeded.
10:15:48.42 [    8.013379] systemd[1]: Finished Load Kernel Module drm.
10:15:48.42 [    8.028402] systemd[1]: Finished Load Kernel Modules.
10:15:48.42 [    8.028649] RPC: Registered named UNIX socket transport module.
10:15:48.42 [    8.029843] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
10:15:48.42 [    8.031000] RPC: Registered udp transport module.
10:15:48.42 [    8.033579] RPC: Registered tcp transport module.
10:15:48.42 [    8.033580] RPC: Registered tcp NFSv4.1 backchannel transport module.
10:15:48.42 [    8.037864] systemd[1]: Mounted RPC Pipe File System.
10:15:48.42 [    8.040132] systemd[1]: Finished Remount Root and Kernel File Systems.
10:15:48.42 [    8.048088] systemd[1]: Condition check resulted in FUSE Control File System being skipped.
10:15:48.42 [    8.052295] systemd[1]: Condition check resulted in Kernel Configuration File System being skipped.
10:15:48.42 [    8.058078] systemd[1]: Starting pNFS block layout mapping daemon...
10:15:48.42 [    8.087828] systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
10:15:48.42 [    8.090272] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.
10:15:48.42 [    8.096264] systemd[1]: Starting Apply Kernel Variables...
10:15:48.42 [    8.099229] systemd[1]: Starting Create System Users...
10:15:48.42 [    8.101210] systemd[1]: Started pNFS block layout mapping daemon.
10:15:48.42 [    8.114407] systemd[1]: Finished udev Coldplug all Devices.
10:15:48.42 [    8.118303] systemd[1]: Starting Helper to synchronize boot up for ifupdown...
10:15:48.42 [    8.121369] systemd[1]: Starting udev Wait for Complete Device Initialization...
10:15:48.42 [    8.140717] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
10:15:48.42 [    8.145150] systemd[1]: Mounted NFSD configuration filesystem.
10:15:48.42 [    8.180192] systemd[1]: Finished Create System Users.
10:15:48.42 [    8.187143] systemd[1]: Finished Apply Kernel Variables.
10:15:48.42 [    8.206073] systemd[1]: Starting Create Static Device Nodes in /dev...
10:15:48.42 [    8.241481] systemd[1]: Finished Create Static Device Nodes in /dev.
10:15:48.42 [    8.243166] systemd[1]: Reached target Local File Systems (Pre).
10:15:48.42 [    8.246184] systemd[1]: Starting udev Kernel Device Manager...
10:15:48.42 [    8.317203] systemd[1]: Started udev Kernel Device Manager.
10:15:48.42 [    8.367424] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
10:15:48.42 [    8.376389] ACPI: Power Button [PWRF]
10:15:48.42 [    8.485050] sd 2:0:0:0: Attached scsi generic sg0 type 0
10:15:48.42 [    8.506501] systemd[1]: Started Journal Service.
10:15:48.42 [    8.528275] systemd-journald[254]: Received client request to flush runtime journal.
10:15:48.42 [    8.885969] cryptd: max_cpu_qlen set to 1000
10:15:48.42 [    8.980391] AVX2 version of gcm_enc/dec engaged.
10:15:48.42 [    8.982099] AES CTR mode by8 optimization enabled
10:15:48.42 [    9.394633] spl: loading out-of-tree module taints kernel.
10:15:48.42 [    9.396134] spl: module verification failed: signature and/or required key missing - tainting kernel
10:15:48.42 [    9.404298] znvpair: module license 'CDDL' taints kernel.
10:15:48.42 [    9.405552] Disabling lock debugging due to kernel taint
10:15:48.42 [   11.592700] ZFS: Loaded module v0.8.4~0-0, ZFS pool version 5000, ZFS filesystem version 5
10:15:48.42 [   11.822196] audit: type=1400 audit(1588931918.844:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/man" pid=428 comm="apparmor_parser"
10:15:48.42 [   11.827080] audit: type=1400 audit(1588931918.844:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_filter" pid=428 comm="apparmor_parser"
10:15:48.42 [   11.832387] audit: type=1400 audit(1588931918.844:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_groff" pid=428 comm="apparmor_parser"
10:15:48.42 [   11.835718] audit: type=1400 audit(1588931918.844:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lsb_release" pid=429 comm="apparmor_parser"
10:15:48.42 [   11.835721] audit: type=1400 audit(1588931918.844:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=431 comm="apparmor_parser"
10:15:48.42 [   11.835725] audit: type=1400 audit(1588931918.844:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=431 comm="apparmor_parser"
10:15:48.42 [   11.835727] audit: type=1400 audit(1588931918.852:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/ntpd" pid=430 comm="apparmor_parser"
10:15:48.42 [   12.198267] audit: type=1400 audit(1588931919.219:9): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/run/systemd/userdb/" pid=498 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
10:15:48.42 [   13.407131] NFSD: Using UMH upcall client tracking operations.
10:15:48.42 [   13.408978] NFSD: starting 90-second grace period (net f0000098)
10:15:48.42 [  592.157701] audit: type=1400 audit(1588932497.954:10): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/run/systemd/userdb/" pid=1700 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
10:15:48.42 [  959.157710] loop: module loaded
10:15:48.42 [ 1024.262020] virtio_balloon virtio3: Out of puff! Can't get 1 pages

This is on a (hosted offsite) shared VM. The virtio_balloon error apparently indicates that the VM was not allocated enough memory at some point in the past. I can reproduce this test failure without the virtio_balloon complaint occurring during the run of the test.

EDIT: This test case passes on Debian's Linux kernel 5.5.17-1 and fails consistently on 5.6.7-1. Are we missing some 5.6 compatibility patches?

Outdated: I was able to get the full test suite to pass (after significant adjustments) on kernel 5.4 with ZFS 0.8.3, so I suspect this represents something actually failing.

There are other failures that I can reproduce, but this is the first one that occurs, and I've learned not to trust subsequent errors. If this is helpful, let me know and I can feed more test failures.

@ahrens
Copy link
Member

ahrens commented May 8, 2020

@Atemu We want to add the deprecation notice (which does NOT remove any functionality) so that folks can be aware of this in advance of the next major release (2.0), which will have the functionality removed.

@tonyhutter
Copy link
Contributor Author

Quick update - I've been testing the prospective 0.8.4 packages on Centos 6-8 and Fedora 30-32. They seem to be passing Centos, but are failing on the Fedoras with mostly the same tests:

Tests with results other than PASS that are unexpected:
    FAIL alloc_class/alloc_class_013_pos (expected PASS)
    FAIL cli_root/zpool_expand/zpool_expand_001_pos (expected PASS)
    FAIL cli_root/zpool_expand/zpool_expand_005_pos (expected PASS)
    FAIL removal/removal_remap (expected PASS)
    FAIL rsend/rsend_007_pos (expected PASS)
    FAIL rsend/rsend_010_pos (expected PASS)
    FAIL rsend/rsend_011_pos (expected PASS)

@aerusso that's the same alloc_class_013_pos failure I'm seeing on the Fedora 30-32. It's passing for me on Centos 6, 7, & 8 though. I'm going to try bisecting it down to see if it was caused by a commit, or if it's a kernel issue.

@Bronek yea the zvol changes are really great. I'd like to include them in the next release though, just to reduce risk in this release.

@aerusso
Copy link
Contributor

aerusso commented May 9, 2020

@tonyhutter The problem doesn't appear for me in Linux 5.5, but does in 5.6. (See my edit)

Also, I have seen some of those failures in my testing, but I haven't tried to understand any ones after the first failing test because the VM I'm running in is flaky and earlier failing results seem to trigger cascades of failures (i.e., "unable to create testpool" because it already exists).

@Atemu
Copy link

Atemu commented May 9, 2020

@ahrens thanks for clarifying, that makes a lot of sense actually!

@behlendorf
Copy link
Contributor

@tonyhutter @aerusso we're also seeing these test failures on the master branch with the 5.6 kernel.

@gamanakis
Copy link
Contributor

May I ask for #10283 to be considered? Now this is technically a new feature enabling mirrored pools with indirect vdevs to be split, and was just merged, but the added code is minimal.

@behlendorf behlendorf added the Status: Accepted Ready to integrate (reviewed, tested) label May 12, 2020
@tonyhutter tonyhutter merged commit 6b18d7d into openzfs:zfs-0.8-release May 12, 2020
@tonyhutter
Copy link
Contributor Author

@gamanakis thanks. We just put out the 0.8.4 release, but we'll take a look at that patch for 0.8.5.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Accepted Ready to integrate (reviewed, tested)
Projects
None yet
Development

Successfully merging this pull request may close these issues.