************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity2-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg215-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.z4Mhz/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity2-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg215-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 19:03:50 EDT 2024 UPTIME: 01:03:03 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 255 NODENAME: oleg215-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 17 last 5s 61 last 60s 75 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 251 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 ----- -------------- ------ ---------------------------- 4434 dbuf_evict 0 ms (no user stack) 66 kworker/1:1 0 ms (no user stack) 4437 l2arc_feed 0 ms (no user stack) 4432 zthr_procedure 0 ms (no user stack) 3680 lnet_discovery 50 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 735940 2.8 GB 77% of TOTAL MEM USED 219127 856 MB 22% of TOTAL MEM SHARED 16647 65 MB 1% of TOTAL MEM BUFFERS 14042 54.9 MB 1% of TOTAL MEM CACHED 66778 260.9 MB 6% of TOTAL MEM SLAB 16632 65 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 3780.8 eth0 n/a 3.8 RSS_TOTAL=49692 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff88013767a800 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff8800b5238800 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff88013767b000 tmpfs tmpfs /dev/shm ffff880137668c40 ffff88012b260800 devpts devpts /dev/pts ffff880137668e00 ffff88013767b800 tmpfs tmpfs /run ffff880137668fc0 ffff88013767c000 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff88013767c800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff88013767d000 pstore pstore /sys/fs/pstore ffff880137669500 ffff88013767f000 cgroup cgroup /sys/fs/cgroup/cpuset ffff8801376696c0 ffff88013767e800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff880137669880 ffff88013767e000 cgroup cgroup /sys/fs/cgroup/freezer ffff880137669a40 ffff88013767d800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff880137669c00 ffff88013767f800 cgroup cgroup /sys/fs/cgroup/perf_event ffff880137669dc0 ffff88012a350000 cgroup cgroup /sys/fs/cgroup/memory ffff88012a34e000 ffff88012a350800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a34e1c0 ffff88012a351000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a34e380 ffff88012a351800 cgroup cgroup /sys/fs/cgroup/pids ffff88012a34e540 ffff88012a352000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff8801377f3180 ffff8800b523a800 configfs configfs /sys/kernel/config ffff8801377f3340 ffff8800b523f800 ext4 /dev/nbd0 / ffff8800b5270380 ffff8800b525b800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8800b5270540 ffff8800b410f800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a34f6c0 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff88012a34f880 ffff88012b262000 mqueue mqueue /dev/mqueue ffff88012a34fa40 ffff88012a366800 hugetlbfs hugetlbfs /dev/hugepages ffff8800b5270700 ffff8800b40d2000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8800b52708c0 ffff8800b40d7000 ramfs none /mnt ffff88012a34fc00 ffff880129e8f800 squashfs /dev/vda /home/green/git/lustre-release ffff8801377f2e00 ffff8800b4e3d000 tmpfs none /var/lib/stateless/writable ffff8800b5270a80 ffff8800b4e3d000 tmpfs none /var/cache/man ffff8800b5270c40 ffff8800b4e3d000 tmpfs none /var/log ffff8801377f36c0 ffff8800b4e3d000 tmpfs none /var/lib/dbus ffff8800b5270e00 ffff8800b4e3d000 tmpfs none /tmp ffff8800b5270fc0 ffff8800b4e3d000 tmpfs none /var/lib/dhclient ffff8800b5271180 ffff8800b4e3d000 tmpfs none /var/tmp ffff8800b5271340 ffff8800b4e3d000 tmpfs none /var/lib/NetworkManager ffff8800b5271500 ffff8800b4e3d000 tmpfs none /var/lib/systemd/random-seed ffff8800b52716c0 ffff8800b4e3d000 tmpfs none /var/spool ffff8800b5271880 ffff8800b4e3d000 tmpfs none /var/lib/nfs ffff8800b1f20000 ffff8800b4e3d000 tmpfs none /var/lib/gssproxy ffff8800b1f201c0 ffff8800b4e3d000 tmpfs none /var/lib/logrotate ffff8800b1f20380 ffff8800b4e3d000 tmpfs none /etc ffff8800b5271a40 ffff8800b4e3d000 tmpfs none /var/lib/rsyslog ffff8800b1f20540 ffff8800b4e3d000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8801377f3500 ffff880129e88800 nfs4 192.168.200.253:/exports/state/oleg215-server.virtnet /var/lib/stateless/state ffff8800b1f20a80 ffff880129e88800 nfs4 192.168.200.253:/exports/state/oleg215-server.virtnet /boot ffff8801377f3a40 ffff880129e88800 nfs4 192.168.200.253:/exports/state/oleg215-server.virtnet /etc/etc/kdump.conf ffff880138ccafc0 ffff8800b525b800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff880138ccb880 ffff880129e8f800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800aa279c00 ffff880129e8a000 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff8800aa2788c0 ffff880136a2c000 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff8800aa278000 ffff8800a6522000 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff8800aa278540 ffff8800a6b02000 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 152.913162] Lustre: *** cfs_fail_loc=19a, val=0*** [ 153.390919] LustreError: 8274:0:(llog_cat.c:737:llog_cat_cancel_arr_rec()) lustre-MDT0001-osd: fail to cancel 1 llog-records: rc = -5 [ 153.393787] LustreError: 8274:0:(llog_cat.c:773:llog_cat_cancel_records()) lustre-MDT0001-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 153.642729] Lustre: *** cfs_fail_loc=19a, val=0*** [ 153.644058] Lustre: Skipped 2 previous similar messages [ 154.569299] LustreError: 7151:0:(llog_cat.c:737:llog_cat_cancel_arr_rec()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 llog-records: rc = -2 [ 154.574019] LustreError: 7151:0:(llog_cat.c:773:llog_cat_cancel_records()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 of 1 llog-records: rc = -2 [ 154.880950] Lustre: *** cfs_fail_loc=19a, val=0*** [ 154.882199] Lustre: Skipped 4 previous similar messages [ 155.900008] LustreError: 7151:0:(llog_cat.c:737:llog_cat_cancel_arr_rec()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 llog-records: rc = -116 [ 155.904525] LustreError: 7151:0:(llog_cat.c:773:llog_cat_cancel_records()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 of 1 llog-records: rc = -116 [ 157.102670] Lustre: *** cfs_fail_loc=19a, val=0*** [ 157.104139] Lustre: Skipped 8 previous similar messages [ 161.112779] Lustre: *** cfs_fail_loc=19a, val=0*** [ 161.114138] Lustre: Skipped 15 previous similar messages [ 165.323992] LustreError: 7151:0:(llog_cat.c:737:llog_cat_cancel_arr_rec()) lustre-MDT0000-osd: fail to cancel 1 llog-records: rc = -5 [ 165.328805] LustreError: 7151:0:(llog_cat.c:737:llog_cat_cancel_arr_rec()) Skipped 6 previous similar messages [ 165.331762] LustreError: 7151:0:(llog_cat.c:773:llog_cat_cancel_records()) lustre-MDT0000-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 165.334836] LustreError: 7151:0:(llog_cat.c:773:llog_cat_cancel_records()) Skipped 6 previous similar messages [ 169.130068] Lustre: *** cfs_fail_loc=19a, val=0*** [ 169.131858] Lustre: Skipped 32 previous similar messages [ 172.991945] LustreError: 7151:0:(llog_cat.c:737:llog_cat_cancel_arr_rec()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 llog-records: rc = -116 [ 172.997337] LustreError: 7151:0:(llog_cat.c:773:llog_cat_cancel_records()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 of 1 llog-records: rc = -116 [ 181.965647] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 18:03:48 (1715205828) [ 182.208815] Lustre: *** cfs_fail_loc=188, val=0*** [ 222.345465] Lustre: ll_ost00_014: service thread pid 17169 was inactive for 40.032 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 222.349504] Pid: 17169, comm: ll_ost00_014 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 222.351238] Call Trace: [ 222.351905] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 222.353411] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 222.354665] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 222.355914] [<0>] ofd_getattr_hdl+0x385/0x750 [ofd] [ 222.357035] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 222.358182] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 222.359576] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 222.360761] [<0>] kthread+0xe4/0xf0 [ 222.361680] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 222.362849] [<0>] 0xfffffffffffffffe [ 282.505461] LustreError: 7113:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.202.15@tcp ns: filter-lustre-OST0000_UUID lock: ffff88006f220000/0x4b4e28bad1a4c700 lrc: 3/0,0 mode: PW/PW res: [0x280000401:0x9c8:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4095) gid 0 flags: 0x60000400000020 nid: 192.168.202.15@tcp remote: 0xdf0123842fe0be36 expref: 9 pid: 17169 timeout: 281 lvb_type: 0 [ 314.409775] Lustre: lustre-OST0000: haven't heard from client 4568204a-976a-48fe-9679-1d1f5a5f8a5c (at 192.168.202.15@tcp) in 31 seconds. I think it's dead, and I am evicting it. exp ffff8801357c3800, cur 1715205960 expire 1715205930 last 1715205929 ****************************************************************************** ************************ 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.14s (real) 6.43s (CPU), Child processes: 5.69s