************************ crashinfo ************************* /exports/testreports/47154/testresults/replay-ost-single-zfs-centos7_x86_64-centos7_x86_64/oleg354-server-timeout-core (3.10.0-7.9-debug) +==========================+ | *** Crashinfo v1.3.7 *** | +==========================+ +++WARNING+++ PARTIAL DUMP with size(vmcore) < 25% size(RAM) KERNEL: /tmp/crash-anaysis.ZQjLQ/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/replay-ost-single-zfs-centos7_x86_64-centos7_x86_64/oleg354-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 12:30:48 EST 2024 UPTIME: 00:23:39 LOAD AVERAGE: 0.06, 0.03, 0.05 TASKS: 328 NODENAME: oleg354-server.virtnet RELEASE: 3.10.0-7.9-debug VERSION: #1 SMP Sat Mar 26 23:28:42 EDT 2022 MACHINE: x86_64 (2399 Mhz) MEMORY: 4 GB PANIC: "" +--------------------------+ >------------------------| Per-cpu Stacks ('bt -a') |------------------------< +--------------------------+ -- CPU#0 -- PID=0 CPU=0 CMD=swapper/0 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 rest_init+0x8e #7 start_kernel+0x456 #8 x86_64_start_reservations+0x2a #9 x86_64_start_kernel+0x152 #10 start_cpu+0x5 -- CPU#1 -- PID=0 CPU=1 CMD=swapper/1 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 start_secondary+0x1eb #7 start_cpu+0x5 -- CPU#2 -- PID=0 CPU=2 CMD=swapper/2 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 start_secondary+0x1eb #7 start_cpu+0x5 -- CPU#3 -- PID=0 CPU=3 CMD=swapper/3 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 start_secondary+0x1eb #7 start_cpu+0x5 +--------------------------------+ >---------------------| How This Dump Has Been Created |---------------------< +--------------------------------+ Cannot identify the specific condition that triggered vmcore +---------------+ >------------------------------| Tasks Summary |------------------------------< +---------------+ Number of Threads That Ran Recently ----------------------------------- last second 25 last 5s 62 last 60s 76 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 324 TASK_RUNNING 1 +++WARNING+++ There are 3 threads running in their own namespaces Use 'taskinfo --ns' to get more details +-----------------------+ >--------------------------| 5 Most Recent Threads |--------------------------< +-----------------------+ PID CMD Age ARGS ----- -------------- ------ ---------------------------- 27 rcuos/2 0 ms (no user stack) 46 kworker/0:1 0 ms (no user stack) 3483 dbuf_evict 0 ms (no user stack) 9345 z_null_int 0 ms (no user stack) 9344 z_null_iss 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 746416 2.8 GB 78% of TOTAL MEM USED 208651 815 MB 21% of TOTAL MEM SHARED 9174 35.8 MB 0% of TOTAL MEM BUFFERS 5123 20 MB 0% of TOTAL MEM CACHED 70524 275.5 MB 7% of TOTAL MEM SLAB 16811 65.7 MB 1% of TOTAL MEM TOTAL HUGE 0 0 ---- HUGE FREE 0 0 0% of TOTAL HUGE TOTAL SWAP 262143 1024 MB ---- SWAP USED 0 0 0% of TOTAL SWAP SWAP FREE 262143 1024 MB 100% of TOTAL SWAP COMMIT LIMIT 739676 2.8 GB ---- COMMITTED 58986 230.4 MB 7% of TOTAL LIMIT +-------------------------------+ >----------------------| Scheduler Runqueues (per CPU) |----------------------< +-------------------------------+ ---+ CPU=0 ---- | CURRENT TASK , CMD=swapper/0 ---+ CPU=1 ---- | CURRENT TASK , CMD=swapper/1 ---+ CPU=2 ---- | CURRENT TASK , CMD=swapper/2 ---+ CPU=3 ---- | CURRENT TASK , CMD=swapper/3 +------------------------+ >-------------------------| Network Status Summary |-------------------------< +------------------------+ TCP Connection Info ------------------- ESTABLISHED 9 LISTEN 3 NAGLE disabled (TCP_NODELAY): 7 user_data set (NFS etc.): 8 UDP Connection Info ------------------- 2 UDP sockets, 0 in ESTABLISHED Unix Connection Info ------------------------ ESTABLISHED 26 CLOSE 17 LISTEN 8 Raw sockets info -------------------- ESTABLISHED 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 1416.4 eth0 n/a 1.3 RSS_TOTAL=51980 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a39c000 ffff88012a3a0000 sysfs sysfs /sys ffff88012a39c1c0 ffff880139944000 proc proc /proc ffff88012a39c380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a39c540 ffff8800b51e2000 securityfs securityfs /sys/kernel/security ffff88012a39c700 ffff88012a3a0800 tmpfs tmpfs /dev/shm ffff88012a39c8c0 ffff880137161800 devpts devpts /dev/pts ffff88012a39ca80 ffff88012a3a1000 tmpfs tmpfs /run ffff88012a39cc40 ffff88012a3a1800 tmpfs tmpfs /sys/fs/cgroup ffff88012a39ce00 ffff88012a3a2000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a39cfc0 ffff88012a3a2800 pstore pstore /sys/fs/pstore ffff88012a39d180 ffff88012a3a4800 cgroup cgroup /sys/fs/cgroup/memory ffff88012a39d340 ffff88012a3a4000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a39d500 ffff88012a3a3800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a39d6c0 ffff88012a3a3000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a39d880 ffff88012a3a5000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a39da40 ffff88012a3a5800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a39dc00 ffff88012a3a6000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a39ddc0 ffff88012a3a6800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a304000 ffff88012a3a7000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a3041c0 ffff88012a3a7800 cgroup cgroup /sys/fs/cgroup/cpuset ffff8800b48c2000 ffff880129cd2800 configfs configfs /sys/kernel/config ffff88012a304380 ffff8800b5222000 ext4 /dev/nbd0 / ffff88012a304540 ffff8800b51e4800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8800b48c2540 ffff8800b402c000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a304c40 ffff880137163000 mqueue mqueue /dev/mqueue ffff8800b48c2700 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8800b48c28c0 ffff8800b402a800 hugetlbfs hugetlbfs /dev/hugepages ffff88012a304e00 ffff88013683a800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012a305180 ffff880136839800 ramfs none /mnt ffff88012a305340 ffff880136838800 tmpfs none /var/lib/stateless/writable ffff8800b48c2a80 ffff880129cd5800 squashfs /dev/vda /home/green/git/lustre-release ffff88012a305500 ffff880136838800 tmpfs none /var/cache/man ffff8800b48c2c40 ffff880136838800 tmpfs none /var/log ffff88012a3056c0 ffff880136838800 tmpfs none /var/lib/dbus ffff88012a305880 ffff880136838800 tmpfs none /tmp ffff88012a305a40 ffff880136838800 tmpfs none /var/lib/dhclient ffff880137668700 ffff880136838800 tmpfs none /var/tmp ffff8800b48c2e00 ffff880136838800 tmpfs none /var/lib/NetworkManager ffff88012a305c00 ffff880136838800 tmpfs none /var/lib/systemd/random-seed ffff8800b48c2fc0 ffff880136838800 tmpfs none /var/spool ffff88012a305dc0 ffff880136838800 tmpfs none /var/lib/nfs ffff88012a304a80 ffff880136838800 tmpfs none /var/lib/gssproxy ffff8801376688c0 ffff880136838800 tmpfs none /var/lib/logrotate ffff88012a3048c0 ffff880136838800 tmpfs none /etc ffff88012a304700 ffff880136838800 tmpfs none /var/lib/rsyslog ffff8800b1974000 ffff880136838800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8800b48c3180 ffff8800b4996000 nfs4 192.168.200.253:/exports/state/oleg354-server.virtnet /var/lib/stateless/state ffff8800b19741c0 ffff8800b4996000 nfs4 192.168.200.253:/exports/state/oleg354-server.virtnet /boot ffff8800b1974380 ffff8800b4996000 nfs4 192.168.200.253:/exports/state/oleg354-server.virtnet /etc/etc/kdump.conf ffff8800b1974540 ffff8800b51e4800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b23c5a40 ffff880129cd5800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b1b31880 ffff8800a50d4800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8801376696c0 ffff88009c139800 lustre lustre-ost2/ost2 /mnt/lustre-ost2 ffff8800a885b180 ffff8800944ff000 lustre lustre-ost1/ost1 /mnt/lustre-ost1 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 124.944244] LustreError: lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 124.950442] LustreError: Skipped 1 previous similar message [ 128.921203] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 128.927531] mount.lustre (17452) used greatest stack depth: 9672 bytes left [ 130.355104] Lustre: DEBUG MARKER: oleg354-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 130.669265] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 130.898133] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 130.903820] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.203.154@tcp (at 0@lo) [ 133.185455] Lustre: DEBUG MARKER: oleg354-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 133.586431] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 136.218281] Lustre: DEBUG MARKER: == replay-ost-single test 2: |x| 10 open(O_CREAT)s ======= 12:09:25 (1731517765) [ 136.802257] Lustre: Failing over lustre-OST0000 [ 136.821224] Lustre: server umount lustre-OST0000 complete [ 138.927212] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 138.929348] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 138.932300] LustreError: lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 138.935220] LustreError: Skipped 1 previous similar message [ 148.481173] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 149.540410] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 150.045557] Lustre: DEBUG MARKER: oleg354-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 150.347037] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 150.350509] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.203.154@tcp (at 0@lo) [ 152.684589] Lustre: DEBUG MARKER: oleg354-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 153.084604] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 198.607740] Lustre: ll_ost00_000: service thread pid 8372 was inactive for 40.120 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 198.611777] Pid: 8372, comm: ll_ost00_000 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 198.613612] Call Trace: [ 198.614295] [<0>] ldlm_completion_ast+0x913/0xd50 [ptlrpc] [ 198.615662] [<0>] ldlm_cli_enqueue_local+0x259/0x890 [ptlrpc] [ 198.617080] [<0>] ofd_destroy_by_fid+0x19c/0x610 [ofd] [ 198.618201] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 198.619577] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 198.621112] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 198.622965] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 198.624616] [<0>] kthread+0xe4/0xf0 [ 198.625667] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 198.627334] [<0>] 0xfffffffffffffffe [ 258.639859] LustreError: 7033:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 101s: evicting client at 192.168.203.54@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a5ef58c0/0xcdd19ad4e7f121c lrc: 3/0,0 mode: PR/PR res: [0x240000400:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400010020 nid: 192.168.203.54@tcp remote: 0x87cc564758a76ac0 expref: 15 pid: 8372 timeout: 257 lvb_type: 1 [ 258.663446] Lustre: ll_ost00_000: service thread pid 8372 completed after 100.176s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 293.712186] Lustre: lustre-OST0000: haven't heard from client fb6c388c-d38d-4d71-bfc0-1dda32a060f4 (at 192.168.203.54@tcp) in 32 seconds. I think it's dead, and I am evicting it. exp ffff88012c9d1000, cur 1731517922 expire 1731517892 last 1731517890 ****************************************************************************** ************************ A Summary Of Problems Found ************************* ****************************************************************************** -------------------- A list of all +++WARNING+++ messages -------------------- PARTIAL DUMP with size(vmcore) < 25% size(RAM) There are 3 threads running in their own namespaces Use 'taskinfo --ns' to get more details ------------------------------------------------------------------------------ ** Execution took 12.38s (real) 6.87s (CPU), Child processes: 5.45s