************************ crashinfo ************************* /exports/testreports/47154/testresults/replay-single-zfs-centos7_x86_64-centos7_x86_64/oleg451-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.nSEeQ/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/replay-single-zfs-centos7_x86_64-centos7_x86_64/oleg451-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 13:55:24 EST 2024 UPTIME: 01:48:13 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 358 NODENAME: oleg451-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 42 last 5s 69 last 60s 81 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 354 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 ----- -------------- ------ ---------------------------- 9 rcu_sched 0 ms (no user stack) 34 rcuos/3 0 ms (no user stack) 3488 arc_reap 0 ms (no user stack) 9551 mdt00_000 0 ms (no user stack) 14588 mdt00_005 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 706558 2.7 GB 73% of TOTAL MEM USED 248509 970.7 MB 26% of TOTAL MEM SHARED 9952 38.9 MB 1% of TOTAL MEM BUFFERS 5123 20 MB 0% of TOTAL MEM CACHED 71548 279.5 MB 7% of TOTAL MEM SLAB 20419 79.8 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 60044 234.5 MB 8% 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 6491.0 eth0 n/a 2.7 RSS_TOTAL=50484 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff88013767b000 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff8800b5236800 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff88013767b800 tmpfs tmpfs /dev/shm ffff880137668c40 ffff880137335800 devpts devpts /dev/pts ffff880137668e00 ffff88013767c000 tmpfs tmpfs /run ffff880137668fc0 ffff88013767c800 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff88013767d000 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff88013767d800 pstore pstore /sys/fs/pstore ffff880137669500 ffff88013767f800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff8801376696c0 ffff88013767f000 cgroup cgroup /sys/fs/cgroup/blkio ffff880137669880 ffff88013767e800 cgroup cgroup /sys/fs/cgroup/cpuset ffff880137669a40 ffff88013767e000 cgroup cgroup /sys/fs/cgroup/perf_event ffff880137669c00 ffff88012a320000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880137669dc0 ffff88012a320800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012aa0c000 ffff88012a321000 cgroup cgroup /sys/fs/cgroup/devices ffff88012aa0c1c0 ffff88012a321800 cgroup cgroup /sys/fs/cgroup/pids ffff88012aa0c380 ffff88012a322000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012aa0c540 ffff88012a322800 cgroup cgroup /sys/fs/cgroup/memory ffff88012aa0c700 ffff88012a325000 configfs configfs /sys/kernel/config ffff8801377f7180 ffff88012a2f3000 ext4 /dev/nbd0 / ffff88012aa0d880 ffff8800b4ce9800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff880138ccae00 ffff88012a2f6800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012aa0da40 ffff8800b4cea800 hugetlbfs hugetlbfs /dev/hugepages ffff8800b4c06380 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8800b4c06540 ffff880137337000 mqueue mqueue /dev/mqueue ffff88012aa0dc00 ffff880136872000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8800b4c06700 ffff8800b41f4800 ramfs none /mnt ffff88012e1c2000 ffff88012a3d5800 tmpfs none /var/lib/stateless/writable ffff8801377f7880 ffff8800b4280800 squashfs /dev/vda /home/green/git/lustre-release ffff88012e1c2380 ffff88012a3d5800 tmpfs none /var/cache/man ffff8800b4c068c0 ffff88012a3d5800 tmpfs none /var/log ffff8801377f7a40 ffff88012a3d5800 tmpfs none /var/lib/dbus ffff88012e1c2540 ffff88012a3d5800 tmpfs none /tmp ffff8800b4c06a80 ffff88012a3d5800 tmpfs none /var/lib/dhclient ffff88012e1c2700 ffff88012a3d5800 tmpfs none /var/tmp ffff88012e1c28c0 ffff88012a3d5800 tmpfs none /var/lib/NetworkManager ffff88012e1c2a80 ffff88012a3d5800 tmpfs none /var/lib/systemd/random-seed ffff8800b4c06c40 ffff88012a3d5800 tmpfs none /var/spool ffff8800b4c06e00 ffff88012a3d5800 tmpfs none /var/lib/nfs ffff8800b4c06fc0 ffff88012a3d5800 tmpfs none /var/lib/gssproxy ffff88012e1c2c40 ffff88012a3d5800 tmpfs none /var/lib/logrotate ffff88012e1c2e00 ffff88012a3d5800 tmpfs none /etc ffff88012e1c2fc0 ffff88012a3d5800 tmpfs none /var/lib/rsyslog ffff88012e1c3180 ffff88012a3d5800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8801377f7c00 ffff880129f82000 nfs4 192.168.200.253:/exports/state/oleg451-server.virtnet /var/lib/stateless/state ffff8800b4c07340 ffff880129f82000 nfs4 192.168.200.253:/exports/state/oleg451-server.virtnet /boot ffff8801377f7dc0 ffff880129f82000 nfs4 192.168.200.253:/exports/state/oleg451-server.virtnet /etc/etc/kdump.conf ffff8800b4c07180 ffff8800b4ce9800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b4c43c00 ffff8800b4280800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b7b20380 ffff88009470d000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 ffff880130e49180 ffff88012b73f800 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff8800b7b21340 ffff88009a2ae000 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 3150.707732] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6408 to 0x240000400:6433) [ 3150.707763] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6345 to 0x280000400:6369) [ 3151.507859] Lustre: DEBUG MARKER: oleg451-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3151.908896] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3155.131872] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3156.485656] Lustre: DEBUG MARKER: test_70b fail mds1 11 times [ 3156.967557] Lustre: Failing over lustre-MDT0000 [ 3157.061527] Lustre: server umount lustre-MDT0000 complete [ 3169.593699] Lustre: DEBUG MARKER: oleg451-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3175.814260] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6450 to 0x280000400:6465) [ 3175.814262] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6513 to 0x240000400:6529) [ 3176.585380] Lustre: DEBUG MARKER: oleg451-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3176.986734] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3180.239979] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3181.629386] Lustre: DEBUG MARKER: test_70b fail mds1 12 times [ 3182.161305] Lustre: Failing over lustre-MDT0000 [ 3182.172535] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.51@tcp (stopping) [ 3182.262773] Lustre: server umount lustre-MDT0000 complete [ 3193.853191] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 3194.659998] Lustre: DEBUG MARKER: oleg451-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3200.870431] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6532 to 0x280000400:6561) [ 3200.870448] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6596 to 0x240000400:6625) [ 3201.659640] Lustre: DEBUG MARKER: oleg451-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3202.041096] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3295.309127] Lustre: ll_ost00_003: service thread pid 9782 was inactive for 40.090 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 3295.321220] Pid: 9782, comm: ll_ost00_003 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 3295.326953] Call Trace: [ 3295.329170] [<0>] ldlm_completion_ast+0x913/0xd50 [ptlrpc] [ 3295.332019] [<0>] ldlm_cli_enqueue_local+0x259/0x890 [ptlrpc] [ 3295.335899] [<0>] ofd_destroy_by_fid+0x19c/0x610 [ofd] [ 3295.339338] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 3295.342186] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 3295.345508] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 3295.348666] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 3295.351277] [<0>] kthread+0xe4/0xf0 [ 3295.353387] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 3295.355339] [<0>] 0xfffffffffffffffe [ 3355.597075] LustreError: 7018:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 101s: evicting client at 192.168.204.51@tcp ns: filter-lustre-OST0001_UUID lock: ffff88009c041200/0xaf17b9af55658f36 lrc: 3/0,0 mode: PR/PR res: [0x280000400:0x1512:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400010020 nid: 192.168.204.51@tcp remote: 0x241f7a1422a887b0 expref: 33 pid: 8370 timeout: 3354 lvb_type: 1 [ 3355.609801] Lustre: ll_ost00_003: service thread pid 9782 completed after 100.390s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 3389.213425] Lustre: lustre-OST0001: haven't heard from client 5b2f29fa-a82e-43ba-a1cc-e289c57ba952 (at 192.168.204.51@tcp) in 33 seconds. I think it's dead, and I am evicting it. exp ffff88009cbaa000, cur 1731521019 expire 1731520989 last 1731520986 ****************************************************************************** ************************ 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.92s (CPU), Child processes: 5.44s