************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-pcc-zfs-centos7_x86_64-centos7_x86_64/oleg150-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.TULGM/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-pcc-zfs-centos7_x86_64-centos7_x86_64/oleg150-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 18:34:16 EDT 2024 UPTIME: 00:33:26 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 388 NODENAME: oleg150-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 68 last 60s 79 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 384 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 ----- -------------- ------ ---------------------------- 17153 kworker/u8:1 0 ms (no user stack) 572 kworker/0:1H 0 ms (no user stack) 3409 dbuf_evict 0 ms (no user stack) 3407 zthr_procedure 0 ms (no user stack) 49 kworker/2:1 0 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 711382 2.7 GB 74% of TOTAL MEM USED 243685 951.9 MB 25% of TOTAL MEM SHARED 8808 34.4 MB 0% of TOTAL MEM BUFFERS 5096 19.9 MB 0% of TOTAL MEM CACHED 65021 254 MB 6% of TOTAL MEM SLAB 25426 99.3 MB 2% 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 57953 226.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 2004.3 eth0 n/a 0.0 RSS_TOTAL=51996 pages, %mem= 0.9 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a360000 ffff88012a368000 sysfs sysfs /sys ffff88012a3601c0 ffff880139944000 proc proc /proc ffff88012a360380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a360540 ffff8800b51e2000 securityfs securityfs /sys/kernel/security ffff88012a360700 ffff88012a368800 tmpfs tmpfs /dev/shm ffff88012a3608c0 ffff880137102800 devpts devpts /dev/pts ffff88012a360a80 ffff88012a369000 tmpfs tmpfs /run ffff88012a360c40 ffff88012a369800 tmpfs tmpfs /sys/fs/cgroup ffff88012a360e00 ffff88012a36a000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a360fc0 ffff88012a36a800 pstore pstore /sys/fs/pstore ffff88012a361180 ffff88012a36c800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a361340 ffff88012a36c000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a361500 ffff88012a36b800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a3616c0 ffff88012a36b000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a361880 ffff88012a36d000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a361a40 ffff88012a36d800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012a361c00 ffff88012a36e000 cgroup cgroup /sys/fs/cgroup/memory ffff88012a361dc0 ffff88012a36e800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a392000 ffff88012a36f000 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a3921c0 ffff88012a36f800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff8801376688c0 ffff8800b51e5800 configfs configfs /sys/kernel/config ffff88012a392540 ffff8800b5224000 ext4 /dev/nbd0 / ffff88012a392700 ffff8800b51e3000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8800b4b741c0 ffff880129f24800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff8800b48b4a80 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff8800b4b74380 ffff880129f25000 hugetlbfs hugetlbfs /dev/hugepages ffff880137668a80 ffff880137104000 mqueue mqueue /dev/mqueue ffff880137668c40 ffff8800b4813800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff880137668e00 ffff8800b4815800 ramfs none /mnt ffff8800b4b74540 ffff880129f20800 tmpfs none /var/lib/stateless/writable ffff88012a392e00 ffff8800b42d9800 squashfs /dev/vda /home/green/git/lustre-release ffff88012a392fc0 ffff880129f20800 tmpfs none /var/cache/man ffff880137668fc0 ffff880129f20800 tmpfs none /var/log ffff88012a393180 ffff880129f20800 tmpfs none /var/lib/dbus ffff88012a393340 ffff880129f20800 tmpfs none /tmp ffff88012a393500 ffff880129f20800 tmpfs none /var/lib/dhclient ffff88012a3936c0 ffff880129f20800 tmpfs none /var/tmp ffff88012a393880 ffff880129f20800 tmpfs none /var/lib/NetworkManager ffff88012a393a40 ffff880129f20800 tmpfs none /var/lib/systemd/random-seed ffff880137669180 ffff880129f20800 tmpfs none /var/spool ffff88012a393c00 ffff880129f20800 tmpfs none /var/lib/nfs ffff880137669340 ffff880129f20800 tmpfs none /var/lib/gssproxy ffff88012a393dc0 ffff880129f20800 tmpfs none /var/lib/logrotate ffff88012a392c40 ffff880129f20800 tmpfs none /etc ffff8800b4b74700 ffff880129f20800 tmpfs none /var/lib/rsyslog ffff88012a392a80 ffff880129f20800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012a3928c0 ffff880129ca5800 nfs4 192.168.200.253:/exports/state/oleg150-server.virtnet /var/lib/stateless/state ffff8800b25be1c0 ffff880129ca5800 nfs4 192.168.200.253:/exports/state/oleg150-server.virtnet /boot ffff8800b4b74a80 ffff880129ca5800 nfs4 192.168.200.253:/exports/state/oleg150-server.virtnet /etc/etc/kdump.conf ffff8800b25be380 ffff8800b51e3000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b2754fc0 ffff8800b42d9800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b2755340 ffff8800b27fa800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b27548c0 ffff88009c0be800 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff8800b1c9d500 ffff88012ea1e800 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 53.596041] Lustre: DEBUG MARKER: oleg150-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 56.044507] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 56.048507] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 56.076587] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 56.660954] Lustre: lustre-OST0001: new disk, initializing [ 56.663202] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 56.680595] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 57.928492] Lustre: DEBUG MARKER: oleg150-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 62.632362] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 63.753326] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 63.755606] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 63.777549] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 67.732547] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 73.396547] Lustre: DEBUG MARKER: oleg150-server.virtnet: executing check_logdir /tmp/testlogs/ [ 74.205931] Lustre: DEBUG MARKER: oleg150-server.virtnet: executing yml_node [ 75.191728] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 75.790046] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 76.384388] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 76.748042] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-pcc ============----- Wed May 8 18:02:05 EDT 2024 [ 80.703499] Lustre: DEBUG MARKER: oleg150-client.virtnet: executing check_config_client /mnt/lustre [ 84.533957] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 85.347713] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 85.904128] Lustre: DEBUG MARKER: oleg150-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 86.366833] Lustre: DEBUG MARKER: excepting tests: [ 108.579994] Lustre: DEBUG MARKER: == sanity-pcc test 1a: Test manual lfs pcc attach with manual HSM restore ========================================================== 18:02:37 (1715205757) [ 149.656721] Lustre: ll_ost00_002: service thread pid 8558 was inactive for 40.150 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 149.661426] Pid: 8558, comm: ll_ost00_002 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 149.663271] Call Trace: [ 149.664196] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 149.665538] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 149.667154] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 149.668538] [<0>] ofd_getattr_hdl+0x385/0x750 [ofd] [ 149.669733] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 149.671120] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 149.673152] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 149.674660] [<0>] kthread+0xe4/0xf0 [ 149.675700] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 149.677112] [<0>] 0xfffffffffffffffe [ 209.560759] LustreError: 7013:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.201.50@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a7664480/0x390968330c3e9ad2 lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x2:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4095) gid 0 flags: 0x60000400020020 nid: 192.168.201.50@tcp remote: 0xb12fc2dbeb5b5b8a expref: 7 pid: 8558 timeout: 208 lvb_type: 0 [ 241.336984] Lustre: lustre-OST0000: haven't heard from client 9256ee2d-b824-4f4a-b0ff-9ad2d30bbb8b (at 192.168.201.50@tcp) in 31 seconds. I think it's dead, and I am evicting it. exp ffff88008f694800, cur 1715205890 expire 1715205860 last 1715205859 ****************************************************************************** ************************ 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.69s (real) 7.15s (CPU), Child processes: 5.51s