************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-flr-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg129-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.wf2EK/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-flr-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg129-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 18:34:29 EDT 2024 UPTIME: 00:33:39 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 243 NODENAME: oleg129-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 14 last 5s 59 last 60s 71 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 239 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 ----- -------------- ------ ---------------------------- 7110 ldlm_bl_02 0 ms (no user stack) 4432 zthr_procedure 0 ms (no user stack) 4434 dbuf_evict 0 ms (no user stack) 484 kworker/2:2 0 ms (no user stack) 4437 l2arc_feed 262 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 742089 2.8 GB 77% of TOTAL MEM USED 212978 831.9 MB 22% of TOTAL MEM SHARED 10809 42.2 MB 1% of TOTAL MEM BUFFERS 8460 33 MB 0% of TOTAL MEM CACHED 69262 270.6 MB 7% of TOTAL MEM SLAB 15233 59.5 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 61381 239.8 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 2016.9 eth0 n/a 0.1 RSS_TOTAL=50220 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a32e1c0 ffff88012b3b5800 sysfs sysfs /sys ffff88012a32e380 ffff880139944000 proc proc /proc ffff88012a32e540 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a32e700 ffff88012b3b5000 securityfs securityfs /sys/kernel/security ffff88012a32e8c0 ffff88012b3b6000 tmpfs tmpfs /dev/shm ffff88012a32ea80 ffff8801372f6000 devpts devpts /dev/pts ffff88012a32ec40 ffff88012b3b6800 tmpfs tmpfs /run ffff88012a32ee00 ffff88012b3b7000 tmpfs tmpfs /sys/fs/cgroup ffff88012a32efc0 ffff88012b3b7800 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a32f180 ffff88012a360000 pstore pstore /sys/fs/pstore ffff88012a32f340 ffff88012a362000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a32f500 ffff88012a361800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a32f6c0 ffff88012a361000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a32f880 ffff88012a360800 cgroup cgroup /sys/fs/cgroup/memory ffff88012a32fa40 ffff88012a362800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a32fc00 ffff88012a363000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a32fdc0 ffff88012a363800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a2b8000 ffff88012a364000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a2b81c0 ffff88012a364800 cgroup cgroup /sys/fs/cgroup/devices ffff88012a2b8380 ffff88012a365000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880138ccafc0 ffff88012a62f800 configfs configfs /sys/kernel/config ffff88012a2b8a80 ffff8800b48ed000 ext4 /dev/nbd0 / ffff880138ccb180 ffff88012a366800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a2b8fc0 ffff8800b49de000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012a2b9180 ffff8800b49de800 hugetlbfs hugetlbfs /dev/hugepages ffff88012a2b9340 ffff8801372f7800 mqueue mqueue /dev/mqueue ffff88012b26ac40 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880137669340 ffff8800b4bd4000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012b26ae00 ffff8800b4892800 ramfs none /mnt ffff880138ccb340 ffff88012a2e2000 squashfs /dev/vda /home/green/git/lustre-release ffff88012a2b96c0 ffff8800b4167800 tmpfs none /var/lib/stateless/writable ffff88012a2b9880 ffff8800b4167800 tmpfs none /var/cache/man ffff88012a2b9a40 ffff8800b4167800 tmpfs none /var/log ffff8801376696c0 ffff8800b4167800 tmpfs none /var/lib/dbus ffff88012a2b9c00 ffff8800b4167800 tmpfs none /tmp ffff880137669880 ffff8800b4167800 tmpfs none /var/lib/dhclient ffff88012a2b9dc0 ffff8800b4167800 tmpfs none /var/tmp ffff880137669a40 ffff8800b4167800 tmpfs none /var/lib/NetworkManager ffff880137669c00 ffff8800b4167800 tmpfs none /var/lib/systemd/random-seed ffff880137669dc0 ffff8800b4167800 tmpfs none /var/spool ffff8800b1960000 ffff8800b4167800 tmpfs none /var/lib/nfs ffff88012b26afc0 ffff8800b4167800 tmpfs none /var/lib/gssproxy ffff88012b26b180 ffff8800b4167800 tmpfs none /var/lib/logrotate ffff8800b19601c0 ffff8800b4167800 tmpfs none /etc ffff88012b26b340 ffff8800b4167800 tmpfs none /var/lib/rsyslog ffff8800b1960380 ffff8800b4167800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012a2b8e00 ffff8800b4162800 nfs4 192.168.200.253:/exports/state/oleg129-server.virtnet /var/lib/stateless/state ffff8800b52ae1c0 ffff8800b4162800 nfs4 192.168.200.253:/exports/state/oleg129-server.virtnet /boot ffff88012b26b500 ffff8800b4162800 nfs4 192.168.200.253:/exports/state/oleg129-server.virtnet /etc/etc/kdump.conf ffff88012b26b6c0 ffff88012a366800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b1960540 ffff88012a2e2000 squashfs /dev/vda /usr/sbin/mount.lustre ffff880138ccbdc0 ffff88012a2e6000 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff88012e15f500 ffff88008fe13800 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff88012e15e540 ffff880077fa6000 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff88012e15e1c0 ffff8801353d9800 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 91.776549] Lustre: DEBUG MARKER: oleg129-server.virtnet: executing check_logdir /tmp/testlogs/ [ 92.650756] Lustre: DEBUG MARKER: oleg129-server.virtnet: executing yml_node [ 93.675613] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 94.285225] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 94.876418] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 95.238095] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-flr ============----- Wed May 8 18:02:24 EDT 2024 [ 98.672891] Lustre: DEBUG MARKER: excepting tests: 6 201 44c [ 99.249137] Lustre: DEBUG MARKER: oleg129-client.virtnet: executing check_config_client /mnt/lustre [ 103.940064] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 104.794763] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 105.414042] Lustre: DEBUG MARKER: oleg129-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 107.296895] Lustre: DEBUG MARKER: == sanity-flr test 0a: lfs mirror create with -N option == 18:02:36 (1715205756) [ 112.198790] Lustre: DEBUG MARKER: == sanity-flr test 0b: lfs mirror create plain layout mirrors ========================================================== 18:02:41 (1715205761) [ 112.555650] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0b need >= 4 OSTs [ 114.541787] Lustre: DEBUG MARKER: == sanity-flr test 0c: lfs mirror create composite layout mirrors ========================================================== 18:02:43 (1715205763) [ 114.881903] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0c need >= 4 OSTs [ 116.805964] Lustre: DEBUG MARKER: == sanity-flr test 0d: lfs mirror extend with -N option == 18:02:45 (1715205765) [ 157.871114] Lustre: ll_ost00_001: service thread pid 9384 was inactive for 40.079 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 157.877237] Pid: 9384, comm: ll_ost00_001 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 157.880471] Call Trace: [ 157.881597] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 157.883240] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 157.885126] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 157.886570] [<0>] ofd_getattr_hdl+0x385/0x750 [ofd] [ 157.888280] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 157.890368] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 157.892500] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 157.894411] [<0>] kthread+0xe4/0xf0 [ 157.895498] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 157.897184] [<0>] 0xfffffffffffffffe [ 218.031149] LustreError: 7111:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.201.29@tcp ns: filter-lustre-OST0001_UUID lock: ffff8800746e8000/0xa85bd5f393720a6d lrc: 3/0,0 mode: PR/PR res: [0x2c0000401:0x5:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4194303) gid 0 flags: 0x60000400020020 nid: 192.168.201.29@tcp remote: 0x18627c8c9010a1fb expref: 8 pid: 9384 timeout: 217 lvb_type: 0 [ 218.387867] Lustre: DEBUG MARKER: sanity-flr test_0d: @@@@@@ FAIL: extend mirror with -f failed [ 221.193680] Lustre: DEBUG MARKER: == sanity-flr test 0e: lfs mirror extend plain layout mirrors ========================================================== 18:04:30 (1715205870) [ 221.512277] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0e need >= 4 OSTs [ 223.280060] Lustre: DEBUG MARKER: == sanity-flr test 0f: lfs mirror extend composite layout mirrors ========================================================== 18:04:32 (1715205872) [ 223.602255] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0f need >= 4 OSTs [ 225.360047] Lustre: DEBUG MARKER: == sanity-flr test 0g: lfs mirror create flags support === 18:04:34 (1715205874) [ 253.631491] Lustre: lustre-OST0001: haven't heard from client 841d7f27-f41f-4bb0-bea3-6e3663b4c229 (at 192.168.201.29@tcp) in 35 seconds. I think it's dead, and I am evicting it. exp ffff88007472f800, cur 1715205902 expire 1715205872 last 1715205867 [ 325.807117] LustreError: 7111:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 101s: evicting client at 192.168.201.29@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800746e8000/0xa85bd5f393720b93 lrc: 3/0,0 mode: PW/PW res: [0x280000401:0x5:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->1048575) gid 0 flags: 0x60000480020020 nid: 192.168.201.29@tcp remote: 0x18627c8c9010a256 expref: 9 pid: 9383 timeout: 324 lvb_type: 0 [ 358.799584] Lustre: lustre-OST0000: haven't heard from client 841d7f27-f41f-4bb0-bea3-6e3663b4c229 (at 192.168.201.29@tcp) in 31 seconds. I think it's dead, and I am evicting it. exp ffff8800a1a4d800, cur 1715206008 expire 1715205978 last 1715205977 ****************************************************************************** ************************ 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 11.81s (real) 6.26s (CPU), Child processes: 5.52s