************************ crashinfo ************************* /exports/testreports/42096/testresults/racer-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg218-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.weP4r/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42096/testresults/racer-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg218-client-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Thu Apr 18 03:33:53 EDT 2024 UPTIME: 00:11:59 LOAD AVERAGE: 54.14, 127.25, 97.61 TASKS: 331 NODENAME: oleg218-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=31656 CPU=1 CMD=rm #-1 __raw_callee_save___pv_queued_spin_unlock+0x5, 449 bytes of data #0 do_raw_spin_unlock+0x49 #1 _raw_spin_unlock+0xe #2 __debug_object_init+0x1a7 #3 debug_object_init+0x1b #4 rcuhead_fixup_activate+0x23 #5 debug_object_activate+0x149 #6 __call_rcu+0x3f #7 call_rcu_sched+0x1d #8 lovsub_object_free+0xfc #9 lu_object_free+0x13d #10 lu_object_put+0xb1 #11 cl_object_put+0xe #12 lov_delete_composite+0x31b #13 lov_object_delete+0x79 #14 lu_object_free+0xcd #15 lu_object_put+0xb1 #16 cl_object_put+0xe #17 cl_inode_fini+0x75 #18 ll_clear_inode+0x1e9 #19 ll_delete_inode+0x40 #20 evict+0xaf #21 iput+0xf5 #22 do_unlinkat+0x1ae #23 sys_unlinkat+0x1b #24 system_call_fastpath+0x1f, 477 bytes of data -- 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=32267 CPU=3 CMD=file_rm.sh #0 native_send_call_func_single_ipi+0x3c #1 generic_exec_single+0x139 #2 smp_call_function_single+0x6f #3 smp_call_function_many+0x223 #4 native_flush_tlb_others+0xb8 #5 flush_tlb_mm_range+0x7b #6 tlb_flush_mmu_tlbonly+0x2f #7 arch_tlb_finish_mmu+0x3f #8 tlb_finish_mmu+0x23 #9 exit_mmap+0xdb #10 mmput+0x7f #11 flush_old_exec+0x3b1 #12 load_elf_binary+0x340 #13 search_binary_handler+0x98 #14 do_execve_common+0x608 #15 sys_execve+0x29 #16 stub_execve+0x48, 477 bytes of data +--------------------------------+ >---------------------| How This Dump Has Been Created |---------------------< +--------------------------------+ Cannot identify the specific condition that triggered vmcore +++WARNING+++ High Load Averages: 54.14, 127.25, 97.61 +---------------+ >------------------------------| Tasks Summary |------------------------------< +---------------+ Number of Threads That Ran Recently ----------------------------------- last second 130 last 5s 146 last 60s 155 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 277 TASK_RUNNING 3 TASK_UNINTERRUPTIBLE 48 +++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 ----- -------------- ------ ---------------------------- 32267 file_rm.sh 0 ms 22 migration/2 0 ms (no user stack) 5269 file_rm.sh 0 ms /bin/bash ./file_rm.sh /mnt/lustre2/racer0 20 9 rcu_sched 0 ms (no user stack) 29 migration/3 1 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955079 3.6 GB ---- FREE 645739 2.5 GB 67% of TOTAL MEM USED 309340 1.2 GB 32% of TOTAL MEM SHARED 14286 55.8 MB 1% of TOTAL MEM BUFFERS 5147 20.1 MB 0% of TOTAL MEM CACHED 50273 196.4 MB 5% of TOTAL MEM SLAB 186198 727.3 MB 19% 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 90330 352.9 MB 12% of TOTAL LIMIT +++three oldest UNINTERRUPTIBLE threads ... ran 244s ago PID=21901 CPU=3 CMD=mrename #0 __schedule+0x2e2 #1 schedule_preempt_disabled+0x39 #2 __mutex_lock_slowpath+0x13a #3 mutex_lock+0x2d #4 lock_rename+0xc0 #5 SYSC_renameat2+0x22f #6 sys_renameat2+0xe #7 sys_rename+0x1e #8 system_call_fastpath+0x1f, 477 bytes of data ... ran 244s ago PID=21896 CPU=1 CMD=touch #0 __schedule+0x2e2 #1 schedule_preempt_disabled+0x39 #2 __mutex_lock_slowpath+0x13a #3 mutex_lock+0x2d #4 lookup_slow+0x33 #5 link_path_walk+0x81f #6 path_openat+0xae #7 do_filp_open+0x4d #8 do_sys_open+0x124 #9 sys_open+0x1e #10 system_call_fastpath+0x1f, 477 bytes of data ... ran 244s ago PID=21888 CPU=0 CMD=mrename #0 __schedule+0x2e2 #1 schedule_preempt_disabled+0x39 #2 __mutex_lock_slowpath+0x13a #3 mutex_lock+0x2d #4 lock_rename+0xc0 #5 SYSC_renameat2+0x22f #6 sys_renameat2+0xe #7 sys_rename+0x1e #8 system_call_fastpath+0x1f, 477 bytes of data +-------------------------------+ >----------------------| Scheduler Runqueues (per CPU) |----------------------< +-------------------------------+ ---+ CPU=0 ---- | CURRENT TASK , CMD=swapper/0 ---+ CPU=1 ---- | CURRENT TASK , CMD=rm ---+ CPU=2 ---- | CURRENT TASK , CMD=swapper/2 ---+ CPU=3 ---- | CURRENT TASK , CMD=file_rm.sh +------------------------+ >-------------------------| 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 -------------------- CLOSE 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 717.5 eth0 n/a 0.0 RSS_TOTAL=295780 pages, %mem= 2.5 +++WARNING+++ Possible hang +++WARNING+++ Run 'hanginfo' to get more details +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012ab04000 ffff88012ab08000 sysfs sysfs /sys ffff88012ab041c0 ffff880139944000 proc proc /proc ffff88012ab04380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012ab04540 ffff8800b6cea000 securityfs securityfs /sys/kernel/security ffff88012ab04700 ffff88012ab08800 tmpfs tmpfs /dev/shm ffff88012ab048c0 ffff8801372f6000 devpts devpts /dev/pts ffff88012ab04a80 ffff88012ab09000 tmpfs tmpfs /run ffff88012ab04c40 ffff88012ab09800 tmpfs tmpfs /sys/fs/cgroup ffff88012ab04e00 ffff88012ab0a000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012ab04fc0 ffff88012ab0a800 pstore pstore /sys/fs/pstore ffff88012ab05180 ffff88012ab0c800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012ab05340 ffff88012ab0c000 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012ab05500 ffff88012ab0b800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012ab056c0 ffff88012ab0b000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012ab05880 ffff88012ab0d000 cgroup cgroup /sys/fs/cgroup/devices ffff88012ab05a40 ffff88012ab0d800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012ab05c00 ffff88012ab0e000 cgroup cgroup /sys/fs/cgroup/memory ffff88012ab05dc0 ffff88012ab0e800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012aad4000 ffff88012ab0f000 cgroup cgroup /sys/fs/cgroup/pids ffff88012aad41c0 ffff88012ab0f800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012b266a80 ffff8800b7c0b000 configfs configfs /sys/kernel/config ffff88012b266c40 ffff8800b7c0c800 ext4 /dev/nbd0 / ffff8800b58f61c0 ffff88012abc0800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff880137668540 ffff8800b6df3000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012b267340 ffff88012a47d800 hugetlbfs hugetlbfs /dev/hugepages ffff88012aad48c0 ffff8801372f7800 mqueue mqueue /dev/mqueue ffff880137668700 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff88012aad4a80 ffff88012abc2800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8801376688c0 ffff8800b7c0d800 ramfs none /mnt ffff880137668a80 ffff8800b7c0c000 tmpfs none /var/lib/stateless/writable ffff88012b2676c0 ffff88012abc6800 squashfs /dev/vda /home/green/git/lustre-release ffff880137668c40 ffff8800b7c0c000 tmpfs none /var/cache/man ffff8800b58f6380 ffff8800b7c0c000 tmpfs none /var/log ffff880137668e00 ffff8800b7c0c000 tmpfs none /var/lib/dbus ffff880137668fc0 ffff8800b7c0c000 tmpfs none /tmp ffff880137669180 ffff8800b7c0c000 tmpfs none /var/lib/dhclient ffff880137669340 ffff8800b7c0c000 tmpfs none /var/tmp ffff880137669500 ffff8800b7c0c000 tmpfs none /var/lib/NetworkManager ffff8801376696c0 ffff8800b7c0c000 tmpfs none /var/lib/systemd/random-seed ffff8800b58f6540 ffff8800b7c0c000 tmpfs none /var/spool ffff880137669880 ffff8800b7c0c000 tmpfs none /var/lib/nfs ffff88012aad4c40 ffff8800b7c0c000 tmpfs none /var/lib/gssproxy ffff880137669a40 ffff8800b7c0c000 tmpfs none /var/lib/logrotate ffff88012aad4e00 ffff8800b7c0c000 tmpfs none /etc ffff88012aad4fc0 ffff8800b7c0c000 tmpfs none /var/lib/rsyslog ffff880137669c00 ffff8800b7c0c000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012aad5180 ffff8800b590d800 nfs4 192.168.200.253:/exports/state/oleg218-client.virtnet /var/lib/stateless/state ffff88012aad5340 ffff8800b590d800 nfs4 192.168.200.253:/exports/state/oleg218-client.virtnet /boot ffff880137669dc0 ffff8800b590d800 nfs4 192.168.200.253:/exports/state/oleg218-client.virtnet /etc/etc/kdump.conf ffff8800b3d7e000 ffff88012abc0800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800aecba000 ffff8800b5801000 nfs4 192.168.200.253://exports/testreports/42096/testresults/racer-ldiskfs-DNE-centos7_x86_64-centos7_x86_64 /tmp/tmp/testlogs ffff88012b266fc0 ffff8800b5802800 tmpfs tmpfs /run/user/0 ffff8800b3d7e380 ffff88012abc6800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8801368181c0 ffff8800b60e8800 lustre 192.168.202.118@tcp:/lustre /mnt/lustre ffff8800aecba540 ffff8800aa6d6000 lustre 192.168.202.118@tcp:/lustre /mnt/lustre2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 600.760833] [] SyS_rename+0x1e/0x20 [ 600.762830] [] system_call_fastpath+0x1f/0x24 [ 600.765691] INFO: task lfs:21921 blocked for more than 120 seconds. [ 600.768725] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 600.771703] lfs D ffff8800ac4dd100 12720 21921 5194 0x00000000 [ 600.775186] Call Trace: [ 600.776169] [] schedule_preempt_disabled+0x39/0x90 [ 600.779330] [] __mutex_lock_slowpath+0x13a/0x340 [ 600.782518] [] mutex_lock+0x2d/0x40 [ 600.784945] [] lookup_slow+0x33/0xa7 [ 600.787305] [] path_lookupat+0x89e/0x8d0 [ 600.789998] [] ? kmem_cache_alloc+0x11b/0x2e0 [ 600.792893] [] ? getname_flags+0x4f/0x1a0 [ 600.795661] [] filename_lookup+0x2b/0xc0 [ 600.798645] [] user_path_at_empty+0x67/0xc0 [ 600.800922] [] user_path_at+0x11/0x20 [ 600.803138] [] vfs_fstatat+0x63/0xc0 [ 600.804250] [] SYSC_newstat+0x2e/0x60 [ 600.805394] [] ? trace_do_page_fault+0x56/0x170 [ 600.807858] [] SyS_newstat+0xe/0x10 [ 600.809274] [] system_call_fastpath+0x1f/0x24 [ 600.810677] INFO: task dd:21922 blocked for more than 120 seconds. [ 600.812068] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 600.813468] dd D ffff8800a7186660 12920 21922 5204 0x00000000 [ 600.815252] Call Trace: [ 600.815695] [] schedule_preempt_disabled+0x39/0x90 [ 600.817193] [] __mutex_lock_slowpath+0x13a/0x340 [ 600.818877] [] mutex_lock+0x2d/0x40 [ 600.820651] [] do_last+0x296/0x1280 [ 600.822946] [] ? link_path_walk+0x27e/0x8c0 [ 600.825624] [] path_openat+0xcd/0x5b0 [ 600.828151] [] ? __handle_mm_fault+0x31d/0x720 [ 600.829958] [] do_filp_open+0x4d/0xb0 [ 600.831649] [] ? do_raw_spin_unlock+0x49/0x90 [ 600.834330] [] ? _raw_spin_unlock+0xe/0x20 [ 600.835899] [] ? __alloc_fd+0xc3/0x170 [ 600.837419] [] do_sys_open+0x124/0x220 [ 600.838892] [] ? filp_close+0x5b/0x80 [ 600.840206] [] SyS_open+0x1e/0x20 [ 600.841730] [] system_call_fastpath+0x1f/0x24 ****************************************************************************** ************************ A Summary Of Problems Found ************************* ****************************************************************************** -------------------- A list of all +++WARNING+++ messages -------------------- PARTIAL DUMP with size(vmcore) < 25% size(RAM) High Load Averages: 54.14, 127.25, 97.61 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.51s (real) 6.21s (CPU), Child processes: 5.23s