************************ crashinfo ************************* /exports/testreports/43439/testresults/sanity-hsm-ldiskfs-centos7_x86_64-centos7_x86_64/oleg215-client-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.vsRsY/vmlinux [TAINTED] DUMPFILE: /exports/testreports/43439/testresults/sanity-hsm-ldiskfs-centos7_x86_64-centos7_x86_64/oleg215-client-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Fri Jun 14 18:11:51 EDT 2024 UPTIME: 01:23:46 LOAD AVERAGE: 2.00, 1.99, 1.95 TASKS: 156 NODENAME: oleg215-client.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 15 last 5s 29 last 60s 39 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 150 TASK_RUNNING 1 TASK_UNINTERRUPTIBLE 2 +++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 ----- -------------- ------ ---------------------------- 30208 ldlm_bl_05 0 ms (no user stack) 1829 monitor_thread 0 ms (no user stack) 1831 ptlrpcd_00_00 0 ms (no user stack) 12966 kworker/2:1 198 ms (no user stack) 1826 socknal_sd01_01 198 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955079 3.6 GB ---- FREE 837375 3.2 GB 87% of TOTAL MEM USED 117704 459.8 MB 12% of TOTAL MEM SHARED 20637 80.6 MB 2% of TOTAL MEM BUFFERS 5425 21.2 MB 0% of TOTAL MEM CACHED 65433 255.6 MB 6% of TOTAL MEM SLAB 15217 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 739682 2.8 GB ---- COMMITTED 65650 256.4 MB 8% of TOTAL LIMIT +++three oldest UNINTERRUPTIBLE threads ... ran 3189s ago PID=30167 CPU=1 CMD=lhsmtool_posix #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 wait_woken+0x66 #4 obd_get_mod_rpc_slot+0x1e4 #5 ptlrpc_get_mod_rpc_slot+0x41 #6 mdc_close+0x262 #7 lmv_close+0x1a0 #8 ll_close_inode_openhandle+0x322 #9 ll_md_real_close+0xf0 #10 ll_file_release+0x6db #11 ll_dir_release+0x2f #12 __fput+0xfc #13 ____fput+0xe #14 task_work_run+0xb5 #15 do_notify_resume+0x92 #16 int_signal+0x12, 477 bytes of data ... ran 3292s ago PID=31154 CPU=2 CMD=lhsmtool_posix #0 __schedule+0x2e2 #1 schedule+0x29 #2 schedule_timeout+0x209 #3 wait_woken+0x66 #4 obd_get_mod_rpc_slot+0x1e4 #5 ptlrpc_get_mod_rpc_slot+0x41 #6 ldlm_cli_enqueue+0x4d1 #7 mdc_enqueue_base+0x352 #8 mdc_intent_lock+0x135 #9 lmv_intent_open+0x3a5 #10 lmv_intent_lock+0x1e7 #11 ll_lookup_it.constprop.40+0x789 #12 ll_atomic_open+0x1b4 #13 do_last+0xa40 #14 path_openat+0xcd #15 do_filp_open+0x4d #16 do_sys_open+0x124 #17 sys_open+0x1e #18 system_call_fastpath+0x1f, 477 bytes of data +-------------------------------+ >----------------------| 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 6 LISTEN 3 NAGLE disabled (TCP_NODELAY): 5 user_data set (NFS etc.): 4 UDP Connection Info ------------------- 2 UDP sockets, 0 in ESTABLISHED Unix Connection Info ------------------------ ESTABLISHED 26 CLOSE 18 LISTEN 8 Raw sockets info -------------------- ESTABLISHED 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 5024.1 eth0 n/a 0.5 RSS_TOTAL=70352 pages, %mem= 1.1 +++WARNING+++ Possible hang +++WARNING+++ Run 'hanginfo' to get more details +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012aa9c000 ffff88012aac8000 sysfs sysfs /sys ffff88012aa9c1c0 ffff880139944000 proc proc /proc ffff88012aa9c380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012aa9c540 ffff8800b6d2a000 securityfs securityfs /sys/kernel/security ffff88012aa9c700 ffff88012aac8800 tmpfs tmpfs /dev/shm ffff88012aa9c8c0 ffff8801372f6000 devpts devpts /dev/pts ffff88012aa9ca80 ffff88012aac9000 tmpfs tmpfs /run ffff88012aa9cc40 ffff88012aac9800 tmpfs tmpfs /sys/fs/cgroup ffff88012aa9ce00 ffff88012aaca000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012aa9cfc0 ffff88012aaca800 pstore pstore /sys/fs/pstore ffff88012aa9d180 ffff88012aacc800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012aa9d340 ffff88012aacc000 cgroup cgroup /sys/fs/cgroup/devices ffff88012aa9d500 ffff88012aacb800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012aa9d6c0 ffff88012aacb000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012aa9d880 ffff88012aacd000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012aa9da40 ffff88012aacd800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012aa9dc00 ffff88012aace000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012aa9ddc0 ffff88012aace800 cgroup cgroup /sys/fs/cgroup/pids ffff88012aad8000 ffff88012aacf000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012aad81c0 ffff88012aacf800 cgroup cgroup /sys/fs/cgroup/memory ffff880138ccb180 ffff8800b6cc4000 configfs configfs /sys/kernel/config ffff8801376696c0 ffff8800b6d2c800 ext4 /dev/nbd0 / ffff88012aad8540 ffff8800b6d2e000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff880137669880 ffff8800b588c800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880137669a40 ffff8801372f7800 mqueue mqueue /dev/mqueue ffff88012aad8c40 ffff8800b604e000 hugetlbfs hugetlbfs /dev/hugepages ffff88012aad8e00 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880138ccb340 ffff8800b63fe800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012aad9180 ffff8800b63d5800 ramfs none /mnt ffff880137669c00 ffff88012aba2000 tmpfs none /var/lib/stateless/writable ffff88012aad9340 ffff8800b63d4000 squashfs /dev/vda /home/green/git/lustre-release ffff88012aad9500 ffff88012aba2000 tmpfs none /var/cache/man ffff88012aad96c0 ffff88012aba2000 tmpfs none /var/log ffff88012b26ac40 ffff88012aba2000 tmpfs none /var/lib/dbus ffff88012aad9880 ffff88012aba2000 tmpfs none /tmp ffff88012b26ae00 ffff88012aba2000 tmpfs none /var/lib/dhclient ffff88012b26afc0 ffff88012aba2000 tmpfs none /var/tmp ffff88012aad9a40 ffff88012aba2000 tmpfs none /var/lib/NetworkManager ffff880138ccb500 ffff88012aba2000 tmpfs none /var/lib/systemd/random-seed ffff880137668540 ffff88012aba2000 tmpfs none /var/spool ffff8800b6efc000 ffff88012aba2000 tmpfs none /var/lib/nfs ffff8800b6efc1c0 ffff88012aba2000 tmpfs none /var/lib/gssproxy ffff880138ccb6c0 ffff88012aba2000 tmpfs none /var/lib/logrotate ffff88012aad9c00 ffff88012aba2000 tmpfs none /etc ffff8800b6efc380 ffff88012aba2000 tmpfs none /var/lib/rsyslog ffff88012aad9dc0 ffff88012aba2000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8800b6efc540 ffff8800b63d7800 nfs4 192.168.200.253:/exports/state/oleg215-client.virtnet /var/lib/stateless/state ffff8800b6efca80 ffff8800b63d7800 nfs4 192.168.200.253:/exports/state/oleg215-client.virtnet /boot ffff88012aad88c0 ffff8800b63d7800 nfs4 192.168.200.253:/exports/state/oleg215-client.virtnet /etc/etc/kdump.conf ffff880138ccb880 ffff8800b6d2e000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b6efd6c0 ffff8800b604f000 nfs4 192.168.200.253://exports/testreports/43439/testresults/sanity-hsm-ldiskfs-centos7_x86_64-centos7_x86_64 /tmp/tmp/testlogs ffff8800b043a1c0 ffff8800b6170000 tmpfs tmpfs /run/user/0 ffff8800b6efd180 ffff8800b63d4000 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b6efda40 ffff8800aacf4800 lustre 192.168.202.115@tcp:/lustre /mnt/lustre2 ffff8800b043b180 ffff8800a88f4800 lustre 192.168.202.115@tcp:/lustre /mnt/lustre +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 2521.347808] [] ? lprocfs_counter_add+0xf9/0x160 [obdclass] [ 2521.350722] [] ? __wake_up_common+0x70/0x100 [ 2521.353287] [] wait_woken+0x66/0x90 [ 2521.355592] [] obd_get_mod_rpc_slot+0x1e4/0x260 [obdclass] [ 2521.358764] [] ? obd_mod_rpc_stats_seq_show+0x140/0x140 [obdclass] [ 2521.362054] [] ptlrpc_get_mod_rpc_slot+0x41/0xe0 [ptlrpc] [ 2521.365128] [] mdc_close+0x262/0x9b0 [mdc] [ 2521.367658] [] lmv_close+0x1a0/0x3d0 [lmv] [ 2521.370020] [] ? lprocfs_counter_add+0xf9/0x160 [obdclass] [ 2521.373120] [] ll_close_inode_openhandle+0x322/0xe40 [lustre] [ 2521.375716] [] ll_md_real_close+0xf0/0x200 [lustre] [ 2521.378780] [] ll_file_release+0x6db/0x910 [lustre] [ 2521.380744] [] ? __d_free+0x35/0x40 [ 2521.382065] [] ll_dir_release+0x2f/0xf0 [lustre] [ 2521.384015] [] __fput+0xfc/0x240 [ 2521.385314] [] ____fput+0xe/0x10 [ 2521.386576] [] task_work_run+0xb5/0xf0 [ 2521.388088] [] do_notify_resume+0x92/0xb0 [ 2521.389544] [] int_signal+0x12/0x17 [ 2932.817400] Lustre: 30206:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1718400416/real 1718400416] req@ffff8800a8bcb440 x1801871040064064/t0(0) o58->lustre-MDT0000-mdc-ffff8800aacf4800@192.168.202.115@tcp:12/10 lens 512/224 e 23 to 1 dl 1718401017 ref 2 fl Rpc:XQr/2/ffffffff rc -19/-1 job:'md5sum.0' [ 2932.823064] Lustre: lustre-MDT0000-mdc-ffff8800aacf4800: Connection to lustre-MDT0000 (at 192.168.202.115@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2932.826193] Lustre: Skipped 1 previous similar message [ 2932.832610] Lustre: lustre-MDT0000-mdc-ffff8800aacf4800: Connection restored to 192.168.202.115@tcp (at 192.168.202.115@tcp) [ 2932.835239] Lustre: Skipped 1 previous similar message [ 3533.836353] Lustre: 30206:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1718401017/real 1718401017] req@ffff8800a8bcb440 x1801871040064064/t0(0) o58->lustre-MDT0000-mdc-ffff8800aacf4800@192.168.202.115@tcp:12/10 lens 512/224 e 23 to 1 dl 1718401618 ref 2 fl Rpc:XQr/2/ffffffff rc -19/-1 job:'md5sum.0' [ 3533.836375] Lustre: lustre-MDT0000-mdc-ffff8800a88f4800: Connection to lustre-MDT0000 (at 192.168.202.115@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3533.836377] Lustre: Skipped 1 previous similar message [ 3533.846946] Lustre: lustre-MDT0000-mdc-ffff8800a88f4800: Connection restored to 192.168.202.115@tcp (at 192.168.202.115@tcp) [ 3533.846948] Lustre: Skipped 1 previous similar message [ 3533.859272] Lustre: 30206:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 4134.846501] Lustre: 30205:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1718401618/real 1718401618] req@ffff8800a8bf3dc0 x1801871040064192/t0(0) o58->lustre-MDT0000-mdc-ffff8800a88f4800@192.168.202.115@tcp:12/10 lens 512/224 e 23 to 1 dl 1718402219 ref 2 fl Rpc:XQr/2/ffffffff rc -19/-1 job:'md5sum.0' [ 4134.860933] Lustre: lustre-MDT0000-mdc-ffff8800a88f4800: Connection to lustre-MDT0000 (at 192.168.202.115@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4134.868958] Lustre: Skipped 1 previous similar message [ 4134.873482] Lustre: lustre-MDT0000-mdc-ffff8800a88f4800: Connection restored to 192.168.202.115@tcp (at 192.168.202.115@tcp) [ 4134.878650] Lustre: Skipped 1 previous similar message [ 4735.881410] Lustre: 30205:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1718402219/real 1718402219] req@ffff8800a8bf3dc0 x1801871040064192/t0(0) o58->lustre-MDT0000-mdc-ffff8800a88f4800@192.168.202.115@tcp:12/10 lens 512/224 e 23 to 1 dl 1718402820 ref 2 fl Rpc:XQr/2/ffffffff rc -19/-1 job:'md5sum.0' [ 4735.881512] Lustre: lustre-MDT0000-mdc-ffff8800aacf4800: Connection to lustre-MDT0000 (at 192.168.202.115@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4735.888248] Lustre: lustre-MDT0000-mdc-ffff8800aacf4800: Connection restored to 192.168.202.115@tcp (at 192.168.202.115@tcp) [ 4735.888251] Lustre: Skipped 1 previous similar message [ 4735.913454] Lustre: 30205:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages ****************************************************************************** ************************ 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 Possible hang Run 'hanginfo' to get more details ------------------------------------------------------------------------------ ** Execution took 11.06s (real) 5.75s (CPU), Child processes: 5.25s