************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-pfl-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg250-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.xFXxg/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-pfl-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg250-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 19:04:07 EDT 2024 UPTIME: 01:03:17 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 263 NODENAME: oleg250-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 49 last 5s 61 last 60s 75 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 259 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 ----- -------------- ------ ---------------------------- 918 in:imjournal 0 ms /usr/sbin/rsyslogd -n 68 kworker/3:1 0 ms (no user stack) 3674 lnet_discovery 0 ms (no user stack) 4426 zthr_procedure 0 ms (no user stack) 9 rcu_sched 39 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 732961 2.8 GB 76% of TOTAL MEM USED 222106 867.6 MB 23% of TOTAL MEM SHARED 13890 54.3 MB 1% of TOTAL MEM BUFFERS 11747 45.9 MB 1% of TOTAL MEM CACHED 69044 269.7 MB 7% of TOTAL MEM SLAB 18522 72.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 59995 234.4 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 3795.2 eth0 n/a 5.0 RSS_TOTAL=51960 pages, %mem= 0.9 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff880137678800 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff88012b37e800 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff880137679000 tmpfs tmpfs /dev/shm ffff880137668c40 ffff88012b260800 devpts devpts /dev/pts ffff880137668e00 ffff880137679800 tmpfs tmpfs /run ffff880137668fc0 ffff88013767a000 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff88013767a800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff88013767b000 pstore pstore /sys/fs/pstore ffff880138ccaa80 ffff8800b5216000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff880138ccac40 ffff8800b5215800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880138ccae00 ffff8800b5215000 cgroup cgroup /sys/fs/cgroup/perf_event ffff880138ccafc0 ffff8800b5214800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff880138ccb180 ffff8800b5216800 cgroup cgroup /sys/fs/cgroup/memory ffff880138ccb340 ffff8800b5217000 cgroup cgroup /sys/fs/cgroup/cpuset ffff880138ccb500 ffff8800b5217800 cgroup cgroup /sys/fs/cgroup/pids ffff880138ccb6c0 ffff88012a2f8000 cgroup cgroup /sys/fs/cgroup/freezer ffff880138ccb880 ffff88012a2f8800 cgroup cgroup /sys/fs/cgroup/devices ffff880138ccba40 ffff88012a2f9000 cgroup cgroup /sys/fs/cgroup/blkio ffff880138ccbdc0 ffff88012a2fe000 configfs configfs /sys/kernel/config ffff88012a318fc0 ffff88012a2fe800 ext4 /dev/nbd0 / ffff880137669500 ffff8800b5264000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8801376696c0 ffff8800b425f800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a319180 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880137669880 ffff88012b262000 mqueue mqueue /dev/mqueue ffff88013701d340 ffff88012a2fa000 hugetlbfs hugetlbfs /dev/hugepages ffff8800b53948c0 ffff8800b41df000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8800b5394c40 ffff880129d4c000 ramfs none /mnt ffff88012a319340 ffff8800b4048800 squashfs /dev/vda /home/green/git/lustre-release ffff880137669a40 ffff8800b53df000 tmpfs none /var/lib/stateless/writable ffff8800b5394e00 ffff8800b53df000 tmpfs none /var/cache/man ffff88013701d500 ffff8800b53df000 tmpfs none /var/log ffff88012a3196c0 ffff8800b53df000 tmpfs none /var/lib/dbus ffff8800b5394fc0 ffff8800b53df000 tmpfs none /tmp ffff88013701d6c0 ffff8800b53df000 tmpfs none /var/lib/dhclient ffff880137669c00 ffff8800b53df000 tmpfs none /var/tmp ffff8800b5395180 ffff8800b53df000 tmpfs none /var/lib/NetworkManager ffff88013701d880 ffff8800b53df000 tmpfs none /var/lib/systemd/random-seed ffff8800b5395340 ffff8800b53df000 tmpfs none /var/spool ffff8800b5395500 ffff8800b53df000 tmpfs none /var/lib/nfs ffff88013701da40 ffff8800b53df000 tmpfs none /var/lib/gssproxy ffff8800b53956c0 ffff8800b53df000 tmpfs none /var/lib/logrotate ffff88013701dc00 ffff8800b53df000 tmpfs none /etc ffff8800b5395880 ffff8800b53df000 tmpfs none /var/lib/rsyslog ffff8800b5395a40 ffff8800b53df000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff880137669dc0 ffff8800b425d000 nfs4 192.168.200.253:/exports/state/oleg250-server.virtnet /var/lib/stateless/state ffff8800b27781c0 ffff8800b425d000 nfs4 192.168.200.253:/exports/state/oleg250-server.virtnet /boot ffff88013701ce00 ffff8800b425d000 nfs4 192.168.200.253:/exports/state/oleg250-server.virtnet /etc/etc/kdump.conf ffff8800b2778380 ffff8800b5264000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b251cc40 ffff8800b4048800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b4e9ce00 ffff8800b1a3b800 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff8800b4e9c540 ffff8800b41da800 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff8800b4e9c1c0 ffff880095b56800 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff8800b4e9d340 ffff88009e0ee800 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 158.710055] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x280000404 to 0x280000407 [ 174.090618] Lustre: DEBUG MARKER: == sanity-pfl test 2a: Add components to existing file === 18:03:42 (1715205822) [ 178.373009] Lustre: DEBUG MARKER: == sanity-pfl test 2b: Add components w/DOM to existing file ========================================================== 18:03:47 (1715205827) [ 182.617787] Lustre: DEBUG MARKER: == sanity-pfl test 3a: Delete components from existing file ========================================================== 18:03:51 (1715205831) [ 185.940166] Lustre: DEBUG MARKER: == sanity-pfl test 3b: Delete components w/DOM from existing file ========================================================== 18:03:54 (1715205834) [ 189.171863] Lustre: DEBUG MARKER: == sanity-pfl test 4: Modify component flags in existing file ========================================================== 18:03:57 (1715205837) [ 189.524963] Lustre: DEBUG MARKER: SKIP: sanity-pfl test_4 Not supported in PFL [ 191.429579] Lustre: DEBUG MARKER: == sanity-pfl test 5: Inherit composite layout from parent directory ========================================================== 18:04:00 (1715205840) [ 194.471121] Lustre: DEBUG MARKER: == sanity-pfl test 6: Migrate composite file ============= 18:04:03 (1715205843) [ 224.372441] Lustre: ll_ost00_011: service thread pid 18675 was inactive for 40.126 seconds. Watchdog stack traces are limited to 3 per 300 seconds, skipping this one. [ 224.372442] Lustre: ll_ost00_005: service thread pid 13194 was inactive for 40.126 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 224.372448] Pid: 13194, comm: ll_ost00_005 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 224.372448] Call Trace: [ 224.372556] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 224.372605] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 224.372622] [<0>] ofd_destroy_by_fid+0x1d1/0x520 [ofd] [ 224.372661] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 224.372720] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 224.372763] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 224.372804] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 224.372811] [<0>] kthread+0xe4/0xf0 [ 224.372814] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 224.372828] [<0>] 0xfffffffffffffffe [ 224.393763] Pid: 18677, comm: ll_ost00_012 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 224.395715] Call Trace: [ 224.396714] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 224.398185] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 224.400442] [<0>] ofd_destroy_by_fid+0x1d1/0x520 [ofd] [ 224.402026] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 224.403479] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 224.404839] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 224.406570] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 224.407785] [<0>] kthread+0xe4/0xf0 [ 224.408708] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 224.410119] [<0>] 0xfffffffffffffffe [ 280.052516] LustreError: 7105:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.202.50@tcp ns: mdt-lustre-MDT0001_UUID lock: ffff88009efc3cc0/0xc064e4e878ac3bd0 lrc: 3/0,0 mode: PW/PW res: [0x240000402:0x20a:0x0].0x0 bits 0x40/0x0 rrc: 3 type: IBT gid 0 flags: 0x60200400010020 nid: 192.168.202.50@tcp remote: 0x4257a073067c3e0c expref: 24 pid: 7114 timeout: 279 lvb_type: 0 [ 284.060570] LustreError: 7105:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.202.50@tcp ns: filter-lustre-OST0000_UUID lock: ffff88009efc0240/0xc064e4e878ac3d6d lrc: 3/0,0 mode: PW/PW res: [0x280000406:0x5:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 1048576->2097151) gid 0 flags: 0x60000400010020 nid: 192.168.202.50@tcp remote: 0x4257a073067c3e8a expref: 9 pid: 9382 timeout: 283 lvb_type: 0 [ 284.075674] LustreError: 7103:0:(client.c:1281:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff88009d8c1c00 x1798523511545600/t0(0) o105->lustre-OST0000@192.168.202.50@tcp:15/16 lens 392/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 [ 317.028949] Lustre: lustre-MDT0001: haven't heard from client 59e71c76-9ab5-4877-a1d0-8ab03816aaab (at 192.168.202.50@tcp) in 34 seconds. I think it's dead, and I am evicting it. exp ffff88012cecb000, cur 1715205966 expire 1715205936 last 1715205932 [ 322.036889] Lustre: lustre-OST0000: haven't heard from client 59e71c76-9ab5-4877-a1d0-8ab03816aaab (at 192.168.202.50@tcp) in 34 seconds. I think it's dead, and I am evicting it. exp ffff88011d629000, cur 1715205971 expire 1715205941 last 1715205937 ****************************************************************************** ************************ 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.20s (real) 6.50s (CPU), Child processes: 5.69s