************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-slow-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg335-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.EqPvt/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-slow-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg335-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 19:18:05 EDT 2024 UPTIME: 01:17:16 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 275 NODENAME: oleg335-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 21 last 5s 62 last 60s 79 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 271 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 ----- -------------- ------ ---------------------------- 4437 zthr_procedure 0 ms (no user stack) 913 in:imjournal 0 ms /usr/sbin/rsyslogd -n 34 rcuos/3 0 ms (no user stack) 3682 monitor_thread 0 ms (no user stack) 1 systemd 5 ms /usr/lib/systemd/systemd --switched-root --system --deserialize 21 +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 626372 2.4 GB 65% of TOTAL MEM USED 328695 1.3 GB 34% of TOTAL MEM SHARED 115474 451.1 MB 12% of TOTAL MEM BUFFERS 113106 441.8 MB 11% of TOTAL MEM CACHED 70977 277.3 MB 7% of TOTAL MEM SLAB 20506 80.1 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 63095 246.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 4634.3 eth0 n/a 1.8 RSS_TOTAL=53336 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a34a000 ffff88012a350000 sysfs sysfs /sys ffff88012a34a1c0 ffff880139944000 proc proc /proc ffff88012a34a380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a34a540 ffff8800b51e2000 securityfs securityfs /sys/kernel/security ffff88012a34a700 ffff88012a350800 tmpfs tmpfs /dev/shm ffff88012a34a8c0 ffff880137149800 devpts devpts /dev/pts ffff88012a34aa80 ffff88012a351000 tmpfs tmpfs /run ffff88012a34ac40 ffff88012a351800 tmpfs tmpfs /sys/fs/cgroup ffff88012a34ae00 ffff88012a352000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a34afc0 ffff88012a352800 pstore pstore /sys/fs/pstore ffff88012a34b180 ffff88012a354800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a34b340 ffff88012a354000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a34b500 ffff88012a353800 cgroup cgroup /sys/fs/cgroup/pids ffff88012a34b6c0 ffff88012a353000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a34b880 ffff88012a355000 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a34ba40 ffff88012a355800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a34bc00 ffff88012a356000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a34bdc0 ffff88012a356800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a35e000 ffff88012a357000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a35e1c0 ffff88012a357800 cgroup cgroup /sys/fs/cgroup/memory ffff880138ccbc00 ffff8800b499c000 configfs configfs /sys/kernel/config ffff8800b528c1c0 ffff8800b4af1800 ext4 /dev/nbd0 / ffff88012a35f340 ffff8801372e6800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a35fa40 ffff8800b52e8000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a35fc00 ffff88013714b000 mqueue mqueue /dev/mqueue ffff8800b528c380 ffff880129e9d000 hugetlbfs hugetlbfs /dev/hugepages ffff880138ccb880 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8800b528c540 ffff880129e9f000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012a35f880 ffff8800b4bfe800 ramfs none /mnt ffff880137668700 ffff8800b499c800 squashfs /dev/vda /home/green/git/lustre-release ffff8801376688c0 ffff8800b4999000 tmpfs none /var/lib/stateless/writable ffff880137668a80 ffff8800b4999000 tmpfs none /var/cache/man ffff8800b528c700 ffff8800b4999000 tmpfs none /var/log ffff88012a35f500 ffff8800b4999000 tmpfs none /var/lib/dbus ffff880137668c40 ffff8800b4999000 tmpfs none /tmp ffff8801373ca000 ffff8800b4999000 tmpfs none /var/lib/dhclient ffff8801373ca1c0 ffff8800b4999000 tmpfs none /var/tmp ffff880137668e00 ffff8800b4999000 tmpfs none /var/lib/NetworkManager ffff880136a72000 ffff8800b4999000 tmpfs none /var/lib/systemd/random-seed ffff880137668fc0 ffff8800b4999000 tmpfs none /var/spool ffff880137669180 ffff8800b4999000 tmpfs none /var/lib/nfs ffff8801373ca380 ffff8800b4999000 tmpfs none /var/lib/gssproxy ffff8801373ca540 ffff8800b4999000 tmpfs none /var/lib/logrotate ffff880137669340 ffff8800b4999000 tmpfs none /etc ffff880137669500 ffff8800b4999000 tmpfs none /var/lib/rsyslog ffff8801373ca700 ffff8800b4999000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8801373ca8c0 ffff8800b52ee000 nfs4 192.168.200.253:/exports/state/oleg335-server.virtnet /var/lib/stateless/state ffff8801376696c0 ffff8800b52ee000 nfs4 192.168.200.253:/exports/state/oleg335-server.virtnet /boot ffff8801373cae00 ffff8800b52ee000 nfs4 192.168.200.253:/exports/state/oleg335-server.virtnet /etc/etc/kdump.conf ffff8800b528ca80 ffff8801372e6800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff880136a73dc0 ffff8800b499c800 squashfs /dev/vda /usr/sbin/mount.lustre ffff88012a35e8c0 ffff8800b4247000 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff88012a35efc0 ffff88013736a000 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff88009396e000 ffff880093ae4800 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff88009396e8c0 ffff880097105000 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 75.495813] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 75.502103] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 76.952238] random: crng init done [ 80.371757] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 87.618317] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 93.336046] Lustre: DEBUG MARKER: oleg335-server.virtnet: executing check_logdir /tmp/testlogs/ [ 94.124498] Lustre: DEBUG MARKER: oleg335-server.virtnet: executing yml_node [ 95.030463] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 95.560367] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 96.075364] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 96.400570] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Wed May 8 18:02:25 EDT 2024 [ 99.627140] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 411b [ 100.125754] Lustre: DEBUG MARKER: oleg335-client.virtnet: executing check_config_client /mnt/lustre [ 104.377592] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 105.137039] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 105.688459] Lustre: DEBUG MARKER: oleg335-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 107.592604] Lustre: DEBUG MARKER: == sanity test 27m: create file while OST0 was full ====== 18:02:36 (1715205756) [ 107.892321] Lustre: DEBUG MARKER: SKIP: sanity test_27m 7210992 > 600000 skipping out-of-space test on OST0 [ 109.967898] Lustre: DEBUG MARKER: == sanity test 51b: exceed 64k subdirectory nlink limit on create, verify unlink ========================================================== 18:02:39 (1715205759) [ 297.775603] Lustre: DEBUG MARKER: == sanity test 64b: check out-of-space detection on client ========================================================== 18:05:46 (1715205946) [ 302.185794] Lustre: DEBUG MARKER: SKIP: oos test_64b oos.sh: 7210992kB free gt MAXFREE 800000kB, increase 800000 (or reduce test fs size) to proceed [ 305.616959] Lustre: DEBUG MARKER: == sanity test 71: Running dbench on lustre (don't segment fault) ============================================================== 18:05:54 (1715205954) [ 1032.540860] Lustre: DEBUG MARKER: == sanity test 255a: check 'lfs ladvise -a willread' ===== 18:18:01 (1715206681) [ 1075.078342] Lustre: ll_ost_io00_007: service thread pid 18764 was inactive for 40.046 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 1075.078355] Lustre: ll_ost_io00_008: service thread pid 18789 was inactive for 40.046 seconds. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one. [ 1075.098494] Pid: 18764, comm: ll_ost_io00_007 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 1075.103174] Call Trace: [ 1075.104751] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 1075.107695] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 1075.110740] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 1075.113407] [<0>] ofd_ladvise_hdl+0x62b/0x1030 [ofd] [ 1075.116023] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 1075.118868] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 1075.121856] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 1075.124302] [<0>] kthread+0xe4/0xf0 [ 1075.125865] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 1075.127943] [<0>] 0xfffffffffffffffe [ 1135.238281] LustreError: 7118:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.203.35@tcp ns: filter-lustre-OST0000_UUID lock: ffff88008f13af40/0xb73f6b2ce2c379d5 lrc: 3/0,0 mode: PW/PW res: [0x280000401:0x207c:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000480000020 nid: 192.168.203.35@tcp remote: 0x9afc58ce5828a419 expref: 7 pid: 18677 timeout: 1134 lvb_type: 0 [ 1135.599688] Lustre: DEBUG MARKER: sanity test_255a: @@@@@@ FAIL: Ladvise failed with no -l or -e argument [ 1167.222727] Lustre: lustre-OST0000: haven't heard from client 752736b1-8a2f-4789-8625-c7af9bb462b5 (at 192.168.203.35@tcp) in 32 seconds. I think it's dead, and I am evicting it. exp ffff8801228c3000, cur 1715206815 expire 1715206785 last 1715206783 ****************************************************************************** ************************ 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.19s (real) 6.49s (CPU), Child processes: 5.69s