************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-pcc-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg405-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.wkX8b/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-pcc-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg405-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 18:34:20 EDT 2024 UPTIME: 00:33:32 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 244 NODENAME: oleg405-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 30 last 5s 57 last 60s 76 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 240 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 ----- -------------- ------ ---------------------------- 3687 lnet_discovery 0 ms (no user stack) 489 kworker/2:2 0 ms (no user stack) 28 watchdog/3 0 ms (no user stack) 9 rcu_sched 8 ms (no user stack) 1 systemd 10 ms /usr/lib/systemd/systemd --switched-root --system --deserialize 22 +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 742431 2.8 GB 77% of TOTAL MEM USED 212636 830.6 MB 22% of TOTAL MEM SHARED 10645 41.6 MB 1% of TOTAL MEM BUFFERS 8430 32.9 MB 0% of TOTAL MEM CACHED 66861 261.2 MB 7% of TOTAL MEM SLAB 15078 58.9 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 58971 230.4 MB 7% 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 2009.8 eth0 n/a 0.6 RSS_TOTAL=55932 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668e00 ffff88013767f000 sysfs sysfs /sys ffff880137668fc0 ffff880139944000 proc proc /proc ffff880137669180 ffff880137678000 devtmpfs devtmpfs /dev ffff880137669340 ffff880136ab8800 securityfs securityfs /sys/kernel/security ffff880137669500 ffff88013767f800 tmpfs tmpfs /dev/shm ffff8801376696c0 ffff880137679000 devpts devpts /dev/pts ffff880137669880 ffff88012a2a8000 tmpfs tmpfs /run ffff880137669a40 ffff88012a2a8800 tmpfs tmpfs /sys/fs/cgroup ffff880137669c00 ffff88012a2a9000 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669dc0 ffff88012a2a9800 pstore pstore /sys/fs/pstore ffff88012a2b2000 ffff88012a2ab800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a2b21c0 ffff88012a2ab000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a2b2380 ffff88012a2aa800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a2b2540 ffff88012a2aa000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a2b2700 ffff88012a2ac000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a2b28c0 ffff88012a2ac800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a2b2a80 ffff88012a2ad000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a2b2c40 ffff88012a2ad800 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a2b2e00 ffff88012a2ae000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a2b2fc0 ffff88012a2ae800 cgroup cgroup /sys/fs/cgroup/memory ffff88012a2b3340 ffff8800b52ed800 configfs configfs /sys/kernel/config ffff88012a2b3500 ffff8800b52e9000 ext4 /dev/nbd0 / ffff8801370b2700 ffff880136ab9800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8801377f7a40 ffff8800b5226000 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880138ccaa80 ffff88012a2af000 hugetlbfs hugetlbfs /dev/hugepages ffff880138ccac40 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8801370b2540 ffff88013767a800 mqueue mqueue /dev/mqueue ffff88012a2b36c0 ffff880129815800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8801370b28c0 ffff8800b5337800 ramfs none /mnt ffff8801370b2a80 ffff8801373c3000 squashfs /dev/vda /home/green/git/lustre-release ffff88012a2b3880 ffff880129817000 tmpfs none /var/lib/stateless/writable ffff88012a2b3a40 ffff880129817000 tmpfs none /var/cache/man ffff8801370b2c40 ffff880129817000 tmpfs none /var/log ffff8801377f7dc0 ffff880129817000 tmpfs none /var/lib/dbus ffff8801370b2e00 ffff880129817000 tmpfs none /tmp ffff88012a2b3c00 ffff880129817000 tmpfs none /var/lib/dhclient ffff880138ccafc0 ffff880129817000 tmpfs none /var/tmp ffff8801370b2fc0 ffff880129817000 tmpfs none /var/lib/NetworkManager ffff8801370b3180 ffff880129817000 tmpfs none /var/lib/systemd/random-seed ffff880138ccb180 ffff880129817000 tmpfs none /var/spool ffff88012a2b3dc0 ffff880129817000 tmpfs none /var/lib/nfs ffff8801370b3340 ffff880129817000 tmpfs none /var/lib/gssproxy ffff8801377f7880 ffff880129817000 tmpfs none /var/lib/logrotate ffff8801377f76c0 ffff880129817000 tmpfs none /etc ffff880137668c40 ffff880129817000 tmpfs none /var/lib/rsyslog ffff8801370b3500 ffff880129817000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff8800b27dc000 ffff8800b4068000 nfs4 192.168.200.253:/exports/state/oleg405-server.virtnet /var/lib/stateless/state ffff8801370b36c0 ffff8800b4068000 nfs4 192.168.200.253:/exports/state/oleg405-server.virtnet /boot ffff8800b27da1c0 ffff8800b4068000 nfs4 192.168.200.253:/exports/state/oleg405-server.virtnet /etc/etc/kdump.conf ffff8801370b3880 ffff880136ab9800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b27dd180 ffff8801373c3000 squashfs /dev/vda /usr/sbin/mount.lustre ffff880138ccb6c0 ffff8800b4264800 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff8801377f6fc0 ffff880085a0d000 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff8801377f6c40 ffff88006f2ff800 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff8801377f6a80 ffff8800a1bfc000 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 81.360574] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 81.382097] Lustre: lustre-OST0001: new disk, initializing [ 81.383529] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 81.393788] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 82.516135] Lustre: DEBUG MARKER: oleg405-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 83.630596] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 83.633464] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 83.636258] Lustre: Skipped 1 previous similar message [ 83.644555] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 83.646580] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 87.359382] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 92.639346] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 95.313442] random: crng init done [ 98.234173] Lustre: DEBUG MARKER: oleg405-server.virtnet: executing check_logdir /tmp/testlogs/ [ 99.030746] Lustre: DEBUG MARKER: oleg405-server.virtnet: executing yml_node [ 99.975918] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 100.625282] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 101.306889] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 101.725309] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-pcc ============----- Wed May 8 18:02:29 EDT 2024 [ 105.880764] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing check_config_client /mnt/lustre [ 111.281504] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 112.163770] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 112.804825] Lustre: DEBUG MARKER: oleg405-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 113.793432] Lustre: DEBUG MARKER: excepting tests: [ 136.886352] Lustre: DEBUG MARKER: == sanity-pcc test 1a: Test manual lfs pcc attach with manual HSM restore ========================================================== 18:03:05 (1715205785) [ 177.996110] Lustre: ll_ost00_002: service thread pid 9396 was inactive for 40.110 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 178.003691] Pid: 9396, comm: ll_ost00_002 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 178.006023] Call Trace: [ 178.007579] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 178.009648] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 178.011754] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 178.013844] [<0>] ofd_getattr_hdl+0x385/0x750 [ofd] [ 178.015469] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 178.017715] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 178.020339] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 178.022833] [<0>] kthread+0xe4/0xf0 [ 178.023988] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 178.025938] [<0>] 0xfffffffffffffffe [ 238.028116] LustreError: 7122:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.204.5@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a9c77600/0x9a98260cbac9d91b lrc: 3/0,0 mode: PW/PW res: [0x280000401:0x2:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4095) gid 0 flags: 0x60000400020020 nid: 192.168.204.5@tcp remote: 0x9140cb3a65714c71 expref: 7 pid: 9396 timeout: 237 lvb_type: 0 [ 273.948323] Lustre: lustre-OST0000: haven't heard from client ddcc23b7-decf-49fb-9fda-3a3ce0a064d7 (at 192.168.204.5@tcp) in 34 seconds. I think it's dead, and I am evicting it. exp ffff88009c8c9000, cur 1715205921 expire 1715205891 last 1715205887 ****************************************************************************** ************************ 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.32s (real) 6.50s (CPU), Child processes: 5.80s