[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 482836715 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001013] APIC: Switch to symmetric I/O mode setup [ 0.003243] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005012] kvm-guest: setup PV IPIs [ 0.007908] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008021] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009012] pid_max: default: 32768 minimum: 301 [ 0.011014] LSM: Security Framework initializing [ 0.012047] Yama: becoming mindful. [ 0.013036] SELinux: Initializing. [ 0.014080] *** VALIDATE selinux *** [ 0.022825] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026646] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028071] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029115] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030129] *** VALIDATE tmpfs *** [ 0.031478] *** VALIDATE proc *** [ 0.033124] *** VALIDATE cgroup *** [ 0.034011] *** VALIDATE cgroup2 *** [ 0.036088] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037160] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039034] Spectre V2 : User space: Vulnerable [ 0.040011] Speculative Store Bypass: Vulnerable [ 0.043055] debug: unmapping init [mem 0xffffffff85259000-0xffffffff85260fff] [ 0.045991] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046764] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047023] ... version: 2 [ 0.048015] ... bit width: 48 [ 0.049012] ... generic registers: 4 [ 0.049934] ... value mask: 0000ffffffffffff [ 0.050014] ... max period: 00007fffffffffff [ 0.051015] ... fixed-purpose events: 3 [ 0.052013] ... event mask: 000000070000000f [ 0.053307] rcu: Hierarchical SRCU implementation. [ 0.055445] smp: Bringing up secondary CPUs ... [ 0.056500] x86: Booting SMP configuration: [ 0.057020] .... node #0, CPUs: #1 #2 #3 [ 0.061034] smp: Brought up 1 node, 4 CPUs [ 0.063019] smpboot: Max logical packages: 1 [ 0.064013] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.113628] node 0 deferred pages initialised in 46ms [ 0.115101] devtmpfs: initialized [ 0.118177] x86/mm: Memory block size: 128MB [ 0.121101] gcov: version magic: 0x41383552 [ 0.123224] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.127096] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.130326] pinctrl core: initialized pinctrl subsystem [ 0.132171] [ 0.132845] ************************************************************* [ 0.136014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.138015] ** ** [ 0.141013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.144013] ** ** [ 0.147015] ** This means that this kernel is built to expose internal ** [ 0.149011] ** IOMMU data structures, which may compromise security on ** [ 0.152013] ** your system. ** [ 0.154015] ** ** [ 0.157012] ** If you see this message and you are not debugging the ** [ 0.160014] ** kernel, report this immediately to your vendor! ** [ 0.162013] ** ** [ 0.164012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.167014] ************************************************************* [ 0.170440] NET: Registered protocol family 16 [ 0.172548] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.175064] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.178070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.182008] cpuidle: using governor menu [ 0.183875] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.184525] PCI: Using configuration type 1 for base access [ 0.185124] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.194077] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.196022] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.200272] cryptd: max_cpu_qlen set to 1000 [ 0.204254] ACPI: Added _OSI(Module Device) [ 0.206023] ACPI: Added _OSI(Processor Device) [ 0.208018] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.210018] ACPI: Added _OSI(Processor Aggregator Device) [ 0.213822] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.218476] ACPI: Interpreter enabled [ 0.219037] ACPI: PM: (supports S0 S3 S4 S5) [ 0.219921] ACPI: Using IOAPIC for interrupt routing [ 0.221107] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.223250] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.230989] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.232031] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.234012] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.236074] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.240046] acpiphp: Slot [2] registered [ 0.240970] acpiphp: Slot [5] registered [ 0.241094] acpiphp: Slot [6] registered [ 0.241951] acpiphp: Slot [3] registered [ 0.243057] acpiphp: Slot [4] registered [ 0.243912] acpiphp: Slot [7] registered [ 0.245069] acpiphp: Slot [8] registered [ 0.245906] acpiphp: Slot [9] registered [ 0.246127] acpiphp: Slot [10] registered [ 0.246848] acpiphp: Slot [11] registered [ 0.248074] acpiphp: Slot [12] registered [ 0.248949] acpiphp: Slot [13] registered [ 0.250071] acpiphp: Slot [14] registered [ 0.250966] acpiphp: Slot [15] registered [ 0.252046] acpiphp: Slot [16] registered [ 0.252820] acpiphp: Slot [17] registered [ 0.252940] acpiphp: Slot [18] registered [ 0.254052] acpiphp: Slot [19] registered [ 0.254855] acpiphp: Slot [20] registered [ 0.256052] acpiphp: Slot [21] registered [ 0.256757] acpiphp: Slot [22] registered [ 0.258119] acpiphp: Slot [23] registered [ 0.259089] acpiphp: Slot [24] registered [ 0.261097] acpiphp: Slot [25] registered [ 0.262132] acpiphp: Slot [26] registered [ 0.263095] acpiphp: Slot [27] registered [ 0.265086] acpiphp: Slot [28] registered [ 0.267091] acpiphp: Slot [29] registered [ 0.268016] acpiphp: Slot [30] registered [ 0.268837] acpiphp: Slot [31] registered [ 0.270090] PCI host bridge to bus 0000:00 [ 0.272021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.274020] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.277022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.279022] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.281022] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.284029] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.285152] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.288249] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.290201] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.296998] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.302042] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.306022] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.308017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.310020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.313625] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.315772] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.318051] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.321608] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.329021] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.337015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.341019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.344670] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.351019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.356013] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.365014] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.370000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.375020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.380016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.394015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.402659] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.405417] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.408513] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.411356] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.413378] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.418085] iommu: Default domain type: Passthrough [ 0.419404] SCSI subsystem initialized [ 0.421130] ACPI: bus type USB registered [ 0.422129] usbcore: registered new interface driver usbfs [ 0.423064] usbcore: registered new interface driver hub [ 0.425099] usbcore: registered new device driver usb [ 0.426134] pps_core: LinuxPPS API ver. 1 registered [ 0.428010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.430055] PTP clock support registered [ 0.432073] EDAC MC: Ver: 3.0.0 [ 0.433134] PCI: Using ACPI for IRQ routing [ 0.434688] NetLabel: Initializing [ 0.436010] NetLabel: domain hash size = 128 [ 0.437007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.439077] NetLabel: unlabeled traffic allowed by default [ 0.441083] vgaarb: loaded [ 0.442328] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.443013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.449327] clocksource: Switched to clocksource kvm-clock [ 0.546252] VFS: Disk quotas dquot_6.6.0 [ 0.547205] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.549099] *** VALIDATE ramfs *** [ 0.550111] *** VALIDATE hugetlbfs *** [ 0.551264] pnp: PnP ACPI init [ 0.554182] pnp: PnP ACPI: found 6 devices [ 0.569879] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.572147] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.573658] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.575133] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.576702] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.578576] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.580520] NET: Registered protocol family 2 [ 0.582331] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.586229] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.588831] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.592769] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.595386] TCP: Hash tables configured (established 65536 bind 65536) [ 0.597465] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.599768] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.601752] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.603823] NET: Registered protocol family 1 [ 0.606307] RPC: Registered named UNIX socket transport module. [ 0.607910] RPC: Registered udp transport module. [ 0.609220] RPC: Registered tcp transport module. [ 0.610379] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.612144] NET: Registered protocol family 44 [ 0.614563] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.617481] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.620637] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.623901] PCI: CLS 0 bytes, default 64 [ 0.626212] Unpacking initramfs... [ 2.101524] debug: unmapping init [mem 0xffff9fce7cc64000-0xffff9fce7ffcffff] [ 2.105621] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.107971] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.110933] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.629547] Initialise system trusted keyrings [ 2.631273] Key type blacklist registered [ 2.633093] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.642350] zbud: loaded [ 2.645690] *** VALIDATE nfs *** [ 2.647626] *** VALIDATE nfs4 *** [ 2.649516] pstore: using deflate compression [ 2.652784] Platform Keyring initialized [ 2.744927] NET: Registered protocol family 38 [ 2.745893] Key type asymmetric registered [ 2.746991] Asymmetric key parser 'x509' registered [ 2.748597] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.750351] io scheduler mq-deadline registered [ 2.751302] io scheduler kyber registered [ 2.752272] io scheduler bfq registered [ 2.753331] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.755454] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.757372] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.759254] ACPI: Power Button [PWRF] [ 2.762357] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.767854] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.780947] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.811274] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.843234] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.846748] Non-volatile memory driver v1.3 [ 2.848209] Linux agpgart interface v0.103 [ 2.876977] virtio_blk virtio1: [vda] 142768 512-byte logical blocks (73.1 MB/69.7 MiB) [ 2.879540] vda: detected capacity change from 0 to 73097216 [ 2.891113] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.892917] vdb: detected capacity change from 0 to 1073741824 [ 2.902280] libphy: Fixed MDIO Bus: probed [ 2.914879] usbcore: registered new interface driver usbserial_generic [ 2.917322] usbserial: USB Serial support registered for generic [ 2.919592] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.923355] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.924884] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.927203] mousedev: PS/2 mouse device common for all mice [ 2.929548] rtc_cmos 00:05: RTC can wake from S4 [ 2.933209] rtc_cmos 00:05: registered as rtc0 [ 2.933993] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.934861] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.938591] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.940293] intel_pstate: CPU model not supported [ 2.942649] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.946538] hid: raw HID events driver (C) Jiri Kosina [ 2.947961] usbcore: registered new interface driver usbhid [ 2.949437] usbhid: USB HID core driver [ 2.950890] drop_monitor: Initializing network drop monitor service [ 2.953074] Initializing XFRM netlink socket [ 2.954927] NET: Registered protocol family 10 [ 2.957952] Segment Routing with IPv6 [ 2.959878] NET: Registered protocol family 17 [ 2.962420] mpls_gso: MPLS GSO support [ 2.967783] RAS: Correctable Errors collector initialized. [ 2.970883] AVX version of gcm_enc/dec engaged. [ 2.972043] AES CTR mode by8 optimization enabled [ 3.046107] sched_clock: Marking stable (3046085429, 0)->(3947800615, -901715186) [ 3.049579] registered taskstats version 1 [ 3.051298] Loading compiled-in X.509 certificates [ 3.053274] zswap: loaded using pool lzo/zbud [ 3.076393] Key type big_key registered [ 3.089245] Key type encrypted registered [ 3.090664] ima: No TPM chip found, activating TPM-bypass! [ 3.092539] ima: Allocated hash algorithm: sha1 [ 3.094168] ima: No architecture policies found [ 3.095788] evm: Initialising EVM extended attributes: [ 3.097472] evm: security.selinux [ 3.098596] evm: security.ima [ 3.099622] evm: security.capability [ 3.100993] evm: HMAC attrs: 0x1 [ 3.103311] rtc_cmos 00:05: setting system clock to 2026-09-10 16:12:20 UTC (1789056740) [ 3.108952] debug: unmapping init [mem 0xffffffff86203000-0xffffffff863fffff] [ 3.112145] debug: unmapping init [mem 0xffffffff84f82000-0xffffffff85258fff] [ 3.121073] Write protecting the kernel read-only data: 28672k [ 3.123688] debug: unmapping init [mem 0xffffffff83603000-0xffffffff837fffff] [ 3.126371] debug: unmapping init [mem 0xffffffff83f14000-0xffffffff83ffffff] [ 3.155652] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.162847] systemd[1]: Detected virtualization kvm. [ 3.164280] systemd[1]: Detected architecture x86-64. [ 3.165615] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.190265] systemd[1]: No hostname configured. [ 3.192601] systemd[1]: Set hostname to . [ 3.194867] random: systemd: uninitialized urandom read (16 bytes read) [ 3.197404] systemd[1]: Initializing machine ID from random generator. [ 3.325347] random: systemd: uninitialized urandom read (16 bytes read) [ 3.326930] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.330700] random: systemd: uninitialized urandom read (16 bytes read) [ 3.332271] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.335355] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Starting Setup Virtual Console... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Swap. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Sockets. [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.957055] device-mapper: uevent: version 1.0.3 [ 3.958742] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.765613] virtio_net virtio0 ens2: renamed from eth0 [ 4.865624] scsi host0: ata_piix [ 4.880200] scsi host1: ata_piix [ 4.881493] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.883800] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.515102] dracut-initqueue[586]: RTNETLINK answers: File exists [ 9.613919] random: crng init done [ 9.615227] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.170516] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.270942] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.540470] SELinux: Disabled at runtime. [ 11.604604] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.611801] systemd[1]: Detected virtualization kvm. [ 11.613503] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.049402] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.053499] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.057330] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.059773] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.062114] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.068766] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.073029] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice User and Session Slice. Mounting POSIX Message Queue File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Slices. [ OK ] Listening on Process Core Dump Socket. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Switch Root. Mounting Huge Pages File System... Activating swap /dev/disk/by-label/SWAP... Starting udev Coldplug all Devices... [ OK ] Created slice system-getty.slice. Mounting Kernel Debug File System... [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target rpc_pipefs.target. [[ 12.166369] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ 12.498621] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /mnt. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 12.787458] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.836523] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 12.919227] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 12.943232] EDAC sbridge: Ver: 1.1.2 [ 14.176521] Key type dns_resolver registered [ 14.495812] NFS: Registering the id_resolver key type [ 14.498131] Key type id_resolver registered [ 14.499853] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg144-client login: [ 43.412825] hrtimer: interrupt took 4030532 ns [ 67.457809] libcfs: loading out-of-tree module taints kernel. [ 67.591491] Key type ._llcrypt registered [ 67.597948] Key type .llcrypt registered [ 68.835909] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 68.850619] alg: No test for adler32 (adler32-zlib) [ 70.881884] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [ 72.422055] LNet: Added LNI 192.168.201.44@tcp [8/256/0/180] [ 74.280206] Key type lgssc registered [ 76.125333] Lustre: Echo OBD driver; http://www.lustre.org/ [ 84.088553] alg: No test for zstdfast (zstdfast-lustre-generic) [ 84.097172] alg: No test for zstdfast (zstdfast-lustre-scomp) [ 276.180504] Lustre: Mounted lustre-client [ 282.677578] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 295.559222] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing check_logdir /tmp/testlogs/ [ 301.271554] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing yml_node [ 302.053299] Lustre: lustre-OST0000-osc-ffff9fcec302b800: disconnect after 23s idle [ 306.973741] Lustre: DEBUG MARKER: Client: 2.17.53.26 [ 310.586832] Lustre: DEBUG MARKER: MDS: 2.17.53.26 [ 313.156287] Lustre: DEBUG MARKER: OSS: 2.17.53.26 [ 315.224947] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Thu Sep 10 12:17:30 EDT 2026 [ 339.009452] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34682138 <= 34618625) for LU-18938, skip 360 [ 341.202640] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34682138 < 34486116) for LU-14927, skip 0f [ 343.218039] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 817 411a [ 344.832401] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 346.529415] Lustre: DEBUG MARKER: === sanity: start setup 12:18:02 (1789057082) === [ 352.157762] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing check_config_client /mnt/lustre [ 380.035408] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 396.537474] Lustre: DEBUG MARKER: === sanity: finish setup 12:18:52 (1789057132) === [ 404.695848] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 12:19:00 (1789057140) [ 408.315634] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 410.373860] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 12:19:06 (1789057146) [ 419.808402] Lustre: lustre-OST0000-osc-ffff9fcec302b800: disconnect after 23s idle [ 419.821417] Lustre: Skipped 1 previous similar message [ 420.138608] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 12:19:15 (1789057155) [ 598.471068] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 12:22:14 (1789057334) [ 598.800861] Lustre: DEBUG MARKER: test message ID 22794 8255 [ 607.366728] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 12:22:22 (1789057342) [ 616.464530] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 12:22:32 (1789057352) [ 617.304981] LustreError: dumping log to /tmp/f60f.sanity.1789057354.14627 [ 625.072534] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 12:22:40 (1789057360) [ 754.578150] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 12:24:49 (1789057489) [ 756.343373] Lustre: dir [0x240000402:0x1ad:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 756.987086] Lustre: dir [0x240000402:0x1ad:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 759.379640] Lustre: dir [0x240000402:0x1b4:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 759.384793] Lustre: Skipped 2 previous similar messages [ 767.269291] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 768.894307] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 12:25:04 (1789057504) [ 784.759380] Lustre: DEBUG MARKER: SKIP: sanity test_60j path oi.1/0x1:0xb:0x0 is not in 'O/1/d/' format [ 792.211977] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 12:25:27 (1789057527) [ 798.906734] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 12:25:35 (1789057535) [ 806.147488] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 12:25:41 (1789057541) [ 882.601771] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 12:26:58 (1789057618) [ 883.762711] Lustre: *** cfs_fail_loc=406, val=0*** [ 883.765047] LustreError: 21494:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0000-osc-ffff9fcec302b800: prep_req failed: rc = -12 [ 883.786954] LustreError: 21494:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -12 [ 895.077237] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 12:27:11 (1789057631) [ 904.457918] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 906.181977] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 12:27:22 (1789057642) [ 915.117766] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 12:27:30 (1789057650) [ 973.515648] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 12:28:29 (1789057709) [ 976.052568] LustreError: 24848:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec302b800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 976.159184] Lustre: Unmounted lustre-client [ 976.781568] Lustre: Mounted lustre-client [ 981.124615] LustreError: 24958:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec5fdf000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 981.137174] LustreError: 24958:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 981.226025] Lustre: Unmounted lustre-client [ 981.608983] Lustre: Mounted lustre-client [ 991.197461] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 12:28:47 (1789057727) [ 993.598500] LustreError: 25631:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec7c2d000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 993.620707] LustreError: 25631:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 993.755700] Lustre: Unmounted lustre-client [ 994.271743] Lustre: Mounted lustre-client [ 996.946588] LustreError: 25733:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec64ae000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 996.959306] LustreError: 25733:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 997.134343] Lustre: Unmounted lustre-client [ 997.695516] Lustre: Mounted lustre-client [ 1004.957850] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 12:29:00 (1789057740) [ 1029.511986] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 12:29:25 (1789057765) [ 1055.976342] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 12:29:50 (1789057790) [ 1069.548470] Lustre: lustre-OST0000-osc-ffff9fcec6d31000: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1081.824196] Lustre: 2406:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789057803/real 1789057803] req@ffff9fcec8be2680 x1875962038856448/t0(0) o17->lustre-OST0000-osc-ffff9fcec6d31000@192.168.201.144@tcp:28/4 lens 456/432 e 0 to 1 dl 1789057819 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1106.279611] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 1107.866766] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1120.426934] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 12:30:56 (1789057856) [ 1121.646147] LustreError: 2408:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9fcec692bb80 x1875962038868352/t0(0) o4->lustre-OST0000-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 4584/448 e 0 to 0 dl 1789057875 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1131.553361] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 12:31:07 (1789057867) [ 1138.368557] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 12:31:14 (1789057874) [ 1147.107979] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 12:31:22 (1789057882) [ 1155.778477] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 12:31:31 (1789057891) [ 1166.791213] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 12:31:41 (1789057901) [ 1178.068829] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 12:31:53 (1789057913) [ 1184.778231] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 12:32:00 (1789057920) [ 1192.159931] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 12:32:07 (1789057927) [ 1202.658312] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 12:32:17 (1789057937) [ 1214.135209] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 12:32:29 (1789057949) [ 1223.025448] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 12:32:38 (1789057958) [ 1409.293892] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 12:35:44 (1789058144) [ 1418.123844] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 12:35:53 (1789058153) [ 1425.762984] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 12:36:01 (1789058161) [ 1457.324560] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 12:36:33 (1789058193) [ 1486.040716] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 12:37:02 (1789058222) [ 1493.453921] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 12:37:09 (1789058229) [ 1501.481770] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 12:37:16 (1789058236) [ 1509.576787] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 12:37:25 (1789058245) [ 1525.662058] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 12:37:41 (1789058261) [ 1538.748613] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 12:37:54 (1789058274) [ 1554.028668] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1555.896796] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 12:38:11 (1789058291) [ 1563.687448] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 12:38:19 (1789058299) [ 1571.408873] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 12:38:27 (1789058307) [ 1606.382966] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 12:39:02 (1789058342) [ 1613.653142] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 12:39:09 (1789058349) [ 1620.372299] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 12:39:16 (1789058356) [ 1620.525932] Lustre: *** cfs_fail_loc=319, val=0*** [ 1628.651975] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 12:39:24 (1789058364) [ 1718.127768] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 12:40:53 (1789058453) [ 1765.755188] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 12:41:41 (1789058501) [ 1774.719189] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 12:41:50 (1789058510) [ 1775.467137] Lustre: *** cfs_fail_loc=409, val=0*** [ 1775.653383] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], original client csum 172a8144 (type 4), server csum 172a8143 (type 4), client csum now 172a8143 [ 1775.704789] LustreError: 2408:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec8a81180 x1875962043656448/t4294972557(4294972557) o4->lustre-OST0001-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/448 e 0 to 0 dl 1789058528 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1779.592929] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1780.090823] Lustre: *** cfs_fail_loc=408, val=0*** [ 1780.107951] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], client 2dd8382/2dd8382, server 5eec9990, cksum_type 1 [ 1780.117658] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec655aa00 x1875962043658496/t0(0) o3->lustre-OST0001-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/440 e 0 to 0 dl 1789058533 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1784.614771] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1785.329775] Lustre: *** cfs_fail_loc=408, val=0*** [ 1785.364074] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], client 4e17e466/4e17e466, server 5bb4e57b, cksum_type 2 [ 1785.378197] LustreError: 2407:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec637b800 x1875962043660288/t0(0) o3->lustre-OST0001-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/440 e 0 to 0 dl 1789058538 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1789.363715] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1790.104116] Lustre: *** cfs_fail_loc=408, val=0*** [ 1790.131113] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], client 87d762db/87d762db, server 172a8143, cksum_type 4 [ 1790.146203] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec7cd5f80 x1875962043662208/t0(0) o3->lustre-OST0001-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/440 e 0 to 0 dl 1789058543 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1794.381732] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1794.941986] Lustre: *** cfs_fail_loc=408, val=0*** [ 1794.955242] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], client 4831d6af/4831d6af, server 8affd798, cksum_type 10 [ 1794.978246] LustreError: 2405:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec7cd5f80 x1875962043663872/t0(0) o3->lustre-OST0001-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/440 e 0 to 0 dl 1789058548 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1799.455909] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1799.869994] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], client e600fb01/e600fb01, server 2de0fbea, cksum_type 20 [ 1803.543944] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1804.056760] Lustre: *** cfs_fail_loc=408, val=0*** [ 1804.061577] Lustre: Skipped 1 previous similar message [ 1804.092744] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec7cd7b80 x1875962043666048/t0(0) o3->lustre-OST0001-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/440 e 0 to 0 dl 1789058557 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1804.120309] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 1 previous similar message [ 1807.551848] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1808.041332] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3830 extent [0-4194303], client 1b50eeaf/1b50eeaf, server 5b0ded97, cksum_type 80 [ 1808.060886] LustreError: Skipped 1 previous similar message [ 1811.652783] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1817.924842] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 12:42:33 (1789058553) [ 1823.413262] Lustre: *** cfs_fail_loc=408, val=0*** [ 1823.416097] Lustre: Skipped 1 previous similar message [ 1823.420839] Lustre: 2408:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000407:0xc1f:0x0]:[0-1048575]-b62fe989-8bb7681b: dumping checksum data [ 1823.434373] LustreError: dumping log to /tmp/lustre-log.1789058560.2408 [ 1823.500720] LustreError: 2408:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec6379c00 x1875962043673472/t0(0) o3->lustre-OST0000-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/440 e 0 to 0 dl 1789058576 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 1823.510369] LustreError: 2408:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 1 previous similar message [ 1855.947140] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 12:43:11 (1789058591) [ 1856.330738] Lustre: *** cfs_fail_loc=409, val=0*** [ 1856.423501] LustreError: lustre-OST0000-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.201.144@tcp inode [0x200000407:0xc21:0x0] object 0x280000401:3841 extent [0-4194303], original client csum de2bf73f (type 4), server csum de2bf73e (type 4), client csum now de2bf73e [ 1856.434659] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9fcec655b480 x1875962043678464/t8589937214(8589937214) o4->lustre-OST0000-osc-ffff9fcec6d31000@192.168.201.144@tcp:6/4 lens 488/448 e 0 to 0 dl 1789058609 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 1858.054934] LustreError: lustre-OST0000-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc21:0x0] object 0x280000401:3841 extent [4194304-8388607], client f5a99216/f5a99216, server de2bf73e, cksum_type 4 [ 1858.071689] LustreError: Skipped 1 previous similar message [ 1864.625254] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 12:43:21 (1789058601) [ 1866.351734] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1866.990833] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.144@tcp inode [0x200000407:0xc22:0x0] object 0x2c0000401:3831 extent [4194304-8388607], original client csum 8b19b060 (type 1), server csum 8b19b05f (type 1), client csum now 8b19b060 [ 1868.223197] LustreError: 2406:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9fcec6d31000: too many resent retries for object: 11811161089:3831: rc = -11 [ 1870.205607] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1871.209830] LustreError: lustre-OST0000-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.144@tcp inode [0x200000407:0xc23:0x0] object 0x280000401:3842 extent [0-4194303], original client csum 7d33b9a0 (type 2), server csum 7d33b99f (type 2), client csum now 7d33b9a0 [ 1871.221571] LustreError: Skipped 3 previous similar messages [ 1872.638572] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9fcec6d31000: too many resent retries for object: 10737419265:3842: rc = -11 [ 1872.668430] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) Skipped 1 previous similar message [ 1874.234110] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1876.174640] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.144@tcp inode [0x200000407:0xc24:0x0] object 0x2c0000401:3832 extent [0-4194303], original client csum de2bf73f (type 4), server csum de2bf73e (type 4), client csum now de2bf73f [ 1876.207990] LustreError: Skipped 4 previous similar messages [ 1877.446432] LustreError: 2405:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9fcec6d31000: too many resent retries for object: 11811161089:3832: rc = -11 [ 1877.456609] LustreError: 2405:0:(osc_request.c:2607:brw_interpret()) Skipped 1 previous similar message [ 1881.201638] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1883.410611] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9fcec6d31000: too many resent retries for object: 10737419265:3843: rc = -11 [ 1883.420142] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) Skipped 1 previous similar message [ 1885.472919] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1886.336272] LustreError: lustre-OST0001-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.144@tcp inode [0x200000407:0xc26:0x0] object 0x2c0000401:3833 extent [4194304-8388607], original client csum fec05011 (type 20), server csum fec05010 (type 20), client csum now fec05011 [ 1886.383496] LustreError: Skipped 6 previous similar messages [ 1887.805366] LustreError: 2407:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9fcec6d31000: too many resent retries for object: 11811161089:3833: rc = -11 [ 1887.830082] LustreError: 2407:0:(osc_request.c:2607:brw_interpret()) Skipped 1 previous similar message [ 1891.607189] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1897.122865] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1899.242593] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9fcec6d31000: too many resent retries for object: 11811161089:3834: rc = -11 [ 1899.265958] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) Skipped 3 previous similar messages [ 1908.829226] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1911.317484] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 12:44:06 (1789058646) [ 1913.312815] LustreError: lustre-OST0000-osc-ffff9fcec6d31000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.144@tcp inode [0x200000407:0xc29:0x0] object 0x280000401:3845 extent [0-1048575], original client csum 8bb7681b (type 4), server csum 21f56de1 (type 4), client csum now 8bb7681b [ 1913.338673] LustreError: Skipped 11 previous similar messages [ 1918.963769] LustreError: lustre-OST0000-osc-ffff9fcec6d31000: BAD READ CHECKSUM: from 192.168.201.144@tcp inode [0x200000407:0xc29:0x0] object 0x280000401:3845 extent [0-4194303], client 172a8143/172a8143, server 98ea529c, cksum_type 4 [ 1928.952579] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 12:44:25 (1789058665) [ 1936.656180] LustreError: 58916:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec6d31000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1936.671714] LustreError: 58916:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1936.826355] Lustre: Unmounted lustre-client [ 1937.423367] Lustre: Mounted lustre-client [ 1944.224224] LustreError: 59021:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec4f56800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1944.230235] LustreError: 59021:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1944.278551] Lustre: Unmounted lustre-client [ 1944.781033] Lustre: Mounted lustre-client [ 1949.721744] LustreError: 59106:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec44f7000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1949.747316] LustreError: 59106:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1949.877816] Lustre: Unmounted lustre-client [ 1950.781461] Lustre: Mounted lustre-client [ 1952.463101] LustreError: 59183:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec6d34000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1952.474878] LustreError: 59183:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1952.534236] Lustre: Unmounted lustre-client [ 1952.939114] Lustre: Mounted lustre-client [ 1957.406916] Lustre: Mounted lustre-client [ 1968.930632] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 12:45:04 (1789058704) [ 1970.872286] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 1972.565434] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1976.420568] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 1978.146052] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 0 sec [ 1982.316812] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 1984.363768] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 1986.049162] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1990.780690] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2000.871319] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 7 sec [ 2005.476522] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2006.909295] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 2009.143402] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2014.921917] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2020.940348] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 3 sec [ 2027.343794] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2029.264639] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 2031.213970] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2035.415311] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2046.787417] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 9 sec [ 2053.274946] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2055.728821] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 2057.501289] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2062.065529] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2072.275990] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 8 sec [ 2075.786076] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2077.960171] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 2079.527491] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2084.857147] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2093.105923] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 6 sec [ 2098.598568] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2100.812283] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 2102.417976] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2107.736964] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2118.464681] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in IDLE state after 7 sec [ 2123.101479] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid 50 [ 2124.888499] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec4f22800.ost_server_uuid in FULL state after 0 sec [ 2132.662375] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2134.936487] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 12:47:50 (1789058870) [ 2142.157853] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 12:47:57 (1789058877) [ 2144.743509] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2146.294951] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2148.099864] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2149.966896] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2157.667652] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2159.694901] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 12:48:15 (1789058895) [ 2172.455985] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 12:48:28 (1789058908) [ 2181.489758] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 12:48:37 (1789058917) [ 2202.113106] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 12:48:57 (1789058937) [ 2211.966719] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 12:49:07 (1789058947) [ 2222.356134] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 12:49:18 (1789058958) [ 2234.253746] Lustre: DEBUG MARKER: == sanity test 84: lz4/lz4hc/lzstd compression/decompression kernel module ========================================================== 12:49:29 (1789058969) [ 2234.861854] lustre_kcompr_28176: ***** [ 2234.871990] lustre_kcompr_28176: (de)compression test on random binary data [ 2234.878403] lustre_kcompr_28176: ***** [ 2234.909460] lustre_kcompr_28176: compr lz4(1) in 64kB chunks took 3337 us (1198 MB/s), compress ratio: 97.13 [ 2234.925553] lustre_kcompr_28176: compr lz4(1) in 128kB chunks took 3985 us (1003 MB/s), compress ratio: 102.14 [ 2234.937913] lustre_kcompr_28176: compr lz4(1) in 256kB chunks took 3292 us (1215 MB/s), compress ratio: 105.40 [ 2234.968425] lustre_kcompr_28176: compr lz4(1) in 512kB chunks took 3030 us (1320 MB/s), compress ratio: 106.85 [ 2234.988333] lustre_kcompr_28176: compr lz4(1) in 1024kB chunks took 2397 us (1668 MB/s), compress ratio: 107.66 [ 2234.999745] lustre_kcompr_28176: compr lz4(1) in 2048kB chunks took 3280 us (1219 MB/s), compress ratio: 107.75 [ 2235.011681] lustre_kcompr_28176: compr lz4(1) in 4096kB chunks took 4219 us (948 MB/s), compress ratio: 107.76 [ 2235.029082] lustre_kcompr_28176: decompr lz4(1) took 4204 us (8 MB/s) [ 2235.033536] lustre_kcompr_28176: test_comp_compress_decompress(lz4,1) ret 0 [ 2235.038906] lustre_kcompr_28176: acompr lz4(1) of 128kB chunks took 142 us (880 MB/s), compress ratio: 102.96 [ 2235.044897] lustre_kcompr_28176: adecompr lz4(1) took 272 us (4 MB/s) [ 2235.061930] lustre_kcompr_28176: test_acomp_compress_decompress(lz4,1) ret 0 [ 2235.095032] lustre_kcompr_28176: compr lz4(4) in 64kB chunks took 6629 us (603 MB/s), compress ratio: 83.23 [ 2235.117606] lustre_kcompr_28176: compr lz4(4) in 128kB chunks took 4713 us (848 MB/s), compress ratio: 93.36 [ 2235.156321] lustre_kcompr_28176: compr lz4(4) in 256kB chunks took 12342 us (324 MB/s), compress ratio: 99.32 [ 2235.183055] lustre_kcompr_28176: compr lz4(4) in 512kB chunks took 9061 us (441 MB/s), compress ratio: 102.92 [ 2235.194453] lustre_kcompr_28176: compr lz4(4) in 1024kB chunks took 2475 us (1616 MB/s), compress ratio: 104.27 [ 2235.207516] lustre_kcompr_28176: compr lz4(4) in 2048kB chunks took 3098 us (1291 MB/s), compress ratio: 105.37 [ 2235.217299] lustre_kcompr_28176: compr lz4(4) in 4096kB chunks took 2598 us (1539 MB/s), compress ratio: 105.55 [ 2235.268147] lustre_kcompr_28176: decompr lz4(4) took 1636 us (23 MB/s) [ 2235.290217] lustre_kcompr_28176: test_comp_compress_decompress(lz4,4) ret 0 [ 2235.313171] lustre_kcompr_28176: acompr lz4(4) of 128kB chunks took 1228 us (101 MB/s), compress ratio: 96.66 [ 2235.329388] lustre_kcompr_28176: adecompr lz4(4) took 103 us (12 MB/s) [ 2235.376143] lustre_kcompr_28176: test_acomp_compress_decompress(lz4,4) ret 0 [ 2235.399876] lustre_kcompr_28176: compr lz4(9) in 64kB chunks took 2102 us (1902 MB/s), compress ratio: 61.22 [ 2235.420353] lustre_kcompr_28176: compr lz4(9) in 128kB chunks took 2429 us (1646 MB/s), compress ratio: 76.10 [ 2235.434071] lustre_kcompr_28176: compr lz4(9) in 256kB chunks took 5205 us (768 MB/s), compress ratio: 87.07 [ 2235.450211] lustre_kcompr_28176: compr lz4(9) in 512kB chunks took 5068 us (789 MB/s), compress ratio: 94.44 [ 2235.474547] lustre_kcompr_28176: compr lz4(9) in 1024kB chunks took 6064 us (659 MB/s), compress ratio: 97.87 [ 2235.494750] lustre_kcompr_28176: compr lz4(9) in 2048kB chunks took 1433 us (2791 MB/s), compress ratio: 99.63 [ 2235.526336] lustre_kcompr_28176: compr lz4(9) in 4096kB chunks took 7885 us (507 MB/s), compress ratio: 100.40 [ 2235.562580] lustre_kcompr_28176: decompr lz4(9) took 5603 us (7 MB/s) [ 2235.570442] lustre_kcompr_28176: test_comp_compress_decompress(lz4,9) ret 0 [ 2235.588052] lustre_kcompr_28176: acompr lz4(9) of 128kB chunks took 322 us (388 MB/s), compress ratio: 75.50 [ 2235.597720] lustre_kcompr_28176: adecompr lz4(9) took 263 us (6 MB/s) [ 2235.613652] lustre_kcompr_28176: test_acomp_compress_decompress(lz4,9) ret 0 [ 2235.641130] lustre_kcompr_28176: compr lz4(15) in 64kB chunks took 3727 us (1073 MB/s), compress ratio: 29.41 [ 2235.651273] lustre_kcompr_28176: compr lz4(15) in 128kB chunks took 3372 us (1186 MB/s), compress ratio: 43.55 [ 2235.661249] lustre_kcompr_28176: compr lz4(15) in 256kB chunks took 2863 us (1397 MB/s), compress ratio: 59.17 [ 2235.670751] lustre_kcompr_28176: compr lz4(15) in 512kB chunks took 1418 us (2820 MB/s), compress ratio: 71.62 [ 2235.694900] lustre_kcompr_28176: compr lz4(15) in 1024kB chunks took 1673 us (2390 MB/s), compress ratio: 78.96 [ 2235.714928] lustre_kcompr_28176: compr lz4(15) in 2048kB chunks took 3758 us (1064 MB/s), compress ratio: 84.46 [ 2235.731298] lustre_kcompr_28176: compr lz4(15) in 4096kB chunks took 2938 us (1361 MB/s), compress ratio: 87.95 [ 2235.761589] lustre_kcompr_28176: decompr lz4(15) took 2320 us (19 MB/s) [ 2235.774407] lustre_kcompr_28176: test_comp_compress_decompress(lz4,15) ret 0 [ 2235.784052] lustre_kcompr_28176: acompr lz4(15) of 128kB chunks took 428 us (292 MB/s), compress ratio: 43.85 [ 2235.793413] lustre_kcompr_28176: adecompr lz4(15) took 575 us (4 MB/s) [ 2235.802640] lustre_kcompr_28176: test_acomp_compress_decompress(lz4,15) ret 0 [ 2235.858971] lustre_kcompr_28176: compr lz4hc(1) in 64kB chunks took 38320 us (104 MB/s), compress ratio: 97.94 [ 2235.933886] lustre_kcompr_28176: compr lz4hc(1) in 128kB chunks took 55829 us (71 MB/s), compress ratio: 103.93 [ 2236.044983] lustre_kcompr_28176: compr lz4hc(1) in 256kB chunks took 96820 us (41 MB/s), compress ratio: 107.21 [ 2236.098441] lustre_kcompr_28176: compr lz4hc(1) in 512kB chunks took 34265 us (116 MB/s), compress ratio: 108.93 [ 2236.136356] lustre_kcompr_28176: compr lz4hc(1) in 1024kB chunks took 30091 us (132 MB/s), compress ratio: 109.81 [ 2236.192313] lustre_kcompr_28176: compr lz4hc(1) in 2048kB chunks took 48267 us (82 MB/s), compress ratio: 110.25 [ 2236.255839] lustre_kcompr_28176: compr lz4hc(1) in 4096kB chunks took 54151 us (73 MB/s), compress ratio: 110.48 [ 2236.270519] lustre_kcompr_28176: decompr lz4hc(1) took 2221 us (16 MB/s) [ 2236.274445] lustre_kcompr_28176: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2236.281544] lustre_kcompr_28176: acompr lz4hc(1) of 128kB chunks took 1390 us (89 MB/s), compress ratio: 102.88 [ 2236.291995] lustre_kcompr_28176: adecompr lz4hc(1) took 150 us (8 MB/s) [ 2236.300658] lustre_kcompr_28176: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2236.359325] lustre_kcompr_28176: compr lz4hc(3) in 64kB chunks took 45532 us (87 MB/s), compress ratio: 98.37 [ 2236.455527] lustre_kcompr_28176: compr lz4hc(3) in 128kB chunks took 87986 us (45 MB/s), compress ratio: 104.38 [ 2236.547752] lustre_kcompr_28176: compr lz4hc(3) in 256kB chunks took 85712 us (46 MB/s), compress ratio: 107.69 [ 2236.638072] lustre_kcompr_28176: compr lz4hc(3) in 512kB chunks took 83684 us (47 MB/s), compress ratio: 109.41 [ 2236.716532] lustre_kcompr_28176: compr lz4hc(3) in 1024kB chunks took 65723 us (60 MB/s), compress ratio: 110.30 [ 2236.818381] lustre_kcompr_28176: compr lz4hc(3) in 2048kB chunks took 90503 us (44 MB/s), compress ratio: 110.74 [ 2236.907180] lustre_kcompr_28176: compr lz4hc(3) in 4096kB chunks took 81585 us (49 MB/s), compress ratio: 110.97 [ 2236.935139] lustre_kcompr_28176: decompr lz4hc(3) took 6151 us (5 MB/s) [ 2236.943485] lustre_kcompr_28176: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2236.949108] lustre_kcompr_28176: acompr lz4hc(3) of 128kB chunks took 960 us (130 MB/s), compress ratio: 102.88 [ 2236.955318] lustre_kcompr_28176: adecompr lz4hc(3) took 186 us (6 MB/s) [ 2236.960686] lustre_kcompr_28176: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2238.199251] lustre_kcompr_28176: compr lz4hc(8) in 64kB chunks took 1223440 us (3 MB/s), compress ratio: 104.83 [ 2239.834901] lustre_kcompr_28176: compr lz4hc(8) in 128kB chunks took 1618423 us (2 MB/s), compress ratio: 111.99 [ 2241.176573] lustre_kcompr_28176: compr lz4hc(8) in 256kB chunks took 1327223 us (3 MB/s), compress ratio: 115.91 [ 2241.880649] lustre_kcompr_28176: compr lz4hc(8) in 512kB chunks took 701183 us (5 MB/s), compress ratio: 118.00 [ 2242.506540] lustre_kcompr_28176: compr lz4hc(8) in 1024kB chunks took 609741 us (6 MB/s), compress ratio: 119.06 [ 2243.722736] lustre_kcompr_28176: compr lz4hc(8) in 2048kB chunks took 1193593 us (3 MB/s), compress ratio: 119.61 [ 2245.120041] lustre_kcompr_28176: compr lz4hc(8) in 4096kB chunks took 1389231 us (2 MB/s), compress ratio: 119.87 [ 2245.138207] lustre_kcompr_28176: decompr lz4hc(8) took 6329 us (5 MB/s) [ 2245.142181] lustre_kcompr_28176: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2245.165520] lustre_kcompr_28176: acompr lz4hc(8) of 128kB chunks took 18276 us (6 MB/s), compress ratio: 110.23 [ 2245.177291] lustre_kcompr_28176: adecompr lz4hc(8) took 110 us (10 MB/s) [ 2245.198468] lustre_kcompr_28176: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2246.941058] lustre_kcompr_28176: compr lz4hc(15) in 64kB chunks took 1718786 us (2 MB/s), compress ratio: 105.34 [ 2247.798508] lustre_kcompr_28176: compr lz4hc(15) in 128kB chunks took 839819 us (4 MB/s), compress ratio: 113.05 [ 2248.826409] lustre_kcompr_28176: compr lz4hc(15) in 256kB chunks took 1020564 us (3 MB/s), compress ratio: 117.21 [ 2250.122746] lustre_kcompr_28176: compr lz4hc(15) in 512kB chunks took 1284694 us (3 MB/s), compress ratio: 119.48 [ 2251.055444] lustre_kcompr_28176: compr lz4hc(15) in 1024kB chunks took 922178 us (4 MB/s), compress ratio: 120.62 [ 2253.034230] lustre_kcompr_28176: compr lz4hc(15) in 2048kB chunks took 1974372 us (2 MB/s), compress ratio: 121.19 [ 2254.269225] lustre_kcompr_28176: compr lz4hc(15) in 4096kB chunks took 1229067 us (3 MB/s), compress ratio: 121.46 [ 2254.280416] lustre_kcompr_28176: decompr lz4hc(15) took 1922 us (17 MB/s) [ 2254.288746] lustre_kcompr_28176: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2254.316815] lustre_kcompr_28176: acompr lz4hc(15) of 128kB chunks took 22057 us (5 MB/s), compress ratio: 111.83 [ 2254.328688] lustre_kcompr_28176: adecompr lz4hc(15) took 272 us (4 MB/s) [ 2254.370364] lustre_kcompr_28176: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2254.385104] lustre_kcompr_28176: compr lzo(-1) in 64kB chunks took 6187 us (646 MB/s), compress ratio: 82.04 [ 2254.395139] lustre_kcompr_28176: compr lzo(-1) in 128kB chunks took 4138 us (966 MB/s), compress ratio: 87.24 [ 2254.406856] lustre_kcompr_28176: compr lzo(-1) in 256kB chunks took 4524 us (884 MB/s), compress ratio: 87.35 [ 2254.415616] lustre_kcompr_28176: compr lzo(-1) in 512kB chunks took 2434 us (1643 MB/s), compress ratio: 88.61 [ 2254.423896] lustre_kcompr_28176: compr lzo(-1) in 1024kB chunks took 2679 us (1493 MB/s), compress ratio: 88.75 [ 2254.430675] lustre_kcompr_28176: compr lzo(-1) in 2048kB chunks took 2193 us (1823 MB/s), compress ratio: 89.11 [ 2254.437043] lustre_kcompr_28176: compr lzo(-1) in 4096kB chunks took 2550 us (1568 MB/s), compress ratio: 89.41 [ 2254.465577] lustre_kcompr_28176: decompr lzo(-1) took 4563 us (9 MB/s) [ 2254.477685] lustre_kcompr_28176: test_comp_compress_decompress(lzo,-1) ret 0 [ 2254.481436] lustre_kcompr_28176: acompr lzo(-1) of 128kB chunks took 106 us (1179 MB/s), compress ratio: 87.96 [ 2254.488079] lustre_kcompr_28176: adecompr lzo(-1) took 176 us (8 MB/s) [ 2254.498962] lustre_kcompr_28176: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2255.099672] lustre_kcompr_28176: compr deflate(1) in 64kB chunks took 587766 us (6 MB/s), compress ratio: 98.18 [ 2255.716188] lustre_kcompr_28176: compr deflate(1) in 128kB chunks took 605216 us (6 MB/s), compress ratio: 108.50 [ 2256.636870] lustre_kcompr_28176: compr deflate(1) in 256kB chunks took 903730 us (4 MB/s), compress ratio: 114.92 [ 2257.057045] lustre_kcompr_28176: compr deflate(1) in 512kB chunks took 392588 us (10 MB/s), compress ratio: 118.90 [ 2257.816364] lustre_kcompr_28176: compr deflate(1) in 1024kB chunks took 749525 us (5 MB/s), compress ratio: 120.85 [ 2258.337516] lustre_kcompr_28176: compr deflate(1) in 2048kB chunks took 512483 us (7 MB/s), compress ratio: 121.79 [ 2258.887040] lustre_kcompr_28176: compr deflate(1) in 4096kB chunks took 540732 us (7 MB/s), compress ratio: 122.08 [ 2258.921133] lustre_kcompr_28176: decompr deflate(1) took 9873 us (3 MB/s) [ 2258.927210] lustre_kcompr_28176: test_comp_compress_decompress(deflate,1) ret 0 [ 2258.946495] lustre_kcompr_28176: acompr deflate(1) of 128kB chunks took 13987 us (8 MB/s), compress ratio: 106.73 [ 2258.958628] lustre_kcompr_28176: adecompr deflate(1) took 1262 us (0 MB/s) [ 2259.007232] lustre_kcompr_28176: test_acomp_compress_decompress(deflate,1) ret 0 [ 2259.575704] lustre_kcompr_28176: compr deflate(6) in 64kB chunks took 515977 us (7 MB/s), compress ratio: 98.18 [ 2259.987729] lustre_kcompr_28176: compr deflate(6) in 128kB chunks took 392994 us (10 MB/s), compress ratio: 108.50 [ 2260.236429] lustre_kcompr_28176: compr deflate(6) in 256kB chunks took 244215 us (16 MB/s), compress ratio: 114.92 [ 2260.757833] lustre_kcompr_28176: compr deflate(6) in 512kB chunks took 516851 us (7 MB/s), compress ratio: 118.90 [ 2261.133828] lustre_kcompr_28176: compr deflate(6) in 1024kB chunks took 371052 us (10 MB/s), compress ratio: 120.85 [ 2261.424453] lustre_kcompr_28176: compr deflate(6) in 2048kB chunks took 285291 us (14 MB/s), compress ratio: 121.79 [ 2261.771871] lustre_kcompr_28176: compr deflate(6) in 4096kB chunks took 343383 us (11 MB/s), compress ratio: 122.08 [ 2261.791286] lustre_kcompr_28176: decompr deflate(6) took 6956 us (4 MB/s) [ 2261.801068] lustre_kcompr_28176: test_comp_compress_decompress(deflate,6) ret 0 [ 2261.814917] lustre_kcompr_28176: acompr deflate(6) of 128kB chunks took 9503 us (13 MB/s), compress ratio: 106.73 [ 2261.820271] lustre_kcompr_28176: adecompr deflate(6) took 307 us (3 MB/s) [ 2261.827257] lustre_kcompr_28176: test_acomp_compress_decompress(deflate,6) ret 0 [ 2262.131383] lustre_kcompr_28176: compr deflate(9) in 64kB chunks took 291443 us (13 MB/s), compress ratio: 98.18 [ 2262.405823] lustre_kcompr_28176: compr deflate(9) in 128kB chunks took 270246 us (14 MB/s), compress ratio: 108.50 [ 2262.707593] lustre_kcompr_28176: compr deflate(9) in 256kB chunks took 297369 us (13 MB/s), compress ratio: 114.92 [ 2262.986202] lustre_kcompr_28176: compr deflate(9) in 512kB chunks took 273368 us (14 MB/s), compress ratio: 118.90 [ 2263.273887] lustre_kcompr_28176: compr deflate(9) in 1024kB chunks took 282198 us (14 MB/s), compress ratio: 120.85 [ 2263.522777] lustre_kcompr_28176: compr deflate(9) in 2048kB chunks took 244207 us (16 MB/s), compress ratio: 121.79 [ 2263.883975] lustre_kcompr_28176: compr deflate(9) in 4096kB chunks took 356493 us (11 MB/s), compress ratio: 122.08 [ 2263.923831] lustre_kcompr_28176: decompr deflate(9) took 9767 us (3 MB/s) [ 2263.937671] lustre_kcompr_28176: test_comp_compress_decompress(deflate,9) ret 0 [ 2263.971653] lustre_kcompr_28176: acompr deflate(9) of 128kB chunks took 19237 us (6 MB/s), compress ratio: 106.73 [ 2263.984660] lustre_kcompr_28176: adecompr deflate(9) took 211 us (5 MB/s) [ 2263.989664] lustre_kcompr_28176: test_acomp_compress_decompress(deflate,9) ret 0 [ 2264.006317] lustre_kcompr_28176: compr zstd(0) in 64kB chunks took 7871 us (508 MB/s), compress ratio: 160.20 [ 2264.022621] lustre_kcompr_28176: compr zstd(0) in 128kB chunks took 12658 us (316 MB/s), compress ratio: 194.12 [ 2264.035223] lustre_kcompr_28176: compr zstd(0) in 256kB chunks took 10129 us (394 MB/s), compress ratio: 206.53 [ 2264.057748] lustre_kcompr_28176: compr zstd(0) in 512kB chunks took 18538 us (215 MB/s), compress ratio: 212.73 [ 2264.072971] lustre_kcompr_28176: compr zstd(0) in 1024kB chunks took 7458 us (536 MB/s), compress ratio: 214.99 [ 2264.088931] lustre_kcompr_28176: compr zstd(0) in 2048kB chunks took 8034 us (497 MB/s), compress ratio: 216.31 [ 2264.107299] lustre_kcompr_28176: compr zstd(0) in 4096kB chunks took 10736 us (372 MB/s), compress ratio: 217.05 [ 2264.123041] lustre_kcompr_28176: decompr zstd(0) took 3430 us (5 MB/s) [ 2264.127634] lustre_kcompr_28176: test_comp_compress_decompress(zstd,0) ret 0 [ 2264.132098] lustre_kcompr_28176: acompr zstd(0) of 128kB chunks took 667 us (187 MB/s), compress ratio: 190.78 [ 2264.141803] lustre_kcompr_28176: adecompr zstd(0) took 147 us (4 MB/s) [ 2264.165914] lustre_kcompr_28176: test_acomp_compress_decompress(zstd,0) ret 0 [ 2264.182875] lustre_kcompr_28176: compr zstd(1) in 64kB chunks took 3698 us (1081 MB/s), compress ratio: 159.19 [ 2264.194140] lustre_kcompr_28176: compr zstd(1) in 128kB chunks took 2980 us (1342 MB/s), compress ratio: 190.90 [ 2264.208077] lustre_kcompr_28176: compr zstd(1) in 256kB chunks took 4507 us (887 MB/s), compress ratio: 204.39 [ 2264.215612] lustre_kcompr_28176: compr zstd(1) in 512kB chunks took 3235 us (1236 MB/s), compress ratio: 210.72 [ 2264.223053] lustre_kcompr_28176: compr zstd(1) in 1024kB chunks took 2931 us (1364 MB/s), compress ratio: 213.00 [ 2264.239575] lustre_kcompr_28176: compr zstd(1) in 2048kB chunks took 9594 us (416 MB/s), compress ratio: 215.49 [ 2264.250602] lustre_kcompr_28176: compr zstd(1) in 4096kB chunks took 4024 us (994 MB/s), compress ratio: 213.25 [ 2264.280344] lustre_kcompr_28176: decompr zstd(1) took 7964 us (2 MB/s) [ 2264.285932] lustre_kcompr_28176: test_comp_compress_decompress(zstd,1) ret 0 [ 2264.290946] lustre_kcompr_28176: acompr zstd(1) of 128kB chunks took 151 us (827 MB/s), compress ratio: 190.78 [ 2264.299129] lustre_kcompr_28176: adecompr zstd(1) took 125 us (5 MB/s) [ 2264.312027] lustre_kcompr_28176: test_acomp_compress_decompress(zstd,1) ret 0 [ 2264.546343] lustre_kcompr_28176: compr zstd(10) in 64kB chunks took 221479 us (18 MB/s), compress ratio: 162.19 [ 2264.866663] lustre_kcompr_28176: compr zstd(10) in 128kB chunks took 302989 us (13 MB/s), compress ratio: 185.21 [ 2265.300668] lustre_kcompr_28176: compr zstd(10) in 256kB chunks took 421198 us (9 MB/s), compress ratio: 197.22 [ 2265.633189] lustre_kcompr_28176: compr zstd(10) in 512kB chunks took 313328 us (12 MB/s), compress ratio: 218.13 [ 2265.958057] lustre_kcompr_28176: compr zstd(10) in 1024kB chunks took 311481 us (12 MB/s), compress ratio: 222.61 [ 2266.382427] lustre_kcompr_28176: compr zstd(10) in 2048kB chunks took 418134 us (9 MB/s), compress ratio: 224.67 [ 2266.463566] lustre_kcompr_28176: compr zstd(10) in 4096kB chunks took 74157 us (53 MB/s), compress ratio: 225.97 [ 2266.492809] lustre_kcompr_28176: decompr zstd(10) took 5665 us (3 MB/s) [ 2266.522173] lustre_kcompr_28176: test_comp_compress_decompress(zstd,10) ret 0 [ 2266.546426] lustre_kcompr_28176: acompr zstd(10) of 128kB chunks took 6970 us (17 MB/s), compress ratio: 180.29 [ 2266.561850] lustre_kcompr_28176: adecompr zstd(10) took 138 us (5 MB/s) [ 2266.574360] lustre_kcompr_28176: test_acomp_compress_decompress(zstd,10) ret 0 [ 2267.345728] lustre_kcompr_28176: compr zstd(15) in 64kB chunks took 757558 us (5 MB/s), compress ratio: 170.82 [ 2268.309814] lustre_kcompr_28176: compr zstd(15) in 128kB chunks took 946115 us (4 MB/s), compress ratio: 196.38 [ 2269.218512] lustre_kcompr_28176: compr zstd(15) in 256kB chunks took 894671 us (4 MB/s), compress ratio: 210.35 [ 2270.053365] lustre_kcompr_28176: compr zstd(15) in 512kB chunks took 829713 us (4 MB/s), compress ratio: 218.32 [ 2270.720744] lustre_kcompr_28176: compr zstd(15) in 1024kB chunks took 659995 us (6 MB/s), compress ratio: 223.26 [ 2272.018474] lustre_kcompr_28176: compr zstd(15) in 2048kB chunks took 1287388 us (3 MB/s), compress ratio: 222.49 [ 2274.172940] lustre_kcompr_28176: compr zstd(15) in 4096kB chunks took 2148068 us (1 MB/s), compress ratio: 222.28 [ 2274.204842] lustre_kcompr_28176: decompr zstd(15) took 5071 us (3 MB/s) [ 2274.225701] lustre_kcompr_28176: test_comp_compress_decompress(zstd,15) ret 0 [ 2274.266952] lustre_kcompr_28176: acompr zstd(15) of 128kB chunks took 30712 us (4 MB/s), compress ratio: 193.89 [ 2274.273735] lustre_kcompr_28176: adecompr zstd(15) took 240 us (2 MB/s) [ 2274.293473] lustre_kcompr_28176: test_acomp_compress_decompress(zstd,15) ret 0 [ 2274.326935] lustre_kcompr_28176: compr zstdfast(1) in 64kB chunks took 6364 us (628 MB/s), compress ratio: 159.19 [ 2274.350688] lustre_kcompr_28176: compr zstdfast(1) in 128kB chunks took 12802 us (312 MB/s), compress ratio: 190.90 [ 2274.358914] lustre_kcompr_28176: compr zstdfast(1) in 256kB chunks took 2545 us (1571 MB/s), compress ratio: 204.39 [ 2274.366750] lustre_kcompr_28176: compr zstdfast(1) in 512kB chunks took 2619 us (1527 MB/s), compress ratio: 210.87 [ 2274.376334] lustre_kcompr_28176: compr zstdfast(1) in 1024kB chunks took 3779 us (1058 MB/s), compress ratio: 212.80 [ 2274.395591] lustre_kcompr_28176: compr zstdfast(1) in 2048kB chunks took 6413 us (623 MB/s), compress ratio: 213.82 [ 2274.409832] lustre_kcompr_28176: compr zstdfast(1) in 4096kB chunks took 3178 us (1258 MB/s), compress ratio: 213.25 [ 2274.423943] lustre_kcompr_28176: decompr zstdfast(1) took 2559 us (7 MB/s) [ 2274.428254] lustre_kcompr_28176: test_comp_compress_decompress(zstdfast,1) ret 0 [ 2274.433958] lustre_kcompr_28176: acompr zstdfast(1) of 128kB chunks took 164 us (762 MB/s), compress ratio: 190.78 [ 2274.438375] lustre_kcompr_28176: adecompr zstdfast(1) took 284 us (2 MB/s) [ 2274.444509] lustre_kcompr_28176: test_acomp_compress_decompress(zstdfast,1) ret 0 [ 2274.467468] lustre_kcompr_28176: compr zstdfast(5) in 64kB chunks took 3688 us (1084 MB/s), compress ratio: 139.88 [ 2274.476753] lustre_kcompr_28176: compr zstdfast(5) in 128kB chunks took 4270 us (936 MB/s), compress ratio: 164.89 [ 2274.484590] lustre_kcompr_28176: compr zstdfast(5) in 256kB chunks took 3027 us (1321 MB/s), compress ratio: 175.75 [ 2274.491790] lustre_kcompr_28176: compr zstdfast(5) in 512kB chunks took 2283 us (1752 MB/s), compress ratio: 181.68 [ 2274.499949] lustre_kcompr_28176: compr zstdfast(5) in 1024kB chunks took 3002 us (1332 MB/s), compress ratio: 183.35 [ 2274.507550] lustre_kcompr_28176: compr zstdfast(5) in 2048kB chunks took 2809 us (1423 MB/s), compress ratio: 183.80 [ 2274.517965] lustre_kcompr_28176: compr zstdfast(5) in 4096kB chunks took 3386 us (1181 MB/s), compress ratio: 182.89 [ 2274.541616] lustre_kcompr_28176: decompr zstdfast(5) took 3856 us (5 MB/s) [ 2274.548714] lustre_kcompr_28176: test_comp_compress_decompress(zstdfast,5) ret 0 [ 2274.556573] lustre_kcompr_28176: acompr zstdfast(5) of 128kB chunks took 301 us (415 MB/s), compress ratio: 167.39 [ 2274.565761] lustre_kcompr_28176: adecompr zstdfast(5) took 741 us (1 MB/s) [ 2274.584946] lustre_kcompr_28176: test_acomp_compress_decompress(zstdfast,5) ret 0 [ 2274.609728] lustre_kcompr_28176: compr zstdfast(12) in 64kB chunks took 4930 us (811 MB/s), compress ratio: 38.63 [ 2274.621741] lustre_kcompr_28176: compr zstdfast(12) in 128kB chunks took 3527 us (1134 MB/s), compress ratio: 44.48 [ 2274.632546] lustre_kcompr_28176: compr zstdfast(12) in 256kB chunks took 3550 us (1126 MB/s), compress ratio: 48.96 [ 2274.658932] lustre_kcompr_28176: compr zstdfast(12) in 512kB chunks took 5571 us (718 MB/s), compress ratio: 53.09 [ 2274.689276] lustre_kcompr_28176: compr zstdfast(12) in 1024kB chunks took 8905 us (449 MB/s), compress ratio: 61.01 [ 2274.702764] lustre_kcompr_28176: compr zstdfast(12) in 2048kB chunks took 7170 us (557 MB/s), compress ratio: 72.47 [ 2274.716738] lustre_kcompr_28176: compr zstdfast(12) in 4096kB chunks took 1762 us (2270 MB/s), compress ratio: 78.19 [ 2274.747712] lustre_kcompr_28176: decompr zstdfast(12) took 9388 us (5 MB/s) [ 2274.768085] lustre_kcompr_28176: test_comp_compress_decompress(zstdfast,12) ret 0 [ 2274.779577] lustre_kcompr_28176: acompr zstdfast(12) of 128kB chunks took 169 us (739 MB/s), compress ratio: 41.99 [ 2274.788105] lustre_kcompr_28176: adecompr zstdfast(12) took 112 us (26 MB/s) [ 2274.833560] lustre_kcompr_28176: test_acomp_compress_decompress(zstdfast,12) ret 0 [ 2274.867210] lustre_kcompr_28176: compr zstdfast(15) in 64kB chunks took 4631 us (863 MB/s), compress ratio: 19.26 [ 2274.883967] lustre_kcompr_28176: compr zstdfast(15) in 128kB chunks took 7016 us (570 MB/s), compress ratio: 20.05 [ 2274.896450] lustre_kcompr_28176: compr zstdfast(15) in 256kB chunks took 2302 us (1737 MB/s), compress ratio: 21.15 [ 2274.912948] lustre_kcompr_28176: compr zstdfast(15) in 512kB chunks took 2417 us (1654 MB/s), compress ratio: 22.80 [ 2274.921866] lustre_kcompr_28176: compr zstdfast(15) in 1024kB chunks took 3020 us (1324 MB/s), compress ratio: 24.11 [ 2274.930830] lustre_kcompr_28176: compr zstdfast(15) in 2048kB chunks took 2599 us (1539 MB/s), compress ratio: 28.05 [ 2274.939318] lustre_kcompr_28176: compr zstdfast(15) in 4096kB chunks took 3556 us (1124 MB/s), compress ratio: 36.89 [ 2274.971104] lustre_kcompr_28176: decompr zstdfast(15) took 2984 us (36 MB/s) [ 2274.996793] lustre_kcompr_28176: test_comp_compress_decompress(zstdfast,15) ret 0 [ 2275.010864] lustre_kcompr_28176: acompr zstdfast(15) of 128kB chunks took 150 us (833 MB/s), compress ratio: 18.49 [ 2275.026407] lustre_kcompr_28176: adecompr zstdfast(15) took 133 us (50 MB/s) [ 2275.044933] lustre_kcompr_28176: test_acomp_compress_decompress(zstdfast,15) ret 0 [ 2275.053636] lustre_kcompr_28176: SUCCESS [ 2283.016106] lustre_kcompr_771: ***** [ 2283.022552] lustre_kcompr_771: (de)compression test on provided file /tmp/f84.sanity [ 2283.030771] lustre_kcompr_771: ***** [ 2283.123377] lustre_kcompr_771: compr lz4(1) in 64kB chunks took 50120 us (79 MB/s), compress ratio: 2.93 [ 2283.183065] lustre_kcompr_771: compr lz4(1) in 128kB chunks took 54293 us (73 MB/s), compress ratio: 3.04 [ 2283.251878] lustre_kcompr_771: compr lz4(1) in 256kB chunks took 58288 us (68 MB/s), compress ratio: 3.08 [ 2283.337878] lustre_kcompr_771: compr lz4(1) in 512kB chunks took 71188 us (56 MB/s), compress ratio: 3.10 [ 2283.429419] lustre_kcompr_771: compr lz4(1) in 1024kB chunks took 74307 us (53 MB/s), compress ratio: 3.11 [ 2283.509630] lustre_kcompr_771: compr lz4(1) in 2048kB chunks took 64788 us (61 MB/s), compress ratio: 3.11 [ 2283.566436] lustre_kcompr_771: compr lz4(1) in 4096kB chunks took 45677 us (87 MB/s), compress ratio: 3.12 [ 2283.588820] lustre_kcompr_771: decompr lz4(1) took 7159 us (179 MB/s) [ 2283.595045] lustre_kcompr_771: test_comp_compress_decompress(lz4,1) ret 0 [ 2283.615098] lustre_kcompr_771: acompr lz4(1) of 128kB chunks took 671 us (186 MB/s), compress ratio: 2.68 [ 2283.627177] lustre_kcompr_771: adecompr lz4(1) took 340 us (137 MB/s) [ 2283.641242] lustre_kcompr_771: test_acomp_compress_decompress(lz4,1) ret 0 [ 2283.738417] lustre_kcompr_771: compr lz4(4) in 64kB chunks took 58307 us (68 MB/s), compress ratio: 2.67 [ 2283.796516] lustre_kcompr_771: compr lz4(4) in 128kB chunks took 45734 us (87 MB/s), compress ratio: 2.63 [ 2283.851360] lustre_kcompr_771: compr lz4(4) in 256kB chunks took 43846 us (91 MB/s), compress ratio: 2.68 [ 2283.911387] lustre_kcompr_771: compr lz4(4) in 512kB chunks took 41629 us (96 MB/s), compress ratio: 2.71 [ 2283.954454] lustre_kcompr_771: compr lz4(4) in 1024kB chunks took 36073 us (110 MB/s), compress ratio: 2.72 [ 2284.010337] lustre_kcompr_771: compr lz4(4) in 2048kB chunks took 36560 us (109 MB/s), compress ratio: 2.72 [ 2284.065312] lustre_kcompr_771: compr lz4(4) in 4096kB chunks took 43585 us (91 MB/s), compress ratio: 2.73 [ 2284.092277] lustre_kcompr_771: decompr lz4(4) took 7410 us (197 MB/s) [ 2284.102133] lustre_kcompr_771: test_comp_compress_decompress(lz4,4) ret 0 [ 2284.118089] lustre_kcompr_771: acompr lz4(4) of 128kB chunks took 1462 us (85 MB/s), compress ratio: 2.30 [ 2284.127391] lustre_kcompr_771: adecompr lz4(4) took 382 us (141 MB/s) [ 2284.160565] lustre_kcompr_771: test_acomp_compress_decompress(lz4,4) ret 0 [ 2284.208671] lustre_kcompr_771: compr lz4(9) in 64kB chunks took 25962 us (154 MB/s), compress ratio: 2.30 [ 2284.238803] lustre_kcompr_771: compr lz4(9) in 128kB chunks took 22952 us (174 MB/s), compress ratio: 2.15 [ 2284.268552] lustre_kcompr_771: compr lz4(9) in 256kB chunks took 24137 us (165 MB/s), compress ratio: 2.20 [ 2284.331900] lustre_kcompr_771: compr lz4(9) in 512kB chunks took 60823 us (65 MB/s), compress ratio: 2.23 [ 2284.389105] lustre_kcompr_771: compr lz4(9) in 1024kB chunks took 48542 us (82 MB/s), compress ratio: 2.25 [ 2284.480253] lustre_kcompr_771: compr lz4(9) in 2048kB chunks took 66077 us (60 MB/s), compress ratio: 2.25 [ 2284.528713] lustre_kcompr_771: compr lz4(9) in 4096kB chunks took 37356 us (107 MB/s), compress ratio: 2.26 [ 2284.562840] lustre_kcompr_771: decompr lz4(9) took 9032 us (195 MB/s) [ 2284.567822] lustre_kcompr_771: test_comp_compress_decompress(lz4,9) ret 0 [ 2284.574348] lustre_kcompr_771: acompr lz4(9) of 128kB chunks took 659 us (189 MB/s), compress ratio: 1.87 [ 2284.580670] lustre_kcompr_771: adecompr lz4(9) took 356 us (187 MB/s) [ 2284.585733] lustre_kcompr_771: test_acomp_compress_decompress(lz4,9) ret 0 [ 2284.638471] lustre_kcompr_771: compr lz4(15) in 64kB chunks took 32236 us (124 MB/s), compress ratio: 1.63 [ 2284.713817] lustre_kcompr_771: compr lz4(15) in 128kB chunks took 52630 us (76 MB/s), compress ratio: 1.52 [ 2284.759871] lustre_kcompr_771: compr lz4(15) in 256kB chunks took 26479 us (151 MB/s), compress ratio: 1.56 [ 2284.804182] lustre_kcompr_771: compr lz4(15) in 512kB chunks took 35345 us (113 MB/s), compress ratio: 1.58 [ 2284.858483] lustre_kcompr_771: compr lz4(15) in 1024kB chunks took 29303 us (136 MB/s), compress ratio: 1.60 [ 2284.891554] lustre_kcompr_771: compr lz4(15) in 2048kB chunks took 22477 us (177 MB/s), compress ratio: 1.60 [ 2284.931473] lustre_kcompr_771: compr lz4(15) in 4096kB chunks took 26178 us (152 MB/s), compress ratio: 1.60 [ 2284.960229] lustre_kcompr_771: decompr lz4(15) took 8414 us (295 MB/s) [ 2284.973514] lustre_kcompr_771: test_comp_compress_decompress(lz4,15) ret 0 [ 2284.988455] lustre_kcompr_771: acompr lz4(15) of 128kB chunks took 668 us (187 MB/s), compress ratio: 1.33 [ 2284.998128] lustre_kcompr_771: adecompr lz4(15) took 362 us (259 MB/s) [ 2285.020062] lustre_kcompr_771: test_acomp_compress_decompress(lz4,15) ret 0 [ 2285.328203] lustre_kcompr_771: compr lz4hc(1) in 64kB chunks took 251228 us (15 MB/s), compress ratio: 3.58 [ 2285.587826] lustre_kcompr_771: compr lz4hc(1) in 128kB chunks took 242440 us (16 MB/s), compress ratio: 3.77 [ 2285.981267] lustre_kcompr_771: compr lz4hc(1) in 256kB chunks took 386372 us (10 MB/s), compress ratio: 3.88 [ 2286.272150] lustre_kcompr_771: compr lz4hc(1) in 512kB chunks took 282567 us (14 MB/s), compress ratio: 3.93 [ 2286.562631] lustre_kcompr_771: compr lz4hc(1) in 1024kB chunks took 284782 us (14 MB/s), compress ratio: 3.96 [ 2286.921862] lustre_kcompr_771: compr lz4hc(1) in 2048kB chunks took 345468 us (11 MB/s), compress ratio: 3.97 [ 2287.268179] lustre_kcompr_771: compr lz4hc(1) in 4096kB chunks took 337829 us (11 MB/s), compress ratio: 3.98 [ 2287.316412] lustre_kcompr_771: decompr lz4hc(1) took 24316 us (41 MB/s) [ 2287.324342] lustre_kcompr_771: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2287.348244] lustre_kcompr_771: acompr lz4hc(1) of 128kB chunks took 7387 us (16 MB/s), compress ratio: 3.27 [ 2287.356394] lustre_kcompr_771: adecompr lz4hc(1) took 187 us (204 MB/s) [ 2287.371541] lustre_kcompr_771: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2287.782751] lustre_kcompr_771: compr lz4hc(3) in 64kB chunks took 383133 us (10 MB/s), compress ratio: 3.68 [ 2288.072161] lustre_kcompr_771: compr lz4hc(3) in 128kB chunks took 281876 us (14 MB/s), compress ratio: 3.91 [ 2288.298870] lustre_kcompr_771: compr lz4hc(3) in 256kB chunks took 220180 us (18 MB/s), compress ratio: 4.04 [ 2288.756863] lustre_kcompr_771: compr lz4hc(3) in 512kB chunks took 445891 us (8 MB/s), compress ratio: 4.10 [ 2289.111162] lustre_kcompr_771: compr lz4hc(3) in 1024kB chunks took 344839 us (11 MB/s), compress ratio: 4.13 [ 2289.377934] lustre_kcompr_771: compr lz4hc(3) in 2048kB chunks took 260577 us (15 MB/s), compress ratio: 4.15 [ 2289.713763] lustre_kcompr_771: compr lz4hc(3) in 4096kB chunks took 326568 us (12 MB/s), compress ratio: 4.16 [ 2289.730556] lustre_kcompr_771: decompr lz4hc(3) took 6320 us (152 MB/s) [ 2289.734892] lustre_kcompr_771: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2289.757715] lustre_kcompr_771: acompr lz4hc(3) of 128kB chunks took 13513 us (9 MB/s), compress ratio: 3.38 [ 2289.764921] lustre_kcompr_771: adecompr lz4hc(3) took 264 us (139 MB/s) [ 2289.777149] lustre_kcompr_771: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2290.329738] lustre_kcompr_771: compr lz4hc(8) in 64kB chunks took 532084 us (7 MB/s), compress ratio: 3.72 [ 2290.813746] lustre_kcompr_771: compr lz4hc(8) in 128kB chunks took 472809 us (8 MB/s), compress ratio: 3.96 [ 2291.530466] lustre_kcompr_771: compr lz4hc(8) in 256kB chunks took 706910 us (5 MB/s), compress ratio: 4.10 [ 2292.318100] lustre_kcompr_771: compr lz4hc(8) in 512kB chunks took 775377 us (5 MB/s), compress ratio: 4.17 [ 2292.684099] lustre_kcompr_771: compr lz4hc(8) in 1024kB chunks took 357379 us (11 MB/s), compress ratio: 4.21 [ 2293.381237] lustre_kcompr_771: compr lz4hc(8) in 2048kB chunks took 689368 us (5 MB/s), compress ratio: 4.22 [ 2294.087667] lustre_kcompr_771: compr lz4hc(8) in 4096kB chunks took 692215 us (5 MB/s), compress ratio: 4.23 [ 2294.109894] lustre_kcompr_771: decompr lz4hc(8) took 6754 us (139 MB/s) [ 2294.115622] lustre_kcompr_771: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2294.139498] lustre_kcompr_771: acompr lz4hc(8) of 128kB chunks took 15303 us (8 MB/s), compress ratio: 3.42 [ 2294.146883] lustre_kcompr_771: adecompr lz4hc(8) took 260 us (140 MB/s) [ 2294.154643] lustre_kcompr_771: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2294.461729] lustre_kcompr_771: compr lz4hc(15) in 64kB chunks took 291781 us (13 MB/s), compress ratio: 3.72 [ 2294.858901] lustre_kcompr_771: compr lz4hc(15) in 128kB chunks took 392900 us (10 MB/s), compress ratio: 3.96 [ 2295.547722] lustre_kcompr_771: compr lz4hc(15) in 256kB chunks took 681177 us (5 MB/s), compress ratio: 4.10 [ 2295.949404] lustre_kcompr_771: compr lz4hc(15) in 512kB chunks took 397925 us (10 MB/s), compress ratio: 4.17 [ 2296.321793] lustre_kcompr_771: compr lz4hc(15) in 1024kB chunks took 361725 us (11 MB/s), compress ratio: 4.21 [ 2296.849576] lustre_kcompr_771: compr lz4hc(15) in 2048kB chunks took 523457 us (7 MB/s), compress ratio: 4.22 [ 2297.854504] lustre_kcompr_771: compr lz4hc(15) in 4096kB chunks took 995680 us (4 MB/s), compress ratio: 4.23 [ 2297.885907] lustre_kcompr_771: decompr lz4hc(15) took 12536 us (75 MB/s) [ 2297.891563] lustre_kcompr_771: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2297.906988] lustre_kcompr_771: acompr lz4hc(15) of 128kB chunks took 11096 us (11 MB/s), compress ratio: 3.42 [ 2297.915285] lustre_kcompr_771: adecompr lz4hc(15) took 675 us (53 MB/s) [ 2297.924079] lustre_kcompr_771: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2297.980790] lustre_kcompr_771: compr lzo(-1) in 64kB chunks took 48803 us (81 MB/s), compress ratio: 2.90 [ 2298.048258] lustre_kcompr_771: compr lzo(-1) in 128kB chunks took 56730 us (70 MB/s), compress ratio: 2.95 [ 2298.103385] lustre_kcompr_771: compr lzo(-1) in 256kB chunks took 39946 us (100 MB/s), compress ratio: 2.96 [ 2298.168654] lustre_kcompr_771: compr lzo(-1) in 512kB chunks took 54992 us (72 MB/s), compress ratio: 2.98 [ 2298.229515] lustre_kcompr_771: compr lzo(-1) in 1024kB chunks took 52345 us (76 MB/s), compress ratio: 2.97 [ 2298.280621] lustre_kcompr_771: compr lzo(-1) in 2048kB chunks took 38080 us (105 MB/s), compress ratio: 2.97 [ 2298.308556] lustre_kcompr_771: compr lzo(-1) in 4096kB chunks took 23009 us (173 MB/s), compress ratio: 2.96 [ 2298.354908] lustre_kcompr_771: decompr lzo(-1) took 25215 us (53 MB/s) [ 2298.362664] lustre_kcompr_771: test_comp_compress_decompress(lzo,-1) ret 0 [ 2298.379191] lustre_kcompr_771: acompr lzo(-1) of 128kB chunks took 4597 us (27 MB/s), compress ratio: 2.62 [ 2298.389500] lustre_kcompr_771: adecompr lzo(-1) took 973 us (49 MB/s) [ 2298.401286] lustre_kcompr_771: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2299.155105] lustre_kcompr_771: compr deflate(1) in 64kB chunks took 730599 us (5 MB/s), compress ratio: 3.51 [ 2299.697812] lustre_kcompr_771: compr deflate(1) in 128kB chunks took 539461 us (7 MB/s), compress ratio: 3.53 [ 2300.197912] lustre_kcompr_771: compr deflate(1) in 256kB chunks took 490665 us (8 MB/s), compress ratio: 3.53 [ 2300.607478] lustre_kcompr_771: compr deflate(1) in 512kB chunks took 404995 us (9 MB/s), compress ratio: 3.54 [ 2301.027730] lustre_kcompr_771: compr deflate(1) in 1024kB chunks took 414072 us (9 MB/s), compress ratio: 3.54 [ 2302.047032] lustre_kcompr_771: compr deflate(1) in 2048kB chunks took 995266 us (4 MB/s), compress ratio: 3.54 [ 2303.208727] lustre_kcompr_771: compr deflate(1) in 4096kB chunks took 1147307 us (3 MB/s), compress ratio: 3.54 [ 2303.286757] lustre_kcompr_771: decompr deflate(1) took 61868 us (18 MB/s) [ 2303.311058] lustre_kcompr_771: test_comp_compress_decompress(deflate,1) ret 0 [ 2303.346511] lustre_kcompr_771: acompr deflate(1) of 128kB chunks took 22791 us (5 MB/s), compress ratio: 3.09 [ 2303.357592] lustre_kcompr_771: adecompr deflate(1) took 1299 us (31 MB/s) [ 2303.418162] lustre_kcompr_771: test_acomp_compress_decompress(deflate,1) ret 0 [ 2304.337639] lustre_kcompr_771: compr deflate(6) in 64kB chunks took 899898 us (4 MB/s), compress ratio: 3.51 [ 2305.452167] lustre_kcompr_771: compr deflate(6) in 128kB chunks took 1101209 us (3 MB/s), compress ratio: 3.53 [ 2306.583828] lustre_kcompr_771: compr deflate(6) in 256kB chunks took 1119715 us (3 MB/s), compress ratio: 3.53 [ 2307.695497] lustre_kcompr_771: compr deflate(6) in 512kB chunks took 1091081 us (3 MB/s), compress ratio: 3.54 [ 2308.908996] lustre_kcompr_771: compr deflate(6) in 1024kB chunks took 1199721 us (3 MB/s), compress ratio: 3.54 [ 2310.019823] lustre_kcompr_771: compr deflate(6) in 2048kB chunks took 1100807 us (3 MB/s), compress ratio: 3.54 [ 2311.006909] lustre_kcompr_771: compr deflate(6) in 4096kB chunks took 976567 us (4 MB/s), compress ratio: 3.54 [ 2311.134949] lustre_kcompr_771: decompr deflate(6) took 90139 us (12 MB/s) [ 2311.148412] lustre_kcompr_771: test_comp_compress_decompress(deflate,6) ret 0 [ 2311.179743] lustre_kcompr_771: acompr deflate(6) of 128kB chunks took 25777 us (4 MB/s), compress ratio: 3.09 [ 2311.194210] lustre_kcompr_771: adecompr deflate(6) took 2769 us (14 MB/s) [ 2311.224352] lustre_kcompr_771: test_acomp_compress_decompress(deflate,6) ret 0 [ 2311.914675] lustre_kcompr_771: compr deflate(9) in 64kB chunks took 680114 us (5 MB/s), compress ratio: 3.51 [ 2312.639529] lustre_kcompr_771: compr deflate(9) in 128kB chunks took 714676 us (5 MB/s), compress ratio: 3.53 [ 2313.649427] lustre_kcompr_771: compr deflate(9) in 256kB chunks took 1001470 us (3 MB/s), compress ratio: 3.53 [ 2314.307709] lustre_kcompr_771: compr deflate(9) in 512kB chunks took 648666 us (6 MB/s), compress ratio: 3.54 [ 2314.917449] lustre_kcompr_771: compr deflate(9) in 1024kB chunks took 604749 us (6 MB/s), compress ratio: 3.54 [ 2315.833607] lustre_kcompr_771: compr deflate(9) in 2048kB chunks took 903207 us (4 MB/s), compress ratio: 3.54 [ 2316.338204] lustre_kcompr_771: compr deflate(9) in 4096kB chunks took 496410 us (8 MB/s), compress ratio: 3.54 [ 2316.380060] lustre_kcompr_771: decompr deflate(9) took 32309 us (34 MB/s) [ 2316.384661] lustre_kcompr_771: test_comp_compress_decompress(deflate,9) ret 0 [ 2316.402187] lustre_kcompr_771: acompr deflate(9) of 128kB chunks took 13032 us (9 MB/s), compress ratio: 3.09 [ 2316.408906] lustre_kcompr_771: adecompr deflate(9) took 1518 us (26 MB/s) [ 2316.414364] lustre_kcompr_771: test_acomp_compress_decompress(deflate,9) ret 0 [ 2316.513440] lustre_kcompr_771: compr zstd(0) in 64kB chunks took 87642 us (45 MB/s), compress ratio: 4.28 [ 2316.636661] lustre_kcompr_771: compr zstd(0) in 128kB chunks took 105103 us (38 MB/s), compress ratio: 4.46 [ 2316.861891] lustre_kcompr_771: compr zstd(0) in 256kB chunks took 218518 us (18 MB/s), compress ratio: 4.61 [ 2317.155901] lustre_kcompr_771: compr zstd(0) in 512kB chunks took 264629 us (15 MB/s), compress ratio: 4.72 [ 2317.283442] lustre_kcompr_771: compr zstd(0) in 1024kB chunks took 121463 us (32 MB/s), compress ratio: 4.80 [ 2317.545640] lustre_kcompr_771: compr zstd(0) in 2048kB chunks took 258119 us (15 MB/s), compress ratio: 4.85 [ 2317.802402] lustre_kcompr_771: compr zstd(0) in 4096kB chunks took 241906 us (16 MB/s), compress ratio: 4.88 [ 2317.898218] lustre_kcompr_771: decompr zstd(0) took 80369 us (10 MB/s) [ 2317.907923] lustre_kcompr_771: test_comp_compress_decompress(zstd,0) ret 0 [ 2317.919909] lustre_kcompr_771: acompr zstd(0) of 128kB chunks took 2758 us (45 MB/s), compress ratio: 3.98 [ 2317.927763] lustre_kcompr_771: adecompr zstd(0) took 1676 us (18 MB/s) [ 2317.943541] lustre_kcompr_771: test_acomp_compress_decompress(zstd,0) ret 0 [ 2318.020211] lustre_kcompr_771: compr zstd(1) in 64kB chunks took 60826 us (65 MB/s), compress ratio: 4.06 [ 2318.087994] lustre_kcompr_771: compr zstd(1) in 128kB chunks took 62297 us (64 MB/s), compress ratio: 4.20 [ 2318.157893] lustre_kcompr_771: compr zstd(1) in 256kB chunks took 51834 us (77 MB/s), compress ratio: 4.34 [ 2318.240078] lustre_kcompr_771: compr zstd(1) in 512kB chunks took 76848 us (52 MB/s), compress ratio: 4.34 [ 2318.295288] lustre_kcompr_771: compr zstd(1) in 1024kB chunks took 49208 us (81 MB/s), compress ratio: 4.37 [ 2318.366879] lustre_kcompr_771: compr zstd(1) in 2048kB chunks took 66467 us (60 MB/s), compress ratio: 4.39 [ 2318.420967] lustre_kcompr_771: compr zstd(1) in 4096kB chunks took 50021 us (79 MB/s), compress ratio: 4.40 [ 2318.448563] lustre_kcompr_771: decompr zstd(1) took 15059 us (60 MB/s) [ 2318.453925] lustre_kcompr_771: test_comp_compress_decompress(zstd,1) ret 0 [ 2318.458924] lustre_kcompr_771: acompr zstd(1) of 128kB chunks took 1509 us (82 MB/s), compress ratio: 3.73 [ 2318.463544] lustre_kcompr_771: adecompr zstd(1) took 700 us (47 MB/s) [ 2318.468471] lustre_kcompr_771: test_acomp_compress_decompress(zstd,1) ret 0 [ 2320.589350] lustre_kcompr_771: compr zstd(10) in 64kB chunks took 2112811 us (1 MB/s), compress ratio: 4.80 [ 2323.077403] lustre_kcompr_771: compr zstd(10) in 128kB chunks took 2461181 us (1 MB/s), compress ratio: 5.09 [ 2324.468656] lustre_kcompr_771: compr zstd(10) in 256kB chunks took 1383184 us (2 MB/s), compress ratio: 5.34 [ 2326.507495] lustre_kcompr_771: compr zstd(10) in 512kB chunks took 2032449 us (1 MB/s), compress ratio: 5.45 [ 2327.642790] lustre_kcompr_771: compr zstd(10) in 1024kB chunks took 1125573 us (3 MB/s), compress ratio: 5.62 [ 2329.004989] lustre_kcompr_771: compr zstd(10) in 2048kB chunks took 1358122 us (2 MB/s), compress ratio: 5.76 [ 2331.491156] lustre_kcompr_771: compr zstd(10) in 4096kB chunks took 2472487 us (1 MB/s), compress ratio: 5.89 [ 2331.550950] lustre_kcompr_771: decompr zstd(10) took 46402 us (14 MB/s) [ 2331.558533] lustre_kcompr_771: test_comp_compress_decompress(zstd,10) ret 0 [ 2331.626690] lustre_kcompr_771: acompr zstd(10) of 128kB chunks took 63178 us (1 MB/s), compress ratio: 4.46 [ 2331.631514] lustre_kcompr_771: adecompr zstd(10) took 568 us (49 MB/s) [ 2331.646821] lustre_kcompr_771: test_acomp_compress_decompress(zstd,10) ret 0 [ 2350.793680] lustre_kcompr_771: compr zstd(15) in 64kB chunks took 19129002 us (0 MB/s), compress ratio: 4.96 [ 2369.710196] lustre_kcompr_771: compr zstd(15) in 128kB chunks took 18913482 us (0 MB/s), compress ratio: 5.28 [ 2380.055655] lustre_kcompr_771: compr zstd(15) in 256kB chunks took 10341098 us (0 MB/s), compress ratio: 5.57 [ 2390.067815] lustre_kcompr_771: compr zstd(15) in 512kB chunks took 10007867 us (0 MB/s), compress ratio: 5.83 [ 2400.147177] lustre_kcompr_771: compr zstd(15) in 1024kB chunks took 10068764 us (0 MB/s), compress ratio: 6.06 [ 2412.103733] lustre_kcompr_771: compr zstd(15) in 2048kB chunks took 11947404 us (0 MB/s), compress ratio: 6.26 [ 2433.631723] lustre_kcompr_771: compr zstd(15) in 4096kB chunks took 21513038 us (0 MB/s), compress ratio: 6.46 [ 2433.751933] lustre_kcompr_771: decompr zstd(15) took 93245 us (6 MB/s) [ 2433.763962] lustre_kcompr_771: test_comp_compress_decompress(zstd,15) ret 0 [ 2434.279639] lustre_kcompr_771: acompr zstd(15) of 128kB chunks took 508889 us (0 MB/s), compress ratio: 4.64 [ 2434.288319] lustre_kcompr_771: adecompr zstd(15) took 652 us (41 MB/s) [ 2434.354273] lustre_kcompr_771: test_acomp_compress_decompress(zstd,15) ret 0 [ 2434.472818] lustre_kcompr_771: compr zstdfast(1) in 64kB chunks took 100709 us (39 MB/s), compress ratio: 3.49 [ 2434.548609] lustre_kcompr_771: compr zstdfast(1) in 128kB chunks took 57048 us (70 MB/s), compress ratio: 3.62 [ 2434.594960] lustre_kcompr_771: compr zstdfast(1) in 256kB chunks took 39272 us (101 MB/s), compress ratio: 3.84 [ 2434.624598] lustre_kcompr_771: compr zstdfast(1) in 512kB chunks took 27004 us (148 MB/s), compress ratio: 3.73 [ 2434.659206] lustre_kcompr_771: compr zstdfast(1) in 1024kB chunks took 32134 us (124 MB/s), compress ratio: 3.76 [ 2434.702358] lustre_kcompr_771: compr zstdfast(1) in 2048kB chunks took 39909 us (100 MB/s), compress ratio: 3.77 [ 2434.742903] lustre_kcompr_771: compr zstdfast(1) in 4096kB chunks took 37397 us (106 MB/s), compress ratio: 3.78 [ 2434.767945] lustre_kcompr_771: decompr zstdfast(1) took 13998 us (75 MB/s) [ 2434.773270] lustre_kcompr_771: test_comp_compress_decompress(zstdfast,1) ret 0 [ 2434.779436] lustre_kcompr_771: acompr zstdfast(1) of 128kB chunks took 1612 us (77 MB/s), compress ratio: 3.19 [ 2434.785599] lustre_kcompr_771: adecompr zstdfast(1) took 798 us (49 MB/s) [ 2434.791318] lustre_kcompr_771: test_acomp_compress_decompress(zstdfast,1) ret 0 [ 2434.842492] lustre_kcompr_771: compr zstdfast(5) in 64kB chunks took 38784 us (103 MB/s), compress ratio: 2.81 [ 2434.906945] lustre_kcompr_771: compr zstdfast(5) in 128kB chunks took 60182 us (66 MB/s), compress ratio: 2.93 [ 2434.940590] lustre_kcompr_771: compr zstdfast(5) in 256kB chunks took 30951 us (129 MB/s), compress ratio: 3.16 [ 2434.974029] lustre_kcompr_771: compr zstdfast(5) in 512kB chunks took 29704 us (134 MB/s), compress ratio: 3.04 [ 2435.032854] lustre_kcompr_771: compr zstdfast(5) in 1024kB chunks took 54269 us (73 MB/s), compress ratio: 3.07 [ 2435.090484] lustre_kcompr_771: compr zstdfast(5) in 2048kB chunks took 52043 us (76 MB/s), compress ratio: 3.08 [ 2435.133383] lustre_kcompr_771: compr zstdfast(5) in 4096kB chunks took 38347 us (104 MB/s), compress ratio: 3.09 [ 2435.163824] lustre_kcompr_771: decompr zstdfast(5) took 15094 us (85 MB/s) [ 2435.184578] lustre_kcompr_771: test_comp_compress_decompress(zstdfast,5) ret 0 [ 2435.198157] lustre_kcompr_771: acompr zstdfast(5) of 128kB chunks took 4610 us (27 MB/s), compress ratio: 2.56 [ 2435.207150] lustre_kcompr_771: adecompr zstdfast(5) took 2022 us (24 MB/s) [ 2435.232380] lustre_kcompr_771: test_acomp_compress_decompress(zstdfast,5) ret 0 [ 2435.299775] lustre_kcompr_771: compr zstdfast(12) in 64kB chunks took 48857 us (81 MB/s), compress ratio: 1.43 [ 2435.362575] lustre_kcompr_771: compr zstdfast(12) in 128kB chunks took 44525 us (89 MB/s), compress ratio: 1.50 [ 2435.424064] lustre_kcompr_771: compr zstdfast(12) in 256kB chunks took 52722 us (75 MB/s), compress ratio: 1.62 [ 2435.492604] lustre_kcompr_771: compr zstdfast(12) in 512kB chunks took 55264 us (72 MB/s), compress ratio: 1.55 [ 2435.645706] lustre_kcompr_771: compr zstdfast(12) in 1024kB chunks took 143843 us (27 MB/s), compress ratio: 1.58 [ 2435.795908] lustre_kcompr_771: compr zstdfast(12) in 2048kB chunks took 127101 us (31 MB/s), compress ratio: 1.60 [ 2435.887082] lustre_kcompr_771: compr zstdfast(12) in 4096kB chunks took 56998 us (70 MB/s), compress ratio: 1.60 [ 2435.955727] lustre_kcompr_771: decompr zstdfast(12) took 48737 us (51 MB/s) [ 2435.964472] lustre_kcompr_771: test_comp_compress_decompress(zstdfast,12) ret 0 [ 2435.978128] lustre_kcompr_771: acompr zstdfast(12) of 128kB chunks took 1136 us (110 MB/s), compress ratio: 1.37 [ 2435.989923] lustre_kcompr_771: adecompr zstdfast(12) took 2795 us (32 MB/s) [ 2436.074757] lustre_kcompr_771: test_acomp_compress_decompress(zstdfast,12) ret 0 [ 2436.151789] lustre_kcompr_771: compr zstdfast(15) in 64kB chunks took 34409 us (116 MB/s), compress ratio: 1.12 [ 2436.217550] lustre_kcompr_771: compr zstdfast(15) in 128kB chunks took 44559 us (89 MB/s), compress ratio: 1.16 [ 2436.292792] lustre_kcompr_771: compr zstdfast(15) in 256kB chunks took 69040 us (57 MB/s), compress ratio: 1.22 [ 2436.400430] lustre_kcompr_771: compr zstdfast(15) in 512kB chunks took 87136 us (45 MB/s), compress ratio: 1.20 [ 2436.486519] lustre_kcompr_771: compr zstdfast(15) in 1024kB chunks took 66906 us (59 MB/s), compress ratio: 1.22 [ 2436.538555] lustre_kcompr_771: compr zstdfast(15) in 2048kB chunks took 31484 us (127 MB/s), compress ratio: 1.23 [ 2436.596577] lustre_kcompr_771: compr zstdfast(15) in 4096kB chunks took 51230 us (78 MB/s), compress ratio: 1.23 [ 2436.624123] lustre_kcompr_771: decompr zstdfast(15) took 10753 us (301 MB/s) [ 2436.633593] lustre_kcompr_771: test_comp_compress_decompress(zstdfast,15) ret 0 [ 2436.638613] lustre_kcompr_771: acompr zstdfast(15) of 128kB chunks took 612 us (204 MB/s), compress ratio: 1.08 [ 2436.648683] lustre_kcompr_771: adecompr zstdfast(15) took 270 us (427 MB/s) [ 2436.657615] lustre_kcompr_771: test_acomp_compress_decompress(zstdfast,15) ret 0 [ 2436.662443] lustre_kcompr_771: SUCCESS [ 2443.081070] lustre_kcompr_31161: ***** [ 2443.095316] lustre_kcompr_31161: (de)compression test on provided file /tmp/f84.sanity [ 2443.103511] lustre_kcompr_31161: ***** [ 2443.133588] lustre_kcompr_31161: compr lz4(1) in 64kB chunks took 18114 us (220 MB/s), compress ratio: 2.45 [ 2443.159502] lustre_kcompr_31161: compr lz4(1) in 128kB chunks took 20086 us (199 MB/s), compress ratio: 2.39 [ 2443.206651] lustre_kcompr_31161: compr lz4(1) in 256kB chunks took 42198 us (94 MB/s), compress ratio: 2.39 [ 2443.277920] lustre_kcompr_31161: compr lz4(1) in 512kB chunks took 49605 us (80 MB/s), compress ratio: 2.39 [ 2443.306793] lustre_kcompr_31161: compr lz4(1) in 1024kB chunks took 23338 us (171 MB/s), compress ratio: 2.39 [ 2443.368525] lustre_kcompr_31161: compr lz4(1) in 2048kB chunks took 47185 us (84 MB/s), compress ratio: 2.39 [ 2443.442482] lustre_kcompr_31161: compr lz4(1) in 4096kB chunks took 60093 us (66 MB/s), compress ratio: 2.39 [ 2443.460484] lustre_kcompr_31161: decompr lz4(1) took 4403 us (379 MB/s) [ 2443.470932] lustre_kcompr_31161: test_comp_compress_decompress(lz4,1) ret 0 [ 2443.479394] lustre_kcompr_31161: acompr lz4(1) of 128kB chunks took 293 us (426 MB/s), compress ratio: 15.67 [ 2443.488573] lustre_kcompr_31161: adecompr lz4(1) took 189 us (42 MB/s) [ 2443.525808] lustre_kcompr_31161: test_acomp_compress_decompress(lz4,1) ret 0 [ 2443.568624] lustre_kcompr_31161: compr lz4(4) in 64kB chunks took 17280 us (231 MB/s), compress ratio: 2.36 [ 2443.593378] lustre_kcompr_31161: compr lz4(4) in 128kB chunks took 20939 us (191 MB/s), compress ratio: 2.35 [ 2443.617653] lustre_kcompr_31161: compr lz4(4) in 256kB chunks took 18191 us (219 MB/s), compress ratio: 2.35 [ 2443.647466] lustre_kcompr_31161: compr lz4(4) in 512kB chunks took 17828 us (224 MB/s), compress ratio: 2.35 [ 2443.674860] lustre_kcompr_31161: compr lz4(4) in 1024kB chunks took 14501 us (275 MB/s), compress ratio: 2.35 [ 2443.706375] lustre_kcompr_31161: compr lz4(4) in 2048kB chunks took 22623 us (176 MB/s), compress ratio: 2.35 [ 2443.751920] lustre_kcompr_31161: compr lz4(4) in 4096kB chunks took 41682 us (95 MB/s), compress ratio: 2.35 [ 2443.795118] lustre_kcompr_31161: decompr lz4(4) took 12509 us (135 MB/s) [ 2443.823099] lustre_kcompr_31161: test_comp_compress_decompress(lz4,4) ret 0 [ 2443.848891] lustre_kcompr_31161: acompr lz4(4) of 128kB chunks took 173 us (722 MB/s), compress ratio: 15.30 [ 2443.859316] lustre_kcompr_31161: adecompr lz4(4) took 199 us (41 MB/s) [ 2443.883934] lustre_kcompr_31161: test_acomp_compress_decompress(lz4,4) ret 0 [ 2443.928715] lustre_kcompr_31161: compr lz4(9) in 64kB chunks took 14289 us (279 MB/s), compress ratio: 2.32 [ 2443.956655] lustre_kcompr_31161: compr lz4(9) in 128kB chunks took 12515 us (319 MB/s), compress ratio: 2.31 [ 2443.988339] lustre_kcompr_31161: compr lz4(9) in 256kB chunks took 20517 us (194 MB/s), compress ratio: 2.31 [ 2444.017698] lustre_kcompr_31161: compr lz4(9) in 512kB chunks took 16947 us (236 MB/s), compress ratio: 2.31 [ 2444.045411] lustre_kcompr_31161: compr lz4(9) in 1024kB chunks took 16169 us (247 MB/s), compress ratio: 2.31 [ 2444.066762] lustre_kcompr_31161: compr lz4(9) in 2048kB chunks took 14019 us (285 MB/s), compress ratio: 2.32 [ 2444.088502] lustre_kcompr_31161: compr lz4(9) in 4096kB chunks took 13854 us (288 MB/s), compress ratio: 2.32 [ 2444.106802] lustre_kcompr_31161: decompr lz4(9) took 3221 us (535 MB/s) [ 2444.113965] lustre_kcompr_31161: test_comp_compress_decompress(lz4,9) ret 0 [ 2444.120440] lustre_kcompr_31161: acompr lz4(9) of 128kB chunks took 154 us (811 MB/s), compress ratio: 14.81 [ 2444.129632] lustre_kcompr_31161: adecompr lz4(9) took 157 us (53 MB/s) [ 2444.136155] lustre_kcompr_31161: test_acomp_compress_decompress(lz4,9) ret 0 [ 2444.155895] lustre_kcompr_31161: compr lz4(15) in 64kB chunks took 8268 us (483 MB/s), compress ratio: 2.23 [ 2444.164549] lustre_kcompr_31161: compr lz4(15) in 128kB chunks took 5404 us (740 MB/s), compress ratio: 2.23 [ 2444.178517] lustre_kcompr_31161: compr lz4(15) in 256kB chunks took 9016 us (443 MB/s), compress ratio: 2.23 [ 2444.187811] lustre_kcompr_31161: compr lz4(15) in 512kB chunks took 6507 us (614 MB/s), compress ratio: 2.23 [ 2444.198955] lustre_kcompr_31161: compr lz4(15) in 1024kB chunks took 7213 us (554 MB/s), compress ratio: 2.23 [ 2444.210326] lustre_kcompr_31161: compr lz4(15) in 2048kB chunks took 6607 us (605 MB/s), compress ratio: 2.23 [ 2444.222380] lustre_kcompr_31161: compr lz4(15) in 4096kB chunks took 7660 us (522 MB/s), compress ratio: 2.23 [ 2444.234412] lustre_kcompr_31161: decompr lz4(15) took 2719 us (657 MB/s) [ 2444.239703] lustre_kcompr_31161: test_comp_compress_decompress(lz4,15) ret 0 [ 2444.244553] lustre_kcompr_31161: acompr lz4(15) of 128kB chunks took 172 us (726 MB/s), compress ratio: 14.18 [ 2444.249724] lustre_kcompr_31161: adecompr lz4(15) took 112 us (78 MB/s) [ 2444.257579] lustre_kcompr_31161: test_acomp_compress_decompress(lz4,15) ret 0 [ 2444.382482] lustre_kcompr_31161: compr lz4hc(1) in 64kB chunks took 112807 us (35 MB/s), compress ratio: 2.54 [ 2444.610981] lustre_kcompr_31161: compr lz4hc(1) in 128kB chunks took 222616 us (17 MB/s), compress ratio: 2.61 [ 2444.779891] lustre_kcompr_31161: compr lz4hc(1) in 256kB chunks took 157129 us (25 MB/s), compress ratio: 2.64 [ 2444.930333] lustre_kcompr_31161: compr lz4hc(1) in 512kB chunks took 144841 us (27 MB/s), compress ratio: 2.66 [ 2445.236912] lustre_kcompr_31161: compr lz4hc(1) in 1024kB chunks took 301804 us (13 MB/s), compress ratio: 2.67 [ 2445.538128] lustre_kcompr_31161: compr lz4hc(1) in 2048kB chunks took 287986 us (13 MB/s), compress ratio: 2.67 [ 2445.732702] lustre_kcompr_31161: compr lz4hc(1) in 4096kB chunks took 186851 us (21 MB/s), compress ratio: 2.67 [ 2445.761913] lustre_kcompr_31161: decompr lz4hc(1) took 6308 us (236 MB/s) [ 2445.782359] lustre_kcompr_31161: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2445.793574] lustre_kcompr_31161: acompr lz4hc(1) of 128kB chunks took 1811 us (69 MB/s), compress ratio: 15.97 [ 2445.809176] lustre_kcompr_31161: adecompr lz4hc(1) took 221 us (35 MB/s) [ 2445.875505] lustre_kcompr_31161: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2446.032717] lustre_kcompr_31161: compr lz4hc(3) in 64kB chunks took 123071 us (32 MB/s), compress ratio: 2.57 [ 2446.155892] lustre_kcompr_31161: compr lz4hc(3) in 128kB chunks took 118608 us (33 MB/s), compress ratio: 2.64 [ 2446.315454] lustre_kcompr_31161: compr lz4hc(3) in 256kB chunks took 156056 us (25 MB/s), compress ratio: 2.68 [ 2446.473769] lustre_kcompr_31161: compr lz4hc(3) in 512kB chunks took 153067 us (26 MB/s), compress ratio: 2.69 [ 2446.639939] lustre_kcompr_31161: compr lz4hc(3) in 1024kB chunks took 160517 us (24 MB/s), compress ratio: 2.70 [ 2446.810630] lustre_kcompr_31161: compr lz4hc(3) in 2048kB chunks took 165778 us (24 MB/s), compress ratio: 2.71 [ 2446.980299] lustre_kcompr_31161: compr lz4hc(3) in 4096kB chunks took 164342 us (24 MB/s), compress ratio: 2.71 [ 2447.000431] lustre_kcompr_31161: decompr lz4hc(3) took 5736 us (256 MB/s) [ 2447.005062] lustre_kcompr_31161: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2447.011318] lustre_kcompr_31161: acompr lz4hc(3) of 128kB chunks took 1030 us (121 MB/s), compress ratio: 16.00 [ 2447.017732] lustre_kcompr_31161: adecompr lz4hc(3) took 153 us (51 MB/s) [ 2447.026902] lustre_kcompr_31161: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2447.475276] lustre_kcompr_31161: compr lz4hc(8) in 64kB chunks took 428377 us (9 MB/s), compress ratio: 2.60 [ 2448.048475] lustre_kcompr_31161: compr lz4hc(8) in 128kB chunks took 569352 us (7 MB/s), compress ratio: 2.66 [ 2448.440692] lustre_kcompr_31161: compr lz4hc(8) in 256kB chunks took 379753 us (10 MB/s), compress ratio: 2.70 [ 2448.954343] lustre_kcompr_31161: compr lz4hc(8) in 512kB chunks took 508470 us (7 MB/s), compress ratio: 2.71 [ 2449.470923] lustre_kcompr_31161: compr lz4hc(8) in 1024kB chunks took 510695 us (7 MB/s), compress ratio: 2.72 [ 2449.975642] lustre_kcompr_31161: compr lz4hc(8) in 2048kB chunks took 491177 us (8 MB/s), compress ratio: 2.73 [ 2451.058443] lustre_kcompr_31161: compr lz4hc(8) in 4096kB chunks took 1078028 us (3 MB/s), compress ratio: 2.73 [ 2451.083433] lustre_kcompr_31161: decompr lz4hc(8) took 7585 us (192 MB/s) [ 2451.089837] lustre_kcompr_31161: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2451.116255] lustre_kcompr_31161: acompr lz4hc(8) of 128kB chunks took 7646 us (16 MB/s), compress ratio: 16.17 [ 2451.122569] lustre_kcompr_31161: adecompr lz4hc(8) took 278 us (27 MB/s) [ 2451.130374] lustre_kcompr_31161: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2460.976343] lustre_kcompr_31161: compr lz4hc(15) in 64kB chunks took 9831810 us (0 MB/s), compress ratio: 2.61 [ 2472.968458] lustre_kcompr_31161: compr lz4hc(15) in 128kB chunks took 11985128 us (0 MB/s), compress ratio: 2.67 [ 2482.659100] lustre_kcompr_31161: compr lz4hc(15) in 256kB chunks took 9675695 us (0 MB/s), compress ratio: 2.71 [ 2496.716513] lustre_kcompr_31161: compr lz4hc(15) in 512kB chunks took 14047144 us (0 MB/s), compress ratio: 2.72 [ 2514.332917] lustre_kcompr_31161: compr lz4hc(15) in 1024kB chunks took 17610730 us (0 MB/s), compress ratio: 2.73 [ 2531.427515] lustre_kcompr_31161: compr lz4hc(15) in 2048kB chunks took 17077368 us (0 MB/s), compress ratio: 2.74 [ 2546.760370] lustre_kcompr_31161: compr lz4hc(15) in 4096kB chunks took 15320235 us (0 MB/s), compress ratio: 2.74 [ 2546.788997] lustre_kcompr_31161: decompr lz4hc(15) took 9022 us (161 MB/s) [ 2546.800874] lustre_kcompr_31161: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2546.834462] lustre_kcompr_31161: acompr lz4hc(15) of 128kB chunks took 21780 us (5 MB/s), compress ratio: 16.30 [ 2546.847045] lustre_kcompr_31161: adecompr lz4hc(15) took 196 us (39 MB/s) [ 2546.857645] lustre_kcompr_31161: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2546.882805] lustre_kcompr_31161: compr lzo(-1) in 64kB chunks took 20783 us (192 MB/s), compress ratio: 2.35 [ 2546.912278] lustre_kcompr_31161: compr lzo(-1) in 128kB chunks took 23322 us (171 MB/s), compress ratio: 2.35 [ 2546.940566] lustre_kcompr_31161: compr lzo(-1) in 256kB chunks took 23655 us (169 MB/s), compress ratio: 2.35 [ 2546.978120] lustre_kcompr_31161: compr lzo(-1) in 512kB chunks took 25719 us (155 MB/s), compress ratio: 2.36 [ 2547.005776] lustre_kcompr_31161: compr lzo(-1) in 1024kB chunks took 21994 us (181 MB/s), compress ratio: 2.36 [ 2547.049919] lustre_kcompr_31161: compr lzo(-1) in 2048kB chunks took 39239 us (101 MB/s), compress ratio: 2.36 [ 2547.077666] lustre_kcompr_31161: compr lzo(-1) in 4096kB chunks took 17893 us (223 MB/s), compress ratio: 2.36 [ 2547.108488] lustre_kcompr_31161: decompr lzo(-1) took 8822 us (192 MB/s) [ 2547.114371] lustre_kcompr_31161: test_comp_compress_decompress(lzo,-1) ret 0 [ 2547.119156] lustre_kcompr_31161: acompr lzo(-1) of 128kB chunks took 264 us (473 MB/s), compress ratio: 15.45 [ 2547.124295] lustre_kcompr_31161: adecompr lzo(-1) took 227 us (35 MB/s) [ 2547.128774] lustre_kcompr_31161: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2547.895568] lustre_kcompr_31161: compr deflate(1) in 64kB chunks took 756577 us (5 MB/s), compress ratio: 3.27 [ 2548.662212] lustre_kcompr_31161: compr deflate(1) in 128kB chunks took 748040 us (5 MB/s), compress ratio: 3.28 [ 2549.548187] lustre_kcompr_31161: compr deflate(1) in 256kB chunks took 880823 us (4 MB/s), compress ratio: 3.28 [ 2550.329538] lustre_kcompr_31161: compr deflate(1) in 512kB chunks took 775033 us (5 MB/s), compress ratio: 3.28 [ 2551.176022] lustre_kcompr_31161: compr deflate(1) in 1024kB chunks took 836295 us (4 MB/s), compress ratio: 3.28 [ 2551.923609] lustre_kcompr_31161: compr deflate(1) in 2048kB chunks took 737636 us (5 MB/s), compress ratio: 3.28 [ 2552.918286] lustre_kcompr_31161: compr deflate(1) in 4096kB chunks took 976412 us (4 MB/s), compress ratio: 3.28 [ 2553.038415] lustre_kcompr_31161: decompr deflate(1) took 97402 us (12 MB/s) [ 2553.054394] lustre_kcompr_31161: test_comp_compress_decompress(deflate,1) ret 0 [ 2553.084546] lustre_kcompr_31161: acompr deflate(1) of 128kB chunks took 18578 us (6 MB/s), compress ratio: 21.43 [ 2553.091490] lustre_kcompr_31161: adecompr deflate(1) took 363 us (16 MB/s) [ 2553.111557] lustre_kcompr_31161: test_acomp_compress_decompress(deflate,1) ret 0 [ 2553.776463] lustre_kcompr_31161: compr deflate(6) in 64kB chunks took 648076 us (6 MB/s), compress ratio: 3.27 [ 2554.469522] lustre_kcompr_31161: compr deflate(6) in 128kB chunks took 687654 us (5 MB/s), compress ratio: 3.28 [ 2555.165412] lustre_kcompr_31161: compr deflate(6) in 256kB chunks took 684272 us (5 MB/s), compress ratio: 3.28 [ 2556.047982] lustre_kcompr_31161: compr deflate(6) in 512kB chunks took 877188 us (4 MB/s), compress ratio: 3.28 [ 2556.644506] lustre_kcompr_31161: compr deflate(6) in 1024kB chunks took 585694 us (6 MB/s), compress ratio: 3.28 [ 2557.254343] lustre_kcompr_31161: compr deflate(6) in 2048kB chunks took 595646 us (6 MB/s), compress ratio: 3.28 [ 2557.826393] lustre_kcompr_31161: compr deflate(6) in 4096kB chunks took 566425 us (7 MB/s), compress ratio: 3.28 [ 2557.931879] lustre_kcompr_31161: decompr deflate(6) took 70007 us (17 MB/s) [ 2557.946852] lustre_kcompr_31161: test_comp_compress_decompress(deflate,6) ret 0 [ 2557.978236] lustre_kcompr_31161: acompr deflate(6) of 128kB chunks took 20267 us (6 MB/s), compress ratio: 21.43 [ 2557.991430] lustre_kcompr_31161: adecompr deflate(6) took 1681 us (3 MB/s) [ 2558.010261] lustre_kcompr_31161: test_acomp_compress_decompress(deflate,6) ret 0 [ 2558.877715] lustre_kcompr_31161: compr deflate(9) in 64kB chunks took 843843 us (4 MB/s), compress ratio: 3.27 [ 2559.488308] lustre_kcompr_31161: compr deflate(9) in 128kB chunks took 602528 us (6 MB/s), compress ratio: 3.28 [ 2560.270821] lustre_kcompr_31161: compr deflate(9) in 256kB chunks took 774565 us (5 MB/s), compress ratio: 3.28 [ 2560.829447] lustre_kcompr_31161: compr deflate(9) in 512kB chunks took 539881 us (7 MB/s), compress ratio: 3.28 [ 2561.436838] lustre_kcompr_31161: compr deflate(9) in 1024kB chunks took 602964 us (6 MB/s), compress ratio: 3.28 [ 2562.122771] lustre_kcompr_31161: compr deflate(9) in 2048kB chunks took 674158 us (5 MB/s), compress ratio: 3.28 [ 2562.580765] lustre_kcompr_31161: compr deflate(9) in 4096kB chunks took 451903 us (8 MB/s), compress ratio: 3.28 [ 2562.636566] lustre_kcompr_31161: decompr deflate(9) took 39633 us (30 MB/s) [ 2562.642855] lustre_kcompr_31161: test_comp_compress_decompress(deflate,9) ret 0 [ 2562.662380] lustre_kcompr_31161: acompr deflate(9) of 128kB chunks took 13637 us (9 MB/s), compress ratio: 21.43 [ 2562.668354] lustre_kcompr_31161: adecompr deflate(9) took 495 us (11 MB/s) [ 2562.675531] lustre_kcompr_31161: test_acomp_compress_decompress(deflate,9) ret 0 [ 2562.792208] lustre_kcompr_31161: compr zstd(0) in 64kB chunks took 103818 us (38 MB/s), compress ratio: 3.28 [ 2562.997221] lustre_kcompr_31161: compr zstd(0) in 128kB chunks took 193666 us (20 MB/s), compress ratio: 3.26 [ 2563.246197] lustre_kcompr_31161: compr zstd(0) in 256kB chunks took 237363 us (16 MB/s), compress ratio: 3.31 [ 2563.542257] lustre_kcompr_31161: compr zstd(0) in 512kB chunks took 289997 us (13 MB/s), compress ratio: 3.32 [ 2563.893385] lustre_kcompr_31161: compr zstd(0) in 1024kB chunks took 344221 us (11 MB/s), compress ratio: 3.32 [ 2564.067137] lustre_kcompr_31161: compr zstd(0) in 2048kB chunks took 167490 us (23 MB/s), compress ratio: 3.33 [ 2564.538774] lustre_kcompr_31161: compr zstd(0) in 4096kB chunks took 460477 us (8 MB/s), compress ratio: 3.33 [ 2564.576810] lustre_kcompr_31161: decompr zstd(0) took 19325 us (62 MB/s) [ 2564.582534] lustre_kcompr_31161: test_comp_compress_decompress(zstd,0) ret 0 [ 2564.586937] lustre_kcompr_31161: acompr zstd(0) of 128kB chunks took 440 us (284 MB/s), compress ratio: 22.64 [ 2564.591761] lustre_kcompr_31161: adecompr zstd(0) took 177 us (31 MB/s) [ 2564.597292] lustre_kcompr_31161: test_acomp_compress_decompress(zstd,0) ret 0 [ 2564.673339] lustre_kcompr_31161: compr zstd(1) in 64kB chunks took 64527 us (61 MB/s), compress ratio: 3.22 [ 2564.755984] lustre_kcompr_31161: compr zstd(1) in 128kB chunks took 63723 us (62 MB/s), compress ratio: 3.18 [ 2564.877810] lustre_kcompr_31161: compr zstd(1) in 256kB chunks took 114458 us (34 MB/s), compress ratio: 3.19 [ 2564.958532] lustre_kcompr_31161: compr zstd(1) in 512kB chunks took 64613 us (61 MB/s), compress ratio: 3.19 [ 2565.091812] lustre_kcompr_31161: compr zstd(1) in 1024kB chunks took 131179 us (30 MB/s), compress ratio: 3.19 [ 2565.198247] lustre_kcompr_31161: compr zstd(1) in 2048kB chunks took 95697 us (41 MB/s), compress ratio: 3.19 [ 2565.300472] lustre_kcompr_31161: compr zstd(1) in 4096kB chunks took 91668 us (43 MB/s), compress ratio: 3.19 [ 2565.373524] lustre_kcompr_31161: decompr zstd(1) took 47120 us (26 MB/s) [ 2565.408977] lustre_kcompr_31161: test_comp_compress_decompress(zstd,1) ret 0 [ 2565.419245] lustre_kcompr_31161: acompr zstd(1) of 128kB chunks took 326 us (383 MB/s), compress ratio: 22.79 [ 2565.430339] lustre_kcompr_31161: adecompr zstd(1) took 197 us (27 MB/s) [ 2565.470578] lustre_kcompr_31161: test_acomp_compress_decompress(zstd,1) ret 0 [ 2566.455486] lustre_kcompr_31161: compr zstd(10) in 64kB chunks took 950332 us (4 MB/s), compress ratio: 3.33 [ 2567.345098] lustre_kcompr_31161: compr zstd(10) in 128kB chunks took 882392 us (4 MB/s), compress ratio: 3.33 [ 2568.653851] lustre_kcompr_31161: compr zstd(10) in 256kB chunks took 1304236 us (3 MB/s), compress ratio: 3.37 [ 2569.660927] lustre_kcompr_31161: compr zstd(10) in 512kB chunks took 998488 us (4 MB/s), compress ratio: 3.40 [ 2570.279536] lustre_kcompr_31161: compr zstd(10) in 1024kB chunks took 610478 us (6 MB/s), compress ratio: 3.42 [ 2571.834201] lustre_kcompr_31161: compr zstd(10) in 2048kB chunks took 1550235 us (2 MB/s), compress ratio: 3.46 [ 2573.359026] lustre_kcompr_31161: compr zstd(10) in 4096kB chunks took 1509916 us (2 MB/s), compress ratio: 3.50 [ 2573.412182] lustre_kcompr_31161: decompr zstd(10) took 39013 us (29 MB/s) [ 2573.418395] lustre_kcompr_31161: test_comp_compress_decompress(zstd,10) ret 0 [ 2573.429139] lustre_kcompr_31161: acompr zstd(10) of 128kB chunks took 4238 us (29 MB/s), compress ratio: 22.78 [ 2573.435569] lustre_kcompr_31161: adecompr zstd(10) took 529 us (10 MB/s) [ 2573.442266] lustre_kcompr_31161: test_acomp_compress_decompress(zstd,10) ret 0 [ 2584.236390] lustre_kcompr_31161: compr zstd(15) in 64kB chunks took 10783966 us (0 MB/s), compress ratio: 3.36 [ 2592.172217] lustre_kcompr_31161: compr zstd(15) in 128kB chunks took 7906327 us (0 MB/s), compress ratio: 3.39 [ 2598.042969] lustre_kcompr_31161: compr zstd(15) in 256kB chunks took 5866682 us (0 MB/s), compress ratio: 3.40 [ 2603.858861] lustre_kcompr_31161: compr zstd(15) in 512kB chunks took 5807088 us (0 MB/s), compress ratio: 3.42 [ 2608.670895] lustre_kcompr_31161: compr zstd(15) in 1024kB chunks took 4802344 us (0 MB/s), compress ratio: 3.43 [ 2613.768505] lustre_kcompr_31161: compr zstd(15) in 2048kB chunks took 5094661 us (0 MB/s), compress ratio: 3.48 [ 2617.507775] lustre_kcompr_31161: compr zstd(15) in 4096kB chunks took 3735750 us (1 MB/s), compress ratio: 3.56 [ 2617.615167] lustre_kcompr_31161: decompr zstd(15) took 91079 us (12 MB/s) [ 2617.637331] lustre_kcompr_31161: test_comp_compress_decompress(zstd,15) ret 0 [ 2617.725131] lustre_kcompr_31161: acompr zstd(15) of 128kB chunks took 75842 us (1 MB/s), compress ratio: 23.92 [ 2617.733434] lustre_kcompr_31161: adecompr zstd(15) took 187 us (27 MB/s) [ 2617.741378] lustre_kcompr_31161: test_acomp_compress_decompress(zstd,15) ret 0 [ 2617.765485] lustre_kcompr_31161: compr zstdfast(1) in 64kB chunks took 14310 us (279 MB/s), compress ratio: 2.47 [ 2617.789587] lustre_kcompr_31161: compr zstdfast(1) in 128kB chunks took 20139 us (198 MB/s), compress ratio: 2.48 [ 2617.812788] lustre_kcompr_31161: compr zstdfast(1) in 256kB chunks took 17616 us (227 MB/s), compress ratio: 2.53 [ 2617.829823] lustre_kcompr_31161: compr zstdfast(1) in 512kB chunks took 13468 us (297 MB/s), compress ratio: 2.42 [ 2617.855244] lustre_kcompr_31161: compr zstdfast(1) in 1024kB chunks took 20138 us (198 MB/s), compress ratio: 2.42 [ 2617.878105] lustre_kcompr_31161: compr zstdfast(1) in 2048kB chunks took 17395 us (229 MB/s), compress ratio: 2.42 [ 2617.902242] lustre_kcompr_31161: compr zstdfast(1) in 4096kB chunks took 18159 us (220 MB/s), compress ratio: 2.42 [ 2617.917895] lustre_kcompr_31161: decompr zstdfast(1) took 4274 us (385 MB/s) [ 2617.923789] lustre_kcompr_31161: test_comp_compress_decompress(zstdfast,1) ret 0 [ 2617.932854] lustre_kcompr_31161: acompr zstdfast(1) of 128kB chunks took 232 us (538 MB/s), compress ratio: 17.28 [ 2617.940442] lustre_kcompr_31161: adecompr zstdfast(1) took 136 us (53 MB/s) [ 2617.956207] lustre_kcompr_31161: test_acomp_compress_decompress(zstdfast,1) ret 0 [ 2617.987836] lustre_kcompr_31161: compr zstdfast(5) in 64kB chunks took 18468 us (216 MB/s), compress ratio: 2.38 [ 2618.030658] lustre_kcompr_31161: compr zstdfast(5) in 128kB chunks took 30608 us (130 MB/s), compress ratio: 2.38 [ 2618.070604] lustre_kcompr_31161: compr zstdfast(5) in 256kB chunks took 33706 us (118 MB/s), compress ratio: 2.40 [ 2618.111992] lustre_kcompr_31161: compr zstdfast(5) in 512kB chunks took 29508 us (135 MB/s), compress ratio: 2.36 [ 2618.156358] lustre_kcompr_31161: compr zstdfast(5) in 1024kB chunks took 20500 us (195 MB/s), compress ratio: 2.36 [ 2618.201739] lustre_kcompr_31161: compr zstdfast(5) in 2048kB chunks took 35310 us (113 MB/s), compress ratio: 2.36 [ 2618.237412] lustre_kcompr_31161: compr zstdfast(5) in 4096kB chunks took 20480 us (195 MB/s), compress ratio: 2.36 [ 2618.261208] lustre_kcompr_31161: decompr zstdfast(5) took 5202 us (324 MB/s) [ 2618.271033] lustre_kcompr_31161: test_comp_compress_decompress(zstdfast,5) ret 0 [ 2618.284244] lustre_kcompr_31161: acompr zstdfast(5) of 128kB chunks took 189 us (661 MB/s), compress ratio: 16.12 [ 2618.298373] lustre_kcompr_31161: adecompr zstdfast(5) took 194 us (39 MB/s) [ 2618.324468] lustre_kcompr_31161: test_acomp_compress_decompress(zstdfast,5) ret 0 [ 2618.381222] lustre_kcompr_31161: compr zstdfast(12) in 64kB chunks took 20115 us (198 MB/s), compress ratio: 2.07 [ 2618.460871] lustre_kcompr_31161: compr zstdfast(12) in 128kB chunks took 44231 us (90 MB/s), compress ratio: 2.07 [ 2618.509453] lustre_kcompr_31161: compr zstdfast(12) in 256kB chunks took 29289 us (136 MB/s), compress ratio: 2.08 [ 2618.553632] lustre_kcompr_31161: compr zstdfast(12) in 512kB chunks took 17398 us (229 MB/s), compress ratio: 2.07 [ 2618.599753] lustre_kcompr_31161: compr zstdfast(12) in 1024kB chunks took 31360 us (127 MB/s), compress ratio: 2.07 [ 2618.640616] lustre_kcompr_31161: compr zstdfast(12) in 2048kB chunks took 24819 us (161 MB/s), compress ratio: 2.07 [ 2618.692559] lustre_kcompr_31161: compr zstdfast(12) in 4096kB chunks took 31536 us (126 MB/s), compress ratio: 2.08 [ 2618.734178] lustre_kcompr_31161: decompr zstdfast(12) took 9530 us (201 MB/s) [ 2618.757926] lustre_kcompr_31161: test_comp_compress_decompress(zstdfast,12) ret 0 [ 2618.772248] lustre_kcompr_31161: acompr zstdfast(12) of 128kB chunks took 5416 us (23 MB/s), compress ratio: 13.13 [ 2618.786723] lustre_kcompr_31161: adecompr zstdfast(12) took 114 us (83 MB/s) [ 2618.840451] lustre_kcompr_31161: test_acomp_compress_decompress(zstdfast,12) ret 0 [ 2618.907414] lustre_kcompr_31161: compr zstdfast(15) in 64kB chunks took 13193 us (303 MB/s), compress ratio: 1.82 [ 2618.932226] lustre_kcompr_31161: compr zstdfast(15) in 128kB chunks took 9006 us (444 MB/s), compress ratio: 1.83 [ 2618.980653] lustre_kcompr_31161: compr zstdfast(15) in 256kB chunks took 13032 us (306 MB/s), compress ratio: 1.83 [ 2619.026768] lustre_kcompr_31161: compr zstdfast(15) in 512kB chunks took 16408 us (243 MB/s), compress ratio: 1.83 [ 2619.061317] lustre_kcompr_31161: compr zstdfast(15) in 1024kB chunks took 21760 us (183 MB/s), compress ratio: 1.83 [ 2619.097097] lustre_kcompr_31161: compr zstdfast(15) in 2048kB chunks took 4926 us (812 MB/s), compress ratio: 1.83 [ 2619.126098] lustre_kcompr_31161: compr zstdfast(15) in 4096kB chunks took 10870 us (367 MB/s), compress ratio: 1.84 [ 2619.165418] lustre_kcompr_31161: decompr zstdfast(15) took 6409 us (338 MB/s) [ 2619.177271] lustre_kcompr_31161: test_comp_compress_decompress(zstdfast,15) ret 0 [ 2619.187993] lustre_kcompr_31161: acompr zstdfast(15) of 128kB chunks took 299 us (418 MB/s), compress ratio: 10.73 [ 2619.200262] lustre_kcompr_31161: adecompr zstdfast(15) took 239 us (48 MB/s) [ 2619.210799] lustre_kcompr_31161: test_acomp_compress_decompress(zstdfast,15) ret 0 [ 2619.217465] lustre_kcompr_31161: SUCCESS [ 2630.325278] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 12:56:05 (1789059365) [ 2655.278180] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 12:56:31 (1789059391) [ 2663.270464] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 12:56:39 (1789059399) [ 2873.085867] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 13:00:08 (1789059608) [ 2912.901359] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 13:00:48 (1789059648) [ 3007.018108] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 13:02:22 (1789059742) [ 3305.575824] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 13:07:21 (1789060041) [ 3413.574669] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 13:09:09 (1789060149) [ 3424.630649] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 13:09:19 (1789060159) [ 3432.515545] LustreError: 81666:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec4f22800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3432.523460] LustreError: 81666:0:(lov_obd.c:792:lov_cleanup()) Skipped 3 previous similar messages [ 3432.617216] Lustre: Unmounted lustre-client [ 3432.618889] Lustre: Skipped 1 previous similar message [ 3433.194307] Lustre: Mounted lustre-client [ 3475.424394] LustreError: 81809:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcefdf9d800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3475.445895] LustreError: 81809:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 3475.516883] Lustre: Unmounted lustre-client [ 3476.060334] Lustre: Mounted lustre-client [ 3506.625303] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 13:10:42 (1789060242) [ 3532.722699] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 13:11:08 (1789060268) [ 3545.693626] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 13:11:21 (1789060281) [ 3617.400155] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 13:12:32 (1789060352) [ 3618.910302] Lustre: DEBUG MARKER: Test readahead: size=4096 ramax= iosz=1048576 [ 3619.434267] Lustre: DEBUG MARKER: Test readahead: size=16384 ramax= iosz=1048576 [ 3619.933282] Lustre: DEBUG MARKER: Test readahead: size=16385 ramax= iosz=1048576 [ 3620.328268] Lustre: DEBUG MARKER: Test readahead: size=16383 ramax= iosz=1048576 [ 3620.736787] Lustre: DEBUG MARKER: Test readahead: size=1048577 ramax= iosz=2097152 [ 3621.263770] Lustre: DEBUG MARKER: Test readahead: size=1064960 ramax= iosz=2097152 [ 3622.241792] Lustre: DEBUG MARKER: Test readahead: size=1064960 ramax= iosz=2097152 [ 3623.096995] Lustre: DEBUG MARKER: Test readahead: size=2113536 ramax= iosz=3145728 [ 3624.307321] Lustre: DEBUG MARKER: Test readahead: size=4210688 ramax= iosz=5242880 [ 3634.786595] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 13:12:50 (1789060370) [ 3645.764346] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 13:13:00 (1789060380) [ 3659.665817] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 13:13:15 (1789060395) [ 3669.260958] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 13:13:24 (1789060404) [ 3690.176527] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 13:13:45 (1789060425) [ 3710.135064] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 13:14:05 (1789060445) [ 3712.919465] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3714.775221] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3716.446468] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3718.343607] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3725.785895] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 13:14:21 (1789060461) [ 3729.237139] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3731.663281] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3734.095386] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3736.113606] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3738.888892] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3746.579528] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 13:14:42 (1789060482) [ 3755.016222] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 13:14:50 (1789060490) [ 3774.400716] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 13:15:09 (1789060509) [ 3784.699833] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 13:15:20 (1789060520) [ 3793.679824] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 13:15:29 (1789060529) [ 3802.373678] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 13:15:38 (1789060538) [ 3812.616344] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 13:15:48 (1789060548) [ 3820.678955] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 13:15:56 (1789060556) [ 3828.908723] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 13:16:04 (1789060564) [ 3837.699763] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 13:16:13 (1789060573) [ 3838.221398] LustreError: lustre-MDT0000-mdc-ffff9fcec6e3b000: operation mds_getxattr to node 192.168.201.144@tcp failed: rc = -95 [ 3845.788852] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 13:16:21 (1789060581) [ 3855.235695] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 13:16:30 (1789060590) [ 4144.968470] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 13:21:20 (1789060880) [ 4351.924793] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 13:24:47 (1789061087) [ 4360.938525] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 13:24:56 (1789061096) [ 4393.823979] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 13:25:29 (1789061129) [ 4418.806833] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 13:25:54 (1789061154) [ 4428.169696] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 13:26:04 (1789061164) [ 4428.695070] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4428.768156] Lustre: lustre-OST0000-osc-ffff9fcec6e3b000: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4428.817859] LustreError: lustre-OST0000-osc-ffff9fcec6e3b000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4433.087644] Lustre: DEBUG MARKER: oleg144-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9fcec6e3b000.ost_server_uuid 50 [ 4434.517328] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fcec6e3b000.ost_server_uuid in FULL state after 0 sec [ 4442.732964] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 13:26:17 (1789061177) [ 4451.396567] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 13:26:26 (1789061186) [ 4453.264468] Lustre: DEBUG MARKER: SKIP: sanity test_104c zfs only test [ 4455.443907] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 13:26:31 (1789061191) [ 4463.859414] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 13:26:39 (1789061199) [ 4472.672349] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 13:26:47 (1789061207) [ 4481.528936] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 13:26:57 (1789061217) [ 4490.729835] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 13:27:06 (1789061226) [ 4491.660416] LustreError: 116941:0:(ldlm_flock.c:851:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 4501.680504] LustreError: 116941:0:(ldlm_flock.c:851:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 4510.870478] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 13:27:26 (1789061246) [ 4519.757523] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 13:27:35 (1789061255) [ 4531.396837] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 13:27:47 (1789061267) [ 4532.137525] Lustre: *** cfs_fail_loc=32f, val=0*** [ 4532.140626] LustreError: 118797:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff9fcec6e3b000 lock: ffff9fcef5216a00/0x3857192d7996e3f6 lrc: 4/0,1 mode: PW/PW res: [0x20000040a:0xb3d:0x0].0xc rrc: 2 type: FLK pid: 118796 [0->9223372036854775807] flags: 0x0 nid: local remote: 0x9114dfbafae7b6c2 expref: -99 pid: 118797 timeout: 0 [ 4532.160776] CPU: 3 PID: 118797 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 4532.168356] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 4532.174299] Call Trace: [ 4532.175158] ? dump_stack+0xbb/0x10e [ 4532.176313] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 4532.179501] ? _raw_spin_unlock+0x12/0x30 [ 4532.185227] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 4532.189149] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 4532.194596] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 4532.205084] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 4532.208822] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4532.211825] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4532.223106] ? mdc_enqueue_base+0x458/0x1db0 [mdc] [ 4532.228042] ? mdc_enqueue+0x1c/0x30 [mdc] [ 4532.230140] ? lmv_enqueue+0x28a/0x530 [lmv] [ 4532.234369] ? ll_file_flock+0x962/0x1420 [lustre] [ 4532.241262] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4532.246182] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4532.249351] ? filemap_map_pages+0x3f8/0x770 [ 4532.254284] ? slab_post_alloc_hook+0x66/0x380 [ 4532.256435] ? locks_alloc_lock+0x1f/0x90 [ 4532.258286] ? kmem_cache_alloc+0x184/0x430 [ 4532.267635] ? vfs_lock_file+0x22/0x50 [ 4532.270345] ? fcntl_setlk+0xde/0x4e0 [ 4532.274806] ? __might_sleep+0x59/0xc0 [ 4532.276945] ? do_fcntl+0x7da/0xb80 [ 4532.278196] ? __x64_sys_fcntl+0xc4/0x110 [ 4532.280484] ? do_syscall_64+0xc1/0x440 [ 4532.285599] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 4543.215304] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 13:27:58 (1789061278) [ 4552.939578] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 13:28:08 (1789061288) [ 4558.354879] LustreError: lustre-MDT0000-mdc-ffff9fcec6e3b000: operation ldlm_enqueue to node 192.168.201.144@tcp failed: rc = -35 [ 4567.576053] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 13:28:22 (1789061302) [ 4576.072365] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 13:28:31 (1789061311) [ 4587.073494] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 13:28:42 (1789061322) [ 4597.734283] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 13:28:53 (1789061333) [ 4782.036203] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 13:31:57 (1789061517) [ 4797.802411] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 13:32:13 (1789061533) [ 4806.299343] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 13:32:22 (1789061542) [ 4815.652600] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 13:32:31 (1789061551) [ 4828.845871] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4831.230593] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4833.762019] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 13:32:49 (1789061569) [ 4834.823975] Lustre: *** cfs_fail_loc=40a, val=0*** [ 4834.829024] Lustre: Skipped 57 previous similar messages [ 4834.834096] LustreError: 127642:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0001-osc-ffff9fcec6e3b000: prep_req failed: rc = -22 [ 4834.869501] LustreError: 127642:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -22 [ 4845.191132] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 13:33:00 (1789061580) [ 4845.831542] Lustre: *** cfs_fail_loc=406, val=0*** [ 4845.839254] LustreError: 128239:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0000-osc-ffff9fcec6e3b000: prep_req failed: rc = -12 [ 4845.844903] LustreError: 128239:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -12 [ 4854.353749] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 13:33:09 (1789061589) [ 4856.698486] LustreError: lustre-OST0001-osc-ffff9fcec6e3b000: operation ost_write to node 192.168.201.144@tcp failed: rc = -5 [ 4856.706805] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9fcef534e300 x1875962059507328/t0(0) o4->lustre-OST0001-osc-ffff9fcec6e3b000@192.168.201.144@tcp:6/4 lens 4584/224 e 0 to 0 dl 1789061610 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4856.733387] LustreError: 2406:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 17 previous similar messages [ 4857.773944] LustreError: lustre-OST0001-osc-ffff9fcec6e3b000: operation ost_write to node 192.168.201.144@tcp failed: rc = -5 [ 4860.391158] LustreError: lustre-OST0001-osc-ffff9fcec6e3b000: operation ost_write to node 192.168.201.144@tcp failed: rc = -5 [ 4867.496110] LustreError: lustre-OST0001-osc-ffff9fcec6e3b000: operation ost_write to node 192.168.201.144@tcp failed: rc = -5 [ 4867.504771] LustreError: Skipped 1 previous similar message [ 4867.508162] LustreError: 2406:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9fcec6e3b000: too many resent retries for object: 11811161089:6418: rc = -5 [ 4867.521580] LustreError: 2406:0:(osc_request.c:2607:brw_interpret()) Skipped 1 previous similar message [ 4867.534363] Lustre: 2406:0:(llite_lib.c:4187:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.144@tcp:/lustre/fid: [0x20000040a:0xe7f:0x0]// may get corrupted (rc -5) [ 4878.407688] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 13:33:34 (1789061614) [ 4880.597570] LustreError: lustre-OST0001-osc-ffff9fcec6e3b000: operation ost_write to node 192.168.201.144@tcp failed: rc = -5 [ 4880.604884] LustreError: 2405:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9fcefb564380 x1875962059516800/t0(0) o4->lustre-OST0001-osc-ffff9fcec6e3b000@192.168.201.144@tcp:6/4 lens 4584/224 e 0 to 0 dl 1789061633 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4880.622666] LustreError: 2405:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4895.543974] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 13:33:51 (1789061631) [ 4898.371170] LustreError: lustre-OST0001-osc-ffff9fcec6e3b000: operation ost_write to node 192.168.201.144@tcp failed: rc = -14 [ 4898.378555] LustreError: Skipped 2 previous similar messages [ 4906.761163] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 13:34:02 (1789061642) [ 4909.257933] LustreError: 2407:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9fcec46bb800 x1875962059528576/t0(0) o4->lustre-OST0001-osc-ffff9fcec6e3b000@192.168.201.144@tcp:6/4 lens 488/224 e 0 to 0 dl 1789061662 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 4909.287935] LustreError: 2407:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 2 previous similar messages [ 4930.799706] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 13:34:26 (1789061666) [ 4939.856380] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 13:34:35 (1789061675) [ 4949.531300] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 13:34:44 (1789061684) [ 4964.223154] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 13:34:59 (1789061699) [ 4974.087523] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 13:35:09 (1789061709) [ 4983.795043] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 13:35:19 (1789061719) [ 4993.306873] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 13:35:28 (1789061728) [ 5036.929562] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 13:36:12 (1789061772) [ 5084.504260] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 13:37:00 (1789061820) [ 5132.275677] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 13:37:47 (1789061867) [ 5167.324265] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 5169.360713] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 13:38:25 (1789061905) [ 5171.747325] sysctl (138121): drop_caches: 3 [ 5171.939662] Lustre: *** cfs_fail_loc=1429, val=0*** [ 5172.970195] Lustre: *** cfs_fail_loc=1429, val=0*** [ 5181.776727] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 13:38:37 (1789061917) [ 5204.003351] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 13:38:59 (1789061939) [ 5212.712411] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 13:39:08 (1789061948) [ 5215.558760] Lustre: DEBUG MARKER: SKIP: sanity test_119n need ZFS server without unaligned_dio support [ 5218.265316] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 13:39:13 (1789061953) [ 5220.510911] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without unaligned_dio support. [ 5223.347079] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 13:39:18 (1789061958) [ 5233.449675] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 13:39:29 (1789061969) [ 5249.511485] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 13:39:44 (1789061984) [ 5261.835420] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 13:39:57 (1789061997) [ 5273.178669] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 13:40:08 (1789062008) [ 5288.334282] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 13:40:23 (1789062023) [ 5299.673611] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 13:40:35 (1789062035) [ 5317.051609] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 13:40:52 (1789062052) [ 5339.365184] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 13:41:13 (1789062073) [ 5771.823399] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 13:48:27 (1789062507) [ 5772.104521] Lustre: *** cfs_fail_loc=310, val=0*** [ 5779.931413] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 13:48:35 (1789062515) [ 5790.591980] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 5793.658766] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 5841.246160] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 28 sec [ 5852.886921] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 8 sec [ 5855.226115] Lustre: DEBUG MARKER: 'ls -l' done [ 5879.810489] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 21 seconds [ 5899.641262] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 13:50:35 (1789062635) [ 5910.200388] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 5912.988584] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 5953.112634] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 23 sec [ 5964.269606] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 6 sec [ 5966.310177] Lustre: DEBUG MARKER: 'statx -l' done [ 5989.965339] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 22 seconds [ 6006.476527] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 13:52:21 (1789062741) [ 6019.258701] Lustre: DEBUG MARKER: 'statx -c 0 [ 6021.980219] Lustre: DEBUG MARKER: 'statx -c 0 [ 6055.012618] Lustre: DEBUG MARKER: 'statx -c 0 [ 6062.300504] Lustre: DEBUG MARKER: 'statx -c 0 [ 6064.033956] Lustre: DEBUG MARKER: 'statx -c 0 [ 6085.497590] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 20 seconds [ 6094.497443] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 1 sec [ 6096.652203] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 6118.201813] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 1 sec [ 6121.489663] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 6253.462218] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 1 sec [ 6257.740250] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 1 sec [ 6260.075469] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6610.716452] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 349 seconds [ 6630.705723] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 14:02:46 (1789063366) [ 6642.859806] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 6648.767139] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 2 sec [ 6700.020716] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 30 sec [ 6717.214222] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 12 sec [ 6721.118965] Lustre: DEBUG MARKER: 'ls -l' done [ 6751.103058] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 28 seconds [ 7459.560436] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 7464.529914] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 7507.993459] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 24 sec [ 7519.094210] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 7521.250728] Lustre: DEBUG MARKER: 'ls -l' done [ 7548.660618] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 26 seconds [ 8079.002263] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 14:26:54 (1789064814) [ 8108.957625] Lustre: DEBUG MARKER: ls done [ 8138.978133] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 14:27:54 (1789064874) [ 8143.798570] LustreError: 176288:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec6e3b000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 8143.811781] LustreError: 176288:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 8143.958245] Lustre: Unmounted lustre-client [ 8145.004392] Lustre: Mounted lustre-client [ 8153.741854] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 14:28:09 (1789064889) [ 8160.414610] LustreError: 176963:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec60dc000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 8160.436324] LustreError: 176963:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 8160.610467] Lustre: Unmounted lustre-client [ 8161.436104] Lustre: Mounted lustre-client [ 8180.190724] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 14:28:35 (1789064915) [ 8504.026584] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 14:33:59 (1789065239) [ 9804.881816] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 14:55:40 (1789066540) [ 9894.651915] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 14:57:10 (1789066630) [11432.664550] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 15:22:48 (1789068168) [11557.211895] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 15:24:52 (1789068292) [11566.308673] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 15:25:02 (1789068302) [11568.643393] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [11570.418611] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 15:25:06 (1789068306) [11575.828940] LustreError: 183539:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [11610.921324] LustreError: 183539:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [11653.728217] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 15:26:29 (1789068389) [11655.685264] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [11697.532656] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9fcec7c2e800 [11699.906561] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9fcec7c2e800 [11701.745413] Lustre: DEBUG MARKER: LRU=1004 [11703.384793] Lustre: DEBUG MARKER: LIMIT=46162 [11705.207452] Lustre: DEBUG MARKER: LVF=5517300 [11706.623600] Lustre: DEBUG MARKER: OLD_LVF=100 [11708.048342] Lustre: DEBUG MARKER: Sleep 50 sec [11760.678650] Lustre: DEBUG MARKER: Dropped 534 locks in 50s [11763.174091] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [11791.139364] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 15:28:47 (1789068527) [11891.910831] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [11988.926737] Lustre: DEBUG MARKER: ls -la time: 95 seconds [11991.805469] Lustre: DEBUG MARKER: lru_size = 400 [12187.988224] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [12282.461986] Lustre: DEBUG MARKER: ls -la time: 89 seconds [12284.524974] Lustre: DEBUG MARKER: lru_size = 4006 [12286.356585] Lustre: DEBUG MARKER: ls -la is 6% faster with lru resize enabled [12355.045708] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 15:38:10 (1789069090) [12388.160701] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 15:38:44 (1789069124) [12420.652528] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 15:39:16 (1789069156) [12467.934324] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 15:40:03 (1789069203) [12550.793959] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 15:41:26 (1789069286) [13213.439203] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 15:52:29 (1789069949) [13222.274498] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 15:52:37 (1789069957) [13230.247633] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 15:52:46 (1789069966) [13239.392930] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 15:52:55 (1789069975) [13248.162817] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [13279.293904] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 15:53:35 (1789070015) [13290.365816] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 15:53:45 (1789070025) [13309.397565] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 15:54:04 (1789070044) [13333.699424] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 15:54:29 (1789070069) [13341.263175] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 15:54:36 (1789070076) [13422.455299] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 15:55:58 (1789070158) [13430.525378] Lustre: DEBUG MARKER: == sanity test 130b: FIEMAP (2-stripe file) ============== 15:56:06 (1789070166) [13438.609922] Lustre: DEBUG MARKER: == sanity test 130c: FIEMAP (2-stripe file with hole) ==== 15:56:14 (1789070174) [13447.276610] Lustre: DEBUG MARKER: == sanity test 130d: FIEMAP (N-stripe file) ============== 15:56:22 (1789070182) [13449.078325] Lustre: DEBUG MARKER: SKIP: sanity test_130d needs >= 3 OSTs [13451.399878] Lustre: DEBUG MARKER: == sanity test 130e: FIEMAP (test continuation FIEMAP calls) ========================================================== 15:56:26 (1789070186) [13516.980417] Lustre: DEBUG MARKER: == sanity test 130f: FIEMAP (unstriped file) ============= 15:57:32 (1789070252) [13525.125405] Lustre: DEBUG MARKER: == sanity test 130g: FIEMAP (overstripe file) ============ 15:57:40 (1789070260) [13576.245390] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 15:58:31 (1789070311) [13578.360292] LustreError: 233904:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [13583.385058] LustreError: 233904:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [13591.168410] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 15:58:46 (1789070326) [13641.633574] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 15:59:37 (1789070377) [13648.335243] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 15:59:44 (1789070384) [13656.685735] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 15:59:51 (1789070391) [13665.927871] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 16:00:01 (1789070401) [13677.961972] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 16:00:12 (1789070412) [13687.780209] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 16:00:24 (1789070424) [13713.193414] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 16:00:48 (1789070448) [13729.343607] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 16:01:04 (1789070464) [13764.053794] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 16:01:39 (1789070499) [13797.772770] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 16:02:13 (1789070533) [13812.363947] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 16:02:27 (1789070547) [13815.480823] LNet: 245232:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [13815.480823] mask usage: [+|-] ... [13815.943773] Lustre: DEBUG MARKER:  [13815.945249] Lustre: DEBUG MARKER:  [13816.190571] LNet: 245297:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [13816.190571] mask usage: [+|-] ... [13816.199539] LNet: 245297:0:(debug.c:376:cfs_str2mask()) Skipped 4 previous similar messages [13832.554317] LustreError: 245902:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec7c2e800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [13832.566417] LustreError: 245902:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [13832.644069] Lustre: Unmounted lustre-client [13893.693215] Key type lgssc unregistered [13894.065831] LNet: 246553:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13894.069387] LNetError: 246553:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [13894.085812] LNet: Removed LNI 192.168.201.44@tcp [13895.286264] Key type .llcrypt unregistered [13895.288145] Key type ._llcrypt unregistered [13910.772220] Key type ._llcrypt registered [13910.774529] Key type .llcrypt registered [13911.523810] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [13911.545756] alg: No test for adler32 (adler32-zlib) [13912.883383] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [13913.769434] LNet: Added LNI 192.168.201.44@tcp [8/256/0/180] [13915.640169] Key type lgssc registered [13918.052484] Lustre: Echo OBD driver; http://www.lustre.org/ [13924.265074] alg: No test for zstdfast (zstdfast-lustre-generic) [13924.299113] alg: No test for zstdfast (zstdfast-lustre-scomp) [14037.557470] Lustre: Mounted lustre-client [14043.235873] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14057.479437] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 16:06:33 (1789070793) [14063.072499] Lustre: lustre-OST0000-osc-ffff9fcee50b3800: disconnect after 23s idle [14200.192886] LustreError: 250306:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcee50b3800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [14200.295024] Lustre: Unmounted lustre-client [14261.930089] Key type lgssc unregistered [14262.135688] LNet: 250991:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14262.140705] LNetError: 250991:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [14262.153391] LNet: Removed LNI 192.168.201.44@tcp [14262.914232] Key type .llcrypt unregistered [14262.915790] Key type ._llcrypt unregistered [14276.522961] Key type ._llcrypt registered [14276.568043] Key type .llcrypt registered [14277.114932] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [14277.136967] alg: No test for adler32 (adler32-zlib) [14278.450612] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [14278.871626] LNet: Added LNI 192.168.201.44@tcp [8/256/0/180] [14280.656443] Key type lgssc registered [14282.264568] Lustre: Echo OBD driver; http://www.lustre.org/ [14286.429565] alg: No test for zstdfast (zstdfast-lustre-generic) [14286.437834] alg: No test for zstdfast (zstdfast-lustre-scomp) [14410.120837] Lustre: Mounted lustre-client [14416.553256] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14428.493790] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 16:12:44 (1789071164) [14435.820435] Lustre: lustre-OST0000-osc-ffff9fcec5eb2000: disconnect after 23s idle [14471.668853] Lustre: lustre-OST0000-osc-ffff9fcec5eb2000: disconnect after 22s idle [14471.681842] Lustre: Skipped 1 previous similar message [14512.608437] Lustre: lustre-OST0000-osc-ffff9fcec5eb2000: disconnect after 21s idle [14512.610638] Lustre: Skipped 1 previous similar message [14517.728697] Lustre: lustre-OST0001-osc-ffff9fcec5eb2000: disconnect after 22s idle [15776.731168] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 16:35:12 (1789072512) [15828.772146] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 16:36:04 (1789072564) [15838.688938] Lustre: lustre-OST0001-osc-ffff9fcec5eb2000: disconnect after 24s idle [15881.970424] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [15884.555433] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [15886.581957] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 16:37:02 (1789072622) [15941.025734] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 16:37:57 (1789072677) [15958.719077] LustreError: 275352:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec5eb2000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [15959.093832] Lustre: Unmounted lustre-client [15959.783029] Lustre: Mounted lustre-client [15990.029438] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 16:38:45 (1789072725) [16020.275283] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 16:39:16 (1789072756) [16061.450187] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 16:39:56 (1789072796) [16083.089507] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 16:40:18 (1789072818) [16110.128852] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 16:40:44 (1789072844) [16143.444969] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 16:41:19 (1789072879) [16172.587693] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 16:41:46 (1789072906) [16206.364874] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 16:42:21 (1789072941) [16216.667522] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 16:42:32 (1789072952) [16239.942873] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 16:42:55 (1789072975) [16266.583093] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 16:43:22 (1789073002) [16268.389432] Lustre: DEBUG MARKER: SKIP: sanity test_150ic only check on DoM component [16270.349613] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 16:43:26 (1789073006) [16302.356808] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 16:43:57 (1789073037) [16314.194952] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 16:44:08 (1789073048) [16325.077840] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 16:44:20 (1789073060) [16337.598451] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 16:44:32 (1789073072) [16349.542541] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 16:44:44 (1789073084) [16379.524195] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 16:45:14 (1789073114) [16381.610800] LustreError: 290709:0:(lmv_fld.c:51:lmv_fld_lookup()) lustre-clilmv-ffff9fcec4f52800: Error while looking for mds number. Seq 0xf00000400: rc = -2 [16389.965727] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 16:45:25 (1789073125) [16391.580436] LustreError: 291351:0:(lmv_fld.c:51:lmv_fld_lookup()) lustre-clilmv-ffff9fcec4f52800: Error while looking for mds number. Seq 0xf00000400: rc = -2 [16391.586045] LustreError: 291351:0:(lmv_fld.c:51:lmv_fld_lookup()) Skipped 1 previous similar message [16402.647615] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 16:45:37 (1789073137) [16411.692718] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 16:45:47 (1789073147) [16422.201525] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 16:45:57 (1789073157) [16431.060781] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 16:46:06 (1789073166) [16497.612521] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 16:47:13 (1789073233) [16506.390935] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 16:47:22 (1789073242) [17848.711825] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 17:09:44 (1789074584) [17857.354449] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 17:09:53 (1789074593) [17900.120659] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 17:10:35 (1789074635) [17930.029602] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 17:11:05 (1789074665) [17946.032898] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 17:11:21 (1789074681) [17960.876267] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 17:11:36 (1789074696) [17976.632882] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 17:11:52 (1789074712) [17992.699356] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 17:12:08 (1789074728) [18042.689563] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 17:12:58 (1789074778) [18091.175676] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 17:13:46 (1789074826) [18134.152403] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 17:14:30 (1789074870) [18180.646079] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 17:15:16 (1789074916) [18194.842952] Lustre: DEBUG MARKER: Turn on read and write cache [18200.372175] Lustre: DEBUG MARKER: Write data and read it back. [18202.555394] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [18209.164924] Lustre: DEBUG MARKER: cache hits: before: 28718, after: 28721 [18211.142931] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [18215.395182] Lustre: DEBUG MARKER: cache hits:: before: 28721, after: 28724 [18218.219230] Lustre: DEBUG MARKER: Turn off the read cache and turn on the write cache [18223.723126] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [18228.194371] Lustre: DEBUG MARKER: cache hits:: before: 28724, after: 28727 [18229.847836] Lustre: DEBUG MARKER: Write data and read it back. [18231.506462] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [18236.386821] Lustre: DEBUG MARKER: cache hits:: before: 28727, after: 28730 [18238.258208] Lustre: DEBUG MARKER: Turn off read and write cache [18242.777874] Lustre: DEBUG MARKER: Write data and read it back [18244.685367] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [18249.131485] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [18250.848569] Lustre: DEBUG MARKER: Turn on the read cache and turn off the write cache [18254.756850] Lustre: DEBUG MARKER: Write data and read it back [18256.263416] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [18260.241796] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [18262.154480] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [18266.173295] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28733 [18275.770286] Lustre: DEBUG MARKER: == sanity test 157: llapi pool pinning API tests ========= 17:16:51 (1789075011) [18284.001625] Lustre: DEBUG MARKER: == sanity test 157a: lustre.pin inheritance on create ==== 17:16:59 (1789075019) [18293.598742] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 17:17:09 (1789075029) [18320.899657] Lustre: lustre-MDT0000-mdc-ffff9fcec4f52800: Connection to lustre-MDT0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [18331.118969] LustreError: MGC192.168.201.144@tcp: Connection to MGS (at 192.168.201.144@tcp) was lost; in progress operations using this service will fail [18331.147875] Lustre: Evicted from MGS (at 192.168.201.144@tcp) after server handle changed from 0x521d29ac2f6d25ff to 0x521d29ac2f76f34e [18331.167615] Lustre: MGC192.168.201.144@tcp: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [18331.190498] LustreError: 251358:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9fcef30b5f80 x1875976932006272/t12884907136(12884907136) o101->lustre-MDT0000-mdc-ffff9fcec4f52800@192.168.201.144@tcp:12/10 lens 912/608 e 0 to 0 dl 1789075084 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18331.691503] LustreError: 251358:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9fcec6b10700 x1875976939576832/t12884924518(12884924518) o101->lustre-MDT0000-mdc-ffff9fcec4f52800@192.168.201.144@tcp:12/10 lens 968/608 e 0 to 0 dl 1789075085 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18331.745053] LustreError: 251358:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 37 previous similar messages [18336.403593] Lustre: lustre-MDT0000-mdc-ffff9fcec4f52800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [18359.396050] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 17:18:15 (1789075095) [18385.356540] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 17:18:40 (1789075120) [18410.816905] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 17:19:06 (1789075146) [18431.658994] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 17:19:27 (1789075167) [18455.678471] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 17:19:50 (1789075190) [18471.189961] Lustre: DEBUG MARKER: 1789075206: creating first dirs [18535.610675] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 17:21:11 (1789075271) [18595.038614] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 17:22:10 (1789075330) [18643.434567] Lustre: lustre-MDT0001-mdc-ffff9fcec4f52800: Connection to lustre-MDT0001 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [18663.917303] LustreError: MGC192.168.201.144@tcp: Connection to MGS (at 192.168.201.144@tcp) was lost; in progress operations using this service will fail [18663.952340] Lustre: Evicted from MGS (at 192.168.201.144@tcp) after server handle changed from 0x521d29ac2f76f34e to 0x521d29ac2f770b57 [18663.974286] Lustre: MGC192.168.201.144@tcp: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [18674.332758] LustreError: 251358:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9fcec6b11c00 x1875976939562880/t12884924481(12884924481) o101->lustre-MDT0000-mdc-ffff9fcec4f52800@192.168.201.144@tcp:12/10 lens 968/608 e 0 to 0 dl 1789075427 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18674.368115] LustreError: 251358:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 34 previous similar messages [18682.156125] Lustre: lustre-MDT0001-mdc-ffff9fcec4f52800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [18719.029758] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 17:24:14 (1789075454) [18766.697988] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 17:25:01 (1789075501) [18767.801555] Lustre: Mounted lustre-client [18775.971432] LustreError: 327177:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec4f52800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [18776.000647] LustreError: 327177:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [18776.249275] Lustre: Unmounted lustre-client [18784.299246] Lustre: Mounted lustre-client [18794.500921] LustreError: 327757:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcec302a800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [18794.516793] LustreError: 327757:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [18794.634388] Lustre: Unmounted lustre-client [18796.985328] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 17:25:32 (1789075532) [18833.028224] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 17:26:08 (1789075568) [18863.337182] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 17:26:38 (1789075598) [18909.304520] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 17:27:24 (1789075644) [21169.524710] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 18:05:05 (1789077905) [21216.068663] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 18:05:51 (1789077951) [21229.564959] Lustre: lustre-MDT0000-mdc-ffff9fcefdd84800: Connection to lustre-MDT0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [21229.599248] Lustre: Skipped 1 previous similar message [21244.896178] Lustre: 251359:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789077966/real 1789077966] req@ffff9fcef6d78000 x1875976975093120/t0(0) o400->MGC192.168.201.144@tcp@192.168.201.144@tcp:26/25 lens 224/224 e 0 to 1 dl 1789077982 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [21244.924361] LustreError: MGC192.168.201.144@tcp: Connection to MGS (at 192.168.201.144@tcp) was lost; in progress operations using this service will fail [21244.993904] Lustre: Evicted from MGS (at 192.168.201.144@tcp) after server handle changed from 0x521d29ac2f770b57 to 0x521d29ac2fba875e [21245.011515] Lustre: MGC192.168.201.144@tcp: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [21245.030494] Lustre: Skipped 1 previous similar message [21248.658402] Lustre: lustre-MDT0000-mdc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [21264.546910] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 18:06:40 (1789078000) [21278.596698] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 18:06:53 (1789078013) [21323.957438] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 18:07:39 (1789078059) [21459.011549] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 18:09:54 (1789078194) [21484.834905] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 18:10:19 (1789078219) [21487.003849] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [21489.349356] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 18:10:24 (1789078224) [21531.428314] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 18:11:07 (1789078267) [21576.269357] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 18:11:52 (1789078312) [21617.769828] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 18:12:33 (1789078353) [21642.778725] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 18:12:58 (1789078378) [21652.938432] LustreError: 373839:0:(namei.c:1578:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [21655.696114] LustreError: 373839:0:(namei.c:1578:ll_create_node()) cfs_fail_timeout interrupted [21674.965449] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 18:13:30 (1789078410) [21684.623891] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 18:13:40 (1789078420) [21694.061149] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 18:13:49 (1789078429) [21816.512353] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 18:15:51 (1789078551) [21828.627811] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [21860.093817] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 18:16:35 (1789078595) [21900.321129] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [21914.751431] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [21925.133736] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 18:17:40 (1789078660) [21961.789272] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [21975.558831] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [21986.502963] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 18:18:41 (1789078721) [22038.512623] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [22048.380409] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [22058.964685] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 18:19:54 (1789078794) [22084.609309] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [22095.008931] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [22105.885764] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 18:20:40 (1789078840) [22115.304348] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [22139.444801] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [22153.042881] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 18:21:28 (1789078888) [22202.375401] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection to lustre-OST0000 (at 192.168.201.144@tcp) was lost; in progress operations using this service will wait for recovery to complete [22221.843325] Lustre: lustre-OST0000-osc-ffff9fcefdd84800: Connection restored to 192.168.201.144@tcp (at 192.168.201.144@tcp) [22232.627464] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 18:22:47 (1789078967) [22234.911941] Lustre: DEBUG MARKER: creating a 10 Mb file [22336.729510] Lustre: DEBUG MARKER: starting reads [22339.349609] Lustre: DEBUG MARKER: truncating the file [22341.878845] Lustre: DEBUG MARKER: killing dd [22344.249446] Lustre: DEBUG MARKER: removing the temporary file [22353.886525] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 18:24:49 (1789079089) [22354.276792] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [22354.391264] Lustre: shutting down debug daemon thread... [22354.446658] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [22354.535475] Lustre: shutting down debug daemon thread... [22364.480323] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 18:24:59 (1789079099) [22402.238609] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 18:25:37 (1789079137) [22402.549366] LustreError: 388967:0:(file.c:482:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [22405.584183] LustreError: 388967:0:(file.c:482:ll_file_release()) cfs_fail_timeout id 50e awake [22405.601630] LustreError: dumping log to /tmp/lustre-log.1789079142.388967 [22414.801296] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 18:25:50 (1789079150) [22418.195144] LustreError: 389550:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fcefdd84800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [22418.205319] LustreError: 389550:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [22418.369441] Lustre: *** cfs_fail_loc=60e, val=0*** [22418.374250] Lustre: Unmounted lustre-client [22425.347112] Lustre: Mounted lustre-client [22427.662932] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 18:26:03 (1789079163) [22429.880875] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [22432.557540] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 18:26:08 (1789079168) [22462.768700] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 18:26:37 (1789079197) [22495.127320] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 18:27:10 (1789079230) [22593.475272] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 18:28:49 (1789079329) [22705.299655] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 18:30:41 (1789079441) [23391.281569] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 18:42:07 (1789080127) [23401.930490] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 18:42:17 (1789080137) [23416.257405] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 18:42:32 (1789080152) [23423.639407] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 18:42:39 (1789080159) [23482.988762] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 18:43:38 (1789080218) [23495.079628] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 18:43:50 (1789080230) [23506.197906] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 18:44:01 (1789080241) [23513.935460] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 18:44:09 (1789080249) [23523.369421] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 18:44:18 (1789080258) [23535.451616] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 18:44:31 (1789080271) [23546.659662] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 18:44:42 (1789080282) [23554.836374] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 18:44:50 (1789080290) [23563.243260] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 18:44:58 (1789080298) [23599.935268] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 18:45:35 (1789080335) [23625.213272] Lustre: DEBUG MARKER: == sanity test complete, duration 23308 sec ============== 18:46:00 (1789080360) [23627.942387] Lustre: DEBUG MARKER: === sanity: start cleanup 18:46:03 (1789080363) === [23683.954492] Lustre: DEBUG MARKER: === sanity: finish cleanup 18:46:59 (1789080419) === [23686.331440] LustreError: 418891:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9fceee691000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [23686.341283] LustreError: 418891:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [23686.452736] Lustre: Unmounted lustre-client [23745.678831] Key type lgssc unregistered [23745.889678] LNet: 419577:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [23745.896646] LNetError: 419577:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [23745.913927] LNet: Removed LNI 192.168.201.44@tcp [23746.864157] Key type .llcrypt unregistered [23746.865878] Key type ._llcrypt unregistered