************************ crashinfo ************************* /exports/testreports/47154/testresults/replay-ost-single-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg140-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.Go54H/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/replay-ost-single-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg140-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 12:30:51 EST 2024 UPTIME: 00:23:41 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 242 NODENAME: oleg140-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 37 last 5s 56 last 60s 72 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 238 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 ----- -------------- ------ ---------------------------- 3763 ptlrpcd_00_00 0 ms (no user stack) 21420 mdt_out00_003 0 ms (no user stack) 7213 mdt_out00_000 0 ms (no user stack) 3764 ptlrpcd_00_01 0 ms (no user stack) 8356 ldlm_bl_03 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 741159 2.8 GB 77% of TOTAL MEM USED 213908 835.6 MB 22% of TOTAL MEM SHARED 10540 41.2 MB 1% of TOTAL MEM BUFFERS 7883 30.8 MB 0% of TOTAL MEM CACHED 71241 278.3 MB 7% of TOTAL MEM SLAB 15207 59.4 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 58973 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 1418.7 eth0 n/a 1.7 RSS_TOTAL=51220 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff880137679000 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff88012a2f0000 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff880137679800 tmpfs tmpfs /dev/shm ffff880137668c40 ffff88013731e000 devpts devpts /dev/pts ffff880137668e00 ffff88013767a000 tmpfs tmpfs /run ffff880137668fc0 ffff88013767a800 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff88013767b000 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff88013767b800 pstore pstore /sys/fs/pstore ffff880138ccafc0 ffff8800b51f0800 cgroup cgroup /sys/fs/cgroup/memory ffff880138ccb180 ffff8800b51f1000 cgroup cgroup /sys/fs/cgroup/blkio ffff880138ccb340 ffff8800b51f1800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff880138ccb500 ffff8800b51f2000 cgroup cgroup /sys/fs/cgroup/cpuset ffff880138ccb6c0 ffff8800b51f2800 cgroup cgroup /sys/fs/cgroup/devices ffff880138ccb880 ffff8800b51f3000 cgroup cgroup /sys/fs/cgroup/freezer ffff880138ccba40 ffff8800b51f3800 cgroup cgroup /sys/fs/cgroup/perf_event ffff880138ccbc00 ffff8800b51f4000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880138ccbdc0 ffff8800b51f4800 cgroup cgroup /sys/fs/cgroup/pids ffff88012a316000 ffff8800b51f5000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff880137669500 ffff88013767d000 configfs configfs /sys/kernel/config ffff8801376696c0 ffff8800b4061000 ext4 /dev/nbd0 / ffff880137669880 ffff88012a2f7800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a2eca80 ffff8800b41d6800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880137669a40 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880137669c00 ffff88013731f800 mqueue mqueue /dev/mqueue ffff880137669dc0 ffff8800b5225800 hugetlbfs hugetlbfs /dev/hugepages ffff8800b4e9a000 ffff8800b5227000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012b290a80 ffff8800b4dc1000 ramfs none /mnt ffff88012a2ecc40 ffff880129d64000 squashfs /dev/vda /home/green/git/lustre-release ffff88012a317340 ffff8800b4dc2800 tmpfs none /var/lib/stateless/writable ffff88012a2ece00 ffff8800b4dc2800 tmpfs none /var/cache/man ffff88012b290c40 ffff8800b4dc2800 tmpfs none /var/log ffff88012a2ecfc0 ffff8800b4dc2800 tmpfs none /var/lib/dbus ffff8800b4e9a1c0 ffff8800b4dc2800 tmpfs none /tmp ffff8800b4e9a380 ffff8800b4dc2800 tmpfs none /var/lib/dhclient ffff88012a2ed180 ffff8800b4dc2800 tmpfs none /var/tmp ffff8800b4e9a540 ffff8800b4dc2800 tmpfs none /var/lib/NetworkManager ffff88012a3176c0 ffff8800b4dc2800 tmpfs none /var/lib/systemd/random-seed ffff8800b4e9a700 ffff8800b4dc2800 tmpfs none /var/spool ffff88012a317880 ffff8800b4dc2800 tmpfs none /var/lib/nfs ffff8800b4e9a8c0 ffff8800b4dc2800 tmpfs none /var/lib/gssproxy ffff8800b4e9aa80 ffff8800b4dc2800 tmpfs none /var/lib/logrotate ffff88012a317a40 ffff8800b4dc2800 tmpfs none /etc ffff8800b4e9ac40 ffff8800b4dc2800 tmpfs none /var/lib/rsyslog ffff88012a317c00 ffff8800b4dc2800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012a317dc0 ffff880129ee2800 nfs4 192.168.200.253:/exports/state/oleg140-server.virtnet /var/lib/stateless/state ffff88012a2ed500 ffff880129ee2800 nfs4 192.168.200.253:/exports/state/oleg140-server.virtnet /boot ffff88012a2ed340 ffff880129ee2800 nfs4 192.168.200.253:/exports/state/oleg140-server.virtnet /etc/etc/kdump.conf ffff88012a2ed6c0 ffff88012a2f7800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff88012a2b5500 ffff880129d64000 squashfs /dev/vda /usr/sbin/mount.lustre ffff880136baba40 ffff8800b1949800 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff880136baaa80 ffff880129ee7000 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff880136baa1c0 ffff8800761f0000 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 ffff88012b291340 ffff88012cc66000 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 157.014537] Lustre: DEBUG MARKER: oleg140-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 157.534434] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 157.618952] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 157.618974] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.201.140@tcp (at 0@lo) [ 157.618975] Lustre: Skipped 1 previous similar message [ 159.357054] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 159.710885] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 162.242391] Lustre: DEBUG MARKER: == replay-ost-single test 2: |x| 10 open(O_CREAT)s ======= 12:09:51 (1731517791) [ 162.733314] Lustre: Failing over lustre-OST0000 [ 162.745385] Lustre: server umount lustre-OST0000 complete [ 165.912547] 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 [ 165.912868] 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. [ 165.912869] LustreError: Skipped 1 previous similar message [ 165.922325] Lustre: Skipped 2 previous similar messages [ 174.563545] LDISKFS-fs (dm-2): file extents enabled, maximum tree depth=5 [ 174.566785] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 174.604356] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 175.718452] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 175.720070] Lustre: DEBUG MARKER: oleg140-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 175.876477] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 175.876479] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.201.140@tcp (at 0@lo) [ 175.876483] Lustre: Skipped 1 previous similar message [ 178.118981] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 178.485009] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 220.968211] Lustre: ll_ost00_002: service thread pid 9552 was inactive for 40.078 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 220.975706] Pid: 9552, comm: ll_ost00_002 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 220.978863] Call Trace: [ 220.980057] [<0>] ldlm_completion_ast+0x913/0xd50 [ptlrpc] [ 220.981813] [<0>] ldlm_cli_enqueue_local+0x259/0x890 [ptlrpc] [ 220.983481] [<0>] ofd_destroy_by_fid+0x19c/0x610 [ofd] [ 220.984569] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 220.986435] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 220.987925] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 220.989770] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 220.991363] [<0>] kthread+0xe4/0xf0 [ 220.992584] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 220.994036] [<0>] 0xfffffffffffffffe [ 281.128213] LustreError: 7200:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.201.40@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a8104b40/0xdb6a936e9eb94e4f lrc: 3/0,0 mode: PR/PR res: [0x280000401:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400010020 nid: 192.168.201.40@tcp remote: 0xac323d5ac6e8b63e expref: 15 pid: 9552 timeout: 280 lvb_type: 1 [ 281.138917] Lustre: ll_ost00_002: service thread pid 9552 completed after 100.249s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 314.824667] Lustre: lustre-OST0000: haven't heard from client e949e171-7f14-48c9-86c8-1de4ec0fd43c (at 192.168.201.40@tcp) in 32 seconds. I think it's dead, and I am evicting it. exp ffff88012cc62000, cur 1731517944 expire 1731517914 last 1731517912 ****************************************************************************** ************************ 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 11.02s (real) 5.90s (CPU), Child processes: 5.08s