************************ crashinfo ************************* /exports/testreports/42551/testresults/recovery-small-zfs-centos7_x86_64-centos7_x86_64/oleg318-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.SGNCu/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/recovery-small-zfs-centos7_x86_64-centos7_x86_64/oleg318-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 19:09:16 EDT 2024 UPTIME: 01:08:26 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 392 NODENAME: oleg318-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 43 last 5s 63 last 60s 77 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 388 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 ----- -------------- ------ ---------------------------- 3221 ptlrpcd_00_03 0 ms (no user stack) 8539 ll_ost_create00 0 ms (no user stack) 9823 mmp 0 ms (no user stack) 50 kworker/3:1 0 ms (no user stack) 9749 z_null_int 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 703936 2.7 GB 73% of TOTAL MEM USED 251131 981 MB 26% of TOTAL MEM SHARED 8577 33.5 MB 0% of TOTAL MEM BUFFERS 5130 20 MB 0% of TOTAL MEM CACHED 66045 258 MB 6% of TOTAL MEM SLAB 25689 100.3 MB 2% 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 59003 230.5 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 4103.2 eth0 n/a 4.0 RSS_TOTAL=56972 pages, %mem= 0.9 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff880137678800 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff8800b5239800 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff880137679000 tmpfs tmpfs /dev/shm ffff880137668c40 ffff88012b290800 devpts devpts /dev/pts ffff880137668e00 ffff880137679800 tmpfs tmpfs /run ffff880137668fc0 ffff88013767a000 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff88013767a800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff88013767b000 pstore pstore /sys/fs/pstore ffff880137669500 ffff88013767d000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff8801376696c0 ffff88013767c800 cgroup cgroup /sys/fs/cgroup/devices ffff880137669880 ffff88013767c000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff880137669a40 ffff88013767b800 cgroup cgroup /sys/fs/cgroup/freezer ffff880137669c00 ffff88013767d800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880137669dc0 ffff88013767e000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a340000 ffff88013767e800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a3401c0 ffff88013767f000 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a340380 ffff88013767f800 cgroup cgroup /sys/fs/cgroup/memory ffff88012a340540 ffff88012a350000 cgroup cgroup /sys/fs/cgroup/perf_event ffff8800b4cb61c0 ffff8800b4d3a000 configfs configfs /sys/kernel/config ffff8800b4cb7340 ffff8800b4d39800 ext4 /dev/nbd0 / ffff8800b4cb7500 ffff88012b357000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff880137013340 ffff8800b4282800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880138ccaa80 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880138ccac40 ffff8800b4db8000 hugetlbfs hugetlbfs /dev/hugepages ffff880137013180 ffff88012b292000 mqueue mqueue /dev/mqueue ffff8801370136c0 ffff8800b4280800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8800b4cb76c0 ffff880129c9b000 ramfs none /mnt ffff880137013880 ffff8800b4046800 squashfs /dev/vda /home/green/git/lustre-release ffff88012a340e00 ffff8800b4d3c800 tmpfs none /var/lib/stateless/writable ffff88012a340fc0 ffff8800b4d3c800 tmpfs none /var/cache/man ffff880138ccae00 ffff8800b4d3c800 tmpfs none /var/log ffff88012a341180 ffff8800b4d3c800 tmpfs none /var/lib/dbus ffff88012a341340 ffff8800b4d3c800 tmpfs none /tmp ffff8800b4cb7a40 ffff8800b4d3c800 tmpfs none /var/lib/dhclient ffff880138ccafc0 ffff8800b4d3c800 tmpfs none /var/tmp ffff88012a341500 ffff8800b4d3c800 tmpfs none /var/lib/NetworkManager ffff880138ccb180 ffff8800b4d3c800 tmpfs none /var/lib/systemd/random-seed ffff88012a3416c0 ffff8800b4d3c800 tmpfs none /var/spool ffff8800b4cb7c00 ffff8800b4d3c800 tmpfs none /var/lib/nfs ffff8800b4cb7dc0 ffff8800b4d3c800 tmpfs none /var/lib/gssproxy ffff88012a341880 ffff8800b4d3c800 tmpfs none /var/lib/logrotate ffff880138ccb340 ffff8800b4d3c800 tmpfs none /etc ffff88012a341a40 ffff8800b4d3c800 tmpfs none /var/lib/rsyslog ffff88012a341c00 ffff8800b4d3c800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff880137013a40 ffff8800b523d800 nfs4 192.168.200.253:/exports/state/oleg318-server.virtnet /var/lib/stateless/state ffff88012a3961c0 ffff8800b523d800 nfs4 192.168.200.253:/exports/state/oleg318-server.virtnet /boot ffff880138ccb500 ffff8800b523d800 nfs4 192.168.200.253:/exports/state/oleg318-server.virtnet /etc/etc/kdump.conf ffff880138ccb6c0 ffff88012b357000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff880129cba1c0 ffff8800b4046800 squashfs /dev/vda /usr/sbin/mount.lustre ffff88012a297dc0 ffff8800a6b2d800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff88012a297500 ffff880099f49800 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff880129cbb180 ffff880092a5b000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 402.703914] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 402.706258] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 402.707505] [<0>] kthread+0xe4/0xf0 [ 402.708658] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 402.710153] [<0>] 0xfffffffffffffffe [ 404.980552] Lustre: ll_ost00_000: service thread pid 8535 was inactive for 40.133 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 404.988389] Pid: 8535, comm: ll_ost00_000 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 404.991937] Call Trace: [ 404.993257] [<0>] ptlrpc_set_wait+0x7cf/0x850 [ptlrpc] [ 404.995416] [<0>] ldlm_run_ast_work+0xe3/0x400 [ptlrpc] [ 404.997757] [<0>] ldlm_handle_conflict_lock+0x70/0x300 [ptlrpc] [ 404.999997] [<0>] ldlm_lock_enqueue+0x5c2/0xbb0 [ptlrpc] [ 405.002271] [<0>] ldlm_cli_enqueue_local+0x377/0x880 [ptlrpc] [ 405.003905] [<0>] ofd_destroy_by_fid+0x1d1/0x520 [ofd] [ 405.005468] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 405.006540] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 405.007766] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 405.009480] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 405.010476] [<0>] kthread+0xe4/0xf0 [ 405.011306] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 405.012602] [<0>] 0xfffffffffffffffe [ 410.582616] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1715206044/real 1715206044] req@ffff88008d883480 x1798523513254848/t0(0) o104->lustre-MDT0000@192.168.203.18@tcp:15/16 lens 328/224 e 0 to 1 dl 1715206060 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 426.590566] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1715206060/real 1715206060] req@ffff88008d883480 x1798523513254848/t0(0) o104->lustre-MDT0000@192.168.203.18@tcp:15/16 lens 328/224 e 0 to 1 dl 1715206076 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 426.598586] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 442.600588] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1715206076/real 1715206076] req@ffff88008d883480 x1798523513254848/t0(0) o104->lustre-MDT0000@192.168.203.18@tcp:15/16 lens 328/224 e 0 to 1 dl 1715206092 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 442.607721] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 474.610564] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1715206108/real 1715206108] req@ffff88008d883480 x1798523513254848/t0(0) o104->lustre-MDT0000@192.168.203.18@tcp:15/16 lens 328/224 e 0 to 1 dl 1715206124 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 474.617962] Lustre: 8576:0:(client.c:2343:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 474.620270] LustreError: 8576:0:(ldlm_lockd.c:780:ldlm_handle_ast_error()) ### client (nid 192.168.203.18@tcp) failed to reply to blocking AST (req@ffff88008d883480 x1798523513254848 status 0 rc -110), evict it ns: mdt-lustre-MDT0000_UUID lock: ffff8800a6cd5d40/0x29a0ba74a4234889 lrc: 4/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x60200400000020 nid: 192.168.203.18@tcp remote: 0xd88b6d1d4ac46455 expref: 9 pid: 8576 timeout: 558 lvb_type: 0 [ 474.630693] LustreError: 138-a: lustre-MDT0000: A client on nid 192.168.203.18@tcp was evicted due to a lock blocking callback time out: rc -110 [ 474.633713] LustreError: 6936:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 16s: evicting client at 192.168.203.18@tcp ns: mdt-lustre-MDT0000_UUID lock: ffff8800a6cd5d40/0x29a0ba74a4234889 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x60200400000020 nid: 192.168.203.18@tcp remote: 0xd88b6d1d4ac46455 expref: 10 pid: 8576 timeout: 0 lvb_type: 0 [ 476.861569] LustreError: 8535:0:(ldlm_lockd.c:780:ldlm_handle_ast_error()) ### client (nid 192.168.203.18@tcp) failed to reply to blocking AST (req@ffff88008e63ad80 x1798523513254976 status 0 rc -110), evict it ns: filter-lustre-OST0000_UUID lock: ffff8800a6cd5680/0x29a0ba74a4234747 lrc: 4/0,0 mode: PW/PW res: [0x240000400:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4194303) gid 0 flags: 0x60000400030020 nid: 192.168.203.18@tcp remote: 0xd88b6d1d4ac463f3 expref: 6 pid: 11807 timeout: 560 lvb_type: 0 [ 476.872146] LustreError: 138-a: lustre-OST0000: A client on nid 192.168.203.18@tcp was evicted due to a lock blocking callback time out: rc -110 [ 476.875625] LustreError: 6936:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 16s: evicting client at 192.168.203.18@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a6cd5680/0x29a0ba74a4234747 lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4194303) gid 0 flags: 0x60000400030020 nid: 192.168.203.18@tcp remote: 0xd88b6d1d4ac463f3 expref: 7 pid: 11807 timeout: 0 lvb_type: 0 [ 477.779033] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 18:08:46 (1715206126) [ 496.877221] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 18:09:06 (1715206146) [ 497.939686] Lustre: lustre-MDT0000: Client 2c4cbcf6-7c0b-429e-b511-ec9c5e994379 (at 192.168.203.18@tcp) reconnecting [ 497.942648] Lustre: Skipped 2 previous similar messages [ 500.841099] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 18:09:10 (1715206150) [ 512.229008] Lustre: lustre-OST0000: haven't heard from client 2c4cbcf6-7c0b-429e-b511-ec9c5e994379 (at 192.168.203.18@tcp) in 32 seconds. I think it's dead, and I am evicting it. exp ffff88008d3e2000, cur 1715206162 expire 1715206132 last 1715206130 ****************************************************************************** ************************ 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.55s (real) 7.09s (CPU), Child processes: 5.45s