************************ crashinfo ************************* /exports/testreports/47154/testresults/sanity-hsm-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg434-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.8Vzdb/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/sanity-hsm-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg434-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 13:09:25 EST 2024 UPTIME: 01:02:12 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 247 NODENAME: oleg434-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 29 last 5s 62 last 60s 76 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 243 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 ----- -------------- ------ ---------------------------- 11504 ll_ost_create00 0 ms (no user stack) 7202 ll_evictor 0 ms (no user stack) 7194 ldlm_bl_01 0 ms (no user stack) 3758 lnet_discovery 0 ms (no user stack) 10232 osp-pre-0-1 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 739415 2.8 GB 77% of TOTAL MEM USED 215652 842.4 MB 22% of TOTAL MEM SHARED 10716 41.9 MB 1% of TOTAL MEM BUFFERS 8508 33.2 MB 0% of TOTAL MEM CACHED 71184 278.1 MB 7% of TOTAL MEM SLAB 15208 59.4 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 58975 230.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 3730.0 eth0 n/a 5.0 RSS_TOTAL=53348 pages, %mem= 0.9 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a350000 ffff88012a358000 sysfs sysfs /sys ffff88012a3501c0 ffff880139944000 proc proc /proc ffff88012a350380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a350540 ffff8800b521a000 securityfs securityfs /sys/kernel/security ffff88012a350700 ffff88012a358800 tmpfs tmpfs /dev/shm ffff88012a3508c0 ffff8801372f6000 devpts devpts /dev/pts ffff88012a350a80 ffff88012a359000 tmpfs tmpfs /run ffff88012a350c40 ffff88012a359800 tmpfs tmpfs /sys/fs/cgroup ffff88012a350e00 ffff88012a35a000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a350fc0 ffff88012a35a800 pstore pstore /sys/fs/pstore ffff88012a351180 ffff88012a35c800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a351340 ffff88012a35c000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a351500 ffff88012a35b800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a3516c0 ffff88012a35b000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a351880 ffff88012a35d000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a351a40 ffff88012a35d800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a351c00 ffff88012a35e000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a351dc0 ffff88012a35e800 cgroup cgroup /sys/fs/cgroup/devices ffff88012a318000 ffff88012a35f000 cgroup cgroup /sys/fs/cgroup/memory ffff88012a3181c0 ffff88012a35f800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012b266a80 ffff8800b7c0c800 configfs configfs /sys/kernel/config ffff88012b266e00 ffff8800b3e0b000 ext4 /dev/nbd0 / ffff880137668a80 ffff8800b521d000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a319880 ffff8800b3e0e800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012b266fc0 ffff8800b4bf4800 hugetlbfs hugetlbfs /dev/hugepages ffff88012b267180 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff88012b267340 ffff8801372f7800 mqueue mqueue /dev/mqueue ffff880137668c40 ffff8800b3c95800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012a319a40 ffff8800b5262000 ramfs none /mnt ffff88012a319c00 ffff880129dd7000 squashfs /dev/vda /home/green/git/lustre-release ffff880138ccafc0 ffff8800b7c0e000 tmpfs none /var/lib/stateless/writable ffff88012b2676c0 ffff8800b7c0e000 tmpfs none /var/cache/man ffff88012a3196c0 ffff8800b7c0e000 tmpfs none /var/log ffff880137668e00 ffff8800b7c0e000 tmpfs none /var/lib/dbus ffff880137668fc0 ffff8800b7c0e000 tmpfs none /tmp ffff880137669180 ffff8800b7c0e000 tmpfs none /var/lib/dhclient ffff88012a319500 ffff8800b7c0e000 tmpfs none /var/tmp ffff880137669340 ffff8800b7c0e000 tmpfs none /var/lib/NetworkManager ffff880138ccb180 ffff8800b7c0e000 tmpfs none /var/lib/systemd/random-seed ffff880137669500 ffff8800b7c0e000 tmpfs none /var/spool ffff88012a319340 ffff8800b7c0e000 tmpfs none /var/lib/nfs ffff8800b3e3a000 ffff8800b7c0e000 tmpfs none /var/lib/gssproxy ffff8801376696c0 ffff8800b7c0e000 tmpfs none /var/lib/logrotate ffff88012b267880 ffff8800b7c0e000 tmpfs none /etc ffff880137669880 ffff8800b7c0e000 tmpfs none /var/lib/rsyslog ffff8800b3e3a1c0 ffff8800b7c0e000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012b267a40 ffff8800b3c38800 nfs4 192.168.200.253:/exports/state/oleg434-server.virtnet /var/lib/stateless/state ffff8800b3e3a540 ffff8800b3c38800 nfs4 192.168.200.253:/exports/state/oleg434-server.virtnet /boot ffff88012b267dc0 ffff8800b3c38800 nfs4 192.168.200.253:/exports/state/oleg434-server.virtnet /etc/etc/kdump.conf ffff8800b3e3a700 ffff8800b521d000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b1d92e00 ffff880129dd7000 squashfs /dev/vda /usr/sbin/mount.lustre ffff880138ccb6c0 ffff8800b3d36800 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff8800b244cc40 ffff880081564800 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff8800b244d6c0 ffff88008bd11000 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff8800b244cfc0 ffff8801303cf000 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 74.212847] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 74.224867] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 75.512009] Lustre: DEBUG MARKER: oleg434-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 79.984550] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 79.988936] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 80.002222] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 80.297757] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 86.504188] Lustre: Setting parameter general.lod.*.mdt_hash in log params [ 92.810182] Lustre: DEBUG MARKER: oleg434-server.virtnet: executing check_logdir /tmp/testlogs/ [ 93.699649] Lustre: DEBUG MARKER: oleg434-server.virtnet: executing yml_node [ 94.638954] Lustre: DEBUG MARKER: Client: 2.16.0.1 [ 95.216586] Lustre: DEBUG MARKER: MDS: 2.16.0.1 [ 95.798404] Lustre: DEBUG MARKER: OSS: 2.16.0.1 [ 96.165696] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-hsm ============----- Wed Nov 13 12:08:48 EST 2024 [ 99.754912] Lustre: DEBUG MARKER: excepting tests: [ 100.088010] Lustre: DEBUG MARKER: === sanity-hsm: start setup 12:08:52 (1731517732) === [ 100.928955] Lustre: DEBUG MARKER: oleg434-client.virtnet: executing check_config_client /mnt/lustre [ 105.334513] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 106.106326] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 106.691307] Lustre: DEBUG MARKER: oleg434-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 107.752487] Lustre: DEBUG MARKER: === sanity-hsm: finish setup 12:09:00 (1731517740) === [ 129.646166] Lustre: DEBUG MARKER: == sanity-hsm test 1A: lfs hsm flags root/non-root access ========================================================== 12:09:22 (1731517762) [ 131.268128] Lustre: DEBUG MARKER: == sanity-hsm test 1a: mmap [ 172.993557] Lustre: ll_ost00_002: service thread pid 9547 was inactive for 40.088 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 172.997583] Pid: 9547, comm: ll_ost00_002 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 172.999502] Call Trace: [ 173.000482] [<0>] ldlm_completion_ast+0x913/0xd50 [ptlrpc] [ 173.001800] [<0>] ldlm_cli_enqueue_local+0x259/0x890 [ptlrpc] [ 173.003003] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 173.004315] [<0>] ofd_getattr_hdl+0x385/0x760 [ofd] [ 173.005486] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 173.006803] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 173.008112] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 173.009363] [<0>] kthread+0xe4/0xf0 [ 173.010245] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 173.011406] [<0>] 0xfffffffffffffffe [ 233.153584] LustreError: 7196:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.204.34@tcp ns: filter-lustre-OST0001_UUID lock: ffff88009c5d3a80/0x72f1910cad9d6d09 lrc: 3/0,0 mode: PR/PR res: [0x2c0000401:0x2:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400000020 nid: 192.168.204.34@tcp remote: 0xe87dd184f4de0f9b expref: 6 pid: 9547 timeout: 232 lvb_type: 1 [ 233.163996] Lustre: ll_ost00_002: service thread pid 9547 completed after 100.258s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 270.290018] Lustre: lustre-OST0001: haven't heard from client ef3fdd9c-2d33-4f7b-b6af-79baaf47239f (at 192.168.204.34@tcp) in 35 seconds. I think it's dead, and I am evicting it. exp ffff880091ec9800, cur 1731517902 expire 1731517872 last 1731517867 [ 533.199160] Lustre: lustre-MDT0000: Client dbc3e5a9-dcc0-4a1f-95f7-1e41edd28b5a (at 192.168.204.34@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.09s (real) 6.43s (CPU), Child processes: 5.62s