************************ crashinfo ************************* /exports/testreports/47154/testresults/sanity-hsm-zfs-centos7_x86_64-centos7_x86_64/oleg315-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.PHzh0/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/sanity-hsm-zfs-centos7_x86_64-centos7_x86_64/oleg315-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 13:09:06 EST 2024 UPTIME: 01:01:58 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 333 NODENAME: oleg315-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 31 last 5s 69 last 60s 78 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 329 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 ----- -------------- ------ ---------------------------- 11 rcuos/0 0 ms (no user stack) 6691 z_null_iss 0 ms (no user stack) 10760 ldlm_bl_04 0 ms (no user stack) 3487 dbuf_evict 0 ms (no user stack) 49 kworker/0:1 7 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 741120 2.8 GB 77% of TOTAL MEM USED 213947 835.7 MB 22% of TOTAL MEM SHARED 9910 38.7 MB 1% of TOTAL MEM BUFFERS 5123 20 MB 0% of TOTAL MEM CACHED 69492 271.5 MB 7% of TOTAL MEM SLAB 16979 66.3 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 57965 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 -------------------- ESTABLISHED 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 3715.8 eth0 n/a 0.8 RSS_TOTAL=53880 pages, %mem= 0.9 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a35a000 ffff8800b5219800 sysfs sysfs /sys ffff88012a35a1c0 ffff880139944000 proc proc /proc ffff88012a35a380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a35a540 ffff8800b51ab000 securityfs securityfs /sys/kernel/security ffff88012a35a700 ffff8800b521a000 tmpfs tmpfs /dev/shm ffff88012a35a8c0 ffff88013771f000 devpts devpts /dev/pts ffff88012a35aa80 ffff8800b521a800 tmpfs tmpfs /run ffff88012a35ac40 ffff8800b521b000 tmpfs tmpfs /sys/fs/cgroup ffff88012a35ae00 ffff8800b521b800 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a35afc0 ffff8800b521c000 pstore pstore /sys/fs/pstore ffff88012a35b180 ffff8800b521e000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a35b340 ffff8800b521d800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a35b500 ffff8800b521d000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a35b6c0 ffff8800b521c800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a35b880 ffff8800b521e800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a35ba40 ffff8800b521f000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a35bc00 ffff8800b521f800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a35bdc0 ffff88012a308000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a324000 ffff88012a308800 cgroup cgroup /sys/fs/cgroup/memory ffff88012a3241c0 ffff88012a309000 cgroup cgroup /sys/fs/cgroup/pids ffff880137668380 ffff88013767e000 configfs configfs /sys/kernel/config ffff88012a324540 ffff88012a30e800 ext4 /dev/nbd0 / ffff88012a324700 ffff88012a30c800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a324e00 ffff880129cb7000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880137668540 ffff880129ed5800 hugetlbfs hugetlbfs /dev/hugepages ffff880137668700 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8801376688c0 ffff88012b2b8800 mqueue mqueue /dev/mqueue ffff8801377f68c0 ffff88012a30f000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8801377f6c40 ffff88012a30b800 ramfs none /mnt ffff8801377f6e00 ffff8800b42a9000 tmpfs none /var/lib/stateless/writable ffff880129d148c0 ffff88013767c000 squashfs /dev/vda /home/green/git/lustre-release ffff88012a324fc0 ffff8800b42a9000 tmpfs none /var/cache/man ffff88012a325180 ffff8800b42a9000 tmpfs none /var/log ffff8801377f6fc0 ffff8800b42a9000 tmpfs none /var/lib/dbus ffff88012a325340 ffff8800b42a9000 tmpfs none /tmp ffff88012a325500 ffff8800b42a9000 tmpfs none /var/lib/dhclient ffff88012a3256c0 ffff8800b42a9000 tmpfs none /var/tmp ffff88012a325880 ffff8800b42a9000 tmpfs none /var/lib/NetworkManager ffff88012a325a40 ffff8800b42a9000 tmpfs none /var/lib/systemd/random-seed ffff88012a325c00 ffff8800b42a9000 tmpfs none /var/spool ffff88012a325dc0 ffff8800b42a9000 tmpfs none /var/lib/nfs ffff88012a324c40 ffff8800b42a9000 tmpfs none /var/lib/gssproxy ffff8801377f7180 ffff8800b42a9000 tmpfs none /var/lib/logrotate ffff880137668a80 ffff8800b42a9000 tmpfs none /etc ffff880137668c40 ffff8800b42a9000 tmpfs none /var/lib/rsyslog ffff88012a324a80 ffff8800b42a9000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012a3248c0 ffff880129df2000 nfs4 192.168.200.253:/exports/state/oleg315-server.virtnet /var/lib/stateless/state ffff88012a324380 ffff880129df2000 nfs4 192.168.200.253:/exports/state/oleg315-server.virtnet /boot ffff880129d14c40 ffff880129df2000 nfs4 192.168.200.253:/exports/state/oleg315-server.virtnet /etc/etc/kdump.conf ffff880137668e00 ffff88012a30c800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff880137669880 ffff88013767c000 squashfs /dev/vda /usr/sbin/mount.lustre ffff880129d15a40 ffff8800b403f800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff880129d156c0 ffff8800b403e800 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff8800b25308c0 ffff8800a8884000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 55.016301] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 56.264448] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 56.354837] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 56.357397] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 56.381365] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 56.388523] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 60.938717] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 67.160064] Lustre: Setting parameter general.lod.*.mdt_hash in log params [ 73.518708] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing check_logdir /tmp/testlogs/ [ 74.285080] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing yml_node [ 75.219100] Lustre: DEBUG MARKER: Client: 2.16.0.1 [ 75.797874] Lustre: DEBUG MARKER: MDS: 2.16.0.1 [ 76.380937] Lustre: DEBUG MARKER: OSS: 2.16.0.1 [ 76.734683] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-hsm ============----- Wed Nov 13 12:08:23 EST 2024 [ 80.393071] Lustre: DEBUG MARKER: excepting tests: [ 80.743192] Lustre: DEBUG MARKER: === sanity-hsm: start setup 12:08:27 (1731517707) === [ 81.656675] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing check_config_client /mnt/lustre [ 86.250352] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 87.222679] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 87.881298] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 88.656818] Lustre: DEBUG MARKER: === sanity-hsm: finish setup 12:08:35 (1731517715) === [ 109.950794] Lustre: DEBUG MARKER: == sanity-hsm test 1A: lfs hsm flags root/non-root access ========================================================== 12:08:56 (1731517736) [ 111.584676] Lustre: DEBUG MARKER: == sanity-hsm test 1a: mmap [ 152.070766] Lustre: ll_ost00_004: service thread pid 14683 was inactive for 40.091 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 152.078253] Pid: 14683, comm: ll_ost00_004 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 152.081858] Call Trace: [ 152.083668] [<0>] ldlm_completion_ast+0x913/0xd50 [ptlrpc] [ 152.087152] [<0>] ldlm_cli_enqueue_local+0x259/0x890 [ptlrpc] [ 152.089512] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 152.091423] [<0>] ofd_getattr_hdl+0x385/0x760 [ofd] [ 152.093511] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 152.095612] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 152.098241] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 152.099978] [<0>] kthread+0xe4/0xf0 [ 152.101376] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 152.103591] [<0>] 0xfffffffffffffffe [ 212.358724] LustreError: 7015:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.203.15@tcp ns: filter-lustre-OST0001_UUID lock: ffff88012dc13a80/0x8a88dc33341ed912 lrc: 3/0,0 mode: PR/PR res: [0x280000400:0x3:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400000020 nid: 192.168.203.15@tcp remote: 0x2051f96ea83cec36 expref: 6 pid: 14683 timeout: 211 lvb_type: 1 [ 212.379662] Lustre: ll_ost00_004: service thread pid 14683 completed after 100.400s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 246.631019] Lustre: lustre-OST0001: haven't heard from client d1ef7eab-b5b2-4c80-b996-5ac8b3d43a71 (at 192.168.203.15@tcp) in 31 seconds. I think it's dead, and I am evicting it. exp ffff88013448e000, cur 1731517874 expire 1731517844 last 1731517843 [ 512.447666] Lustre: lustre-MDT0000: Client 7ff5cdb1-2f40-497e-afca-33d9656978fc (at 192.168.203.15@tcp) reconnecting ****************************************************************************** ************************ 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.49s (real) 6.90s (CPU), Child processes: 5.55s