************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-slow-zfs-centos7_x86_64-centos7_x86_64/oleg246-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.nlW4D/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-slow-zfs-centos7_x86_64-centos7_x86_64/oleg246-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 19:18:33 EDT 2024 UPTIME: 01:17:45 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 418 NODENAME: oleg246-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 44 last 5s 65 last 60s 77 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 414 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 ----- -------------- ------ ---------------------------- 6734 mmp 0 ms (no user stack) 906 in:imjournal 0 ms /usr/sbin/rsyslogd -n 775 kworker/1:1H 0 ms (no user stack) 3206 socknal_reaper 0 ms (no user stack) 798 kworker/1:2 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 654104 2.5 GB 68% of TOTAL MEM USED 300963 1.1 GB 31% of TOTAL MEM SHARED 8371 32.7 MB 0% of TOTAL MEM BUFFERS 5096 19.9 MB 0% of TOTAL MEM CACHED 70267 274.5 MB 7% of TOTAL MEM SLAB 63354 247.5 MB 6% 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 63127 246.6 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 -------------------- CLOSE 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 4663.0 eth0 n/a 1.3 RSS_TOTAL=49556 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a2d8000 ffff880137300800 sysfs sysfs /sys ffff88012a2d81c0 ffff880139944000 proc proc /proc ffff88012a2d8380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a2d8540 ffff8800b51d9000 securityfs securityfs /sys/kernel/security ffff88012a2d8700 ffff880137301000 tmpfs tmpfs /dev/shm ffff88012a2d88c0 ffff88013771f000 devpts devpts /dev/pts ffff88012a2d8a80 ffff880137301800 tmpfs tmpfs /run ffff88012a2d8c40 ffff880137302000 tmpfs tmpfs /sys/fs/cgroup ffff88012a2d8e00 ffff880137302800 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a2d8fc0 ffff880137303000 pstore pstore /sys/fs/pstore ffff88012a2d9180 ffff880137305000 cgroup cgroup /sys/fs/cgroup/memory ffff88012a2d9340 ffff880137304800 cgroup cgroup /sys/fs/cgroup/pids ffff88012a2d9500 ffff880137304000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a2d96c0 ffff880137303800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a2d9880 ffff880137305800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a2d9a40 ffff880137306000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a2d9c00 ffff880137306800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a2d9dc0 ffff880137307000 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a38a000 ffff880137307800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a38a1c0 ffff88012a318000 cgroup cgroup /sys/fs/cgroup/devices ffff880138ccb880 ffff8800b49c8000 configfs configfs /sys/kernel/config ffff8801377f6540 ffff8800b7e56800 ext4 /dev/nbd0 / ffff880137668700 ffff88012a31f800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8801377f6c40 ffff8800b42d9800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff8801376688c0 ffff88012b2b0800 mqueue mqueue /dev/mqueue ffff8801377f6e00 ffff8800b42da000 hugetlbfs hugetlbfs /dev/hugepages ffff8801377f6fc0 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8801377f7180 ffff8800b42dc000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012a38a700 ffff8800b51dc000 ramfs none /mnt ffff88012a38a8c0 ffff8800b51da800 squashfs /dev/vda /home/green/git/lustre-release ffff880137668a80 ffff8800b4098000 tmpfs none /var/lib/stateless/writable ffff880137668c40 ffff8800b4098000 tmpfs none /var/cache/man ffff880137668e00 ffff8800b4098000 tmpfs none /var/log ffff880137668fc0 ffff8800b4098000 tmpfs none /var/lib/dbus ffff880137669180 ffff8800b4098000 tmpfs none /tmp ffff880137669340 ffff8800b4098000 tmpfs none /var/lib/dhclient ffff8800b4b6ec40 ffff8800b4098000 tmpfs none /var/tmp ffff880137669500 ffff8800b4098000 tmpfs none /var/lib/NetworkManager ffff8801376696c0 ffff8800b4098000 tmpfs none /var/lib/systemd/random-seed ffff880137669880 ffff8800b4098000 tmpfs none /var/spool ffff8800b4b6ee00 ffff8800b4098000 tmpfs none /var/lib/nfs ffff88012a38aa80 ffff8800b4098000 tmpfs none /var/lib/gssproxy ffff880137669a40 ffff8800b4098000 tmpfs none /var/lib/logrotate ffff880137669c00 ffff8800b4098000 tmpfs none /etc ffff880137669dc0 ffff8800b4098000 tmpfs none /var/lib/rsyslog ffff880138ccb340 ffff8800b4098000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8800b1c5e000 ffff8800b4325000 nfs4 192.168.200.253:/exports/state/oleg246-server.virtnet /var/lib/stateless/state ffff8801377f7340 ffff8800b4325000 nfs4 192.168.200.253:/exports/state/oleg246-server.virtnet /boot ffff8800b1c5e1c0 ffff8800b4325000 nfs4 192.168.200.253:/exports/state/oleg246-server.virtnet /etc/etc/kdump.conf ffff8800b1c5e380 ffff88012a31f800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b247aa80 ffff8800b51da800 squashfs /dev/vda /usr/sbin/mount.lustre ffff88012a38b340 ffff880129e98800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b4b6e700 ffff880129ef8000 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff88012a38ba40 ffff8801359b2800 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 58.649950] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 58.699821] Lustre: DEBUG MARKER: oleg246-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 63.515000] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 68.726156] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 74.351289] Lustre: DEBUG MARKER: oleg246-server.virtnet: executing check_logdir /tmp/testlogs/ [ 75.208690] Lustre: DEBUG MARKER: oleg246-server.virtnet: executing yml_node [ 76.154971] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 76.771838] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 77.348672] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 77.693942] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Wed May 8 18:02:04 EDT 2024 [ 81.283035] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 411b 130b 130c 130d 130e 130f 130g 312 [ 81.896522] Lustre: DEBUG MARKER: oleg246-client.virtnet: executing check_config_client /mnt/lustre [ 85.863145] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 86.689426] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 87.278614] Lustre: DEBUG MARKER: oleg246-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 89.047270] Lustre: DEBUG MARKER: == sanity test 27m: create file while OST0 was full ====== 18:02:16 (1715205736) [ 89.402712] Lustre: DEBUG MARKER: SKIP: sanity test_27m 7532544 > 600000 skipping out-of-space test on OST0 [ 91.783065] Lustre: DEBUG MARKER: == sanity test 51b: exceed 64k subdirectory nlink limit on create, verify unlink ========================================================== 18:02:18 (1715205738) [ 326.470155] Lustre: DEBUG MARKER: == sanity test 64b: check out-of-space detection on client ========================================================== 18:06:13 (1715205973) [ 331.039185] Lustre: DEBUG MARKER: SKIP: oos test_64b oos.sh: 7532544kB free gt MAXFREE 800000kB, increase 800000 (or reduce test fs size) to proceed [ 334.428563] Lustre: DEBUG MARKER: == sanity test 71: Running dbench on lustre (don't segment fault) ============================================================== 18:06:21 (1715205981) [ 576.418688] Lustre: lustre-MDT0000: Client b27a384f-5d18-4c42-97fc-1535f4867527 (at 192.168.202.46@tcp) reconnecting [ 1061.348321] Lustre: DEBUG MARKER: == sanity test 255a: check 'lfs ladvise -a willread' ===== 18:18:28 (1715206708) [ 1104.096434] Lustre: ll_ost_io00_007: service thread pid 9357 was inactive for 40.005 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 1104.096441] Lustre: ll_ost_io00_002: service thread pid 8523 was inactive for 40.005 seconds. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one. [ 1104.115507] Pid: 9357, comm: ll_ost_io00_007 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 1104.121766] Call Trace: [ 1104.124112] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 1104.127207] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 1104.130327] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 1104.132913] [<0>] ofd_ladvise_hdl+0x62b/0x1030 [ofd] [ 1104.135329] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 1104.138453] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 1104.141907] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 1104.144566] [<0>] kthread+0xe4/0xf0 [ 1104.146621] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 1104.149474] [<0>] 0xfffffffffffffffe [ 1164.256373] LustreError: 6978:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.202.46@tcp ns: filter-lustre-OST0000_UUID lock: ffff880124e73a80/0xb078992ba32d37a lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x2bbc:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000480000020 nid: 192.168.202.46@tcp remote: 0x7b94c2d995ce370e expref: 7 pid: 8517 timeout: 1163 lvb_type: 0 [ 1164.868635] Lustre: DEBUG MARKER: sanity test_255a: @@@@@@ FAIL: Ladvise failed with no -l or -e argument [ 1195.360901] Lustre: lustre-OST0000: haven't heard from client b27a384f-5d18-4c42-97fc-1535f4867527 (at 192.168.202.46@tcp) in 31 seconds. I think it's dead, and I am evicting it. exp ffff88008f14b000, cur 1715206842 expire 1715206812 last 1715206811 ****************************************************************************** ************************ 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.60s (real) 6.75s (CPU), Child processes: 5.83s