************************ crashinfo ************************* /exports/testreports/47154/testresults/recovery-small-zfs-centos7_x86_64-centos7_x86_64/oleg360-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.5nANf/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/recovery-small-zfs-centos7_x86_64-centos7_x86_64/oleg360-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 13:15:28 EST 2024 UPTIME: 01:08:17 LOAD AVERAGE: 0.00, 0.03, 0.05 TASKS: 331 NODENAME: oleg360-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 67 last 60s 76 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 327 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 ----- -------------- ------ ---------------------------- 9446 mmp 0 ms (no user stack) 7055 ldlm_bl_01 0 ms (no user stack) 64 kworker/0:1 0 ms (no user stack) 46 kworker/2:1 0 ms (no user stack) 9389 z_null_int 143 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 736710 2.8 GB 77% of TOTAL MEM USED 218357 853 MB 22% of TOTAL MEM SHARED 9546 37.3 MB 0% of TOTAL MEM BUFFERS 5123 20 MB 0% of TOTAL MEM CACHED 70516 275.5 MB 7% of TOTAL MEM SLAB 17114 66.9 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 58982 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 4095.0 eth0 n/a 1.4 RSS_TOTAL=51768 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff8800b5229800 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff88012a2e8000 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff8800b522a000 tmpfs tmpfs /dev/shm ffff880137668c40 ffff880137306800 devpts devpts /dev/pts ffff880137668e00 ffff8800b522a800 tmpfs tmpfs /run ffff880137668fc0 ffff8800b522b000 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff8800b522b800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff8800b522c000 pstore pstore /sys/fs/pstore ffff880137669500 ffff8800b522e000 cgroup cgroup /sys/fs/cgroup/perf_event ffff8801376696c0 ffff8800b522d800 cgroup cgroup /sys/fs/cgroup/freezer ffff880137669880 ffff8800b522d000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff880137669a40 ffff8800b522c800 cgroup cgroup /sys/fs/cgroup/blkio ffff880137669c00 ffff8800b522e800 cgroup cgroup /sys/fs/cgroup/devices ffff880137669dc0 ffff8800b522f000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a2c4000 ffff8800b522f800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a2c41c0 ffff88012a318000 cgroup cgroup /sys/fs/cgroup/memory ffff88012a2c4380 ffff88012a318800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a2c4540 ffff88012a319000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a2c48c0 ffff88012a31c800 configfs configfs /sys/kernel/config ffff880138ccbc00 ffff88012b358800 ext4 /dev/nbd0 / ffff880138ccbdc0 ffff88012a2ec800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8801370b8e00 ffff88012a31f800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a2c4a80 ffff8800b4349800 hugetlbfs hugetlbfs /dev/hugepages ffff8801370b9180 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8801370b8fc0 ffff88012b270000 mqueue mqueue /dev/mqueue ffff88012a2c4c40 ffff8800b4348800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8801370b9340 ffff8800b4eeb800 ramfs none /mnt ffff88012a28ee00 ffff8800b4e22800 tmpfs none /var/lib/stateless/writable ffff88012a2c4e00 ffff8800b21a2000 squashfs /dev/vda /home/green/git/lustre-release ffff88012a2c4fc0 ffff8800b4e22800 tmpfs none /var/cache/man ffff8800b40aa1c0 ffff8800b4e22800 tmpfs none /var/log ffff88012a2c5180 ffff8800b4e22800 tmpfs none /var/lib/dbus ffff88012a2c5340 ffff8800b4e22800 tmpfs none /tmp ffff88012a2c5500 ffff8800b4e22800 tmpfs none /var/lib/dhclient ffff88012a28efc0 ffff8800b4e22800 tmpfs none /var/tmp ffff88012a2c56c0 ffff8800b4e22800 tmpfs none /var/lib/NetworkManager ffff88012a2c5880 ffff8800b4e22800 tmpfs none /var/lib/systemd/random-seed ffff8800b40aa380 ffff8800b4e22800 tmpfs none /var/spool ffff88012a2c5a40 ffff8800b4e22800 tmpfs none /var/lib/nfs ffff8800b40aa540 ffff8800b4e22800 tmpfs none /var/lib/gssproxy ffff88012a2c5c00 ffff8800b4e22800 tmpfs none /var/lib/logrotate ffff88012a2c5dc0 ffff8800b4e22800 tmpfs none /etc ffff8800b42f4000 ffff8800b4e22800 tmpfs none /var/lib/rsyslog ffff8800b42f41c0 ffff8800b4e22800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8800b40aa700 ffff8800b21a3800 nfs4 192.168.200.253:/exports/state/oleg360-server.virtnet /var/lib/stateless/state ffff88012a28f180 ffff8800b21a3800 nfs4 192.168.200.253:/exports/state/oleg360-server.virtnet /boot ffff88012a28f340 ffff8800b21a3800 nfs4 192.168.200.253:/exports/state/oleg360-server.virtnet /etc/etc/kdump.conf ffff88012a28f500 ffff88012a2ec800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff880129c96700 ffff8800b21a2000 squashfs /dev/vda /usr/sbin/mount.lustre ffff8801370b9a40 ffff8800b4e26800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b40ab340 ffff88009b9a5000 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff880129c97340 ffff88012b83f000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 396.581589] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 396.584110] [<0>] kthread+0xe4/0xf0 [ 396.585950] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 396.588558] [<0>] 0xfffffffffffffffe [ 396.813217] Lustre: 8400:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1731518011/real 1731518011] req@ffff8800936cc380 x1815627861946368/t0(0) o104->lustre-OST0001@192.168.203.60@tcp:15/16 lens 328/224 e 0 to 1 dl 1731518027 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 404.509357] Lustre: 7067:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1731518018/real 1731518018] req@ffff8800942c5880 x1815627861944960/t0(0) o104->lustre-MDT0000@192.168.203.60@tcp:15/16 lens 328/224 e 0 to 1 dl 1731518034 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 404.847241] Lustre: ll_ost00_000: service thread pid 8400 was inactive for 40.043 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 404.854406] Pid: 8400, comm: ll_ost00_000 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 404.857623] Call Trace: [ 404.858927] [<0>] ptlrpc_set_wait+0x7cf/0x850 [ptlrpc] [ 404.861138] [<0>] ldlm_run_ast_work+0xe3/0x400 [ptlrpc] [ 404.863750] [<0>] ldlm_handle_conflict_lock+0x70/0x300 [ptlrpc] [ 404.866366] [<0>] ldlm_lock_enqueue+0x27d/0x930 [ptlrpc] [ 404.869045] [<0>] ldlm_cli_enqueue_local+0x36e/0x890 [ptlrpc] [ 404.871691] [<0>] ofd_destroy_by_fid+0x19c/0x610 [ofd] [ 404.874013] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 404.876331] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 404.879170] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 404.882686] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 404.886396] [<0>] kthread+0xe4/0xf0 [ 404.889474] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 404.891870] [<0>] 0xfffffffffffffffe [ 412.827380] Lustre: 8400:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1731518027/real 1731518027] req@ffff8800936cc380 x1815627861946368/t0(0) o104->lustre-OST0001@192.168.203.60@tcp:15/16 lens 328/224 e 0 to 1 dl 1731518043 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 428.841429] Lustre: 8400:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1731518043/real 1731518043] req@ffff8800936cc380 x1815627861946368/t0(0) o104->lustre-OST0001@192.168.203.60@tcp:15/16 lens 328/224 e 0 to 1 dl 1731518059 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 428.859416] Lustre: 8400:0:(client.c:2363:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 460.865311] Lustre: 8400:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1731518075/real 1731518075] req@ffff8800936cc380 x1815627861946368/t0(0) o104->lustre-OST0001@192.168.203.60@tcp:15/16 lens 328/224 e 0 to 1 dl 1731518091 ref 1 fl Rpc:XQr/2/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 460.878470] Lustre: 8400:0:(client.c:2363:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 468.523321] LustreError: 7067:0:(ldlm_lockd.c:759:ldlm_handle_ast_error()) ### client (nid 192.168.203.60@tcp) failed to reply to blocking AST (req@ffff8800942c5880 x1815627861944960 status 0 rc -110), evict it ns: mdt-lustre-MDT0000_UUID lock: ffff8800a8269f80/0x31a3ee66351b2568 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.60@tcp remote: 0xdbf7695996f2b638 expref: 9 pid: 7067 timeout: 551 lvb_type: 0 [ 468.530745] LustreError: lustre-MDT0000: A client on nid 192.168.203.60@tcp was evicted due to a lock blocking callback time out: rc -110 [ 468.532954] LustreError: 7057:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 16s: evicting client at 192.168.203.60@tcp ns: mdt-lustre-MDT0000_UUID lock: ffff8800a8269f80/0x31a3ee66351b2568 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.60@tcp remote: 0xdbf7695996f2b638 expref: 10 pid: 7067 timeout: 0 lvb_type: 0 [ 468.540833] Lustre: mdt00_002: service thread pid 7067 completed after 112.061s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 471.439485] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 12:15:01 (1731518101) [ 476.882390] LustreError: 8400:0:(ldlm_lockd.c:759:ldlm_handle_ast_error()) ### client (nid 192.168.203.60@tcp) failed to reply to blocking AST (req@ffff8800936cc380 x1815627861946368 status 0 rc -110), evict it ns: filter-lustre-OST0001_UUID lock: ffff8800a475d200/0x31a3ee66351b2426 lrc: 4/0,0 mode: PW/PW res: [0x280000400:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4194303) gid 0 flags: 0x60000400030020 nid: 192.168.203.60@tcp remote: 0xdbf7695996f2b5d6 expref: 6 pid: 8402 timeout: 560 lvb_type: 0 [ 476.904040] LustreError: lustre-OST0001: A client on nid 192.168.203.60@tcp was evicted due to a lock blocking callback time out: rc -110 [ 476.909455] LustreError: 7057:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 16s: evicting client at 192.168.203.60@tcp ns: filter-lustre-OST0001_UUID lock: ffff8800a475d200/0x31a3ee66351b2426 lrc: 3/0,0 mode: PW/PW res: [0x280000400:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4194303) gid 0 flags: 0x60000400030020 nid: 192.168.203.60@tcp remote: 0xdbf7695996f2b5d6 expref: 7 pid: 8402 timeout: 0 lvb_type: 0 [ 476.930765] Lustre: ll_ost00_000: service thread pid 8400 completed after 112.126s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 489.871858] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 12:15:19 (1731518119) [ 490.941952] Lustre: lustre-MDT0000: Client bafe183c-2f07-4da5-9855-5fc9b7909539 (at 192.168.203.60@tcp) reconnecting [ 490.947692] Lustre: Skipped 2 previous similar messages [ 492.718804] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 12:15:22 (1731518122) ****************************************************************************** ************************ 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.36s (real) 6.83s (CPU), Child processes: 5.49s