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
