************************ crashinfo ************************* /exports/testreports/47154/testresults/sanity-quota-zfs-centos7_x86_64-centos7_x86_64/oleg455-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.9rn7A/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47154/testresults/sanity-quota-zfs-centos7_x86_64-centos7_x86_64/oleg455-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed Nov 13 13:09:26 EST 2024 UPTIME: 01:02:15 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 334 NODENAME: oleg455-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 67 last 60s 78 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 330 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 ----- -------------- ------ ---------------------------- 20 rcuos/1 0 ms (no user stack) 9 rcu_sched 0 ms (no user stack) 1 systemd 0 ms /usr/lib/systemd/systemd --switched-root --system --deserialize 22 3287 monitor_thread 127 ms (no user stack) 3282 socknal_reaper 131 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 736609 2.8 GB 77% of TOTAL MEM USED 218458 853.4 MB 22% of TOTAL MEM SHARED 9545 37.3 MB 0% of TOTAL MEM BUFFERS 5123 20 MB 0% of TOTAL MEM CACHED 70516 275.5 MB 7% of TOTAL MEM SLAB 17283 67.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 59058 230.7 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 3732.4 eth0 n/a 0.3 RSS_TOTAL=50380 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880137668380 ffff88013767b800 sysfs sysfs /sys ffff880137668540 ffff880139944000 proc proc /proc ffff880137668700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801376688c0 ffff8800b7e92000 securityfs securityfs /sys/kernel/security ffff880137668a80 ffff88013767c000 tmpfs tmpfs /dev/shm ffff880137668c40 ffff8801372f5000 devpts devpts /dev/pts ffff880137668e00 ffff88013767c800 tmpfs tmpfs /run ffff880137668fc0 ffff88013767d000 tmpfs tmpfs /sys/fs/cgroup ffff880137669180 ffff88013767d800 cgroup cgroup /sys/fs/cgroup/systemd ffff880137669340 ffff88013767e000 pstore pstore /sys/fs/pstore ffff880137669500 ffff88012a350000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff8801376696c0 ffff88012a350800 cgroup cgroup /sys/fs/cgroup/memory ffff880137669880 ffff88012a351000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880137669a40 ffff88012a351800 cgroup cgroup /sys/fs/cgroup/cpuset ffff880137669c00 ffff88012a352000 cgroup cgroup /sys/fs/cgroup/perf_event ffff880137669dc0 ffff88012a352800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a380000 ffff88012a353000 cgroup cgroup /sys/fs/cgroup/pids ffff88012a3801c0 ffff88012a353800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a380380 ffff88012a354000 cgroup cgroup /sys/fs/cgroup/devices ffff88012a380540 ffff88012a354800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a3808c0 ffff88012a356000 configfs configfs /sys/kernel/config ffff8801377f6e00 ffff8800b4c16800 ext4 /dev/nbd0 / ffff88012a380a80 ffff88012a355000 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8801377f6fc0 ffff8800b7e92800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880138ccafc0 ffff8800b4ca3000 hugetlbfs hugetlbfs /dev/hugepages ffff88012a380c40 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff88012a380e00 ffff8801372f6800 mqueue mqueue /dev/mqueue ffff88012a380fc0 ffff88012b475800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012a381180 ffff88012b472800 ramfs none /mnt ffff8801377f7180 ffff880129efd000 tmpfs none /var/lib/stateless/writable ffff880138ccb340 ffff8800b4ca7800 squashfs /dev/vda /home/green/git/lustre-release ffff880138ccb500 ffff880129efd000 tmpfs none /var/cache/man ffff88012a327c00 ffff880129efd000 tmpfs none /var/log ffff88012a381340 ffff880129efd000 tmpfs none /var/lib/dbus ffff8801377f7340 ffff880129efd000 tmpfs none /tmp ffff88012a381500 ffff880129efd000 tmpfs none /var/lib/dhclient ffff88012a3816c0 ffff880129efd000 tmpfs none /var/tmp ffff88012a381880 ffff880129efd000 tmpfs none /var/lib/NetworkManager ffff880138ccb6c0 ffff880129efd000 tmpfs none /var/lib/systemd/random-seed ffff88012a327dc0 ffff880129efd000 tmpfs none /var/spool ffff8801377f7500 ffff880129efd000 tmpfs none /var/lib/nfs ffff88012a381a40 ffff880129efd000 tmpfs none /var/lib/gssproxy ffff88012a381c00 ffff880129efd000 tmpfs none /var/lib/logrotate ffff88012a327880 ffff880129efd000 tmpfs none /etc ffff880138ccb880 ffff880129efd000 tmpfs none /var/lib/rsyslog ffff88012a381dc0 ffff880129efd000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012a380700 ffff880129efd800 nfs4 192.168.200.253:/exports/state/oleg455-server.virtnet /var/lib/stateless/state ffff88012a327500 ffff880129efd800 nfs4 192.168.200.253:/exports/state/oleg455-server.virtnet /boot ffff88012a3276c0 ffff880129efd800 nfs4 192.168.200.253:/exports/state/oleg455-server.virtnet /etc/etc/kdump.conf ffff8801369de000 ffff88012a355000 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b1a1b180 ffff8800b4ca7800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b1a1a540 ffff8800b405a800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b1a1ae00 ffff8800a6329000 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff8800b21f8700 ffff880135cbb000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 65.485487] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 65.505078] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 65.508944] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 65.534225] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 70.683888] Lustre: Setting parameter general.lod.*.mdt_hash in log params [ 76.893782] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing check_logdir /tmp/testlogs/ [ 77.742579] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing yml_node [ 78.678135] Lustre: DEBUG MARKER: Client: 2.16.0.1 [ 79.263506] Lustre: DEBUG MARKER: MDS: 2.16.0.1 [ 79.840668] Lustre: DEBUG MARKER: OSS: 2.16.0.1 [ 80.195037] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Wed Nov 13 12:08:31 EST 2024 [ 83.818442] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 84.145273] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 12a 9 [ 84.565116] Lustre: DEBUG MARKER: === sanity-quota: start setup 12:08:35 (1731517715) === [ 85.327813] Lustre: DEBUG MARKER: oleg455-client.virtnet: executing check_config_client /mnt/lustre [ 89.343303] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 90.201964] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 90.824999] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 91.539407] Lustre: DEBUG MARKER: === sanity-quota: finish setup 12:08:42 (1731517722) === [ 101.435179] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 12:08:52 (1731517732) [ 130.075166] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 12:09:21 (1731517761) [ 137.555456] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 138.933386] Lustre: DEBUG MARKER: Write... [ 139.433734] Lustre: DEBUG MARKER: Write out of block quota ... [ 190.109812] Lustre: ll_ost00_004: service thread pid 13977 was inactive for 40.118 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 190.113806] Pid: 13977, comm: ll_ost00_004 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 190.115617] Call Trace: [ 190.116198] [<0>] ldlm_completion_ast+0x913/0xd50 [ptlrpc] [ 190.117415] [<0>] ldlm_cli_enqueue_local+0x259/0x890 [ptlrpc] [ 190.119027] [<0>] ofd_destroy_by_fid+0x19c/0x610 [ofd] [ 190.119965] [<0>] ofd_destroy_hdl+0x20c/0xae0 [ofd] [ 190.121188] [<0>] tgt_request_handle+0x74e/0x1a60 [ptlrpc] [ 190.122313] [<0>] ptlrpc_server_handle_request+0x281/0xce0 [ptlrpc] [ 190.124281] [<0>] ptlrpc_main+0xc7e/0x1690 [ptlrpc] [ 190.126349] [<0>] kthread+0xe4/0xf0 [ 190.127727] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 190.129966] [<0>] 0xfffffffffffffffe [ 250.141894] LustreError: 7049:0:(ldlm_lockd.c:241:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.204.55@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a8a9e1c0/0x471df131e2db764f lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x4:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400010020 nid: 192.168.204.55@tcp remote: 0xcff12a49f3c6dd93 expref: 6 pid: 13977 timeout: 249 lvb_type: 0 [ 250.152360] Lustre: ll_ost00_004: service thread pid 13977 completed after 100.161s. This likely indicates the system was overloaded (too many service threads, or not enough hardware resources). [ 285.838446] Lustre: lustre-OST0000: haven't heard from client 8b15f5dd-c942-4ea2-9841-5e83824687e0 (at 192.168.204.55@tcp) in 32 seconds. I think it's dead, and I am evicting it. exp ffff8801362d3800, cur 1731517916 expire 1731517886 last 1731517884 ****************************************************************************** ************************ 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.30s (real) 6.83s (CPU), Child processes: 5.41s