[Pkg-zfsonlinux-devel] Bug#990100: zfs-dkms: Kernel Call Trace in arc_hdr_set_compress+0x50/0x50
James Youngman
james at youngman.org
Sun Jun 20 16:06:48 BST 2021
Package: zfs-dkms
Version: 2.0.3-1~bpo10+1
Severity: minor
Dear Maintainer,
*** Reporter, please consider answering these questions, where appropriate ***
* Don't know what provoked the call trace. This machine is mostly
used for "zfs recv", it is the target of ZFS replication but
otherwise is simply a standby machine.
* Not sure what provokes/prevents this problem, but it has not
happened for a couple of days now.
This machine has been running ZFS - the same pools - for years without problem. Recent changes:
1. Upgraded from ZFS 0.7.12 to 2.0.3.
2. Upgraded the pools to add support for recent features.
* What was the outcome of this action?
The machine still seems usable, so I'm not sure there's been any
permanent side effect (hence "minor" rating).
Here are some call traces from /var/log/messages:
Jun 13 00:00:05 asteroid rsyslogd: [origin software="rsyslogd" swVersion="8.1901.0" x-pid="1945" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Jun 13 00:00:08 asteroid colord[2885]: failed to get session [pid 4565]: No data available
Jun 13 00:00:13 asteroid colord[2885]: failed to get session [pid 4565]: No data available
Jun 13 00:19:55 asteroid kernel: [ 7281.246851] perf: interrupt took too long (2507 > 2500), lowering kernel.perf_event_max_sample_rate to 79750
Jun 13 02:40:23 asteroid kernel: [15709.868559] txg_sync D 0 817 2 0x80000000
Jun 13 02:40:23 asteroid kernel: [15709.868636] Call Trace:
Jun 13 02:40:23 asteroid kernel: [15709.868686] __schedule+0x29f/0x840
Jun 13 02:40:23 asteroid kernel: [15709.868743] schedule+0x28/0x80
Jun 13 02:40:23 asteroid kernel: [15709.868805] cv_wait_common+0xfb/0x130 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.868870] ? finish_wait+0x80/0x80
Jun 13 02:40:23 asteroid kernel: [15709.869125] arc_read+0x1ad/0x1200 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.869354] ? arc_hdr_set_compress+0x50/0x50 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.869617] dsl_scan_visitbp+0x213/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.869879] dsl_scan_visitbp+0x5ac/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.870139] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.870399] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.870659] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.870918] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.871178] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.871438] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.871698] dsl_scan_visitbp+0x81b/0xcf0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.871958] dsl_scan_visit_rootbp+0xe7/0x150 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.872222] dsl_scan_visitds+0x18c/0x4c0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.872357] ? try_to_wake_up+0x54/0x470
Jun 13 02:40:23 asteroid kernel: [15709.872417] ? __wake_up_common+0x7a/0x190
Jun 13 02:40:23 asteroid kernel: [15709.872476] ? _cond_resched+0x15/0x30
Jun 13 02:40:23 asteroid kernel: [15709.872531] ? __kmalloc_node+0x1ea/0x2c0
Jun 13 02:40:23 asteroid kernel: [15709.872602] ? spl_kmem_alloc+0xc6/0x110 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.872677] ? spl_kmem_alloc+0xc6/0x110 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.872752] ? tsd_hash_search.isra.2+0x42/0x90 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.872834] ? tsd_set+0x21c/0x480 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.873091] dsl_scan_sync+0x869/0x1330 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.873364] spa_sync+0x5fa/0xfb0 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.873421] ? _cond_resched+0x15/0x30
Jun 13 02:40:23 asteroid kernel: [15709.873680] ? spa_txg_history_init_io+0xfe/0x110 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.873961] txg_sync_thread+0x29f/0x480 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.874029] ? __switch_to_asm+0x35/0x70
Jun 13 02:40:23 asteroid kernel: [15709.874292] ? txg_thread_exit.isra.9+0x60/0x60 [zfs]
Jun 13 02:40:23 asteroid kernel: [15709.874375] ? __thread_exit+0x20/0x20 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.874448] thread_generic_wrapper+0x6f/0x80 [spl]
Jun 13 02:40:23 asteroid kernel: [15709.874520] kthread+0x112/0x130
Jun 13 02:40:23 asteroid kernel: [15709.874570] ? kthread_bind+0x30/0x30
Jun 13 02:40:23 asteroid kernel: [15709.874624] ret_from_fork+0x22/0x40
Jun 13 02:42:24 asteroid kernel: [15830.706295] txg_sync D 0 817 2 0x80000000
Jun 13 02:42:24 asteroid kernel: [15830.706372] Call Trace:
Jun 13 02:42:24 asteroid kernel: [15830.706426] __schedule+0x29f/0x840
Jun 13 02:42:24 asteroid kernel: [15830.706484] schedule+0x28/0x80
Jun 13 02:42:24 asteroid kernel: [15830.706547] cv_wait_common+0xfb/0x130 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.706612] ? finish_wait+0x80/0x80
Jun 13 02:42:24 asteroid kernel: [15830.706869] arc_read+0x1ad/0x1200 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.707099] ? arc_hdr_set_compress+0x50/0x50 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.707361] dsl_scan_visitbp+0x213/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.707623] dsl_scan_visitbp+0x5ac/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.707887] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.708147] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.707887] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.708147] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.708407] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.708666] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.708926] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.709185] dsl_scan_visitbp+0x2c0/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.709445] dsl_scan_visitbp+0x81b/0xcf0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.709706] dsl_scan_visit_rootbp+0xe7/0x150 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.709969] dsl_scan_visitds+0x18c/0x4c0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.710088] ? try_to_wake_up+0x54/0x470
Jun 13 02:42:24 asteroid kernel: [15830.710150] ? __wake_up_common+0x7a/0x190
Jun 13 02:42:24 asteroid kernel: [15830.710209] ? _cond_resched+0x15/0x30
Jun 13 02:42:24 asteroid kernel: [15830.710264] ? __kmalloc_node+0x1ea/0x2c0
Jun 13 02:42:24 asteroid kernel: [15830.710335] ? spl_kmem_alloc+0xc6/0x110 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.710410] ? spl_kmem_alloc+0xc6/0x110 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.713520] ? tsd_hash_search.isra.2+0x42/0x90 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.716711] ? tsd_set+0x21c/0x480 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.720152] dsl_scan_sync+0x869/0x1330 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.723422] spa_sync+0x5fa/0xfb0 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.726322] ? _cond_resched+0x15/0x30
Jun 13 02:42:24 asteroid kernel: [15830.729327] ? spa_txg_history_init_io+0xfe/0x110 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.732345] txg_sync_thread+0x29f/0x480 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.735116] ? __switch_to_asm+0x35/0x70
Jun 13 02:42:24 asteroid kernel: [15830.738042] ? txg_thread_exit.isra.9+0x60/0x60 [zfs]
Jun 13 02:42:24 asteroid kernel: [15830.740796] ? __thread_exit+0x20/0x20 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.743561] thread_generic_wrapper+0x6f/0x80 [spl]
Jun 13 02:42:24 asteroid kernel: [15830.746341] kthread+0x112/0x130
Jun 13 02:42:24 asteroid kernel: [15830.749054] ? kthread_bind+0x30/0x30
Jun 13 02:42:24 asteroid kernel: [15830.751811] ret_from_fork+0x22/0x40
Jun 13 14:01:04 asteroid kernel: [56553.020948] zfs D 0 30111 31086 0x00000000
Jun 13 14:01:04 asteroid kernel: [56553.024661] Call Trace:
Jun 13 14:01:04 asteroid kernel: [56553.028386] __schedule+0x29f/0x840
Jun 13 14:01:04 asteroid kernel: [56553.032152] ? spl_kmem_cache_free+0xec/0x1c0 [spl]
Jun 13 14:01:04 asteroid kernel: [56553.035936] schedule+0x28/0x80
Jun 13 14:01:04 asteroid kernel: [56553.039724] io_schedule+0x12/0x40
Jun 13 14:01:04 asteroid kernel: [56553.043541] cv_wait_common+0xaf/0x130 [spl]
Jun 13 14:01:04 asteroid kernel: [56553.047332] ? finish_wait+0x80/0x80
Jun 13 14:01:04 asteroid kernel: [56553.051355] txg_wait_synced_impl+0xc2/0x110 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.055397] txg_wait_synced+0xc/0x40 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.059441] zil_close+0x252/0x270 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.063523] zfsvfs_teardown+0xa1/0x320 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.067645] zfs_ioc_rollback+0xf6/0x180 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.071917] zfsdev_ioctl_common+0x448/0x830 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.076057] zfsdev_ioctl+0x4f/0xe0 [zfs]
Jun 13 14:01:04 asteroid kernel: [56553.079880] do_vfs_ioctl+0xa4/0x630
Jun 13 14:01:04 asteroid kernel: [56553.083682] ? handle_mm_fault+0xd6/0x200
Jun 13 14:01:04 asteroid kernel: [56553.087479] ksys_ioctl+0x60/0x90
Jun 13 14:01:04 asteroid kernel: [56553.091254] __x64_sys_ioctl+0x16/0x20
Jun 13 14:01:04 asteroid kernel: [56553.095033] do_syscall_64+0x53/0x110
Jun 13 14:01:04 asteroid kernel: [56553.098804] entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jun 13 14:01:04 asteroid kernel: [56553.102586] RIP: 0033:0x7fdc0f2ee427
Jun 13 14:01:04 asteroid kernel: [56553.106354] Code: Bad RIP value.
Jun 13 14:01:04 asteroid kernel: [56553.110159] RSP: 002b:00007ffda06fe508 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jun 13 14:01:04 asteroid kernel: [56553.113953] RAX: ffffffffffffffda RBX: 00007ffda06fe530 RCX: 00007fdc0f2ee427
Jun 13 14:01:04 asteroid kernel: [56553.117835] RDX: 00007ffda06fe530 RSI: 0000000000005a19 RDI: 0000000000000005
Jun 13 14:01:04 asteroid kernel: [56553.121687] RBP: 00007ffda0701b20 R08: 0000000000000003 R09: 00007fdc0f3b9cd0
Jun 13 14:01:04 asteroid kernel: [56553.125525] R10: 0000562a3025b010 R11: 0000000000000246 R12: 00007ffda0701b30
Jun 13 14:01:04 asteroid kernel: [56553.129329] R13: 0000000000005a19 R14: 0000000000005a19 R15: 0000562a3025fd80
* What outcome did you expect instead?
Well, I didn't expect stack back-traces in my syslog.
Bug to nitpick, if there are going to be stack backtraces, I'd like
some kind of header to be in there to explain what event motivated
logging the stack back trace.
-- System Information:
Debian Release: 10.9
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Kernel: Linux 4.19.0-16-amd64 (SMP w/2 CPU cores)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_IE.UTF-8, LC_CTYPE=en_IE.UTF-8 (charmap=UTF-8), LANGUAGE=en_IE.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages zfs-dkms depends on:
ii debconf [debconf-2.0] 1.5.71
ii dkms 2.6.1-4
ii file 1:5.35-4+deb10u2
ii libc6-dev [libc-dev] 2.28-10
ii libpython3-stdlib 3.7.3-1
ii lsb-release 10.2019051400
ii perl 5.28.1-6+deb10u1
ii python3-distutils 3.7.3-1
Versions of packages zfs-dkms recommends:
ii linux-libc-dev 4.19.181-1
ii zfs-zed 0.7.12-2+deb10u2
ii zfsutils-linux 2.0.3-1~bpo10+1
Versions of packages zfs-dkms suggests:
ii debhelper 12.1.1
-- debconf information:
* zfs-dkms/note-incompatible-licenses:
zfs-dkms/stop-build-for-32bit-kernel: true
zfs-dkms/stop-build-for-unknown-kernel: true
More information about the Pkg-zfsonlinux-devel
mailing list