************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-benchmark-zfs-centos7_x86_64-centos7_x86_64/oleg149-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.RlC9Z/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-benchmark-zfs-centos7_x86_64-centos7_x86_64/oleg149-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 19:04:55 EDT 2024 UPTIME: 01:04:07 LOAD AVERAGE: 0.00, 0.01, 0.07 TASKS: 464 NODENAME: oleg149-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 23 last 5s 60 last 60s 75 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 460 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 ----- -------------- ------ ---------------------------- 913 in:imjournal 0 ms /usr/sbin/rsyslogd -n 9 rcu_sched 0 ms (no user stack) 9687 mmp 0 ms (no user stack) 9610 z_null_iss 83 ms (no user stack) 8500 ldlm_bl_03 160 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 699799 2.7 GB 73% of TOTAL MEM USED 255268 997.1 MB 26% of TOTAL MEM SHARED 8823 34.5 MB 0% of TOTAL MEM BUFFERS 5096 19.9 MB 0% of TOTAL MEM CACHED 65021 254 MB 6% of TOTAL MEM SLAB 21158 82.6 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 57968 226.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 -------------------- CLOSE 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 3845.0 eth0 n/a 1.2 RSS_TOTAL=51724 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff8800b5221800 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff88012b39e800 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff8800b5222000 tmpfs tmpfs /dev/shm ffff880137668c40 ffff880137189800 devpts devpts /dev/pts ffff880137668e00 ffff8800b5222800 tmpfs tmpfs /run ffff880137668fc0 ffff8800b5223000 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff8800b5223800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff8800b5224000 pstore pstore /sys/fs/pstore ffff880137669500 ffff8800b5226000 cgroup cgroup /sys/fs/cgroup/perf_event ffff8801376696c0 ffff8800b5225800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff880137669880 ffff8800b5225000 cgroup cgroup /sys/fs/cgroup/freezer ffff880137669a40 ffff8800b5224800 cgroup cgroup /sys/fs/cgroup/devices ffff880137669c00 ffff8800b5226800 cgroup cgroup /sys/fs/cgroup/memory ffff880137669dc0 ffff8800b5227000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a320000 ffff8800b5227800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a3201c0 ffff88012a2e0000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a320380 ffff88012a2e0800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a320540 ffff88012a2e1000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a3208c0 ffff8800b4958000 configfs configfs /sys/kernel/config ffff8800b52ac1c0 ffff880137322000 ext4 /dev/nbd0 / ffff8800b52ac380 ffff880137323800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a320c40 ffff8800b4b9f000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a320e00 ffff8800b4b9b000 hugetlbfs hugetlbfs /dev/hugepages ffff88013700f880 ffff88013718b000 mqueue mqueue /dev/mqueue ffff88013700fa40 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880138ccba40 ffff88012a2e7000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88013700fdc0 ffff880129c71800 ramfs none /mnt ffff88012a320fc0 ffff8800b4b9e000 squashfs /dev/vda /home/green/git/lustre-release ffff880138ccbc00 ffff880129c72800 tmpfs none /var/lib/stateless/writable ffff88012a321180 ffff880129c72800 tmpfs none /var/cache/man ffff8800b2482000 ffff880129c72800 tmpfs none /var/log ffff8800b52ac540 ffff880129c72800 tmpfs none /var/lib/dbus ffff88012a321340 ffff880129c72800 tmpfs none /tmp ffff88012a321500 ffff880129c72800 tmpfs none /var/lib/dhclient ffff8800b52ac700 ffff880129c72800 tmpfs none /var/tmp ffff88012a3216c0 ffff880129c72800 tmpfs none /var/lib/NetworkManager ffff88012a321880 ffff880129c72800 tmpfs none /var/lib/systemd/random-seed ffff8800b52ac8c0 ffff880129c72800 tmpfs none /var/spool ffff88012a321a40 ffff880129c72800 tmpfs none /var/lib/nfs ffff88012a321c00 ffff880129c72800 tmpfs none /var/lib/gssproxy ffff88012a321dc0 ffff880129c72800 tmpfs none /var/lib/logrotate ffff8800b1b10000 ffff880129c72800 tmpfs none /etc ffff8800b52aca80 ffff880129c72800 tmpfs none /var/lib/rsyslog ffff8800b52acc40 ffff880129c72800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88013700f6c0 ffff8800b1887000 nfs4 192.168.200.253:/exports/state/oleg149-server.virtnet /var/lib/stateless/state ffff8800b52ace00 ffff8800b1887000 nfs4 192.168.200.253:/exports/state/oleg149-server.virtnet /boot ffff8800b52acfc0 ffff8800b1887000 nfs4 192.168.200.253:/exports/state/oleg149-server.virtnet /etc/etc/kdump.conf ffff8800b52ad180 ffff880137323800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b4304000 ffff8800b4b9e000 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b2487180 ffff8800b2598800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b24868c0 ffff880099b7f000 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff8800b2487880 ffff88013555b800 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 57.766930] Lustre: lustre-OST0001: new disk, initializing [ 57.768609] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 57.784893] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 59.040936] Lustre: DEBUG MARKER: oleg149-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 63.702762] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 64.829917] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 64.833627] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 64.861918] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 69.805952] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 75.445653] Lustre: DEBUG MARKER: oleg149-server.virtnet: executing check_logdir /tmp/testlogs/ [ 76.271866] Lustre: DEBUG MARKER: oleg149-server.virtnet: executing yml_node [ 77.199002] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 77.821177] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 78.426956] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 78.786021] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-benchmark ============----- Wed May 8 18:02:05 EDT 2024 [ 82.442131] Lustre: DEBUG MARKER: excepting tests: [ 82.785583] Lustre: DEBUG MARKER: skipping tests SLOW=no: iozone [ 83.365676] Lustre: DEBUG MARKER: oleg149-client.virtnet: executing check_config_client /mnt/lustre [ 87.249313] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 88.075669] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 88.660542] Lustre: DEBUG MARKER: oleg149-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 90.109086] Lustre: DEBUG MARKER: == sanity-benchmark test dbench: dbench ================== 18:02:16 (1715205736) [ 239.336139] Lustre: DEBUG MARKER: == sanity-benchmark test bonnie: bonnie++ ================ 18:04:46 (1715205886) [ 239.805466] Lustre: DEBUG MARKER: min OST has 3168256kB available, using 4752384kB file size [ 360.072231] Lustre: ll_ost00_008: service thread pid 15307 was inactive for 40.094 seconds. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one. [ 360.072236] Lustre: ll_ost00_020: service thread pid 15914 was inactive for 40.094 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 360.072241] Pid: 15914, comm: ll_ost00_020 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 360.072242] Call Trace: [ 360.072328] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 360.072364] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 360.072373] [<0>] ofd_destroy_by_fid+0x1d1/0x520 [ofd] [ 360.072378] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 360.072423] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 360.072455] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 360.072485] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 360.072491] [<0>] kthread+0xe4/0xf0 [ 360.072493] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 360.072503] [<0>] 0xfffffffffffffffe [ 420.360280] LustreError: 6942:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.201.49@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a673bcc0/0x278755cae8b273da lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x3c55:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->8191) gid 0 flags: 0x60000400010020 nid: 192.168.201.49@tcp remote: 0x6bc8b966ba37368d expref: 6 pid: 15732 timeout: 419 lvb_type: 0 [ 455.432590] Lustre: lustre-OST0001: haven't heard from client 641c15c7-f3f1-4f40-97bf-b2868eafe3e3 (at 192.168.201.49@tcp) in 33 seconds. I think it's dead, and I am evicting it. exp ffff88009bd27000, cur 1715206102 expire 1715206072 last 1715206069 ****************************************************************************** ************************ 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.89s (real) 7.33s (CPU), Child processes: 5.53s