************************ crashinfo ************************* /exports/testreports/40573/testresults/conf-sanity-slow-106-zfs-centos7_x86_64-centos7_x86_64/oleg213-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.BH9HJ/vmlinux [TAINTED] DUMPFILE: /exports/testreports/40573/testresults/conf-sanity-slow-106-zfs-centos7_x86_64-centos7_x86_64/oleg213-client-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Thu Mar 7 01:07:58 EST 2024 UPTIME: 01:26:03 LOAD AVERAGE: 0.65, 0.71, 0.68 TASKS: 147 NODENAME: oleg213-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=17463 CPU=1 CMD=createmany #-1 memcmp+0xf, 449 bytes of data #0 ldlm_res_hop_keycmp+0x17 #1 cfs_hash_bd_lookup_intent+0x57 #2 cfs_hash_bd_lookup_locked+0x16 #3 ldlm_resource_get+0x7a #4 ldlm_lock_match_with_skip+0xbf #5 mdc_lock_match+0xb9 #6 ll_have_md_lock+0x103 #7 ll_lock_cancel_bits+0x5a6 #8 ll_md_blocking_ast+0x30f #9 ldlm_cancel_callback+0x84 #10 ldlm_cli_cancel_local+0xb2 #11 ldlm_cli_cancel_list_local+0xea #12 ldlm_cancel_resource_local+0x189 #13 mdc_resource_get_unused_res+0x111 #14 mdc_unlink+0x447 #15 lmv_unlink+0x2fa #16 ll_unlink+0x282 #17 vfs_unlink+0x106 #18 do_unlinkat+0x26e #19 sys_unlink+0x16 #20 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=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 17 last 5s 31 last 60s 38 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 142 TASK_RUNNING 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 ----- -------------- ------ ---------------------------- 9 rcu_sched 0 ms (no user stack) 20 rcuos/1 0 ms (no user stack) 1791 socknal_sd01_01 0 ms (no user stack) 1790 socknal_sd01_00 13 ms (no user stack) 17463 createmany 14 ms /home/green/git/lustre-release/lustre/tests/createmany -u /mnt/lustre/d106.conf-sanity/f- 64768 +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955079 3.6 GB ---- FREE 799145 3 GB 83% of TOTAL MEM USED 155934 609.1 MB 16% of TOTAL MEM SHARED 10254 40.1 MB 1% of TOTAL MEM BUFFERS 5162 20.2 MB 0% of TOTAL MEM CACHED 45577 178 MB 4% of TOTAL MEM SLAB 72682 283.9 MB 7% 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 62861 245.6 MB 8% of TOTAL LIMIT +-------------------------------+ >----------------------| Scheduler Runqueues (per CPU) |----------------------< +-------------------------------+ ---+ CPU=0 ---- | CURRENT TASK , CMD=swapper/0 ---+ CPU=1 ---- | CURRENT TASK , CMD=createmany ---+ 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 5161.6 eth0 n/a 0.0 RSS_TOTAL=78004 pages, %mem= 1.2 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137652380 ffff880137668800 sysfs sysfs /sys ffff880137652540 ffff880139944000 proc proc /proc ffff880137652700 ffff880137668000 devtmpfs devtmpfs /dev ffff8801376528c0 ffff8800b6cd3000 securityfs securityfs /sys/kernel/security ffff880137652a80 ffff880137669000 tmpfs tmpfs /dev/shm ffff880137652c40 ffff880137315000 devpts devpts /dev/pts ffff880137652e00 ffff880137669800 tmpfs tmpfs /run ffff880137652fc0 ffff88013766a000 tmpfs tmpfs /sys/fs/cgroup ffff880137653180 ffff88013766a800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137653340 ffff88013766b000 pstore pstore /sys/fs/pstore ffff880137653500 ffff88013766d000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff8801376536c0 ffff88013766c800 cgroup cgroup /sys/fs/cgroup/memory ffff880137653880 ffff88013766c000 cgroup cgroup /sys/fs/cgroup/blkio ffff880137653a40 ffff88013766b800 cgroup cgroup /sys/fs/cgroup/cpuset ffff880137653c00 ffff88013766d800 cgroup cgroup /sys/fs/cgroup/devices ffff880137653dc0 ffff88013766e000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012aac0000 ffff88013766e800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012aac01c0 ffff88013766f000 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012aac0380 ffff88013766f800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012aac0540 ffff88012aae0000 cgroup cgroup /sys/fs/cgroup/pids ffff880138ccb6c0 ffff88012a428800 configfs configfs /sys/kernel/config ffff8800b6f3c1c0 ffff8800b6cf4800 ext4 /dev/nbd0 / ffff8800b6f3c380 ffff8800b6cf6000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012aac0700 ffff88012aae6800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012aac08c0 ffff880137316000 mqueue mqueue /dev/mqueue ffff8801370088c0 ffff88012a9f5800 hugetlbfs hugetlbfs /dev/hugepages ffff880137008a80 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8800b6f3c540 ffff88012a42d000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8800b6f3c700 ffff88012a42f800 ramfs none /mnt ffff8800b6f3c8c0 ffff8800b62bd800 tmpfs none /var/lib/stateless/writable ffff88012aac0a80 ffff880137327800 squashfs /dev/vda /home/green/git/lustre-release ffff880137008e00 ffff8800b62bd800 tmpfs none /var/cache/man ffff880137008fc0 ffff8800b62bd800 tmpfs none /var/log ffff88012aac0c40 ffff8800b62bd800 tmpfs none /var/lib/dbus ffff8800b6f3ca80 ffff8800b62bd800 tmpfs none /tmp ffff8800b6f3cc40 ffff8800b62bd800 tmpfs none /var/lib/dhclient ffff88012aac0e00 ffff8800b62bd800 tmpfs none /var/tmp ffff8800b6f3ce00 ffff8800b62bd800 tmpfs none /var/lib/NetworkManager ffff880137009180 ffff8800b62bd800 tmpfs none /var/lib/systemd/random-seed ffff8800b6f3cfc0 ffff8800b62bd800 tmpfs none /var/spool ffff88012aac0fc0 ffff8800b62bd800 tmpfs none /var/lib/nfs ffff880137009340 ffff8800b62bd800 tmpfs none /var/lib/gssproxy ffff88012aac1180 ffff8800b62bd800 tmpfs none /var/lib/logrotate ffff8800b6f3d180 ffff8800b62bd800 tmpfs none /etc ffff880137009500 ffff8800b62bd800 tmpfs none /var/lib/rsyslog ffff8800b6f3d340 ffff8800b62bd800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8800b6f3d500 ffff88012a9f3800 nfs4 192.168.200.253:/exports/state/oleg213-client.virtnet /var/lib/stateless/state ffff880138ccb880 ffff88012a9f3800 nfs4 192.168.200.253:/exports/state/oleg213-client.virtnet /boot ffff88012aac1340 ffff88012a9f3800 nfs4 192.168.200.253:/exports/state/oleg213-client.virtnet /etc/etc/kdump.conf ffff88012aac1500 ffff8800b6cf6000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b6f3d6c0 ffff8800af214800 nfs4 192.168.200.253://exports/testreports/40573/testresults/conf-sanity-slow-106-zfs-centos7_x86_64-centos7_x86_64 /tmp/tmp/testlogs ffff8800b600e380 ffff8800af214000 tmpfs tmpfs /run/user/0 ffff8800b6f3dc00 ffff880137327800 squashfs /dev/vda /usr/sbin/mount.lustre ffff880138ccbc00 ffff88012d7cd800 lustre 192.168.202.113@tcp:/lustre /mnt/lustre +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 21.446029] PCLMULQDQ-NI instructions are not detected. [ 22.094419] Lustre: Lustre: Build Version: 2.15.61_117_gc7b1037 [ 22.290633] LNet: Added LNI 192.168.202.13@tcp [8/256/0/180] [ 22.292973] LNet: Accept secure, port 988 [ 23.844791] Key type lgssc registered [ 24.188621] Lustre: Echo OBD driver; http://www.lustre.org/ [ 63.469762] Lustre: Mounted lustre-client [ 66.057323] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 78.239814] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing check_logdir /tmp/testlogs/ [ 80.036007] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing yml_node [ 81.873954] Lustre: DEBUG MARKER: Client: 2.15.61.117 [ 82.984726] Lustre: DEBUG MARKER: MDS: 2.15.61.117 [ 84.048158] Lustre: DEBUG MARKER: OSS: 2.15.61.117 [ 84.631682] Lustre: DEBUG MARKER: -----============= acceptance-small: conf-sanity ============----- Wed Mar 6 23:43:17 EST 2024 [ 87.237283] Lustre: DEBUG MARKER: excepting tests: 32newtarball 110 [ 87.639445] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 97.666748] Lustre: Unmounted lustre-client [ 136.443201] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 144.298309] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 157.396595] Lustre: DEBUG MARKER: == conf-sanity test 106: check osp llog processing when catalog is wrapped ========================================================== 23:44:30 (1709786670) [ 172.504735] random: crng init done [ 187.495740] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 195.829127] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 196.016656] Lustre: Mounted lustre-client [ 388.945910] Lustre: 12862:0:(client.c:2338:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1709786902/real 1709786902] req@ffff8800a6765180 x1792841129762432/t0(0) o101->lustre-MDT0000-mdc-ffff88012d7cd800@192.168.202.113@tcp:12/10 lens 648/66320 e 0 to 1 dl 1709786918 ref 2 fl Rpc:ReXPQU/200/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 [ 388.958314] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection to lustre-MDT0000 (at 192.168.202.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 388.976429] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection restored to (at 192.168.202.113@tcp) [ 495.647134] Lustre: 12862:0:(client.c:2338:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1709787009/real 1709787009] req@ffff8800a4d1d180 x1792841130917504/t0(0) o35->lustre-MDT0000-mdc-ffff88012d7cd800@192.168.202.113@tcp:23/10 lens 392/624 e 0 to 1 dl 1709787025 ref 2 fl Rpc:ReXQU/200/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 [ 495.657331] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection to lustre-MDT0000 (at 192.168.202.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 495.716635] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection restored to (at 192.168.202.113@tcp) [ 584.831549] Lustre: 12862:0:(client.c:2338:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1709787098/real 1709787098] req@ffff8800a4738a80 x1792841131671936/t0(0) o101->lustre-MDT0000-mdc-ffff88012d7cd800@192.168.202.113@tcp:12/10 lens 648/66320 e 0 to 1 dl 1709787114 ref 2 fl Rpc:ReXPQU/200/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 [ 584.854557] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection to lustre-MDT0000 (at 192.168.202.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 584.877971] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection restored to (at 192.168.202.113@tcp) [ 734.209159] Lustre: 12862:0:(client.c:2338:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1709787247/real 1709787247] req@ffff88012d78e300 x1792841132798720/t0(0) o101->lustre-MDT0000-mdc-ffff88012d7cd800@192.168.202.113@tcp:12/10 lens 648/66320 e 0 to 1 dl 1709787263 ref 2 fl Rpc:ReXPQU/200/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 [ 734.221062] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection to lustre-MDT0000 (at 192.168.202.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 734.238669] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection restored to (at 192.168.202.113@tcp) [ 889.240023] hrtimer: interrupt took 6387962 ns [ 961.141249] Lustre: 12862:0:(client.c:2338:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1709787474/real 1709787474] req@ffff8800a2111c00 x1792841134270720/t0(0) o35->lustre-MDT0000-mdc-ffff88012d7cd800@192.168.202.113@tcp:23/10 lens 392/624 e 0 to 1 dl 1709787490 ref 2 fl Rpc:ReXQU/200/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 [ 961.151931] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection to lustre-MDT0000 (at 192.168.202.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 961.186575] Lustre: lustre-MDT0000-mdc-ffff88012d7cd800: Connection restored to (at 192.168.202.113@tcp) ****************************************************************************** ************************ 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 10.94s (real) 5.55s (CPU), Child processes: 5.36s