[ 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 486659298 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: 2895288K/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.001011] APIC: Switch to symmetric I/O mode setup [ 0.002353] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004014] kvm-guest: setup PV IPIs [ 0.006652] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.007021] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.008010] pid_max: default: 32768 minimum: 301 [ 0.009121] LSM: Security Framework initializing [ 0.010051] Yama: becoming mindful. [ 0.011038] SELinux: Initializing. [ 0.012052] *** VALIDATE selinux *** [ 0.019510] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.023731] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.024154] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.025097] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026096] *** VALIDATE tmpfs *** [ 0.027467] *** VALIDATE proc *** [ 0.029052] *** VALIDATE cgroup *** [ 0.029955] *** VALIDATE cgroup2 *** [ 0.031218] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.033072] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.034007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.035025] Spectre V2 : User space: Vulnerable [ 0.036007] Speculative Store Bypass: Vulnerable [ 0.038887] debug: unmapping init [mem 0xffffffffb1659000-0xffffffffb1660fff] [ 0.040993] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.041608] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.042020] ... version: 2 [ 0.042977] ... bit width: 48 [ 0.043011] ... generic registers: 4 [ 0.043961] ... value mask: 0000ffffffffffff [ 0.044012] ... max period: 00007fffffffffff [ 0.045010] ... fixed-purpose events: 3 [ 0.045949] ... event mask: 000000070000000f [ 0.046260] rcu: Hierarchical SRCU implementation. [ 0.048365] smp: Bringing up secondary CPUs ... [ 0.049541] x86: Booting SMP configuration: [ 0.050020] .... node #0, CPUs: #1 #2 #3 [ 0.053026] smp: Brought up 1 node, 4 CPUs [ 0.055014] smpboot: Max logical packages: 1 [ 0.055918] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.130029] node 0 deferred pages initialised in 73ms [ 0.133253] devtmpfs: initialized [ 0.134208] x86/mm: Memory block size: 128MB [ 0.136366] gcov: version magic: 0x41383552 [ 0.139284] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.142095] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.143285] pinctrl core: initialized pinctrl subsystem [ 0.145161] [ 0.145550] ************************************************************* [ 0.147011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.149012] ** ** [ 0.150011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.152012] ** ** [ 0.154012] ** This means that this kernel is built to expose internal ** [ 0.156012] ** IOMMU data structures, which may compromise security on ** [ 0.157009] ** your system. ** [ 0.159009] ** ** [ 0.161010] ** If you see this message and you are not debugging the ** [ 0.163012] ** kernel, report this immediately to your vendor! ** [ 0.164008] ** ** [ 0.166010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.168011] ************************************************************* [ 0.169599] NET: Registered protocol family 16 [ 0.171417] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.173055] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.175055] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.179031] cpuidle: using governor menu [ 0.181000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.183461] PCI: Using configuration type 1 for base access [ 0.185125] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.195108] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.197083] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.201027] cryptd: max_cpu_qlen set to 1000 [ 0.203380] ACPI: Added _OSI(Module Device) [ 0.205022] ACPI: Added _OSI(Processor Device) [ 0.207013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.208011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.212095] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.217579] ACPI: Interpreter enabled [ 0.218053] ACPI: PM: (supports S0 S3 S4 S5) [ 0.220011] ACPI: Using IOAPIC for interrupt routing [ 0.221110] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.223365] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.233317] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.234034] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.236017] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.239073] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.243261] acpiphp: Slot [2] registered [ 0.244096] acpiphp: Slot [5] registered [ 0.245099] acpiphp: Slot [6] registered [ 0.247090] acpiphp: Slot [3] registered [ 0.248095] acpiphp: Slot [4] registered [ 0.249082] acpiphp: Slot [7] registered [ 0.250076] acpiphp: Slot [8] registered [ 0.251079] acpiphp: Slot [9] registered [ 0.252089] acpiphp: Slot [10] registered [ 0.253076] acpiphp: Slot [11] registered [ 0.254076] acpiphp: Slot [12] registered [ 0.255078] acpiphp: Slot [13] registered [ 0.256093] acpiphp: Slot [14] registered [ 0.258077] acpiphp: Slot [15] registered [ 0.259094] acpiphp: Slot [16] registered [ 0.260072] acpiphp: Slot [17] registered [ 0.261078] acpiphp: Slot [18] registered [ 0.262072] acpiphp: Slot [19] registered [ 0.263075] acpiphp: Slot [20] registered [ 0.264072] acpiphp: Slot [21] registered [ 0.265076] acpiphp: Slot [22] registered [ 0.266095] acpiphp: Slot [23] registered [ 0.267080] acpiphp: Slot [24] registered [ 0.268081] acpiphp: Slot [25] registered [ 0.270080] acpiphp: Slot [26] registered [ 0.271088] acpiphp: Slot [27] registered [ 0.272074] acpiphp: Slot [28] registered [ 0.273101] acpiphp: Slot [29] registered [ 0.274078] acpiphp: Slot [30] registered [ 0.275075] acpiphp: Slot [31] registered [ 0.276050] PCI host bridge to bus 0000:00 [ 0.277017] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.279021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.281023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.282019] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.284022] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.286020] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.288158] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.289878] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.293075] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.298449] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.301920] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.304028] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.306014] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.308015] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.309522] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.311737] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.314037] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.316700] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.320013] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.327014] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.332013] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.336921] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.345016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.352016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.373015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.384000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.391015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.398017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.417021] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.427275] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.430288] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.431258] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.433300] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.437247] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.443758] iommu: Default domain type: Passthrough [ 0.445464] SCSI subsystem initialized [ 0.447128] ACPI: bus type USB registered [ 0.448100] usbcore: registered new interface driver usbfs [ 0.449052] usbcore: registered new interface driver hub [ 0.451072] usbcore: registered new device driver usb [ 0.453186] pps_core: LinuxPPS API ver. 1 registered [ 0.454009] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.457059] PTP clock support registered [ 0.459119] EDAC MC: Ver: 3.0.0 [ 0.461223] PCI: Using ACPI for IRQ routing [ 0.462757] NetLabel: Initializing [ 0.464008] NetLabel: domain hash size = 128 [ 0.465009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.467157] NetLabel: unlabeled traffic allowed by default [ 0.469156] vgaarb: loaded [ 0.471149] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.473010] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.479802] clocksource: Switched to clocksource kvm-clock [ 0.588132] VFS: Disk quotas dquot_6.6.0 [ 0.589482] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.591767] *** VALIDATE ramfs *** [ 0.592667] *** VALIDATE hugetlbfs *** [ 0.593790] pnp: PnP ACPI init [ 0.596161] pnp: PnP ACPI: found 6 devices [ 0.616405] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.619367] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.620663] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.622063] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.624032] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.626106] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.628397] NET: Registered protocol family 2 [ 0.630637] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.635243] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.637374] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.640782] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.642877] TCP: Hash tables configured (established 65536 bind 65536) [ 0.644772] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.646838] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.648841] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.650622] NET: Registered protocol family 1 [ 0.652392] RPC: Registered named UNIX socket transport module. [ 0.654447] RPC: Registered udp transport module. [ 0.656297] RPC: Registered tcp transport module. [ 0.657726] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.659863] NET: Registered protocol family 44 [ 0.661601] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.663927] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.665732] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.667690] PCI: CLS 0 bytes, default 64 [ 0.669705] Unpacking initramfs... [ 2.039099] debug: unmapping init [mem 0xffff9f02fcc64000-0xffff9f02fffcffff] [ 2.043155] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.045266] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.047968] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.527576] Initialise system trusted keyrings [ 2.528938] Key type blacklist registered [ 2.530375] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.538488] zbud: loaded [ 2.542274] *** VALIDATE nfs *** [ 2.543557] *** VALIDATE nfs4 *** [ 2.545027] pstore: using deflate compression [ 2.547963] Platform Keyring initialized [ 2.655031] NET: Registered protocol family 38 [ 2.656367] Key type asymmetric registered [ 2.657559] Asymmetric key parser 'x509' registered [ 2.659063] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.661684] io scheduler mq-deadline registered [ 2.662909] io scheduler kyber registered [ 2.664258] io scheduler bfq registered [ 2.666118] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.668385] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.670418] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.673656] ACPI: Power Button [PWRF] [ 2.678651] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.684105] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.697826] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.727302] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.757781] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.764991] Non-volatile memory driver v1.3 [ 2.766204] Linux agpgart interface v0.103 [ 2.797395] virtio_blk virtio1: [vda] 142768 512-byte logical blocks (73.1 MB/69.7 MiB) [ 2.799632] vda: detected capacity change from 0 to 73097216 [ 2.836787] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.838991] vdb: detected capacity change from 0 to 1073741824 [ 2.859467] libphy: Fixed MDIO Bus: probed [ 2.864373] usbcore: registered new interface driver usbserial_generic [ 2.866138] usbserial: USB Serial support registered for generic [ 2.867513] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.870442] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.871464] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.872798] mousedev: PS/2 mouse device common for all mice [ 2.875271] rtc_cmos 00:05: RTC can wake from S4 [ 2.877827] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.881070] rtc_cmos 00:05: registered as rtc0 [ 2.881989] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.883071] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.885828] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.886932] intel_pstate: CPU model not supported [ 2.890526] hid: raw HID events driver (C) Jiri Kosina [ 2.891855] usbcore: registered new interface driver usbhid [ 2.892978] usbhid: USB HID core driver [ 2.894225] drop_monitor: Initializing network drop monitor service [ 2.896170] Initializing XFRM netlink socket [ 2.897975] NET: Registered protocol family 10 [ 2.899908] Segment Routing with IPv6 [ 2.900646] NET: Registered protocol family 17 [ 2.902033] mpls_gso: MPLS GSO support [ 2.906529] RAS: Correctable Errors collector initialized. [ 2.907645] AVX version of gcm_enc/dec engaged. [ 2.908621] AES CTR mode by8 optimization enabled [ 2.961419] sched_clock: Marking stable (2961404890, 0)->(3808019447, -846614557) [ 2.964088] registered taskstats version 1 [ 2.965165] Loading compiled-in X.509 certificates [ 2.966286] zswap: loaded using pool lzo/zbud [ 2.983828] Key type big_key registered [ 2.995500] Key type encrypted registered [ 2.996750] ima: No TPM chip found, activating TPM-bypass! [ 2.998266] ima: Allocated hash algorithm: sha1 [ 2.999453] ima: No architecture policies found [ 3.000778] evm: Initialising EVM extended attributes: [ 3.002162] evm: security.selinux [ 3.003064] evm: security.ima [ 3.003785] evm: security.capability [ 3.004858] evm: HMAC attrs: 0x1 [ 3.007206] rtc_cmos 00:05: setting system clock to 2026-09-10 16:38:38 UTC (1789058318) [ 3.012860] debug: unmapping init [mem 0xffffffffb2603000-0xffffffffb27fffff] [ 3.015198] debug: unmapping init [mem 0xffffffffb1382000-0xffffffffb1658fff] [ 3.023070] Write protecting the kernel read-only data: 28672k [ 3.025957] debug: unmapping init [mem 0xffffffffafa03000-0xffffffffafbfffff] [ 3.027902] debug: unmapping init [mem 0xffffffffb0314000-0xffffffffb03fffff] [ 3.053555] 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.059282] systemd[1]: Detected virtualization kvm. [ 3.060657] systemd[1]: Detected architecture x86-64. [ 3.062034] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.087584] systemd[1]: No hostname configured. [ 3.088726] systemd[1]: Set hostname to . [ 3.090089] random: systemd: uninitialized urandom read (16 bytes read) [ 3.091684] systemd[1]: Initializing machine ID from random generator. [ 3.196330] random: systemd: uninitialized urandom read (16 bytes read) [ 3.198645] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.203334] random: systemd: uninitialized urandom read (16 bytes read) [ 3.205430] systemd[1]: Reached target Local Encrypted Volumes. [ OK ] Reached target Local Encrypted Volumes. [ 3.208907] systemd[1]: Reached target Paths. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Local File Systems. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... [ OK ] Reached target Swap. Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ 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.792738] device-mapper: uevent: version 1.0.3 [ 3.795116] 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. [ 4.032254] random: fast init done 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. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 4.402136] virtio_net virtio0 ens2: renamed from eth0 [ 4.550488] scsi host0: ata_piix [ 4.574198] scsi host1: ata_piix [ 4.575698] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.578329] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 8.154218] dracut-initqueue[578]: RTNETLINK answers: File exists [ 9.509272] random: crng init done [ 9.510578] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 9.768957] 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... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Swap. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ 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... [ 10.852155] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.164643] SELinux: Disabled at runtime. [ 11.235728] 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.241417] systemd[1]: Detected virtualization kvm. [ 11.244754] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 11.866226] systemd[1]: initrd-switch-root.service: Succeeded. [ 11.869438] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 11.873988] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 11.877417] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 11.880126] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 11.887556] systemd[1]: Starting Journal Service... Starting Journal Service... [ 11.891427] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Control Socket. Starting Remount Root and Kernel File Systems... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice User and Session Slice. Activating swap /dev/disk/by-label/SWAP... Mounting POSIX Message Queue File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Mounting Huge Pages File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Apply Kernel Variables... [ 11.987742] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Kernel Debug File System... [ OK ] Reached target Slices. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Paths. Starting udev Coldplug all Devices... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ 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 Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.282851] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 12.519639] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.630243] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 12.671582] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 12.682426] EDAC sbridge: Ver: 1.1.2 [ 13.650571] Key type dns_resolver registered [ 13.976088] NFS: Registering the id_resolver key type [ 13.977606] Key type id_resolver registered [ 13.978722] 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 RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ 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 ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... [ OK ] Started Login Service. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ 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 Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ 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 System Logging Service... Starting Crash recovery kernel arming... 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 Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Authorization Manager. [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg142-client login: [ 73.269282] hrtimer: interrupt took 6268450 ns [ 79.634537] libcfs: loading out-of-tree module taints kernel. [ 79.884341] Key type ._llcrypt registered [ 79.899229] Key type .llcrypt registered [ 80.968432] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 80.998794] alg: No test for adler32 (adler32-zlib) [ 82.945721] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [ 84.065653] LNet: Added LNI 192.168.201.42@tcp [8/256/0/180] [ 85.936196] Key type lgssc registered [ 88.174958] Lustre: Echo OBD driver; http://www.lustre.org/ [ 95.770904] alg: No test for zstdfast (zstdfast-lustre-generic) [ 95.783972] alg: No test for zstdfast (zstdfast-lustre-scomp) [ 227.980845] Lustre: Mounted lustre-client [ 232.712397] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 245.934959] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing check_logdir /tmp/testlogs/ [ 252.783615] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing yml_node [ 253.920169] Lustre: lustre-OST0000-osc-ffff9f034ab59000: disconnect after 24s idle [ 257.298074] Lustre: DEBUG MARKER: Client: 2.17.53.26 [ 260.190852] Lustre: DEBUG MARKER: MDS: 2.17.53.26 [ 262.706438] Lustre: DEBUG MARKER: OSS: 2.17.53.26 [ 264.724567] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Thu Sep 10 12:42:58 EDT 2026 [ 285.314971] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34682138 <= 34618625) for LU-18938, skip 360 [ 287.247747] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34682138 < 34486116) for LU-14927, skip 0f [ 289.756390] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 817 411a 130b 130c 130d 130e 130f 130g [ 292.603928] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b 51c 51e 834 [ 295.530795] Lustre: DEBUG MARKER: === sanity: start setup 12:43:28 (1789058608) === [ 303.747845] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing check_config_client /mnt/lustre [ 331.121683] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 346.965731] Lustre: DEBUG MARKER: === sanity: finish setup 12:44:20 (1789058660) === [ 355.783178] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 12:44:28 (1789058668) [ 359.578409] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 362.718328] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 12:44:35 (1789058675) [ 371.680441] Lustre: lustre-OST0000-osc-ffff9f034ab59000: disconnect after 24s idle [ 371.683025] Lustre: Skipped 1 previous similar message [ 376.339092] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 12:44:49 (1789058689) [ 588.595295] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 12:48:22 (1789058902) [ 588.697627] Lustre: DEBUG MARKER: test message ID 7782 7650 [ 596.692543] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 12:48:30 (1789058910) [ 605.428779] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 12:48:39 (1789058919) [ 605.800949] LustreError: dumping log to /tmp/f60f.sanity.1789058921.13764 [ 612.455426] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 12:48:46 (1789058926) [ 738.125646] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 12:50:51 (1789059051) [ 740.637144] Lustre: DEBUG MARKER: SKIP: sanity test_60h Need at least 2 MDTs [ 742.997207] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 745.931361] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 12:50:59 (1789059059) [ 748.651664] Lustre: DEBUG MARKER: SKIP: sanity test_60j ldiskfs only test [ 751.259432] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 12:51:04 (1789059064) [ 760.190501] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 12:51:13 (1789059073) [ 769.666147] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 12:51:22 (1789059082) [ 846.913642] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 12:52:39 (1789059159) [ 849.002863] Lustre: *** cfs_fail_loc=406, val=0*** [ 849.007068] LustreError: 20578:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0000-osc-ffff9f034ab59000: prep_req failed: rc = -12 [ 849.020941] LustreError: 20578:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -12 [ 863.161507] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 12:52:55 (1789059175) [ 875.142996] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 877.692748] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 12:53:11 (1789059191) [ 887.631458] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 12:53:20 (1789059200) [ 967.101965] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 12:54:40 (1789059280) [ 969.958196] LustreError: 23862:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f034ab59000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 970.041182] Lustre: Unmounted lustre-client [ 970.563756] Lustre: Mounted lustre-client [ 975.086830] LustreError: 23969:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0265330800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 975.095099] LustreError: 23969:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 975.155118] Lustre: Unmounted lustre-client [ 975.597714] Lustre: Mounted lustre-client [ 986.202748] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 12:54:59 (1789059299) [ 989.696579] LustreError: 24631:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0353d21800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 989.712269] LustreError: 24631:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 989.778798] Lustre: Unmounted lustre-client [ 990.382565] Lustre: Mounted lustre-client [ 993.382782] LustreError: 24728:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0347f12800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 993.394117] LustreError: 24728:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 993.438884] Lustre: Unmounted lustre-client [ 993.898874] Lustre: Mounted lustre-client [ 1003.024679] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 12:55:16 (1789059316) [ 1089.713868] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 12:56:43 (1789059403) [ 1110.084830] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 12:57:04 (1789059424) [ 1122.289685] Lustre: lustre-OST0000-osc-ffff9f0349768800: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1134.562490] Lustre: 2367:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789059434/real 1789059434] req@ffff9f0351b27100 x1875963706152832/t0(0) o17->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:28/4 lens 456/432 e 0 to 1 dl 1789059450 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1156.215588] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 1158.104259] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1178.698936] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 12:58:12 (1789059492) [ 1180.312254] LustreError: 2366:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9f03472e4a80 x1875963706164992/t0(0) o4->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 4584/448 e 0 to 0 dl 1789059511 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1192.052937] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 12:58:26 (1789059506) [ 1200.918738] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 12:58:34 (1789059514) [ 1211.373995] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 12:58:44 (1789059524) [ 1221.348337] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 12:58:54 (1789059534) [ 1231.358642] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 12:59:04 (1789059544) [ 1241.180241] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 12:59:14 (1789059554) [ 1249.703522] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 12:59:23 (1789059563) [ 1260.206871] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 12:59:33 (1789059573) [ 1272.184150] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 12:59:45 (1789059585) [ 1282.800900] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 12:59:56 (1789059596) [ 1292.758452] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 13:00:05 (1789059605) [ 1402.756501] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 13:01:56 (1789059716) [ 1410.795392] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 13:02:04 (1789059724) [ 1420.176741] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 13:02:13 (1789059733) [ 1433.696048] Lustre: DEBUG MARKER: SKIP: sanity test_65n needs >= 2 MDTs [ 1448.539906] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 13:02:42 (1789059762) [ 1478.561300] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 13:03:12 (1789059792) [ 1487.405259] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 13:03:21 (1789059801) [ 1496.820392] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 13:03:30 (1789059810) [ 1506.660526] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 13:03:40 (1789059820) [ 1523.536499] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 13:03:57 (1789059837) [ 1538.335462] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 13:04:12 (1789059852) [ 1554.172859] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1556.002547] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 13:04:29 (1789059869) [ 1566.513706] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 13:04:40 (1789059880) [ 1579.316951] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 13:04:52 (1789059892) [ 1614.544723] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 13:05:28 (1789059928) [ 1623.165076] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 13:05:36 (1789059936) [ 1631.693895] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 13:05:45 (1789059945) [ 1632.112909] Lustre: *** cfs_fail_loc=319, val=0*** [ 1640.937784] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 13:05:54 (1789059954) [ 1732.178961] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 13:07:25 (1789060045) [ 1788.148968] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 13:08:21 (1789060101) [ 1799.848440] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 13:08:32 (1789060112) [ 1800.383411] Lustre: *** cfs_fail_loc=409, val=0*** [ 1800.719764] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [0-1048575], original client csum 1d66faa2 (type 20), server csum 1d66faa1 (type 20), client csum now 1d66faa1 [ 1800.777623] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0348ff2300 x1875963709358208/t8589936190(8589936190) o4->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/448 e 0 to 0 dl 1789060131 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1805.128930] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1805.502360] Lustre: *** cfs_fail_loc=408, val=0*** [ 1805.530457] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [1048576-2097151], client e2dbde98/e2dbde98, server 7d253e67, cksum_type 1 [ 1805.555151] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0348ff3b80 x1875963709361024/t0(0) o3->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/440 e 0 to 0 dl 1789060136 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1810.794544] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1811.316886] Lustre: *** cfs_fail_loc=408, val=0*** [ 1811.326876] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [0-1048575], client 51559360/51559360, server 8d7d94b4, cksum_type 2 [ 1811.346203] LustreError: 2365:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0358f74e00 x1875963709363328/t0(0) o3->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/440 e 0 to 0 dl 1789060142 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1816.065746] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1816.418434] Lustre: *** cfs_fail_loc=408, val=0*** [ 1816.429486] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [0-1048575], client 6ef7c7fd/6ef7c7fd, server d3f0af5f, cksum_type 4 [ 1816.470227] LustreError: 2365:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0358f77800 x1875963709365760/t0(0) o3->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/440 e 0 to 0 dl 1789060147 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1821.986049] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1822.463849] Lustre: *** cfs_fail_loc=408, val=0*** [ 1822.485784] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [0-1048575], client 1e31164c/1e31164c, server be8b16f6, cksum_type 10 [ 1822.527531] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0348ff0380 x1875963709368064/t0(0) o3->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/440 e 0 to 0 dl 1789060153 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1827.824032] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1828.695442] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [1048576-2097151], client d32101a1/d32101a1, server 2d7001ce, cksum_type 20 [ 1832.830923] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1833.725277] Lustre: *** cfs_fail_loc=408, val=0*** [ 1833.732101] Lustre: Skipped 1 previous similar message [ 1833.746053] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0348ff0380 x1875963709371392/t0(0) o3->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/440 e 0 to 0 dl 1789060165 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1833.770329] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 1 previous similar message [ 1838.991949] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1839.523588] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc33:0x0] object 0x240000400:3786 extent [0-1048575], client 6b5cfddf/6b5cfddf, server 240efc3b, cksum_type 80 [ 1839.552677] LustreError: Skipped 1 previous similar message [ 1844.237925] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1854.052862] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 13:09:27 (1789060167) [ 1860.184265] Lustre: *** cfs_fail_loc=408, val=0*** [ 1860.186312] Lustre: Skipped 1 previous similar message [ 1860.195987] Lustre: 2367:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000406:0xc34:0x0]:[0-1048575]-c984f9f7-1d66faa1: dumping checksum data [ 1860.231938] LustreError: dumping log to /tmp/lustre-log.1789060175.2367 [ 1860.555810] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3787 extent [0-1048575], client c984f9f7/c984f9f7, server 1d66faa1, cksum_type 20 [ 1860.599896] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f0348ff3480 x1875963709381248/t0(0) o3->lustre-OST0000-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/440 e 0 to 0 dl 1789060191 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 1860.629133] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 1 previous similar message [ 1897.969744] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 13:10:11 (1789060211) [ 1898.389110] Lustre: *** cfs_fail_loc=409, val=0*** [ 1898.413426] LustreError: 2364:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff9f0349768800: granted 3407872 but already consumed 13631488 [ 1898.784109] LustreError: lustre-OST0001-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.201.142@tcp inode [0x200000406:0xc36:0x0] object 0x280000400:3777 extent [0-1048575], original client csum 30ec5402 (type 20), server csum 30ec5401 (type 20), client csum now 30ec5401 [ 1898.805454] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9f03472f7b80 x1875963709386112/t4294971464(4294971464) o4->lustre-OST0001-osc-ffff9f0349768800@192.168.201.142@tcp:6/4 lens 488/448 e 0 to 0 dl 1789060229 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 1900.683243] LustreError: lustre-OST0001-osc-ffff9f0349768800: BAD READ CHECKSUM: from 192.168.201.142@tcp inode [0x200000406:0xc36:0x0] object 0x280000400:3777 extent [0-1048575], client 53195492/53195492, server 30ec5401, cksum_type 20 [ 1911.654984] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 13:10:25 (1789060225) [ 1914.487910] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1915.003336] LustreError: 2364:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9f0349768800: granted 3407872 but already consumed 13631488 [ 1915.439168] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.142@tcp inode [0x200000406:0xc37:0x0] object 0x240000400:3788 extent [1048576-2097151], original client csum b2f1b12 (type 1), server csum b2f1b11 (type 1), client csum now b2f1b12 [ 1915.507446] LustreError: Skipped 3 previous similar messages [ 1915.646918] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9f0349768800: too many resent retries for object: 9663677440:3788: rc = -11 [ 1917.053911] LustreError: 2365:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9f0349768800: too many resent retries for object: 9663677440:3788: rc = -11 [ 1917.069337] LustreError: 2365:0:(osc_request.c:2607:brw_interpret()) Skipped 2 previous similar messages [ 1919.368407] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1919.960336] LustreError: lustre-OST0001-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.142@tcp inode [0x200000406:0xc38:0x0] object 0x280000400:3778 extent [1048576-2097151], original client csum 19eeae62 (type 2), server csum 19eeae61 (type 2), client csum now 19eeae62 [ 1920.014071] LustreError: Skipped 13 previous similar messages [ 1921.336988] LustreError: 2368:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9f0349768800: too many resent retries for object: 10737419264:3778: rc = -11 [ 1921.355327] LustreError: 2368:0:(osc_request.c:2607:brw_interpret()) Skipped 4 previous similar messages [ 1924.180280] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1924.846222] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.142@tcp inode [0x200000406:0xc39:0x0] object 0x240000400:3789 extent [1048576-2097151], original client csum b5ea7f3c (type 4), server csum b5ea7f3b (type 4), client csum now b5ea7f3c [ 1924.888462] LustreError: Skipped 15 previous similar messages [ 1926.245409] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9f0349768800: too many resent retries for object: 9663677440:3789: rc = -11 [ 1926.269372] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) Skipped 7 previous similar messages [ 1928.454222] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1930.541392] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9f0349768800: too many resent retries for object: 10737419264:3779: rc = -11 [ 1930.561215] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) Skipped 7 previous similar messages [ 1932.864931] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1933.378668] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.142@tcp inode [0x200000406:0xc3b:0x0] object 0x240000400:3790 extent [6291456-7340031], original client csum 30ec5402 (type 20), server csum 30ec5401 (type 20), client csum now 30ec5402 [ 1933.420840] LustreError: Skipped 33 previous similar messages [ 1936.802796] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1938.626915] LustreError: 2365:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9f0349768800: too many resent retries for object: 10737419264:3780: rc = -11 [ 1938.641621] LustreError: 2365:0:(osc_request.c:2607:brw_interpret()) Skipped 16 previous similar messages [ 1940.468911] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1951.595312] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1953.828712] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 13:11:07 (1789060267) [ 1955.866351] LustreError: lustre-OST0000-osc-ffff9f0349768800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.142@tcp inode [0x200000406:0xc3e:0x0] object 0x240000400:3792 extent [0-1048575], original client csum 1d66faa1 (type 20), server csum 480ce478 (type 20), client csum now 1d66faa1 [ 1955.880290] LustreError: Skipped 43 previous similar messages [ 1973.407556] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 13:11:27 (1789060287) [ 1979.824852] LustreError: 56689:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0349768800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1979.846156] LustreError: 56689:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1979.943589] Lustre: Unmounted lustre-client [ 1980.629512] Lustre: Mounted lustre-client [ 1987.542019] LustreError: 56790:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0358e5a000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1987.552924] LustreError: 56790:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1987.622199] Lustre: Unmounted lustre-client [ 1988.206058] Lustre: Mounted lustre-client [ 1993.644818] LustreError: 56874:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0347247000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1993.663660] LustreError: 56874:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1993.801369] Lustre: Unmounted lustre-client [ 1994.419160] Lustre: Mounted lustre-client [ 1998.006782] LustreError: 56947:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0349768800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1998.021546] LustreError: 56947:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1998.116121] Lustre: Unmounted lustre-client [ 1998.778561] Lustre: Mounted lustre-client [ 2002.197621] LustreError: 57019:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0347f13800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2002.206805] LustreError: 57019:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 2002.299618] Lustre: Unmounted lustre-client [ 2003.019161] Lustre: Mounted lustre-client [ 2018.014128] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 13:12:10 (1789060330) [ 2020.914518] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 2023.044359] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2028.470374] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2030.369423] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 0 sec [ 2035.412496] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2037.240332] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2039.621368] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2045.444828] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2056.677770] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 8 sec [ 2061.599330] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2063.854815] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2066.373618] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2072.350633] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2081.741045] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 7 sec [ 2086.262374] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2088.351897] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2090.629438] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2095.284796] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2106.936617] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 9 sec [ 2112.421474] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2114.218840] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2116.785122] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2122.355914] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2132.954335] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 8 sec [ 2137.751696] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2139.901671] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2142.024771] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2146.281604] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2159.065677] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 10 sec [ 2164.025738] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2165.829836] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2168.310588] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2173.838544] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2184.429280] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in IDLE state after 8 sec [ 2189.195568] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid 50 [ 2190.758633] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0353d3e800.ost_server_uuid in FULL state after 0 sec [ 2200.205779] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2202.782428] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 13:15:16 (1789060516) [ 2212.225806] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 13:15:25 (1789060525) [ 2214.706488] Lustre: DEBUG MARKER: SKIP: sanity test_77n f77n.sanity blocks not contiguous around hole [ 2217.308903] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 13:15:30 (1789060530) [ 2232.660890] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 13:15:46 (1789060546) [ 2245.382122] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 13:15:59 (1789060559) [ 2265.931929] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 13:16:19 (1789060579) [ 2277.482256] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 13:16:31 (1789060591) [ 2287.745950] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 13:16:41 (1789060601) [ 2297.007501] Lustre: DEBUG MARKER: == sanity test 84: lz4/lz4hc/lzstd compression/decompression kernel module ========================================================== 13:16:50 (1789060610) [ 2297.531712] lustre_kcompr_5302: ***** [ 2297.534494] lustre_kcompr_5302: (de)compression test on random binary data [ 2297.538094] lustre_kcompr_5302: ***** [ 2297.565268] lustre_kcompr_5302: compr lz4(1) in 64kB chunks took 6784 us (589 MB/s), compress ratio: 98.19 [ 2297.572989] lustre_kcompr_5302: compr lz4(1) in 128kB chunks took 1743 us (2294 MB/s), compress ratio: 102.79 [ 2297.583715] lustre_kcompr_5302: compr lz4(1) in 256kB chunks took 4486 us (891 MB/s), compress ratio: 105.72 [ 2297.594667] lustre_kcompr_5302: compr lz4(1) in 512kB chunks took 3184 us (1256 MB/s), compress ratio: 107.14 [ 2297.603529] lustre_kcompr_5302: compr lz4(1) in 1024kB chunks took 1847 us (2165 MB/s), compress ratio: 108.14 [ 2297.611372] lustre_kcompr_5302: compr lz4(1) in 2048kB chunks took 2523 us (1585 MB/s), compress ratio: 108.16 [ 2297.620560] lustre_kcompr_5302: compr lz4(1) in 4096kB chunks took 1596 us (2506 MB/s), compress ratio: 107.89 [ 2297.637665] lustre_kcompr_5302: decompr lz4(1) took 2318 us (15 MB/s) [ 2297.646981] lustre_kcompr_5302: test_comp_compress_decompress(lz4,1) ret 0 [ 2297.656734] lustre_kcompr_5302: acompr lz4(1) of 128kB chunks took 107 us (1168 MB/s), compress ratio: 96.23 [ 2297.661768] lustre_kcompr_5302: adecompr lz4(1) took 135 us (9 MB/s) [ 2297.667850] lustre_kcompr_5302: test_acomp_compress_decompress(lz4,1) ret 0 [ 2297.681274] lustre_kcompr_5302: compr lz4(4) in 64kB chunks took 2662 us (1502 MB/s), compress ratio: 83.47 [ 2297.685878] lustre_kcompr_5302: compr lz4(4) in 128kB chunks took 1138 us (3514 MB/s), compress ratio: 93.65 [ 2297.695188] lustre_kcompr_5302: compr lz4(4) in 256kB chunks took 2067 us (1935 MB/s), compress ratio: 100.04 [ 2297.707284] lustre_kcompr_5302: compr lz4(4) in 512kB chunks took 1175 us (3404 MB/s), compress ratio: 103.36 [ 2297.718108] lustre_kcompr_5302: compr lz4(4) in 1024kB chunks took 2059 us (1942 MB/s), compress ratio: 105.53 [ 2297.727486] lustre_kcompr_5302: compr lz4(4) in 2048kB chunks took 1997 us (2003 MB/s), compress ratio: 106.23 [ 2297.735646] lustre_kcompr_5302: compr lz4(4) in 4096kB chunks took 1930 us (2072 MB/s), compress ratio: 106.58 [ 2297.764678] lustre_kcompr_5302: decompr lz4(4) took 3696 us (10 MB/s) [ 2297.768997] lustre_kcompr_5302: test_comp_compress_decompress(lz4,4) ret 0 [ 2297.772313] lustre_kcompr_5302: acompr lz4(4) of 128kB chunks took 109 us (1146 MB/s), compress ratio: 85.55 [ 2297.778528] lustre_kcompr_5302: adecompr lz4(4) took 150 us (9 MB/s) [ 2297.788367] lustre_kcompr_5302: test_acomp_compress_decompress(lz4,4) ret 0 [ 2297.816898] lustre_kcompr_5302: compr lz4(9) in 64kB chunks took 1522 us (2628 MB/s), compress ratio: 61.69 [ 2297.829525] lustre_kcompr_5302: compr lz4(9) in 128kB chunks took 3882 us (1030 MB/s), compress ratio: 76.37 [ 2297.842383] lustre_kcompr_5302: compr lz4(9) in 256kB chunks took 3104 us (1288 MB/s), compress ratio: 88.87 [ 2297.864079] lustre_kcompr_5302: compr lz4(9) in 512kB chunks took 3708 us (1078 MB/s), compress ratio: 96.07 [ 2297.883870] lustre_kcompr_5302: compr lz4(9) in 1024kB chunks took 2569 us (1557 MB/s), compress ratio: 99.59 [ 2297.895881] lustre_kcompr_5302: compr lz4(9) in 2048kB chunks took 1249 us (3202 MB/s), compress ratio: 100.94 [ 2297.908322] lustre_kcompr_5302: compr lz4(9) in 4096kB chunks took 2516 us (1589 MB/s), compress ratio: 102.09 [ 2297.944898] lustre_kcompr_5302: decompr lz4(9) took 9769 us (4 MB/s) [ 2297.950797] lustre_kcompr_5302: test_comp_compress_decompress(lz4,9) ret 0 [ 2297.957729] lustre_kcompr_5302: acompr lz4(9) of 128kB chunks took 116 us (1077 MB/s), compress ratio: 70.81 [ 2297.978715] lustre_kcompr_5302: adecompr lz4(9) took 400 us (4 MB/s) [ 2298.002970] lustre_kcompr_5302: test_acomp_compress_decompress(lz4,9) ret 0 [ 2298.021325] lustre_kcompr_5302: compr lz4(15) in 64kB chunks took 2205 us (1814 MB/s), compress ratio: 29.35 [ 2298.033950] lustre_kcompr_5302: compr lz4(15) in 128kB chunks took 3283 us (1218 MB/s), compress ratio: 43.46 [ 2298.059566] lustre_kcompr_5302: compr lz4(15) in 256kB chunks took 5507 us (726 MB/s), compress ratio: 58.03 [ 2298.094683] lustre_kcompr_5302: compr lz4(15) in 512kB chunks took 5402 us (740 MB/s), compress ratio: 71.51 [ 2298.114940] lustre_kcompr_5302: compr lz4(15) in 1024kB chunks took 4167 us (959 MB/s), compress ratio: 80.08 [ 2298.132336] lustre_kcompr_5302: compr lz4(15) in 2048kB chunks took 2662 us (1502 MB/s), compress ratio: 86.17 [ 2298.146675] lustre_kcompr_5302: compr lz4(15) in 4096kB chunks took 3032 us (1319 MB/s), compress ratio: 88.45 [ 2298.168323] lustre_kcompr_5302: decompr lz4(15) took 3994 us (11 MB/s) [ 2298.178802] lustre_kcompr_5302: test_comp_compress_decompress(lz4,15) ret 0 [ 2298.204326] lustre_kcompr_5302: acompr lz4(15) of 128kB chunks took 104 us (1201 MB/s), compress ratio: 38.77 [ 2298.217850] lustre_kcompr_5302: adecompr lz4(15) took 2590 us (1 MB/s) [ 2298.244466] lustre_kcompr_5302: test_acomp_compress_decompress(lz4,15) ret 0 [ 2298.300649] lustre_kcompr_5302: compr lz4hc(1) in 64kB chunks took 34048 us (117 MB/s), compress ratio: 98.58 [ 2298.379556] lustre_kcompr_5302: compr lz4hc(1) in 128kB chunks took 66265 us (60 MB/s), compress ratio: 104.62 [ 2298.441963] lustre_kcompr_5302: compr lz4hc(1) in 256kB chunks took 46019 us (86 MB/s), compress ratio: 107.93 [ 2298.517049] lustre_kcompr_5302: compr lz4hc(1) in 512kB chunks took 64010 us (62 MB/s), compress ratio: 109.65 [ 2298.568352] lustre_kcompr_5302: compr lz4hc(1) in 1024kB chunks took 40862 us (97 MB/s), compress ratio: 110.55 [ 2298.637370] lustre_kcompr_5302: compr lz4hc(1) in 2048kB chunks took 56899 us (70 MB/s), compress ratio: 111.00 [ 2298.689503] lustre_kcompr_5302: compr lz4hc(1) in 4096kB chunks took 45296 us (88 MB/s), compress ratio: 111.22 [ 2298.716720] lustre_kcompr_5302: decompr lz4hc(1) took 4696 us (7 MB/s) [ 2298.725449] lustre_kcompr_5302: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2298.733689] lustre_kcompr_5302: acompr lz4hc(1) of 128kB chunks took 1112 us (112 MB/s), compress ratio: 93.55 [ 2298.741816] lustre_kcompr_5302: adecompr lz4hc(1) took 124 us (10 MB/s) [ 2298.765800] lustre_kcompr_5302: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2298.894734] lustre_kcompr_5302: compr lz4hc(3) in 64kB chunks took 99735 us (40 MB/s), compress ratio: 99.04 [ 2298.946312] lustre_kcompr_5302: compr lz4hc(3) in 128kB chunks took 37422 us (106 MB/s), compress ratio: 105.13 [ 2299.001483] lustre_kcompr_5302: compr lz4hc(3) in 256kB chunks took 50696 us (78 MB/s), compress ratio: 108.46 [ 2299.051784] lustre_kcompr_5302: compr lz4hc(3) in 512kB chunks took 44628 us (89 MB/s), compress ratio: 110.20 [ 2299.098287] lustre_kcompr_5302: compr lz4hc(3) in 1024kB chunks took 38084 us (105 MB/s), compress ratio: 111.08 [ 2299.219593] lustre_kcompr_5302: compr lz4hc(3) in 2048kB chunks took 103343 us (38 MB/s), compress ratio: 111.54 [ 2299.314643] lustre_kcompr_5302: compr lz4hc(3) in 4096kB chunks took 75938 us (52 MB/s), compress ratio: 111.76 [ 2299.345694] lustre_kcompr_5302: decompr lz4hc(3) took 2503 us (14 MB/s) [ 2299.356560] lustre_kcompr_5302: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2299.368052] lustre_kcompr_5302: acompr lz4hc(3) of 128kB chunks took 3100 us (40 MB/s), compress ratio: 93.82 [ 2299.374188] lustre_kcompr_5302: adecompr lz4hc(3) took 96 us (13 MB/s) [ 2299.383385] lustre_kcompr_5302: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2300.325731] lustre_kcompr_5302: compr lz4hc(8) in 64kB chunks took 924000 us (4 MB/s), compress ratio: 105.47 [ 2301.391916] lustre_kcompr_5302: compr lz4hc(8) in 128kB chunks took 1051354 us (3 MB/s), compress ratio: 112.61 [ 2302.468895] lustre_kcompr_5302: compr lz4hc(8) in 256kB chunks took 1073559 us (3 MB/s), compress ratio: 116.58 [ 2303.536734] lustre_kcompr_5302: compr lz4hc(8) in 512kB chunks took 1055065 us (3 MB/s), compress ratio: 118.68 [ 2304.841925] lustre_kcompr_5302: compr lz4hc(8) in 1024kB chunks took 1294553 us (3 MB/s), compress ratio: 119.70 [ 2306.208532] lustre_kcompr_5302: compr lz4hc(8) in 2048kB chunks took 1354889 us (2 MB/s), compress ratio: 120.23 [ 2307.718497] lustre_kcompr_5302: compr lz4hc(8) in 4096kB chunks took 1491168 us (2 MB/s), compress ratio: 120.50 [ 2307.754802] lustre_kcompr_5302: decompr lz4hc(8) took 12487 us (2 MB/s) [ 2307.763833] lustre_kcompr_5302: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2307.814660] lustre_kcompr_5302: acompr lz4hc(8) of 128kB chunks took 33121 us (3 MB/s), compress ratio: 102.08 [ 2307.825453] lustre_kcompr_5302: adecompr lz4hc(8) took 1322 us (0 MB/s) [ 2307.847235] lustre_kcompr_5302: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2309.338397] lustre_kcompr_5302: compr lz4hc(15) in 64kB chunks took 1451127 us (2 MB/s), compress ratio: 106.06 [ 2310.820465] lustre_kcompr_5302: compr lz4hc(15) in 128kB chunks took 1470711 us (2 MB/s), compress ratio: 113.68 [ 2312.188365] lustre_kcompr_5302: compr lz4hc(15) in 256kB chunks took 1339203 us (2 MB/s), compress ratio: 117.99 [ 2313.665467] lustre_kcompr_5302: compr lz4hc(15) in 512kB chunks took 1466999 us (2 MB/s), compress ratio: 120.27 [ 2315.389782] lustre_kcompr_5302: compr lz4hc(15) in 1024kB chunks took 1702761 us (2 MB/s), compress ratio: 121.36 [ 2316.847532] lustre_kcompr_5302: compr lz4hc(15) in 2048kB chunks took 1442036 us (2 MB/s), compress ratio: 121.90 [ 2318.698813] lustre_kcompr_5302: compr lz4hc(15) in 4096kB chunks took 1845048 us (2 MB/s), compress ratio: 122.23 [ 2318.724218] lustre_kcompr_5302: decompr lz4hc(15) took 6571 us (4 MB/s) [ 2318.728283] lustre_kcompr_5302: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2318.830949] lustre_kcompr_5302: acompr lz4hc(15) of 128kB chunks took 82524 us (1 MB/s), compress ratio: 103.04 [ 2318.844189] lustre_kcompr_5302: adecompr lz4hc(15) took 109 us (11 MB/s) [ 2318.856345] lustre_kcompr_5302: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2318.867472] lustre_kcompr_5302: compr lzo(-1) in 64kB chunks took 6083 us (657 MB/s), compress ratio: 82.57 [ 2318.877454] lustre_kcompr_5302: compr lzo(-1) in 128kB chunks took 3622 us (1104 MB/s), compress ratio: 87.58 [ 2318.894340] lustre_kcompr_5302: compr lzo(-1) in 256kB chunks took 5557 us (719 MB/s), compress ratio: 88.05 [ 2318.918784] lustre_kcompr_5302: compr lzo(-1) in 512kB chunks took 9382 us (426 MB/s), compress ratio: 88.98 [ 2318.935339] lustre_kcompr_5302: compr lzo(-1) in 1024kB chunks took 2054 us (1947 MB/s), compress ratio: 88.93 [ 2318.961078] lustre_kcompr_5302: compr lzo(-1) in 2048kB chunks took 4038 us (990 MB/s), compress ratio: 89.68 [ 2318.980410] lustre_kcompr_5302: compr lzo(-1) in 4096kB chunks took 2010 us (1990 MB/s), compress ratio: 89.80 [ 2319.007853] lustre_kcompr_5302: decompr lzo(-1) took 3292 us (13 MB/s) [ 2319.018346] lustre_kcompr_5302: test_comp_compress_decompress(lzo,-1) ret 0 [ 2319.029268] lustre_kcompr_5302: acompr lzo(-1) of 128kB chunks took 274 us (456 MB/s), compress ratio: 83.43 [ 2319.037840] lustre_kcompr_5302: adecompr lzo(-1) took 114 us (13 MB/s) [ 2319.063604] lustre_kcompr_5302: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2319.624217] lustre_kcompr_5302: compr deflate(1) in 64kB chunks took 533311 us (7 MB/s), compress ratio: 98.71 [ 2320.100943] lustre_kcompr_5302: compr deflate(1) in 128kB chunks took 473913 us (8 MB/s), compress ratio: 109.04 [ 2320.712322] lustre_kcompr_5302: compr deflate(1) in 256kB chunks took 598564 us (6 MB/s), compress ratio: 115.59 [ 2321.261518] lustre_kcompr_5302: compr deflate(1) in 512kB chunks took 540023 us (7 MB/s), compress ratio: 119.58 [ 2321.900948] lustre_kcompr_5302: compr deflate(1) in 1024kB chunks took 624223 us (6 MB/s), compress ratio: 121.54 [ 2322.390270] lustre_kcompr_5302: compr deflate(1) in 2048kB chunks took 482400 us (8 MB/s), compress ratio: 122.52 [ 2322.772933] lustre_kcompr_5302: compr deflate(1) in 4096kB chunks took 359717 us (11 MB/s), compress ratio: 122.82 [ 2322.798056] lustre_kcompr_5302: decompr deflate(1) took 5294 us (6 MB/s) [ 2322.806678] lustre_kcompr_5302: test_comp_compress_decompress(deflate,1) ret 0 [ 2322.840585] lustre_kcompr_5302: acompr deflate(1) of 128kB chunks took 24909 us (5 MB/s), compress ratio: 97.74 [ 2322.849241] lustre_kcompr_5302: adecompr deflate(1) took 210 us (6 MB/s) [ 2322.865662] lustre_kcompr_5302: test_acomp_compress_decompress(deflate,1) ret 0 [ 2323.362921] lustre_kcompr_5302: compr deflate(6) in 64kB chunks took 471608 us (8 MB/s), compress ratio: 98.71 [ 2323.942939] lustre_kcompr_5302: compr deflate(6) in 128kB chunks took 571331 us (7 MB/s), compress ratio: 109.04 [ 2324.575067] lustre_kcompr_5302: compr deflate(6) in 256kB chunks took 615976 us (6 MB/s), compress ratio: 115.59 [ 2325.126878] lustre_kcompr_5302: compr deflate(6) in 512kB chunks took 538895 us (7 MB/s), compress ratio: 119.58 [ 2325.823255] lustre_kcompr_5302: compr deflate(6) in 1024kB chunks took 692668 us (5 MB/s), compress ratio: 121.54 [ 2326.449482] lustre_kcompr_5302: compr deflate(6) in 2048kB chunks took 616234 us (6 MB/s), compress ratio: 122.52 [ 2327.075759] lustre_kcompr_5302: compr deflate(6) in 4096kB chunks took 618478 us (6 MB/s), compress ratio: 122.82 [ 2327.128594] lustre_kcompr_5302: decompr deflate(6) took 16225 us (2 MB/s) [ 2327.152358] lustre_kcompr_5302: test_comp_compress_decompress(deflate,6) ret 0 [ 2327.176653] lustre_kcompr_5302: acompr deflate(6) of 128kB chunks took 15888 us (7 MB/s), compress ratio: 97.74 [ 2327.193875] lustre_kcompr_5302: adecompr deflate(6) took 207 us (6 MB/s) [ 2327.216865] lustre_kcompr_5302: test_acomp_compress_decompress(deflate,6) ret 0 [ 2327.750952] lustre_kcompr_5302: compr deflate(9) in 64kB chunks took 492117 us (8 MB/s), compress ratio: 98.71 [ 2328.216017] lustre_kcompr_5302: compr deflate(9) in 128kB chunks took 458754 us (8 MB/s), compress ratio: 109.04 [ 2328.785104] lustre_kcompr_5302: compr deflate(9) in 256kB chunks took 555682 us (7 MB/s), compress ratio: 115.59 [ 2329.368523] lustre_kcompr_5302: compr deflate(9) in 512kB chunks took 568484 us (7 MB/s), compress ratio: 119.58 [ 2330.009472] lustre_kcompr_5302: compr deflate(9) in 1024kB chunks took 627349 us (6 MB/s), compress ratio: 121.54 [ 2330.668249] lustre_kcompr_5302: compr deflate(9) in 2048kB chunks took 645785 us (6 MB/s), compress ratio: 122.52 [ 2331.358232] lustre_kcompr_5302: compr deflate(9) in 4096kB chunks took 674658 us (5 MB/s), compress ratio: 122.82 [ 2331.400611] lustre_kcompr_5302: decompr deflate(9) took 12763 us (2 MB/s) [ 2331.426791] lustre_kcompr_5302: test_comp_compress_decompress(deflate,9) ret 0 [ 2331.466178] lustre_kcompr_5302: acompr deflate(9) of 128kB chunks took 29591 us (4 MB/s), compress ratio: 97.74 [ 2331.479708] lustre_kcompr_5302: adecompr deflate(9) took 206 us (6 MB/s) [ 2331.495440] lustre_kcompr_5302: test_acomp_compress_decompress(deflate,9) ret 0 [ 2331.515633] lustre_kcompr_5302: compr zstd(0) in 64kB chunks took 8055 us (496 MB/s), compress ratio: 161.19 [ 2331.574044] lustre_kcompr_5302: compr zstd(0) in 128kB chunks took 47348 us (84 MB/s), compress ratio: 195.34 [ 2331.620423] lustre_kcompr_5302: compr zstd(0) in 256kB chunks took 33645 us (118 MB/s), compress ratio: 207.91 [ 2331.667187] lustre_kcompr_5302: compr zstd(0) in 512kB chunks took 42349 us (94 MB/s), compress ratio: 215.98 [ 2331.694569] lustre_kcompr_5302: compr zstd(0) in 1024kB chunks took 17204 us (232 MB/s), compress ratio: 219.27 [ 2331.717644] lustre_kcompr_5302: compr zstd(0) in 2048kB chunks took 13956 us (286 MB/s), compress ratio: 218.93 [ 2331.730974] lustre_kcompr_5302: compr zstd(0) in 4096kB chunks took 7834 us (510 MB/s), compress ratio: 219.71 [ 2331.744261] lustre_kcompr_5302: decompr zstd(0) took 2605 us (6 MB/s) [ 2331.748974] lustre_kcompr_5302: test_comp_compress_decompress(zstd,0) ret 0 [ 2331.754103] lustre_kcompr_5302: acompr zstd(0) of 128kB chunks took 346 us (361 MB/s), compress ratio: 167.82 [ 2331.764227] lustre_kcompr_5302: adecompr zstd(0) took 165 us (4 MB/s) [ 2331.792860] lustre_kcompr_5302: test_acomp_compress_decompress(zstd,0) ret 0 [ 2331.824488] lustre_kcompr_5302: compr zstd(1) in 64kB chunks took 5022 us (796 MB/s), compress ratio: 160.53 [ 2331.839431] lustre_kcompr_5302: compr zstd(1) in 128kB chunks took 6542 us (611 MB/s), compress ratio: 194.56 [ 2331.850979] lustre_kcompr_5302: compr zstd(1) in 256kB chunks took 4548 us (879 MB/s), compress ratio: 206.06 [ 2331.869671] lustre_kcompr_5302: compr zstd(1) in 512kB chunks took 12055 us (331 MB/s), compress ratio: 212.33 [ 2331.880546] lustre_kcompr_5302: compr zstd(1) in 1024kB chunks took 3081 us (1298 MB/s), compress ratio: 216.48 [ 2331.888928] lustre_kcompr_5302: compr zstd(1) in 2048kB chunks took 2775 us (1441 MB/s), compress ratio: 217.05 [ 2331.907712] lustre_kcompr_5302: compr zstd(1) in 4096kB chunks took 7037 us (568 MB/s), compress ratio: 215.81 [ 2331.927195] lustre_kcompr_5302: decompr zstd(1) took 6194 us (2 MB/s) [ 2331.945770] lustre_kcompr_5302: test_comp_compress_decompress(zstd,1) ret 0 [ 2331.951036] lustre_kcompr_5302: acompr zstd(1) of 128kB chunks took 226 us (553 MB/s), compress ratio: 167.82 [ 2331.961379] lustre_kcompr_5302: adecompr zstd(1) took 522 us (1 MB/s) [ 2331.990915] lustre_kcompr_5302: test_acomp_compress_decompress(zstd,1) ret 0 [ 2332.354102] lustre_kcompr_5302: compr zstd(10) in 64kB chunks took 334085 us (11 MB/s), compress ratio: 163.34 [ 2332.599451] lustre_kcompr_5302: compr zstd(10) in 128kB chunks took 238670 us (16 MB/s), compress ratio: 186.92 [ 2332.916794] lustre_kcompr_5302: compr zstd(10) in 256kB chunks took 302414 us (13 MB/s), compress ratio: 198.57 [ 2333.209873] lustre_kcompr_5302: compr zstd(10) in 512kB chunks took 285698 us (14 MB/s), compress ratio: 220.74 [ 2333.632468] lustre_kcompr_5302: compr zstd(10) in 1024kB chunks took 415013 us (9 MB/s), compress ratio: 225.36 [ 2334.351444] lustre_kcompr_5302: compr zstd(10) in 2048kB chunks took 699322 us (5 MB/s), compress ratio: 227.60 [ 2334.465920] lustre_kcompr_5302: compr zstd(10) in 4096kB chunks took 101941 us (39 MB/s), compress ratio: 228.98 [ 2334.495809] lustre_kcompr_5302: decompr zstd(10) took 5979 us (2 MB/s) [ 2334.503753] lustre_kcompr_5302: test_comp_compress_decompress(zstd,10) ret 0 [ 2334.513533] lustre_kcompr_5302: acompr zstd(10) of 128kB chunks took 5027 us (24 MB/s), compress ratio: 159.06 [ 2334.527787] lustre_kcompr_5302: adecompr zstd(10) took 132 us (5 MB/s) [ 2334.544515] lustre_kcompr_5302: test_acomp_compress_decompress(zstd,10) ret 0 [ 2335.603189] lustre_kcompr_5302: compr zstd(15) in 64kB chunks took 1022414 us (3 MB/s), compress ratio: 172.67 [ 2336.448939] lustre_kcompr_5302: compr zstd(15) in 128kB chunks took 837924 us (4 MB/s), compress ratio: 199.26 [ 2337.291734] lustre_kcompr_5302: compr zstd(15) in 256kB chunks took 828687 us (4 MB/s), compress ratio: 213.40 [ 2338.032448] lustre_kcompr_5302: compr zstd(15) in 512kB chunks took 719105 us (5 MB/s), compress ratio: 221.27 [ 2338.818456] lustre_kcompr_5302: compr zstd(15) in 1024kB chunks took 759647 us (5 MB/s), compress ratio: 226.15 [ 2340.391545] lustre_kcompr_5302: compr zstd(15) in 2048kB chunks took 1567390 us (2 MB/s), compress ratio: 226.09 [ 2342.279863] lustre_kcompr_5302: compr zstd(15) in 4096kB chunks took 1870543 us (2 MB/s), compress ratio: 225.08 [ 2342.305839] lustre_kcompr_5302: decompr zstd(15) took 5543 us (3 MB/s) [ 2342.323156] lustre_kcompr_5302: test_comp_compress_decompress(zstd,15) ret 0 [ 2342.363841] lustre_kcompr_5302: acompr zstd(15) of 128kB chunks took 30378 us (4 MB/s), compress ratio: 171.56 [ 2342.377607] lustre_kcompr_5302: adecompr zstd(15) took 164 us (4 MB/s) [ 2342.449285] lustre_kcompr_5302: test_acomp_compress_decompress(zstd,15) ret 0 [ 2342.503560] lustre_kcompr_5302: compr zstdfast(1) in 64kB chunks took 3310 us (1208 MB/s), compress ratio: 160.51 [ 2342.525564] lustre_kcompr_5302: compr zstdfast(1) in 128kB chunks took 8187 us (488 MB/s), compress ratio: 194.48 [ 2342.543909] lustre_kcompr_5302: compr zstdfast(1) in 256kB chunks took 7523 us (531 MB/s), compress ratio: 205.92 [ 2342.570279] lustre_kcompr_5302: compr zstdfast(1) in 512kB chunks took 14818 us (269 MB/s), compress ratio: 212.33 [ 2342.582547] lustre_kcompr_5302: compr zstdfast(1) in 1024kB chunks took 4604 us (868 MB/s), compress ratio: 216.48 [ 2342.595622] lustre_kcompr_5302: compr zstdfast(1) in 2048kB chunks took 6222 us (642 MB/s), compress ratio: 217.05 [ 2342.615281] lustre_kcompr_5302: compr zstdfast(1) in 4096kB chunks took 3411 us (1172 MB/s), compress ratio: 215.81 [ 2342.635291] lustre_kcompr_5302: decompr zstdfast(1) took 4285 us (4 MB/s) [ 2342.649366] lustre_kcompr_5302: test_comp_compress_decompress(zstdfast,1) ret 0 [ 2342.659590] lustre_kcompr_5302: acompr zstdfast(1) of 128kB chunks took 700 us (178 MB/s), compress ratio: 167.82 [ 2342.672476] lustre_kcompr_5302: adecompr zstdfast(1) took 1197 us (0 MB/s) [ 2342.686670] lustre_kcompr_5302: test_acomp_compress_decompress(zstdfast,1) ret 0 [ 2342.738666] lustre_kcompr_5302: compr zstdfast(5) in 64kB chunks took 15929 us (251 MB/s), compress ratio: 141.70 [ 2342.756364] lustre_kcompr_5302: compr zstdfast(5) in 128kB chunks took 2290 us (1746 MB/s), compress ratio: 168.66 [ 2342.789830] lustre_kcompr_5302: compr zstdfast(5) in 256kB chunks took 4683 us (854 MB/s), compress ratio: 177.61 [ 2342.818736] lustre_kcompr_5302: compr zstdfast(5) in 512kB chunks took 2110 us (1895 MB/s), compress ratio: 183.23 [ 2342.835682] lustre_kcompr_5302: compr zstdfast(5) in 1024kB chunks took 9388 us (426 MB/s), compress ratio: 186.10 [ 2342.853443] lustre_kcompr_5302: compr zstdfast(5) in 2048kB chunks took 7884 us (507 MB/s), compress ratio: 187.43 [ 2342.877925] lustre_kcompr_5302: compr zstdfast(5) in 4096kB chunks took 4324 us (925 MB/s), compress ratio: 185.44 [ 2342.926796] lustre_kcompr_5302: decompr zstdfast(5) took 6500 us (3 MB/s) [ 2342.943689] lustre_kcompr_5302: test_comp_compress_decompress(zstdfast,5) ret 0 [ 2342.950830] lustre_kcompr_5302: acompr zstdfast(5) of 128kB chunks took 170 us (735 MB/s), compress ratio: 146.28 [ 2342.957290] lustre_kcompr_5302: adecompr zstdfast(5) took 144 us (5 MB/s) [ 2342.963686] lustre_kcompr_5302: test_acomp_compress_decompress(zstdfast,5) ret 0 [ 2342.979718] lustre_kcompr_5302: compr zstdfast(12) in 64kB chunks took 4364 us (916 MB/s), compress ratio: 38.57 [ 2342.988556] lustre_kcompr_5302: compr zstdfast(12) in 128kB chunks took 2860 us (1398 MB/s), compress ratio: 43.53 [ 2342.997236] lustre_kcompr_5302: compr zstdfast(12) in 256kB chunks took 2870 us (1393 MB/s), compress ratio: 46.80 [ 2343.005858] lustre_kcompr_5302: compr zstdfast(12) in 512kB chunks took 2483 us (1610 MB/s), compress ratio: 49.75 [ 2343.017891] lustre_kcompr_5302: compr zstdfast(12) in 1024kB chunks took 2628 us (1522 MB/s), compress ratio: 52.70 [ 2343.029601] lustre_kcompr_5302: compr zstdfast(12) in 2048kB chunks took 3468 us (1153 MB/s), compress ratio: 60.19 [ 2343.052703] lustre_kcompr_5302: compr zstdfast(12) in 4096kB chunks took 7317 us (546 MB/s), compress ratio: 83.10 [ 2343.073511] lustre_kcompr_5302: decompr zstdfast(12) took 2397 us (20 MB/s) [ 2343.079485] lustre_kcompr_5302: test_comp_compress_decompress(zstdfast,12) ret 0 [ 2343.083058] lustre_kcompr_5302: acompr zstdfast(12) of 128kB chunks took 193 us (647 MB/s), compress ratio: 36.73 [ 2343.086948] lustre_kcompr_5302: adecompr zstdfast(12) took 129 us (26 MB/s) [ 2343.090981] lustre_kcompr_5302: test_acomp_compress_decompress(zstdfast,12) ret 0 [ 2343.115757] lustre_kcompr_5302: compr zstdfast(15) in 64kB chunks took 2715 us (1473 MB/s), compress ratio: 19.29 [ 2343.123474] lustre_kcompr_5302: compr zstdfast(15) in 128kB chunks took 3574 us (1119 MB/s), compress ratio: 20.26 [ 2343.133682] lustre_kcompr_5302: compr zstdfast(15) in 256kB chunks took 2508 us (1594 MB/s), compress ratio: 20.46 [ 2343.140057] lustre_kcompr_5302: compr zstdfast(15) in 512kB chunks took 2233 us (1791 MB/s), compress ratio: 21.81 [ 2343.145238] lustre_kcompr_5302: compr zstdfast(15) in 1024kB chunks took 2337 us (1711 MB/s), compress ratio: 23.67 [ 2343.151480] lustre_kcompr_5302: compr zstdfast(15) in 2048kB chunks took 2654 us (1507 MB/s), compress ratio: 28.96 [ 2343.159385] lustre_kcompr_5302: compr zstdfast(15) in 4096kB chunks took 2584 us (1547 MB/s), compress ratio: 30.38 [ 2343.173827] lustre_kcompr_5302: decompr zstdfast(15) took 3108 us (42 MB/s) [ 2343.178484] lustre_kcompr_5302: test_comp_compress_decompress(zstdfast,15) ret 0 [ 2343.183226] lustre_kcompr_5302: acompr zstdfast(15) of 128kB chunks took 184 us (679 MB/s), compress ratio: 16.27 [ 2343.187807] lustre_kcompr_5302: adecompr zstdfast(15) took 122 us (62 MB/s) [ 2343.193814] lustre_kcompr_5302: test_acomp_compress_decompress(zstdfast,15) ret 0 [ 2343.196778] lustre_kcompr_5302: SUCCESS [ 2352.562793] lustre_kcompr_28898: ***** [ 2352.564261] lustre_kcompr_28898: (de)compression test on provided file /tmp/f84.sanity [ 2352.582018] lustre_kcompr_28898: ***** [ 2352.630849] lustre_kcompr_28898: compr lz4(1) in 64kB chunks took 28263 us (141 MB/s), compress ratio: 2.93 [ 2352.665391] lustre_kcompr_28898: compr lz4(1) in 128kB chunks took 29673 us (134 MB/s), compress ratio: 3.04 [ 2352.733594] lustre_kcompr_28898: compr lz4(1) in 256kB chunks took 58742 us (68 MB/s), compress ratio: 3.08 [ 2352.796897] lustre_kcompr_28898: compr lz4(1) in 512kB chunks took 48234 us (82 MB/s), compress ratio: 3.10 [ 2352.868388] lustre_kcompr_28898: compr lz4(1) in 1024kB chunks took 64515 us (62 MB/s), compress ratio: 3.11 [ 2352.915119] lustre_kcompr_28898: compr lz4(1) in 2048kB chunks took 40586 us (98 MB/s), compress ratio: 3.11 [ 2352.958982] lustre_kcompr_28898: compr lz4(1) in 4096kB chunks took 35611 us (112 MB/s), compress ratio: 3.12 [ 2352.996363] lustre_kcompr_28898: decompr lz4(1) took 17068 us (75 MB/s) [ 2353.009427] lustre_kcompr_28898: test_comp_compress_decompress(lz4,1) ret 0 [ 2353.038579] lustre_kcompr_28898: acompr lz4(1) of 128kB chunks took 612 us (204 MB/s), compress ratio: 2.68 [ 2353.053343] lustre_kcompr_28898: adecompr lz4(1) took 326 us (142 MB/s) [ 2353.077522] lustre_kcompr_28898: test_acomp_compress_decompress(lz4,1) ret 0 [ 2353.129536] lustre_kcompr_28898: compr lz4(4) in 64kB chunks took 31008 us (128 MB/s), compress ratio: 2.67 [ 2353.172350] lustre_kcompr_28898: compr lz4(4) in 128kB chunks took 33933 us (117 MB/s), compress ratio: 2.63 [ 2353.248748] lustre_kcompr_28898: compr lz4(4) in 256kB chunks took 64431 us (62 MB/s), compress ratio: 2.68 [ 2353.311097] lustre_kcompr_28898: compr lz4(4) in 512kB chunks took 48051 us (83 MB/s), compress ratio: 2.71 [ 2353.380352] lustre_kcompr_28898: compr lz4(4) in 1024kB chunks took 56015 us (71 MB/s), compress ratio: 2.72 [ 2353.450850] lustre_kcompr_28898: compr lz4(4) in 2048kB chunks took 61795 us (64 MB/s), compress ratio: 2.72 [ 2353.523331] lustre_kcompr_28898: compr lz4(4) in 4096kB chunks took 54306 us (73 MB/s), compress ratio: 2.73 [ 2353.578253] lustre_kcompr_28898: decompr lz4(4) took 28269 us (51 MB/s) [ 2353.583964] lustre_kcompr_28898: test_comp_compress_decompress(lz4,4) ret 0 [ 2353.604995] lustre_kcompr_28898: acompr lz4(4) of 128kB chunks took 748 us (167 MB/s), compress ratio: 2.30 [ 2353.616131] lustre_kcompr_28898: adecompr lz4(4) took 266 us (203 MB/s) [ 2353.648182] lustre_kcompr_28898: test_acomp_compress_decompress(lz4,4) ret 0 [ 2353.704226] lustre_kcompr_28898: compr lz4(9) in 64kB chunks took 31868 us (125 MB/s), compress ratio: 2.30 [ 2353.754381] lustre_kcompr_28898: compr lz4(9) in 128kB chunks took 43671 us (91 MB/s), compress ratio: 2.15 [ 2353.817937] lustre_kcompr_28898: compr lz4(9) in 256kB chunks took 50499 us (79 MB/s), compress ratio: 2.20 [ 2353.900968] lustre_kcompr_28898: compr lz4(9) in 512kB chunks took 63477 us (63 MB/s), compress ratio: 2.23 [ 2353.973335] lustre_kcompr_28898: compr lz4(9) in 1024kB chunks took 65710 us (60 MB/s), compress ratio: 2.25 [ 2354.055978] lustre_kcompr_28898: compr lz4(9) in 2048kB chunks took 58162 us (68 MB/s), compress ratio: 2.25 [ 2354.130480] lustre_kcompr_28898: compr lz4(9) in 4096kB chunks took 58450 us (68 MB/s), compress ratio: 2.26 [ 2354.166430] lustre_kcompr_28898: decompr lz4(9) took 5273 us (335 MB/s) [ 2354.177857] lustre_kcompr_28898: test_comp_compress_decompress(lz4,9) ret 0 [ 2354.186486] lustre_kcompr_28898: acompr lz4(9) of 128kB chunks took 507 us (246 MB/s), compress ratio: 1.87 [ 2354.195147] lustre_kcompr_28898: adecompr lz4(9) took 202 us (330 MB/s) [ 2354.237299] lustre_kcompr_28898: test_acomp_compress_decompress(lz4,9) ret 0 [ 2354.315492] lustre_kcompr_28898: compr lz4(15) in 64kB chunks took 36998 us (108 MB/s), compress ratio: 1.63 [ 2354.360971] lustre_kcompr_28898: compr lz4(15) in 128kB chunks took 36194 us (110 MB/s), compress ratio: 1.52 [ 2354.402650] lustre_kcompr_28898: compr lz4(15) in 256kB chunks took 33389 us (119 MB/s), compress ratio: 1.56 [ 2354.449575] lustre_kcompr_28898: compr lz4(15) in 512kB chunks took 31810 us (125 MB/s), compress ratio: 1.58 [ 2354.504714] lustre_kcompr_28898: compr lz4(15) in 1024kB chunks took 34244 us (116 MB/s), compress ratio: 1.60 [ 2354.550480] lustre_kcompr_28898: compr lz4(15) in 2048kB chunks took 37636 us (106 MB/s), compress ratio: 1.60 [ 2354.590083] lustre_kcompr_28898: compr lz4(15) in 4096kB chunks took 27539 us (145 MB/s), compress ratio: 1.60 [ 2354.623683] lustre_kcompr_28898: decompr lz4(15) took 9703 us (256 MB/s) [ 2354.634129] lustre_kcompr_28898: test_comp_compress_decompress(lz4,15) ret 0 [ 2354.639099] lustre_kcompr_28898: acompr lz4(15) of 128kB chunks took 420 us (297 MB/s), compress ratio: 1.33 [ 2354.652316] lustre_kcompr_28898: adecompr lz4(15) took 1556 us (60 MB/s) [ 2354.680712] lustre_kcompr_28898: test_acomp_compress_decompress(lz4,15) ret 0 [ 2355.064087] lustre_kcompr_28898: compr lz4hc(1) in 64kB chunks took 358553 us (11 MB/s), compress ratio: 3.58 [ 2355.412194] lustre_kcompr_28898: compr lz4hc(1) in 128kB chunks took 327909 us (12 MB/s), compress ratio: 3.77 [ 2355.748649] lustre_kcompr_28898: compr lz4hc(1) in 256kB chunks took 329292 us (12 MB/s), compress ratio: 3.88 [ 2356.155622] lustre_kcompr_28898: compr lz4hc(1) in 512kB chunks took 390277 us (10 MB/s), compress ratio: 3.93 [ 2356.427935] lustre_kcompr_28898: compr lz4hc(1) in 1024kB chunks took 258334 us (15 MB/s), compress ratio: 3.96 [ 2356.720601] lustre_kcompr_28898: compr lz4hc(1) in 2048kB chunks took 287828 us (13 MB/s), compress ratio: 3.97 [ 2356.968305] lustre_kcompr_28898: compr lz4hc(1) in 4096kB chunks took 231941 us (17 MB/s), compress ratio: 3.98 [ 2357.003453] lustre_kcompr_28898: decompr lz4hc(1) took 14468 us (69 MB/s) [ 2357.014438] lustre_kcompr_28898: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2357.035271] lustre_kcompr_28898: acompr lz4hc(1) of 128kB chunks took 12520 us (9 MB/s), compress ratio: 3.27 [ 2357.051544] lustre_kcompr_28898: adecompr lz4hc(1) took 2650 us (14 MB/s) [ 2357.078307] lustre_kcompr_28898: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2357.415584] lustre_kcompr_28898: compr lz4hc(3) in 64kB chunks took 316800 us (12 MB/s), compress ratio: 3.68 [ 2357.829689] lustre_kcompr_28898: compr lz4hc(3) in 128kB chunks took 403333 us (9 MB/s), compress ratio: 3.91 [ 2358.402260] lustre_kcompr_28898: compr lz4hc(3) in 256kB chunks took 564713 us (7 MB/s), compress ratio: 4.04 [ 2358.813492] lustre_kcompr_28898: compr lz4hc(3) in 512kB chunks took 399494 us (10 MB/s), compress ratio: 4.10 [ 2359.141537] lustre_kcompr_28898: compr lz4hc(3) in 1024kB chunks took 313699 us (12 MB/s), compress ratio: 4.13 [ 2359.492220] lustre_kcompr_28898: compr lz4hc(3) in 2048kB chunks took 332273 us (12 MB/s), compress ratio: 4.15 [ 2359.992407] lustre_kcompr_28898: compr lz4hc(3) in 4096kB chunks took 489513 us (8 MB/s), compress ratio: 4.16 [ 2360.052451] lustre_kcompr_28898: decompr lz4hc(3) took 26220 us (36 MB/s) [ 2360.058678] lustre_kcompr_28898: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2360.076346] lustre_kcompr_28898: acompr lz4hc(3) of 128kB chunks took 8144 us (15 MB/s), compress ratio: 3.38 [ 2360.091161] lustre_kcompr_28898: adecompr lz4hc(3) took 261 us (141 MB/s) [ 2360.106639] lustre_kcompr_28898: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2360.552236] lustre_kcompr_28898: compr lz4hc(8) in 64kB chunks took 399058 us (10 MB/s), compress ratio: 3.72 [ 2361.380527] lustre_kcompr_28898: compr lz4hc(8) in 128kB chunks took 811721 us (4 MB/s), compress ratio: 3.96 [ 2362.004880] lustre_kcompr_28898: compr lz4hc(8) in 256kB chunks took 607312 us (6 MB/s), compress ratio: 4.10 [ 2362.916507] lustre_kcompr_28898: compr lz4hc(8) in 512kB chunks took 904603 us (4 MB/s), compress ratio: 4.17 [ 2364.024564] lustre_kcompr_28898: compr lz4hc(8) in 1024kB chunks took 1098252 us (3 MB/s), compress ratio: 4.21 [ 2364.896230] lustre_kcompr_28898: compr lz4hc(8) in 2048kB chunks took 849094 us (4 MB/s), compress ratio: 4.22 [ 2365.972218] lustre_kcompr_28898: compr lz4hc(8) in 4096kB chunks took 1054898 us (3 MB/s), compress ratio: 4.23 [ 2366.004913] lustre_kcompr_28898: decompr lz4hc(8) took 13108 us (72 MB/s) [ 2366.015738] lustre_kcompr_28898: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2366.048533] lustre_kcompr_28898: acompr lz4hc(8) of 128kB chunks took 22227 us (5 MB/s), compress ratio: 3.42 [ 2366.053467] lustre_kcompr_28898: adecompr lz4hc(8) took 449 us (81 MB/s) [ 2366.059894] lustre_kcompr_28898: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2366.665729] lustre_kcompr_28898: compr lz4hc(15) in 64kB chunks took 593853 us (6 MB/s), compress ratio: 3.72 [ 2367.416456] lustre_kcompr_28898: compr lz4hc(15) in 128kB chunks took 743294 us (5 MB/s), compress ratio: 3.96 [ 2368.310803] lustre_kcompr_28898: compr lz4hc(15) in 256kB chunks took 877958 us (4 MB/s), compress ratio: 4.10 [ 2369.209361] lustre_kcompr_28898: compr lz4hc(15) in 512kB chunks took 889227 us (4 MB/s), compress ratio: 4.17 [ 2370.077398] lustre_kcompr_28898: compr lz4hc(15) in 1024kB chunks took 859066 us (4 MB/s), compress ratio: 4.21 [ 2371.015402] lustre_kcompr_28898: compr lz4hc(15) in 2048kB chunks took 930559 us (4 MB/s), compress ratio: 4.22 [ 2371.786437] lustre_kcompr_28898: compr lz4hc(15) in 4096kB chunks took 762712 us (5 MB/s), compress ratio: 4.23 [ 2371.804270] lustre_kcompr_28898: decompr lz4hc(15) took 5960 us (158 MB/s) [ 2371.809108] lustre_kcompr_28898: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2371.828204] lustre_kcompr_28898: acompr lz4hc(15) of 128kB chunks took 13241 us (9 MB/s), compress ratio: 3.42 [ 2371.841775] lustre_kcompr_28898: adecompr lz4hc(15) took 424 us (85 MB/s) [ 2371.849931] lustre_kcompr_28898: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2371.880821] lustre_kcompr_28898: compr lzo(-1) in 64kB chunks took 24104 us (165 MB/s), compress ratio: 2.90 [ 2371.917506] lustre_kcompr_28898: compr lzo(-1) in 128kB chunks took 31225 us (128 MB/s), compress ratio: 2.95 [ 2371.956552] lustre_kcompr_28898: compr lzo(-1) in 256kB chunks took 33035 us (121 MB/s), compress ratio: 2.96 [ 2372.021933] lustre_kcompr_28898: compr lzo(-1) in 512kB chunks took 56173 us (71 MB/s), compress ratio: 2.98 [ 2372.063363] lustre_kcompr_28898: compr lzo(-1) in 1024kB chunks took 27671 us (144 MB/s), compress ratio: 2.97 [ 2372.112922] lustre_kcompr_28898: compr lzo(-1) in 2048kB chunks took 42849 us (93 MB/s), compress ratio: 2.97 [ 2372.164409] lustre_kcompr_28898: compr lzo(-1) in 4096kB chunks took 37634 us (106 MB/s), compress ratio: 2.96 [ 2372.219542] lustre_kcompr_28898: decompr lzo(-1) took 29038 us (46 MB/s) [ 2372.228836] lustre_kcompr_28898: test_comp_compress_decompress(lzo,-1) ret 0 [ 2372.239395] lustre_kcompr_28898: acompr lzo(-1) of 128kB chunks took 978 us (127 MB/s), compress ratio: 2.62 [ 2372.244439] lustre_kcompr_28898: adecompr lzo(-1) took 510 us (93 MB/s) [ 2372.250296] lustre_kcompr_28898: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2373.019725] lustre_kcompr_28898: compr deflate(1) in 64kB chunks took 753921 us (5 MB/s), compress ratio: 3.51 [ 2373.874628] lustre_kcompr_28898: compr deflate(1) in 128kB chunks took 845800 us (4 MB/s), compress ratio: 3.53 [ 2374.588852] lustre_kcompr_28898: compr deflate(1) in 256kB chunks took 694552 us (5 MB/s), compress ratio: 3.53 [ 2375.564843] lustre_kcompr_28898: compr deflate(1) in 512kB chunks took 961537 us (4 MB/s), compress ratio: 3.54 [ 2376.762975] lustre_kcompr_28898: compr deflate(1) in 1024kB chunks took 1172987 us (3 MB/s), compress ratio: 3.54 [ 2377.584480] lustre_kcompr_28898: compr deflate(1) in 2048kB chunks took 809800 us (4 MB/s), compress ratio: 3.54 [ 2378.620704] lustre_kcompr_28898: compr deflate(1) in 4096kB chunks took 1022107 us (3 MB/s), compress ratio: 3.54 [ 2378.802065] lustre_kcompr_28898: decompr deflate(1) took 142489 us (7 MB/s) [ 2378.829985] lustre_kcompr_28898: test_comp_compress_decompress(deflate,1) ret 0 [ 2378.891399] lustre_kcompr_28898: acompr deflate(1) of 128kB chunks took 50704 us (2 MB/s), compress ratio: 3.09 [ 2378.907808] lustre_kcompr_28898: adecompr deflate(1) took 1075 us (37 MB/s) [ 2378.959375] lustre_kcompr_28898: test_acomp_compress_decompress(deflate,1) ret 0 [ 2379.804580] lustre_kcompr_28898: compr deflate(6) in 64kB chunks took 813407 us (4 MB/s), compress ratio: 3.51 [ 2380.743218] lustre_kcompr_28898: compr deflate(6) in 128kB chunks took 924547 us (4 MB/s), compress ratio: 3.53 [ 2381.596221] lustre_kcompr_28898: compr deflate(6) in 256kB chunks took 843841 us (4 MB/s), compress ratio: 3.53 [ 2382.557444] lustre_kcompr_28898: compr deflate(6) in 512kB chunks took 941743 us (4 MB/s), compress ratio: 3.54 [ 2383.774250] lustre_kcompr_28898: compr deflate(6) in 1024kB chunks took 1204097 us (3 MB/s), compress ratio: 3.54 [ 2384.821763] lustre_kcompr_28898: compr deflate(6) in 2048kB chunks took 1013870 us (3 MB/s), compress ratio: 3.54 [ 2385.851113] lustre_kcompr_28898: compr deflate(6) in 4096kB chunks took 1023577 us (3 MB/s), compress ratio: 3.54 [ 2385.957802] lustre_kcompr_28898: decompr deflate(6) took 87381 us (12 MB/s) [ 2385.985542] lustre_kcompr_28898: test_comp_compress_decompress(deflate,6) ret 0 [ 2386.043179] lustre_kcompr_28898: acompr deflate(6) of 128kB chunks took 43396 us (2 MB/s), compress ratio: 3.09 [ 2386.049203] lustre_kcompr_28898: adecompr deflate(6) took 1433 us (28 MB/s) [ 2386.056541] lustre_kcompr_28898: test_acomp_compress_decompress(deflate,6) ret 0 [ 2386.822957] lustre_kcompr_28898: compr deflate(9) in 64kB chunks took 753610 us (5 MB/s), compress ratio: 3.51 [ 2387.569947] lustre_kcompr_28898: compr deflate(9) in 128kB chunks took 728368 us (5 MB/s), compress ratio: 3.53 [ 2388.326358] lustre_kcompr_28898: compr deflate(9) in 256kB chunks took 747131 us (5 MB/s), compress ratio: 3.53 [ 2389.282295] lustre_kcompr_28898: compr deflate(9) in 512kB chunks took 948743 us (4 MB/s), compress ratio: 3.54 [ 2390.139377] lustre_kcompr_28898: compr deflate(9) in 1024kB chunks took 848592 us (4 MB/s), compress ratio: 3.54 [ 2390.980209] lustre_kcompr_28898: compr deflate(9) in 2048kB chunks took 823846 us (4 MB/s), compress ratio: 3.54 [ 2391.758619] lustre_kcompr_28898: compr deflate(9) in 4096kB chunks took 766893 us (5 MB/s), compress ratio: 3.54 [ 2391.809868] lustre_kcompr_28898: decompr deflate(9) took 34791 us (32 MB/s) [ 2391.821482] lustre_kcompr_28898: test_comp_compress_decompress(deflate,9) ret 0 [ 2391.860805] lustre_kcompr_28898: acompr deflate(9) of 128kB chunks took 24526 us (5 MB/s), compress ratio: 3.09 [ 2391.871879] lustre_kcompr_28898: adecompr deflate(9) took 3831 us (10 MB/s) [ 2391.880439] lustre_kcompr_28898: test_acomp_compress_decompress(deflate,9) ret 0 [ 2392.147389] lustre_kcompr_28898: compr zstd(0) in 64kB chunks took 229788 us (17 MB/s), compress ratio: 4.28 [ 2392.396410] lustre_kcompr_28898: compr zstd(0) in 128kB chunks took 231593 us (17 MB/s), compress ratio: 4.46 [ 2392.790584] lustre_kcompr_28898: compr zstd(0) in 256kB chunks took 386358 us (10 MB/s), compress ratio: 4.61 [ 2393.147755] lustre_kcompr_28898: compr zstd(0) in 512kB chunks took 343613 us (11 MB/s), compress ratio: 4.72 [ 2393.529793] lustre_kcompr_28898: compr zstd(0) in 1024kB chunks took 363150 us (11 MB/s), compress ratio: 4.80 [ 2393.864473] lustre_kcompr_28898: compr zstd(0) in 2048kB chunks took 327288 us (12 MB/s), compress ratio: 4.85 [ 2394.208776] lustre_kcompr_28898: compr zstd(0) in 4096kB chunks took 332329 us (12 MB/s), compress ratio: 4.88 [ 2394.308348] lustre_kcompr_28898: decompr zstd(0) took 79149 us (10 MB/s) [ 2394.321897] lustre_kcompr_28898: test_comp_compress_decompress(zstd,0) ret 0 [ 2394.337935] lustre_kcompr_28898: acompr zstd(0) of 128kB chunks took 6945 us (17 MB/s), compress ratio: 3.98 [ 2394.355324] lustre_kcompr_28898: adecompr zstd(0) took 2606 us (12 MB/s) [ 2394.382780] lustre_kcompr_28898: test_acomp_compress_decompress(zstd,0) ret 0 [ 2394.508980] lustre_kcompr_28898: compr zstd(1) in 64kB chunks took 103167 us (38 MB/s), compress ratio: 4.06 [ 2394.592704] lustre_kcompr_28898: compr zstd(1) in 128kB chunks took 70270 us (56 MB/s), compress ratio: 4.20 [ 2394.648706] lustre_kcompr_28898: compr zstd(1) in 256kB chunks took 49319 us (81 MB/s), compress ratio: 4.34 [ 2394.797992] lustre_kcompr_28898: compr zstd(1) in 512kB chunks took 138569 us (28 MB/s), compress ratio: 4.34 [ 2394.914944] lustre_kcompr_28898: compr zstd(1) in 1024kB chunks took 105097 us (38 MB/s), compress ratio: 4.37 [ 2395.007494] lustre_kcompr_28898: compr zstd(1) in 2048kB chunks took 83078 us (48 MB/s), compress ratio: 4.39 [ 2395.136264] lustre_kcompr_28898: compr zstd(1) in 4096kB chunks took 112780 us (35 MB/s), compress ratio: 4.40 [ 2395.223653] lustre_kcompr_28898: decompr zstd(1) took 61165 us (14 MB/s) [ 2395.234690] lustre_kcompr_28898: test_comp_compress_decompress(zstd,1) ret 0 [ 2395.247344] lustre_kcompr_28898: acompr zstd(1) of 128kB chunks took 1474 us (84 MB/s), compress ratio: 3.73 [ 2395.259623] lustre_kcompr_28898: adecompr zstd(1) took 1047 us (31 MB/s) [ 2395.285176] lustre_kcompr_28898: test_acomp_compress_decompress(zstd,1) ret 0 [ 2397.023993] lustre_kcompr_28898: compr zstd(10) in 64kB chunks took 1720004 us (2 MB/s), compress ratio: 4.80 [ 2399.443858] lustre_kcompr_28898: compr zstd(10) in 128kB chunks took 2400267 us (1 MB/s), compress ratio: 5.09 [ 2402.343096] lustre_kcompr_28898: compr zstd(10) in 256kB chunks took 2889191 us (1 MB/s), compress ratio: 5.34 [ 2404.745427] lustre_kcompr_28898: compr zstd(10) in 512kB chunks took 2371110 us (1 MB/s), compress ratio: 5.45 [ 2407.072587] lustre_kcompr_28898: compr zstd(10) in 1024kB chunks took 2318985 us (1 MB/s), compress ratio: 5.62 [ 2409.171744] lustre_kcompr_28898: compr zstd(10) in 2048kB chunks took 2085750 us (1 MB/s), compress ratio: 5.76 [ 2411.646645] lustre_kcompr_28898: compr zstd(10) in 4096kB chunks took 2466988 us (1 MB/s), compress ratio: 5.89 [ 2411.721973] lustre_kcompr_28898: decompr zstd(10) took 55105 us (12 MB/s) [ 2411.729793] lustre_kcompr_28898: test_comp_compress_decompress(zstd,10) ret 0 [ 2411.848295] lustre_kcompr_28898: acompr zstd(10) of 128kB chunks took 104560 us (1 MB/s), compress ratio: 4.46 [ 2411.875769] lustre_kcompr_28898: adecompr zstd(10) took 639 us (43 MB/s) [ 2411.892598] lustre_kcompr_28898: test_acomp_compress_decompress(zstd,10) ret 0 [ 2429.509228] lustre_kcompr_28898: compr zstd(15) in 64kB chunks took 17599175 us (0 MB/s), compress ratio: 4.96 [ 2443.692211] lustre_kcompr_28898: compr zstd(15) in 128kB chunks took 14177196 us (0 MB/s), compress ratio: 5.28 [ 2456.184697] lustre_kcompr_28898: compr zstd(15) in 256kB chunks took 12489366 us (0 MB/s), compress ratio: 5.57 [ 2474.118835] lustre_kcompr_28898: compr zstd(15) in 512kB chunks took 17923295 us (0 MB/s), compress ratio: 5.83 [ 2482.123145] lustre_kcompr_28898: compr zstd(15) in 1024kB chunks took 7996490 us (0 MB/s), compress ratio: 6.06 [ 2489.031604] lustre_kcompr_28898: compr zstd(15) in 2048kB chunks took 6904419 us (0 MB/s), compress ratio: 6.26 [ 2496.310311] lustre_kcompr_28898: compr zstd(15) in 4096kB chunks took 7274713 us (0 MB/s), compress ratio: 6.46 [ 2496.400896] lustre_kcompr_28898: decompr zstd(15) took 58664 us (10 MB/s) [ 2496.426116] lustre_kcompr_28898: test_comp_compress_decompress(zstd,15) ret 0 [ 2496.894121] lustre_kcompr_28898: acompr zstd(15) of 128kB chunks took 443880 us (0 MB/s), compress ratio: 4.64 [ 2496.903581] lustre_kcompr_28898: adecompr zstd(15) took 890 us (30 MB/s) [ 2496.914123] lustre_kcompr_28898: test_acomp_compress_decompress(zstd,15) ret 0 [ 2496.982229] lustre_kcompr_28898: compr zstdfast(1) in 64kB chunks took 50956 us (78 MB/s), compress ratio: 3.49 [ 2497.052933] lustre_kcompr_28898: compr zstdfast(1) in 128kB chunks took 65299 us (61 MB/s), compress ratio: 3.62 [ 2497.114178] lustre_kcompr_28898: compr zstdfast(1) in 256kB chunks took 53395 us (74 MB/s), compress ratio: 3.84 [ 2497.165849] lustre_kcompr_28898: compr zstdfast(1) in 512kB chunks took 44719 us (89 MB/s), compress ratio: 3.73 [ 2497.222623] lustre_kcompr_28898: compr zstdfast(1) in 1024kB chunks took 48867 us (81 MB/s), compress ratio: 3.76 [ 2497.327146] lustre_kcompr_28898: compr zstdfast(1) in 2048kB chunks took 96727 us (41 MB/s), compress ratio: 3.77 [ 2497.387892] lustre_kcompr_28898: compr zstdfast(1) in 4096kB chunks took 54376 us (73 MB/s), compress ratio: 3.78 [ 2497.425176] lustre_kcompr_28898: decompr zstdfast(1) took 22053 us (47 MB/s) [ 2497.431046] lustre_kcompr_28898: test_comp_compress_decompress(zstdfast,1) ret 0 [ 2497.436911] lustre_kcompr_28898: acompr zstdfast(1) of 128kB chunks took 1190 us (105 MB/s), compress ratio: 3.19 [ 2497.445809] lustre_kcompr_28898: adecompr zstdfast(1) took 713 us (54 MB/s) [ 2497.451428] lustre_kcompr_28898: test_acomp_compress_decompress(zstdfast,1) ret 0 [ 2497.507453] lustre_kcompr_28898: compr zstdfast(5) in 64kB chunks took 42802 us (93 MB/s), compress ratio: 2.81 [ 2497.586933] lustre_kcompr_28898: compr zstdfast(5) in 128kB chunks took 73016 us (54 MB/s), compress ratio: 2.93 [ 2497.665995] lustre_kcompr_28898: compr zstdfast(5) in 256kB chunks took 66833 us (59 MB/s), compress ratio: 3.16 [ 2497.756549] lustre_kcompr_28898: compr zstdfast(5) in 512kB chunks took 81743 us (48 MB/s), compress ratio: 3.04 [ 2497.858913] lustre_kcompr_28898: compr zstdfast(5) in 1024kB chunks took 92890 us (43 MB/s), compress ratio: 3.07 [ 2497.949401] lustre_kcompr_28898: compr zstdfast(5) in 2048kB chunks took 85422 us (46 MB/s), compress ratio: 3.08 [ 2498.001470] lustre_kcompr_28898: compr zstdfast(5) in 4096kB chunks took 44510 us (89 MB/s), compress ratio: 3.09 [ 2498.055718] lustre_kcompr_28898: decompr zstdfast(5) took 23788 us (54 MB/s) [ 2498.076993] lustre_kcompr_28898: test_comp_compress_decompress(zstdfast,5) ret 0 [ 2498.096367] lustre_kcompr_28898: acompr zstdfast(5) of 128kB chunks took 5263 us (23 MB/s), compress ratio: 2.56 [ 2498.111385] lustre_kcompr_28898: adecompr zstdfast(5) took 515 us (94 MB/s) [ 2498.133229] lustre_kcompr_28898: test_acomp_compress_decompress(zstdfast,5) ret 0 [ 2498.203847] lustre_kcompr_28898: compr zstdfast(12) in 64kB chunks took 42506 us (94 MB/s), compress ratio: 1.43 [ 2498.254494] lustre_kcompr_28898: compr zstdfast(12) in 128kB chunks took 45809 us (87 MB/s), compress ratio: 1.50 [ 2498.342349] lustre_kcompr_28898: compr zstdfast(12) in 256kB chunks took 74786 us (53 MB/s), compress ratio: 1.62 [ 2498.402777] lustre_kcompr_28898: compr zstdfast(12) in 512kB chunks took 43775 us (91 MB/s), compress ratio: 1.55 [ 2498.458793] lustre_kcompr_28898: compr zstdfast(12) in 1024kB chunks took 34633 us (115 MB/s), compress ratio: 1.58 [ 2498.515123] lustre_kcompr_28898: compr zstdfast(12) in 2048kB chunks took 42986 us (93 MB/s), compress ratio: 1.60 [ 2498.545842] lustre_kcompr_28898: compr zstdfast(12) in 4096kB chunks took 23197 us (172 MB/s), compress ratio: 1.60 [ 2498.575968] lustre_kcompr_28898: decompr zstdfast(12) took 16643 us (149 MB/s) [ 2498.581606] lustre_kcompr_28898: test_comp_compress_decompress(zstdfast,12) ret 0 [ 2498.589862] lustre_kcompr_28898: acompr zstdfast(12) of 128kB chunks took 1023 us (122 MB/s), compress ratio: 1.37 [ 2498.596576] lustre_kcompr_28898: adecompr zstdfast(12) took 535 us (170 MB/s) [ 2498.603888] lustre_kcompr_28898: test_acomp_compress_decompress(zstdfast,12) ret 0 [ 2498.649772] lustre_kcompr_28898: compr zstdfast(15) in 64kB chunks took 14789 us (270 MB/s), compress ratio: 1.12 [ 2498.666230] lustre_kcompr_28898: compr zstdfast(15) in 128kB chunks took 10022 us (399 MB/s), compress ratio: 1.16 [ 2498.710534] lustre_kcompr_28898: compr zstdfast(15) in 256kB chunks took 27817 us (143 MB/s), compress ratio: 1.22 [ 2498.733785] lustre_kcompr_28898: compr zstdfast(15) in 512kB chunks took 16881 us (236 MB/s), compress ratio: 1.20 [ 2498.759983] lustre_kcompr_28898: compr zstdfast(15) in 1024kB chunks took 19037 us (210 MB/s), compress ratio: 1.22 [ 2498.786949] lustre_kcompr_28898: compr zstdfast(15) in 2048kB chunks took 19271 us (207 MB/s), compress ratio: 1.23 [ 2498.841573] lustre_kcompr_28898: compr zstdfast(15) in 4096kB chunks took 36883 us (108 MB/s), compress ratio: 1.23 [ 2498.873430] lustre_kcompr_28898: decompr zstdfast(15) took 8642 us (374 MB/s) [ 2498.888215] lustre_kcompr_28898: test_comp_compress_decompress(zstdfast,15) ret 0 [ 2498.902503] lustre_kcompr_28898: acompr zstdfast(15) of 128kB chunks took 4252 us (29 MB/s), compress ratio: 1.08 [ 2498.911497] lustre_kcompr_28898: adecompr zstdfast(15) took 252 us (458 MB/s) [ 2498.918762] lustre_kcompr_28898: test_acomp_compress_decompress(zstdfast,15) ret 0 [ 2498.923642] lustre_kcompr_28898: SUCCESS [ 2505.182038] lustre_kcompr_16162: ***** [ 2505.191218] lustre_kcompr_16162: (de)compression test on provided file /tmp/f84.sanity [ 2505.197022] lustre_kcompr_16162: ***** [ 2505.261464] lustre_kcompr_16162: compr lz4(1) in 64kB chunks took 32753 us (122 MB/s), compress ratio: 2.45 [ 2505.327639] lustre_kcompr_16162: compr lz4(1) in 128kB chunks took 57181 us (69 MB/s), compress ratio: 2.39 [ 2505.380507] lustre_kcompr_16162: compr lz4(1) in 256kB chunks took 35526 us (112 MB/s), compress ratio: 2.39 [ 2505.431545] lustre_kcompr_16162: compr lz4(1) in 512kB chunks took 32056 us (124 MB/s), compress ratio: 2.39 [ 2505.486474] lustre_kcompr_16162: compr lz4(1) in 1024kB chunks took 38686 us (103 MB/s), compress ratio: 2.39 [ 2505.521274] lustre_kcompr_16162: compr lz4(1) in 2048kB chunks took 19958 us (200 MB/s), compress ratio: 2.39 [ 2505.586550] lustre_kcompr_16162: compr lz4(1) in 4096kB chunks took 44708 us (89 MB/s), compress ratio: 2.39 [ 2505.613876] lustre_kcompr_16162: decompr lz4(1) took 9807 us (170 MB/s) [ 2505.621456] lustre_kcompr_16162: test_comp_compress_decompress(lz4,1) ret 0 [ 2505.632737] lustre_kcompr_16162: acompr lz4(1) of 128kB chunks took 157 us (796 MB/s), compress ratio: 15.67 [ 2505.639467] lustre_kcompr_16162: adecompr lz4(1) took 115 us (69 MB/s) [ 2505.657091] lustre_kcompr_16162: test_acomp_compress_decompress(lz4,1) ret 0 [ 2505.697337] lustre_kcompr_16162: compr lz4(4) in 64kB chunks took 20853 us (191 MB/s), compress ratio: 2.36 [ 2505.724151] lustre_kcompr_16162: compr lz4(4) in 128kB chunks took 15815 us (252 MB/s), compress ratio: 2.35 [ 2505.744394] lustre_kcompr_16162: compr lz4(4) in 256kB chunks took 11763 us (340 MB/s), compress ratio: 2.35 [ 2505.763318] lustre_kcompr_16162: compr lz4(4) in 512kB chunks took 14199 us (281 MB/s), compress ratio: 2.35 [ 2505.797991] lustre_kcompr_16162: compr lz4(4) in 1024kB chunks took 29192 us (137 MB/s), compress ratio: 2.35 [ 2505.852373] lustre_kcompr_16162: compr lz4(4) in 2048kB chunks took 20633 us (193 MB/s), compress ratio: 2.35 [ 2505.883447] lustre_kcompr_16162: compr lz4(4) in 4096kB chunks took 21784 us (183 MB/s), compress ratio: 2.35 [ 2505.914122] lustre_kcompr_16162: decompr lz4(4) took 2279 us (745 MB/s) [ 2505.921995] lustre_kcompr_16162: test_comp_compress_decompress(lz4,4) ret 0 [ 2505.927420] lustre_kcompr_16162: acompr lz4(4) of 128kB chunks took 114 us (1096 MB/s), compress ratio: 15.30 [ 2505.942312] lustre_kcompr_16162: adecompr lz4(4) took 215 us (37 MB/s) [ 2505.983636] lustre_kcompr_16162: test_acomp_compress_decompress(lz4,4) ret 0 [ 2506.027690] lustre_kcompr_16162: compr lz4(9) in 64kB chunks took 14316 us (279 MB/s), compress ratio: 2.32 [ 2506.052925] lustre_kcompr_16162: compr lz4(9) in 128kB chunks took 19670 us (203 MB/s), compress ratio: 2.31 [ 2506.102591] lustre_kcompr_16162: compr lz4(9) in 256kB chunks took 25954 us (154 MB/s), compress ratio: 2.31 [ 2506.138146] lustre_kcompr_16162: compr lz4(9) in 512kB chunks took 19353 us (206 MB/s), compress ratio: 2.31 [ 2506.169738] lustre_kcompr_16162: compr lz4(9) in 1024kB chunks took 23414 us (170 MB/s), compress ratio: 2.31 [ 2506.203330] lustre_kcompr_16162: compr lz4(9) in 2048kB chunks took 27938 us (143 MB/s), compress ratio: 2.32 [ 2506.239657] lustre_kcompr_16162: compr lz4(9) in 4096kB chunks took 25617 us (156 MB/s), compress ratio: 2.32 [ 2506.272140] lustre_kcompr_16162: decompr lz4(9) took 7012 us (245 MB/s) [ 2506.277809] lustre_kcompr_16162: test_comp_compress_decompress(lz4,9) ret 0 [ 2506.290726] lustre_kcompr_16162: acompr lz4(9) of 128kB chunks took 114 us (1096 MB/s), compress ratio: 14.81 [ 2506.301680] lustre_kcompr_16162: adecompr lz4(9) took 990 us (8 MB/s) [ 2506.315610] lustre_kcompr_16162: test_acomp_compress_decompress(lz4,9) ret 0 [ 2506.379339] lustre_kcompr_16162: compr lz4(15) in 64kB chunks took 17512 us (228 MB/s), compress ratio: 2.23 [ 2506.416519] lustre_kcompr_16162: compr lz4(15) in 128kB chunks took 19901 us (200 MB/s), compress ratio: 2.23 [ 2506.442322] lustre_kcompr_16162: compr lz4(15) in 256kB chunks took 16195 us (246 MB/s), compress ratio: 2.23 [ 2506.493581] lustre_kcompr_16162: compr lz4(15) in 512kB chunks took 41878 us (95 MB/s), compress ratio: 2.23 [ 2506.547644] lustre_kcompr_16162: compr lz4(15) in 1024kB chunks took 25601 us (156 MB/s), compress ratio: 2.23 [ 2506.570614] lustre_kcompr_16162: compr lz4(15) in 2048kB chunks took 11000 us (363 MB/s), compress ratio: 2.23 [ 2506.593738] lustre_kcompr_16162: compr lz4(15) in 4096kB chunks took 15663 us (255 MB/s), compress ratio: 2.23 [ 2506.623903] lustre_kcompr_16162: decompr lz4(15) took 9265 us (193 MB/s) [ 2506.629739] lustre_kcompr_16162: test_comp_compress_decompress(lz4,15) ret 0 [ 2506.642819] lustre_kcompr_16162: acompr lz4(15) of 128kB chunks took 118 us (1059 MB/s), compress ratio: 14.18 [ 2506.657441] lustre_kcompr_16162: adecompr lz4(15) took 103 us (85 MB/s) [ 2506.681106] lustre_kcompr_16162: test_acomp_compress_decompress(lz4,15) ret 0 [ 2506.860695] lustre_kcompr_16162: compr lz4hc(1) in 64kB chunks took 159770 us (25 MB/s), compress ratio: 2.54 [ 2507.140109] lustre_kcompr_16162: compr lz4hc(1) in 128kB chunks took 264669 us (15 MB/s), compress ratio: 2.61 [ 2507.530813] lustre_kcompr_16162: compr lz4hc(1) in 256kB chunks took 379961 us (10 MB/s), compress ratio: 2.64 [ 2507.764597] lustre_kcompr_16162: compr lz4hc(1) in 512kB chunks took 225775 us (17 MB/s), compress ratio: 2.66 [ 2508.007814] lustre_kcompr_16162: compr lz4hc(1) in 1024kB chunks took 236896 us (16 MB/s), compress ratio: 2.67 [ 2508.179894] lustre_kcompr_16162: compr lz4hc(1) in 2048kB chunks took 162071 us (24 MB/s), compress ratio: 2.67 [ 2508.497858] lustre_kcompr_16162: compr lz4hc(1) in 4096kB chunks took 310608 us (12 MB/s), compress ratio: 2.67 [ 2508.528673] lustre_kcompr_16162: decompr lz4hc(1) took 6501 us (229 MB/s) [ 2508.533822] lustre_kcompr_16162: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2508.548761] lustre_kcompr_16162: acompr lz4hc(1) of 128kB chunks took 1005 us (124 MB/s), compress ratio: 15.97 [ 2508.553248] lustre_kcompr_16162: adecompr lz4hc(1) took 151 us (51 MB/s) [ 2508.561189] lustre_kcompr_16162: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2508.957315] lustre_kcompr_16162: compr lz4hc(3) in 64kB chunks took 379173 us (10 MB/s), compress ratio: 2.57 [ 2509.263281] lustre_kcompr_16162: compr lz4hc(3) in 128kB chunks took 291389 us (13 MB/s), compress ratio: 2.64 [ 2509.684307] lustre_kcompr_16162: compr lz4hc(3) in 256kB chunks took 397623 us (10 MB/s), compress ratio: 2.68 [ 2510.051036] lustre_kcompr_16162: compr lz4hc(3) in 512kB chunks took 359452 us (11 MB/s), compress ratio: 2.69 [ 2510.435328] lustre_kcompr_16162: compr lz4hc(3) in 1024kB chunks took 378304 us (10 MB/s), compress ratio: 2.70 [ 2510.838743] lustre_kcompr_16162: compr lz4hc(3) in 2048kB chunks took 397037 us (10 MB/s), compress ratio: 2.71 [ 2511.218298] lustre_kcompr_16162: compr lz4hc(3) in 4096kB chunks took 373009 us (10 MB/s), compress ratio: 2.71 [ 2511.250339] lustre_kcompr_16162: decompr lz4hc(3) took 7451 us (197 MB/s) [ 2511.259932] lustre_kcompr_16162: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2511.280379] lustre_kcompr_16162: acompr lz4hc(3) of 128kB chunks took 6986 us (17 MB/s), compress ratio: 16.00 [ 2511.300310] lustre_kcompr_16162: adecompr lz4hc(3) took 129 us (60 MB/s) [ 2511.340735] lustre_kcompr_16162: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2512.041860] lustre_kcompr_16162: compr lz4hc(8) in 64kB chunks took 657114 us (6 MB/s), compress ratio: 2.60 [ 2512.674275] lustre_kcompr_16162: compr lz4hc(8) in 128kB chunks took 627872 us (6 MB/s), compress ratio: 2.66 [ 2513.457746] lustre_kcompr_16162: compr lz4hc(8) in 256kB chunks took 768363 us (5 MB/s), compress ratio: 2.70 [ 2514.233412] lustre_kcompr_16162: compr lz4hc(8) in 512kB chunks took 766330 us (5 MB/s), compress ratio: 2.71 [ 2515.314727] lustre_kcompr_16162: compr lz4hc(8) in 1024kB chunks took 1075791 us (3 MB/s), compress ratio: 2.72 [ 2516.326859] lustre_kcompr_16162: compr lz4hc(8) in 2048kB chunks took 1001919 us (3 MB/s), compress ratio: 2.73 [ 2517.655245] lustre_kcompr_16162: compr lz4hc(8) in 4096kB chunks took 1295427 us (3 MB/s), compress ratio: 2.73 [ 2517.690612] lustre_kcompr_16162: decompr lz4hc(8) took 9656 us (151 MB/s) [ 2517.698639] lustre_kcompr_16162: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2517.722542] lustre_kcompr_16162: acompr lz4hc(8) of 128kB chunks took 8970 us (13 MB/s), compress ratio: 16.17 [ 2517.742386] lustre_kcompr_16162: adecompr lz4hc(8) took 430 us (17 MB/s) [ 2517.787650] lustre_kcompr_16162: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2529.098555] lustre_kcompr_16162: compr lz4hc(15) in 64kB chunks took 11268664 us (0 MB/s), compress ratio: 2.61 [ 2543.768823] lustre_kcompr_16162: compr lz4hc(15) in 128kB chunks took 14641727 us (0 MB/s), compress ratio: 2.67 [ 2558.800918] lustre_kcompr_16162: compr lz4hc(15) in 256kB chunks took 15012991 us (0 MB/s), compress ratio: 2.71 [ 2574.734387] lustre_kcompr_16162: compr lz4hc(15) in 512kB chunks took 15925020 us (0 MB/s), compress ratio: 2.72 [ 2592.360903] lustre_kcompr_16162: compr lz4hc(15) in 1024kB chunks took 17618864 us (0 MB/s), compress ratio: 2.73 [ 2611.161914] lustre_kcompr_16162: compr lz4hc(15) in 2048kB chunks took 18789385 us (0 MB/s), compress ratio: 2.74 [ 2629.303720] lustre_kcompr_16162: compr lz4hc(15) in 4096kB chunks took 18131559 us (0 MB/s), compress ratio: 2.74 [ 2629.344419] lustre_kcompr_16162: decompr lz4hc(15) took 18331 us (79 MB/s) [ 2629.352908] lustre_kcompr_16162: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2629.445474] lustre_kcompr_16162: acompr lz4hc(15) of 128kB chunks took 83496 us (1 MB/s), compress ratio: 16.30 [ 2629.466906] lustre_kcompr_16162: adecompr lz4hc(15) took 550 us (13 MB/s) [ 2629.491848] lustre_kcompr_16162: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2629.517927] lustre_kcompr_16162: compr lzo(-1) in 64kB chunks took 15662 us (255 MB/s), compress ratio: 2.35 [ 2629.541869] lustre_kcompr_16162: compr lzo(-1) in 128kB chunks took 18710 us (213 MB/s), compress ratio: 2.35 [ 2629.616217] lustre_kcompr_16162: compr lzo(-1) in 256kB chunks took 47900 us (83 MB/s), compress ratio: 2.35 [ 2629.673869] lustre_kcompr_16162: compr lzo(-1) in 512kB chunks took 40221 us (99 MB/s), compress ratio: 2.36 [ 2629.734327] lustre_kcompr_16162: compr lzo(-1) in 1024kB chunks took 49562 us (80 MB/s), compress ratio: 2.36 [ 2629.785888] lustre_kcompr_16162: compr lzo(-1) in 2048kB chunks took 39500 us (101 MB/s), compress ratio: 2.36 [ 2629.827908] lustre_kcompr_16162: compr lzo(-1) in 4096kB chunks took 34857 us (114 MB/s), compress ratio: 2.36 [ 2629.868290] lustre_kcompr_16162: decompr lzo(-1) took 22351 us (75 MB/s) [ 2629.880454] lustre_kcompr_16162: test_comp_compress_decompress(lzo,-1) ret 0 [ 2629.889261] lustre_kcompr_16162: acompr lzo(-1) of 128kB chunks took 1854 us (67 MB/s), compress ratio: 15.45 [ 2629.896324] lustre_kcompr_16162: adecompr lzo(-1) took 238 us (33 MB/s) [ 2629.961667] lustre_kcompr_16162: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2630.910553] lustre_kcompr_16162: compr deflate(1) in 64kB chunks took 905860 us (4 MB/s), compress ratio: 3.27 [ 2631.793124] lustre_kcompr_16162: compr deflate(1) in 128kB chunks took 844903 us (4 MB/s), compress ratio: 3.28 [ 2632.693430] lustre_kcompr_16162: compr deflate(1) in 256kB chunks took 888958 us (4 MB/s), compress ratio: 3.28 [ 2633.660580] lustre_kcompr_16162: compr deflate(1) in 512kB chunks took 953972 us (4 MB/s), compress ratio: 3.28 [ 2634.730280] lustre_kcompr_16162: compr deflate(1) in 1024kB chunks took 1049065 us (3 MB/s), compress ratio: 3.28 [ 2635.714426] lustre_kcompr_16162: compr deflate(1) in 2048kB chunks took 964151 us (4 MB/s), compress ratio: 3.28 [ 2636.609393] lustre_kcompr_16162: compr deflate(1) in 4096kB chunks took 887452 us (4 MB/s), compress ratio: 3.28 [ 2636.697987] lustre_kcompr_16162: decompr deflate(1) took 69862 us (17 MB/s) [ 2636.713553] lustre_kcompr_16162: test_comp_compress_decompress(deflate,1) ret 0 [ 2636.794766] lustre_kcompr_16162: acompr deflate(1) of 128kB chunks took 53546 us (2 MB/s), compress ratio: 21.43 [ 2636.831761] lustre_kcompr_16162: adecompr deflate(1) took 1575 us (3 MB/s) [ 2636.867523] lustre_kcompr_16162: test_acomp_compress_decompress(deflate,1) ret 0 [ 2637.746807] lustre_kcompr_16162: compr deflate(6) in 64kB chunks took 835423 us (4 MB/s), compress ratio: 3.27 [ 2638.699176] lustre_kcompr_16162: compr deflate(6) in 128kB chunks took 941598 us (4 MB/s), compress ratio: 3.28 [ 2639.656103] lustre_kcompr_16162: compr deflate(6) in 256kB chunks took 948858 us (4 MB/s), compress ratio: 3.28 [ 2640.688358] lustre_kcompr_16162: compr deflate(6) in 512kB chunks took 1024264 us (3 MB/s), compress ratio: 3.28 [ 2641.721944] lustre_kcompr_16162: compr deflate(6) in 1024kB chunks took 1022439 us (3 MB/s), compress ratio: 3.28 [ 2642.846667] lustre_kcompr_16162: compr deflate(6) in 2048kB chunks took 1118499 us (3 MB/s), compress ratio: 3.28 [ 2643.916957] lustre_kcompr_16162: compr deflate(6) in 4096kB chunks took 1065196 us (3 MB/s), compress ratio: 3.28 [ 2644.056193] lustre_kcompr_16162: decompr deflate(6) took 115098 us (10 MB/s) [ 2644.069810] lustre_kcompr_16162: test_comp_compress_decompress(deflate,6) ret 0 [ 2644.125643] lustre_kcompr_16162: acompr deflate(6) of 128kB chunks took 40298 us (3 MB/s), compress ratio: 21.43 [ 2644.137429] lustre_kcompr_16162: adecompr deflate(6) took 440 us (13 MB/s) [ 2644.170065] lustre_kcompr_16162: test_acomp_compress_decompress(deflate,6) ret 0 [ 2645.225803] lustre_kcompr_16162: compr deflate(9) in 64kB chunks took 1020556 us (3 MB/s), compress ratio: 3.27 [ 2646.040267] lustre_kcompr_16162: compr deflate(9) in 128kB chunks took 788253 us (5 MB/s), compress ratio: 3.28 [ 2647.031306] lustre_kcompr_16162: compr deflate(9) in 256kB chunks took 981412 us (4 MB/s), compress ratio: 3.28 [ 2648.191770] lustre_kcompr_16162: compr deflate(9) in 512kB chunks took 1150029 us (3 MB/s), compress ratio: 3.28 [ 2649.368403] lustre_kcompr_16162: compr deflate(9) in 1024kB chunks took 1150325 us (3 MB/s), compress ratio: 3.28 [ 2650.243522] lustre_kcompr_16162: compr deflate(9) in 2048kB chunks took 863803 us (4 MB/s), compress ratio: 3.28 [ 2651.046456] lustre_kcompr_16162: compr deflate(9) in 4096kB chunks took 787211 us (5 MB/s), compress ratio: 3.28 [ 2651.121499] lustre_kcompr_16162: decompr deflate(9) took 57748 us (21 MB/s) [ 2651.152840] lustre_kcompr_16162: test_comp_compress_decompress(deflate,9) ret 0 [ 2651.188877] lustre_kcompr_16162: acompr deflate(9) of 128kB chunks took 29096 us (4 MB/s), compress ratio: 21.43 [ 2651.211308] lustre_kcompr_16162: adecompr deflate(9) took 341 us (17 MB/s) [ 2651.243763] lustre_kcompr_16162: test_acomp_compress_decompress(deflate,9) ret 0 [ 2651.485620] lustre_kcompr_16162: compr zstd(0) in 64kB chunks took 220228 us (18 MB/s), compress ratio: 3.28 [ 2651.819790] lustre_kcompr_16162: compr zstd(0) in 128kB chunks took 307950 us (12 MB/s), compress ratio: 3.26 [ 2652.131189] lustre_kcompr_16162: compr zstd(0) in 256kB chunks took 296087 us (13 MB/s), compress ratio: 3.31 [ 2652.408178] lustre_kcompr_16162: compr zstd(0) in 512kB chunks took 263354 us (15 MB/s), compress ratio: 3.32 [ 2652.810619] lustre_kcompr_16162: compr zstd(0) in 1024kB chunks took 394111 us (10 MB/s), compress ratio: 3.32 [ 2653.195333] lustre_kcompr_16162: compr zstd(0) in 2048kB chunks took 360220 us (11 MB/s), compress ratio: 3.33 [ 2653.847809] lustre_kcompr_16162: compr zstd(0) in 4096kB chunks took 642257 us (6 MB/s), compress ratio: 3.33 [ 2653.944732] lustre_kcompr_16162: decompr zstd(0) took 57983 us (20 MB/s) [ 2653.968723] lustre_kcompr_16162: test_comp_compress_decompress(zstd,0) ret 0 [ 2653.976741] lustre_kcompr_16162: acompr zstd(0) of 128kB chunks took 824 us (151 MB/s), compress ratio: 22.64 [ 2653.990375] lustre_kcompr_16162: adecompr zstd(0) took 1196 us (4 MB/s) [ 2654.005748] lustre_kcompr_16162: test_acomp_compress_decompress(zstd,0) ret 0 [ 2654.100845] lustre_kcompr_16162: compr zstd(1) in 64kB chunks took 72604 us (55 MB/s), compress ratio: 3.22 [ 2654.180978] lustre_kcompr_16162: compr zstd(1) in 128kB chunks took 70588 us (56 MB/s), compress ratio: 3.18 [ 2654.235984] lustre_kcompr_16162: compr zstd(1) in 256kB chunks took 50112 us (79 MB/s), compress ratio: 3.19 [ 2654.327083] lustre_kcompr_16162: compr zstd(1) in 512kB chunks took 84569 us (47 MB/s), compress ratio: 3.19 [ 2654.447386] lustre_kcompr_16162: compr zstd(1) in 1024kB chunks took 105307 us (37 MB/s), compress ratio: 3.19 [ 2654.552230] lustre_kcompr_16162: compr zstd(1) in 2048kB chunks took 95855 us (41 MB/s), compress ratio: 3.19 [ 2654.646370] lustre_kcompr_16162: compr zstd(1) in 4096kB chunks took 77147 us (51 MB/s), compress ratio: 3.19 [ 2654.704898] lustre_kcompr_16162: decompr zstd(1) took 34927 us (35 MB/s) [ 2654.710831] lustre_kcompr_16162: test_comp_compress_decompress(zstd,1) ret 0 [ 2654.714584] lustre_kcompr_16162: acompr zstd(1) of 128kB chunks took 244 us (512 MB/s), compress ratio: 22.79 [ 2654.718074] lustre_kcompr_16162: adecompr zstd(1) took 157 us (34 MB/s) [ 2654.725696] lustre_kcompr_16162: test_acomp_compress_decompress(zstd,1) ret 0 [ 2656.115826] lustre_kcompr_16162: compr zstd(10) in 64kB chunks took 1375516 us (2 MB/s), compress ratio: 3.33 [ 2656.580318] lustre_kcompr_16162: compr zstd(10) in 128kB chunks took 462333 us (8 MB/s), compress ratio: 3.33 [ 2657.342781] lustre_kcompr_16162: compr zstd(10) in 256kB chunks took 758446 us (5 MB/s), compress ratio: 3.37 [ 2658.062095] lustre_kcompr_16162: compr zstd(10) in 512kB chunks took 709846 us (5 MB/s), compress ratio: 3.40 [ 2659.918318] lustre_kcompr_16162: compr zstd(10) in 1024kB chunks took 1852231 us (2 MB/s), compress ratio: 3.42 [ 2660.880448] lustre_kcompr_16162: compr zstd(10) in 2048kB chunks took 953506 us (4 MB/s), compress ratio: 3.46 [ 2661.738820] lustre_kcompr_16162: compr zstd(10) in 4096kB chunks took 853536 us (4 MB/s), compress ratio: 3.50 [ 2661.769904] lustre_kcompr_16162: decompr zstd(10) took 20980 us (54 MB/s) [ 2661.774359] lustre_kcompr_16162: test_comp_compress_decompress(zstd,10) ret 0 [ 2661.780624] lustre_kcompr_16162: acompr zstd(10) of 128kB chunks took 1668 us (74 MB/s), compress ratio: 22.78 [ 2661.786666] lustre_kcompr_16162: adecompr zstd(10) took 334 us (16 MB/s) [ 2661.793147] lustre_kcompr_16162: test_acomp_compress_decompress(zstd,10) ret 0 [ 2672.061741] lustre_kcompr_16162: compr zstd(15) in 64kB chunks took 10254105 us (0 MB/s), compress ratio: 3.36 [ 2684.144938] lustre_kcompr_16162: compr zstd(15) in 128kB chunks took 12065468 us (0 MB/s), compress ratio: 3.39 [ 2695.316307] lustre_kcompr_16162: compr zstd(15) in 256kB chunks took 11161032 us (0 MB/s), compress ratio: 3.40 [ 2703.243198] lustre_kcompr_16162: compr zstd(15) in 512kB chunks took 7911150 us (0 MB/s), compress ratio: 3.42 [ 2710.165362] lustre_kcompr_16162: compr zstd(15) in 1024kB chunks took 6918852 us (0 MB/s), compress ratio: 3.43 [ 2716.771260] lustre_kcompr_16162: compr zstd(15) in 2048kB chunks took 6595763 us (0 MB/s), compress ratio: 3.48 [ 2722.946465] lustre_kcompr_16162: compr zstd(15) in 4096kB chunks took 6164226 us (0 MB/s), compress ratio: 3.56 [ 2723.058717] lustre_kcompr_16162: decompr zstd(15) took 92797 us (12 MB/s) [ 2723.081584] lustre_kcompr_16162: test_comp_compress_decompress(zstd,15) ret 0 [ 2723.200562] lustre_kcompr_16162: acompr zstd(15) of 128kB chunks took 109671 us (1 MB/s), compress ratio: 23.92 [ 2723.209915] lustre_kcompr_16162: adecompr zstd(15) took 206 us (25 MB/s) [ 2723.234624] lustre_kcompr_16162: test_acomp_compress_decompress(zstd,15) ret 0 [ 2723.320243] lustre_kcompr_16162: compr zstdfast(1) in 64kB chunks took 56072 us (71 MB/s), compress ratio: 2.47 [ 2723.342846] lustre_kcompr_16162: compr zstdfast(1) in 128kB chunks took 19284 us (207 MB/s), compress ratio: 2.48 [ 2723.370914] lustre_kcompr_16162: compr zstdfast(1) in 256kB chunks took 23692 us (168 MB/s), compress ratio: 2.53 [ 2723.415942] lustre_kcompr_16162: compr zstdfast(1) in 512kB chunks took 37940 us (105 MB/s), compress ratio: 2.42 [ 2723.467514] lustre_kcompr_16162: compr zstdfast(1) in 1024kB chunks took 38712 us (103 MB/s), compress ratio: 2.42 [ 2723.498140] lustre_kcompr_16162: compr zstdfast(1) in 2048kB chunks took 18179 us (220 MB/s), compress ratio: 2.42 [ 2723.530884] lustre_kcompr_16162: compr zstdfast(1) in 4096kB chunks took 28213 us (141 MB/s), compress ratio: 2.42 [ 2723.554499] lustre_kcompr_16162: decompr zstdfast(1) took 7543 us (218 MB/s) [ 2723.568989] lustre_kcompr_16162: test_comp_compress_decompress(zstdfast,1) ret 0 [ 2723.576819] lustre_kcompr_16162: acompr zstdfast(1) of 128kB chunks took 237 us (527 MB/s), compress ratio: 17.28 [ 2723.583344] lustre_kcompr_16162: adecompr zstdfast(1) took 241 us (30 MB/s) [ 2723.590687] lustre_kcompr_16162: test_acomp_compress_decompress(zstdfast,1) ret 0 [ 2723.621985] lustre_kcompr_16162: compr zstdfast(5) in 64kB chunks took 23078 us (173 MB/s), compress ratio: 2.38 [ 2723.649948] lustre_kcompr_16162: compr zstdfast(5) in 128kB chunks took 21798 us (183 MB/s), compress ratio: 2.38 [ 2723.678884] lustre_kcompr_16162: compr zstdfast(5) in 256kB chunks took 22899 us (174 MB/s), compress ratio: 2.40 [ 2723.713693] lustre_kcompr_16162: compr zstdfast(5) in 512kB chunks took 29792 us (134 MB/s), compress ratio: 2.36 [ 2723.740937] lustre_kcompr_16162: compr zstdfast(5) in 1024kB chunks took 18711 us (213 MB/s), compress ratio: 2.36 [ 2723.773063] lustre_kcompr_16162: compr zstdfast(5) in 2048kB chunks took 24981 us (160 MB/s), compress ratio: 2.36 [ 2723.808091] lustre_kcompr_16162: compr zstdfast(5) in 4096kB chunks took 27470 us (145 MB/s), compress ratio: 2.36 [ 2723.852915] lustre_kcompr_16162: decompr zstdfast(5) took 16195 us (104 MB/s) [ 2723.860919] lustre_kcompr_16162: test_comp_compress_decompress(zstdfast,5) ret 0 [ 2723.873839] lustre_kcompr_16162: acompr zstdfast(5) of 128kB chunks took 207 us (603 MB/s), compress ratio: 16.12 [ 2723.881784] lustre_kcompr_16162: adecompr zstdfast(5) took 187 us (41 MB/s) [ 2723.899581] lustre_kcompr_16162: test_acomp_compress_decompress(zstdfast,5) ret 0 [ 2723.957625] lustre_kcompr_16162: compr zstdfast(12) in 64kB chunks took 19306 us (207 MB/s), compress ratio: 2.07 [ 2723.980836] lustre_kcompr_16162: compr zstdfast(12) in 128kB chunks took 10673 us (374 MB/s), compress ratio: 2.07 [ 2724.011623] lustre_kcompr_16162: compr zstdfast(12) in 256kB chunks took 18210 us (219 MB/s), compress ratio: 2.08 [ 2724.037283] lustre_kcompr_16162: compr zstdfast(12) in 512kB chunks took 18664 us (214 MB/s), compress ratio: 2.07 [ 2724.115569] lustre_kcompr_16162: compr zstdfast(12) in 1024kB chunks took 46793 us (85 MB/s), compress ratio: 2.07 [ 2724.139790] lustre_kcompr_16162: compr zstdfast(12) in 2048kB chunks took 18052 us (221 MB/s), compress ratio: 2.07 [ 2724.165356] lustre_kcompr_16162: compr zstdfast(12) in 4096kB chunks took 12901 us (310 MB/s), compress ratio: 2.08 [ 2724.216949] lustre_kcompr_16162: decompr zstdfast(12) took 10448 us (183 MB/s) [ 2724.242205] lustre_kcompr_16162: test_comp_compress_decompress(zstdfast,12) ret 0 [ 2724.253572] lustre_kcompr_16162: acompr zstdfast(12) of 128kB chunks took 141 us (886 MB/s), compress ratio: 13.13 [ 2724.267347] lustre_kcompr_16162: adecompr zstdfast(12) took 274 us (34 MB/s) [ 2724.289885] lustre_kcompr_16162: test_acomp_compress_decompress(zstdfast,12) ret 0 [ 2724.320868] lustre_kcompr_16162: compr zstdfast(15) in 64kB chunks took 12862 us (310 MB/s), compress ratio: 1.82 [ 2724.355702] lustre_kcompr_16162: compr zstdfast(15) in 128kB chunks took 13445 us (297 MB/s), compress ratio: 1.83 [ 2724.388374] lustre_kcompr_16162: compr zstdfast(15) in 256kB chunks took 10992 us (363 MB/s), compress ratio: 1.83 [ 2724.410601] lustre_kcompr_16162: compr zstdfast(15) in 512kB chunks took 8535 us (468 MB/s), compress ratio: 1.83 [ 2724.428679] lustre_kcompr_16162: compr zstdfast(15) in 1024kB chunks took 8618 us (464 MB/s), compress ratio: 1.83 [ 2724.445864] lustre_kcompr_16162: compr zstdfast(15) in 2048kB chunks took 8267 us (483 MB/s), compress ratio: 1.83 [ 2724.469584] lustre_kcompr_16162: compr zstdfast(15) in 4096kB chunks took 17630 us (226 MB/s), compress ratio: 1.84 [ 2724.507533] lustre_kcompr_16162: decompr zstdfast(15) took 5141 us (422 MB/s) [ 2724.532219] lustre_kcompr_16162: test_comp_compress_decompress(zstdfast,15) ret 0 [ 2724.542979] lustre_kcompr_16162: acompr zstdfast(15) of 128kB chunks took 161 us (776 MB/s), compress ratio: 10.73 [ 2724.555978] lustre_kcompr_16162: adecompr zstdfast(15) took 114 us (102 MB/s) [ 2724.582305] lustre_kcompr_16162: test_acomp_compress_decompress(zstdfast,15) ret 0 [ 2724.585096] lustre_kcompr_16162: SUCCESS [ 2732.934184] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 13:24:06 (1789061046) [ 2765.082399] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 13:24:38 (1789061078) [ 2774.496556] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 13:24:48 (1789061088) [ 2986.236860] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 13:28:19 (1789061299) [ 3028.157083] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 13:29:01 (1789061341) [ 3128.498818] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 13:30:42 (1789061442) [ 3476.913397] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 13:36:30 (1789061790) [ 3583.759556] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 13:38:17 (1789061897) [ 3597.566153] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 13:38:31 (1789061911) [ 3606.311320] LustreError: 78123:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0353d3e800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3606.317447] LustreError: 78123:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 3606.360643] Lustre: Unmounted lustre-client [ 3606.865985] Lustre: Mounted lustre-client [ 3656.376045] LustreError: 78264:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0381b95000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3656.395436] LustreError: 78264:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 3656.506445] Lustre: Unmounted lustre-client [ 3657.161743] Lustre: Mounted lustre-client [ 3710.050718] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 13:40:23 (1789062023) [ 3734.729938] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 13:40:48 (1789062048) [ 3746.695853] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 13:41:00 (1789062060) [ 3823.714748] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 13:42:16 (1789062136) [ 3826.055633] Lustre: DEBUG MARKER: SKIP: sanity test_101m need >= 2.13.57 and ldiskfs for fallocate [ 3828.323346] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 13:42:21 (1789062141) [ 3839.887261] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 13:42:33 (1789062153) [ 3854.995902] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 13:42:48 (1789062168) [ 3864.456430] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 13:42:58 (1789062178) [ 3886.641755] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 13:43:20 (1789062200) [ 3909.516360] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 13:43:43 (1789062223) [ 3912.711967] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3914.572597] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3916.285949] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3919.504143] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3927.549374] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 13:44:01 (1789062241) [ 3930.522204] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3932.744711] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3934.627720] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3937.211654] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3940.836840] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3949.548735] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 13:44:23 (1789062263) [ 3959.976708] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 13:44:33 (1789062273) [ 3984.819290] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 13:44:59 (1789062299) [ 3995.124792] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 13:45:08 (1789062308) [ 4006.579840] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 13:45:19 (1789062319) [ 4016.981870] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 13:45:30 (1789062330) [ 4027.599278] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 13:45:41 (1789062341) [ 4036.710260] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 13:45:50 (1789062350) [ 4045.817632] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 13:45:59 (1789062359) [ 4055.265716] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 13:46:09 (1789062369) [ 4064.196866] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 13:46:17 (1789062377) [ 4073.436518] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 13:46:27 (1789062387) [ 4430.407603] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 13:52:23 (1789062743) [ 4671.613881] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 13:56:24 (1789062984) [ 4682.723459] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 13:56:36 (1789062996) [ 4717.949240] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 13:57:11 (1789063031) [ 4739.600756] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 13:57:32 (1789063052) [ 4750.542818] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 13:57:44 (1789063064) [ 4751.382872] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4751.443289] Lustre: lustre-OST0000-osc-ffff9f0347247000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4751.479279] LustreError: lustre-OST0000-osc-ffff9f0347247000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4757.812868] Lustre: DEBUG MARKER: oleg142-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9f0347247000.ost_server_uuid 50 [ 4760.008570] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9f0347247000.ost_server_uuid in FULL state after 0 sec [ 4772.258380] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 13:58:04 (1789063084) [ 4782.519522] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 13:58:15 (1789063095) [ 4813.993819] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 13:58:47 (1789063127) [ 4823.751921] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 13:58:57 (1789063137) [ 4833.392480] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 13:59:06 (1789063146) [ 4843.511973] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 13:59:16 (1789063156) [ 4852.106116] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 13:59:25 (1789063165) [ 4852.528458] LustreError: 112952:0:(ldlm_flock.c:851:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 4862.547903] LustreError: 112952:0:(ldlm_flock.c:851:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 4871.285515] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 13:59:45 (1789063185) [ 4882.387974] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 13:59:55 (1789063195) [ 4893.013888] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 14:00:06 (1789063206) [ 4893.531794] Lustre: *** cfs_fail_loc=32f, val=0*** [ 4893.533583] LustreError: 114785:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff9f0347247000 lock: ffff9f0380089200/0xd34942b7c648cb53 lrc: 4/0,1 mode: PW/PW res: [0x200000409:0xb6a:0x0].0xc rrc: 2 type: FLK pid: 114784 [0->9223372036854775807] flags: 0x0 nid: local remote: 0xbc8c43320f7820c expref: -99 pid: 114785 timeout: 0 [ 4893.556421] CPU: 1 PID: 114785 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 4893.573015] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 4893.589467] Call Trace: [ 4893.591855] ? dump_stack+0xbb/0x10e [ 4893.604111] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 4893.606641] ? _raw_spin_unlock+0x12/0x30 [ 4893.615827] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 4893.617901] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 4893.621586] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 4893.625610] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 4893.629154] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4893.632810] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4893.638864] ? mdc_enqueue_base+0x458/0x1db0 [mdc] [ 4893.644322] ? mdc_enqueue+0x1c/0x30 [mdc] [ 4893.647105] ? lmv_enqueue+0x28a/0x530 [lmv] [ 4893.650715] ? ll_file_flock+0x962/0x1420 [lustre] [ 4893.654753] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4893.658125] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4893.669857] ? __mod_memcg_lruvec_state+0x5e/0x130 [ 4893.674543] ? __mod_lruvec_state+0x5a/0x80 [ 4893.677067] ? page_add_new_anon_rmap+0x77/0x1c0 [ 4893.679420] ? slab_post_alloc_hook+0x66/0x380 [ 4893.681683] ? locks_alloc_lock+0x1f/0x90 [ 4893.683214] ? kmem_cache_alloc+0x184/0x430 [ 4893.685024] ? vfs_lock_file+0x22/0x50 [ 4893.687135] ? fcntl_setlk+0xde/0x4e0 [ 4893.691604] ? __might_sleep+0x59/0xc0 [ 4893.693356] ? do_fcntl+0x7da/0xb80 [ 4893.695292] ? __x64_sys_fcntl+0xc4/0x110 [ 4893.696833] ? do_syscall_64+0xc1/0x440 [ 4893.699917] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 4904.999848] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 14:00:18 (1789063218) [ 4916.292811] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 14:00:29 (1789063229) [ 4921.910852] LustreError: lustre-MDT0000-mdc-ffff9f0347247000: operation ldlm_enqueue to node 192.168.201.142@tcp failed: rc = -35 [ 4932.304986] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 14:00:45 (1789063245) [ 4943.659323] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 14:00:56 (1789063256) [ 4956.926933] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 14:01:10 (1789063270) [ 4968.103481] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 14:01:20 (1789063280) [ 5307.728177] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 14:07:01 (1789063621) [ 5328.679623] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 14:07:20 (1789063640) [ 5340.278637] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 14:07:33 (1789063653) [ 5350.488422] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 14:07:43 (1789063663) [ 5366.425521] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 5369.691309] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 5372.791372] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 14:08:05 (1789063685) [ 5373.593522] Lustre: *** cfs_fail_loc=40a, val=0*** [ 5373.602399] Lustre: Skipped 225 previous similar messages [ 5373.610527] LustreError: 124514:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0001-osc-ffff9f0347247000: prep_req failed: rc = -22 [ 5373.630732] LustreError: 124514:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -22 [ 5384.093628] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 14:08:16 (1789063696) [ 5384.735408] Lustre: *** cfs_fail_loc=406, val=0*** [ 5384.738494] LustreError: 125103:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0000-osc-ffff9f0347247000: prep_req failed: rc = -12 [ 5384.745250] LustreError: 125103:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -12 [ 5394.010402] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 14:08:27 (1789063707) [ 5397.455853] LustreError: lustre-OST0001-osc-ffff9f0347247000: operation ost_write to node 192.168.201.142@tcp failed: rc = -5 [ 5397.465303] LustreError: 2366:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9f03482e8000 x1875963724857344/t0(0) o4->lustre-OST0001-osc-ffff9f0347247000@192.168.201.142@tcp:6/4 lens 4584/224 e 0 to 0 dl 1789063728 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 5397.491569] LustreError: 2366:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 59 previous similar messages [ 5400.041929] LustreError: lustre-OST0001-osc-ffff9f0347247000: operation ost_write to node 192.168.201.142@tcp failed: rc = -5 [ 5400.045891] LustreError: Skipped 1 previous similar message [ 5403.139684] LustreError: lustre-OST0001-osc-ffff9f0347247000: operation ost_write to node 192.168.201.142@tcp failed: rc = -5 [ 5407.212584] LustreError: lustre-OST0001-osc-ffff9f0347247000: operation ost_write to node 192.168.201.142@tcp failed: rc = -5 [ 5407.224712] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9f0347247000: too many resent retries for object: 10737419264:6331: rc = -5 [ 5407.237996] LustreError: 2366:0:(osc_request.c:2607:brw_interpret()) Skipped 14 previous similar messages [ 5407.262626] Lustre: 2366:0:(llite_lib.c:4187:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.142@tcp:/lustre/fid: [0x200000409:0xf52:0x0]// may get corrupted (rc -5) [ 5418.095883] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 14:08:51 (1789063731) [ 5420.534444] LustreError: lustre-OST0001-osc-ffff9f0347247000: operation ost_write to node 192.168.201.142@tcp failed: rc = -5 [ 5420.544337] LustreError: 2368:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9f03641f3100 x1875963724865664/t0(0) o4->lustre-OST0001-osc-ffff9f0347247000@192.168.201.142@tcp:6/4 lens 4584/224 e 0 to 0 dl 1789063752 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 5420.571586] LustreError: 2368:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 3 previous similar messages [ 5439.557713] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 14:09:13 (1789063753) [ 5442.242753] LustreError: lustre-OST0001-osc-ffff9f0347247000: operation ost_write to node 192.168.201.142@tcp failed: rc = -14 [ 5442.252596] LustreError: Skipped 3 previous similar messages [ 5452.669345] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 14:09:26 (1789063766) [ 5455.397320] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9f0351c9d500 x1875963724877696/t0(0) o4->lustre-OST0000-osc-ffff9f0347247000@192.168.201.142@tcp:6/4 lens 488/224 e 0 to 0 dl 1789063786 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 5455.425910] LustreError: 2367:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 3 previous similar messages [ 5478.729446] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 14:09:51 (1789063791) [ 5487.756569] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 14:10:01 (1789063801) [ 5496.896657] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 14:10:10 (1789063810) [ 5511.332673] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 14:10:24 (1789063824) [ 5520.603232] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 14:10:34 (1789063834) [ 5530.442131] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 14:10:44 (1789063844) [ 5539.688994] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 14:10:53 (1789063853) [ 5597.433452] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 14:11:50 (1789063910) [ 5647.397653] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 14:12:41 (1789063961) [ 5700.538100] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 14:13:34 (1789064014) [ 5747.441787] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 5751.907598] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 14:14:23 (1789064063) [ 5754.568944] sysctl (134858): drop_caches: 3 [ 5754.823577] Lustre: *** cfs_fail_loc=1429, val=0*** [ 5755.557871] Lustre: *** cfs_fail_loc=1429, val=0*** [ 5766.348559] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 14:14:39 (1789064079) [ 5790.449749] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 14:15:03 (1789064103) [ 5798.103464] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 14:15:12 (1789064112) [ 5800.061650] Lustre: DEBUG MARKER: SKIP: sanity test_119n zfs server without 'unaligned_dio' support [ 5801.916697] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 14:15:16 (1789064116) [ 5804.422025] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without 'unaligned_dio' support [ 5806.720890] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 14:15:20 (1789064120) [ 5816.175723] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 14:15:29 (1789064129) [ 5836.817417] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 14:15:50 (1789064150) [ 5853.652971] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 14:16:06 (1789064166) [ 5867.468779] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 14:16:20 (1789064180) [ 5880.464646] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 14:16:33 (1789064193) [ 5892.634561] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 14:16:46 (1789064206) [ 5912.096643] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 14:17:05 (1789064225) [ 5931.089434] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 14:17:25 (1789064245) [ 6446.975857] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 14:26:00 (1789064760) [ 6447.383178] Lustre: *** cfs_fail_loc=310, val=0*** [ 6456.359730] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 14:26:09 (1789064769) [ 6467.925529] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 6471.052162] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 2 sec [ 6526.276424] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 26 sec [ 6537.714295] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 6539.496628] Lustre: DEBUG MARKER: 'ls -l' done [ 6565.060314] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 23 seconds [ 6580.257759] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 14:28:13 (1789064893) [ 6595.438199] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 6600.036272] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 6648.145598] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 23 sec [ 6661.857153] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 8 sec [ 6664.981819] Lustre: DEBUG MARKER: 'statx -l' done [ 6691.361078] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 24 seconds [ 6705.358199] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 14:30:19 (1789065019) [ 6716.333980] Lustre: DEBUG MARKER: 'statx -c 0 [ 6719.742697] Lustre: DEBUG MARKER: 'statx -c 0 [ 6753.264837] Lustre: DEBUG MARKER: 'statx -c 0 [ 6763.634413] Lustre: DEBUG MARKER: 'statx -c 0 [ 6765.992759] Lustre: DEBUG MARKER: 'statx -c 0 [ 6789.738420] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 22 seconds [ 6797.436869] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 6798.925087] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 6820.934445] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 0 sec [ 6823.670168] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 6984.891366] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 0 sec [ 6988.473106] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 0 sec [ 6990.528873] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 7318.762837] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 326 seconds [ 7338.885582] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 14:40:52 (1789065652) [ 7349.177496] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 7352.349472] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 7393.611594] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 21 sec [ 7407.328972] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 9 sec [ 7409.446242] Lustre: DEBUG MARKER: 'ls -l' done [ 7432.575036] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 22 seconds [ 8077.833260] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 8081.609933] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 8128.866573] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 25 sec [ 8140.575213] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 8142.923766] Lustre: DEBUG MARKER: 'ls -l' done [ 8168.978157] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 24 seconds [ 8656.559094] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 15:02:50 (1789066970) [ 8686.275695] Lustre: DEBUG MARKER: ls done [ 8714.580684] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 15:03:48 (1789067028) [ 8716.975461] Lustre: DEBUG MARKER: SKIP: sanity test_123c needs >= 2 MDTs [ 8719.941902] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 15:03:53 (1789067033) [ 8725.527744] LustreError: 172957:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0347247000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 8725.548564] LustreError: 172957:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 8725.630979] Lustre: Unmounted lustre-client [ 8726.566751] Lustre: Mounted lustre-client [ 8738.597420] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 15:04:12 (1789067052) [ 9079.755484] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 15:09:52 (1789067392) [10380.906204] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 15:31:34 (1789068694) [10479.104835] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 15:33:13 (1789068793) [11982.773307] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 15:58:16 (1789070296) [12121.973145] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 16:00:35 (1789070435) [12124.072803] Lustre: DEBUG MARKER: SKIP: sanity test_123j needs >= 2 MDTs [12125.814160] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 16:00:39 (1789070439) [12128.010777] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [12129.817655] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 16:00:43 (1789070443) [12135.577218] LustreError: 179084:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [12170.616907] LustreError: 179084:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [12212.148166] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 16:02:06 (1789070526) [12213.755271] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [12257.786255] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9f03465ac800 [12260.199790] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9f03465ac800 [12261.799878] Lustre: DEBUG MARKER: LRU=2003 [12263.271805] Lustre: DEBUG MARKER: LIMIT=61549 [12265.163401] Lustre: DEBUG MARKER: LVF=3687400 [12266.910135] Lustre: DEBUG MARKER: OLD_LVF=100 [12268.860693] Lustre: DEBUG MARKER: Sleep 50 sec [12321.515967] Lustre: DEBUG MARKER: Dropped 1073 locks in 50s [12324.203479] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [12356.089519] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 16:04:30 (1789070670) [12456.140950] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [12621.276451] Lustre: DEBUG MARKER: ls -la time: 163 seconds [12623.263960] Lustre: DEBUG MARKER: lru_size = 400 [12833.276969] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [12928.439665] Lustre: DEBUG MARKER: ls -la time: 87 seconds [12931.049783] Lustre: DEBUG MARKER: lru_size = 8005 [12932.859556] Lustre: DEBUG MARKER: ls -la is 46% faster with lru resize enabled [13022.507810] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 16:15:36 (1789071336) [13060.431590] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 16:16:13 (1789071373) [13094.989951] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 16:16:48 (1789071408) [13144.615808] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 16:17:37 (1789071457) [13234.582412] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 16:19:08 (1789071548) [13931.291829] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 16:30:45 (1789072245) [13940.495788] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 16:30:53 (1789072253) [13949.212955] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 16:31:02 (1789072262) [13962.024902] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 16:31:14 (1789072274) [13970.884684] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [14018.187887] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 16:32:11 (1789072331) [14030.443358] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 16:32:24 (1789072344) [14051.111399] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 16:32:45 (1789072365) [14052.657054] Lustre: DEBUG MARKER: SKIP: sanity test_127f ldiskfs only [14054.527869] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 16:32:48 (1789072368) [14063.311343] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 16:32:56 (1789072376) [14065.694874] Lustre: DEBUG MARKER: SKIP: sanity test_129 ldiskfs only test [14067.884784] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 16:33:01 (1789072381) [14070.551669] Lustre: DEBUG MARKER: SKIP: sanity test_130a LU-1941: FIEMAP unimplemented on ZFS [14072.536541] Lustre: DEBUG MARKER: SKIP: sanity test_130b skipping ALWAYS excluded test 130b [14075.238862] Lustre: DEBUG MARKER: SKIP: sanity test_130c skipping ALWAYS excluded test 130c [14077.703211] Lustre: DEBUG MARKER: SKIP: sanity test_130d skipping ALWAYS excluded test 130d [14081.344837] Lustre: DEBUG MARKER: SKIP: sanity test_130e skipping ALWAYS excluded test 130e [14083.871701] Lustre: DEBUG MARKER: SKIP: sanity test_130f skipping ALWAYS excluded test 130f [14085.948800] Lustre: DEBUG MARKER: SKIP: sanity test_130g skipping ALWAYS excluded test 130g [14088.527822] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 16:33:21 (1789072401) [14090.305618] LustreError: 220446:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [14095.336100] LustreError: 220446:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [14102.778283] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 16:33:36 (1789072416) [14104.951456] Lustre: DEBUG MARKER: SKIP: sanity test_130i LU-1941: FIEMAP unimplemented on ZFS [14106.625842] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 16:33:40 (1789072420) [14113.574952] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 16:33:47 (1789072427) [14122.911742] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 16:33:57 (1789072437) [14131.214166] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 16:34:05 (1789072445) [14139.748149] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 16:34:13 (1789072453) [14146.778428] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 16:34:21 (1789072461) [14168.715173] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 16:34:42 (1789072482) [14193.201166] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 16:35:07 (1789072507) [14243.133843] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 16:35:56 (1789072556) [14286.915479] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 16:36:39 (1789072599) [14302.498773] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 16:36:56 (1789072616) [14304.728587] LNet: 228769:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14304.728587] mask usage: [+|-] ... [14305.362853] LNet: 228811:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14305.362853] mask usage: [+|-] ... [14305.376255] LNet: 228811:0:(debug.c:376:cfs_str2mask()) Skipped 5 previous similar messages [14305.427182] Lustre: DEBUG MARKER:  [14305.431780] Lustre: DEBUG MARKER:  [14322.293223] LustreError: 229345:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f03465ac800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [14322.310652] LustreError: 229345:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [14322.397149] Lustre: Unmounted lustre-client [14357.336477] Key type lgssc unregistered [14357.587662] LNet: 229793:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14357.593958] LNetError: 229793:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [14357.607932] LNet: Removed LNI 192.168.201.42@tcp [14358.312178] Key type .llcrypt unregistered [14358.314454] Key type ._llcrypt unregistered [14372.098646] Key type ._llcrypt registered [14372.100281] Key type .llcrypt registered [14372.548880] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [14372.566555] alg: No test for adler32 (adler32-zlib) [14374.079794] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [14375.332708] LNet: Added LNI 192.168.201.42@tcp [8/256/0/180] [14377.488392] Key type lgssc registered [14380.770601] Lustre: Echo OBD driver; http://www.lustre.org/ [14386.753659] alg: No test for zstdfast (zstdfast-lustre-generic) [14386.904802] alg: No test for zstdfast (zstdfast-lustre-scomp) [14484.176196] Lustre: Mounted lustre-client [14490.175746] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14506.618361] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 16:40:20 (1789072820) [14510.048450] Lustre: lustre-OST0000-osc-ffff9f0347246000: disconnect after 23s idle [14599.203391] LustreError: 233163:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0347246000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [14599.246633] Lustre: Unmounted lustre-client [14630.685550] Key type lgssc unregistered [14631.087149] LNet: 233646:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14631.106384] LNetError: 233646:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [14631.149281] LNet: Removed LNI 192.168.201.42@tcp [14631.922159] Key type .llcrypt unregistered [14631.923844] Key type ._llcrypt unregistered [14643.711694] Key type ._llcrypt registered [14643.733305] Key type .llcrypt registered [14644.121953] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [14644.134876] alg: No test for adler32 (adler32-zlib) [14645.153906] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [14645.470792] LNet: Added LNI 192.168.201.42@tcp [8/256/0/180] [14647.112583] Key type lgssc registered [14648.638110] Lustre: Echo OBD driver; http://www.lustre.org/ [14651.521026] alg: No test for zstdfast (zstdfast-lustre-generic) [14651.550832] alg: No test for zstdfast (zstdfast-lustre-scomp) [14735.521519] Lustre: Mounted lustre-client [14743.731035] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14759.748816] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 16:44:32 (1789073072) [14760.931612] Lustre: lustre-OST0000-osc-ffff9f0353da1000: disconnect after 22s idle [14801.889263] Lustre: lustre-OST0000-osc-ffff9f0353da1000: disconnect after 24s idle [14801.901011] Lustre: Skipped 1 previous similar message [14832.622656] Lustre: lustre-OST0000-osc-ffff9f0353da1000: disconnect after 21s idle [14832.638386] Lustre: Skipped 1 previous similar message [14837.728448] Lustre: lustre-OST0001-osc-ffff9f0353da1000: disconnect after 23s idle [15958.022779] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 17:04:32 (1789074272) [16014.824206] Lustre: lustre-OST0001-osc-ffff9f0353da1000: disconnect after 21s idle [16024.225462] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 17:05:37 (1789074337) [16068.604553] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [16070.635859] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [16072.393242] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 17:06:26 (1789074386) [16112.020872] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 17:07:05 (1789074425) [16115.646799] LustreError: 254817:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0353da1000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [16115.751531] Lustre: Unmounted lustre-client [16116.478708] Lustre: Mounted lustre-client [16147.857096] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 17:07:41 (1789074461) [16149.784265] Lustre: DEBUG MARKER: SKIP: sanity test_150b need >= 2.13.57 and ldiskfs for fallocate [16152.138855] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 17:07:45 (1789074465) [16154.508312] Lustre: DEBUG MARKER: SKIP: sanity test_150bb need >= 2.13.57 and ldiskfs for fallocate [16157.529158] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 17:07:50 (1789074470) [16159.928226] Lustre: DEBUG MARKER: SKIP: sanity test_150c need >= 2.13.57 and ldiskfs for fallocate [16161.574333] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 17:07:55 (1789074475) [16163.320191] Lustre: DEBUG MARKER: SKIP: sanity test_150d need >= 2.13.57 and ldiskfs for fallocate [16165.428858] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 17:07:59 (1789074479) [16167.062447] Lustre: DEBUG MARKER: SKIP: sanity test_150e need >= 2.13.57 and ldiskfs for fallocate [16168.958371] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 17:08:02 (1789074482) [16170.462853] Lustre: DEBUG MARKER: SKIP: sanity test_150f LU-14160: punch mode is not implemented on OSD ZFS [16172.873880] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 17:08:06 (1789074486) [16174.988778] Lustre: DEBUG MARKER: SKIP: sanity test_150g LU-14160: punch mode is not implemented on OSD ZFS [16177.480052] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 17:08:10 (1789074490) [16179.142489] Lustre: DEBUG MARKER: SKIP: sanity test_150h need >= 2.13.57 and ldiskfs for fallocate [16181.111304] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 17:08:15 (1789074495) [16183.260948] Lustre: DEBUG MARKER: SKIP: sanity test_150ia zero-range mode is not implemented on OSD ZFS [16184.913430] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 17:08:19 (1789074499) [16187.008869] Lustre: DEBUG MARKER: SKIP: sanity test_150ib zero-range mode is not implemented on OSD ZFS [16189.226634] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 17:08:22 (1789074502) [16191.166622] Lustre: DEBUG MARKER: SKIP: sanity test_150ic zero-range mode is not implemented on OSD ZFS [16193.313086] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 17:08:27 (1789074507) [16197.448976] Lustre: DEBUG MARKER: SKIP: sanity test_151 not cache-capable obdfilter [16199.864209] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 17:08:33 (1789074513) [16208.234758] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 17:08:42 (1789074522) [16216.086596] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 17:08:50 (1789074530) [16225.270978] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 17:08:58 (1789074538) [16233.718782] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 17:09:07 (1789074547) [16264.587579] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 17:09:38 (1789074578) [16276.545734] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 17:09:49 (1789074589) [16279.258803] Lustre: DEBUG MARKER: SKIP: sanity test_154b needs >= 2 MDTs [16280.858170] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 17:09:55 (1789074595) [16287.633672] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 17:10:01 (1789074601) [16295.706950] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 17:10:09 (1789074609) [16301.850711] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 17:10:15 (1789074615) [16353.872344] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 17:11:08 (1789074668) [16363.439642] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 17:11:17 (1789074677) [17752.072842] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 17:34:26 (1789076066) [17759.798958] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 17:34:32 (1789076072) [17800.818572] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 17:35:14 (1789076114) [17802.951456] Lustre: DEBUG MARKER: SKIP: sanity test_154j needs >= 2 MDTs [17805.232711] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 17:35:18 (1789076118) [17824.611484] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 17:35:37 (1789076137) [17843.251907] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 17:35:56 (1789076156) [17859.495522] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 17:36:13 (1789076173) [17874.512702] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 17:36:28 (1789076188) [17930.744069] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 17:37:24 (1789076244) [17988.938546] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 17:38:22 (1789076302) [18064.136725] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 17:39:37 (1789076377) [18129.073376] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 17:40:41 (1789076441) [18132.180222] Lustre: DEBUG MARKER: SKIP: sanity test_156 LU-1956/LU-2261: stats not implemented on OSD ZFS [18135.916821] Lustre: DEBUG MARKER: == sanity test 157: llapi pool pinning API tests ========= 17:40:48 (1789076448) [18148.684471] Lustre: DEBUG MARKER: == sanity test 157a: lustre.pin inheritance on create ==== 17:41:02 (1789076462) [18160.893709] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 17:41:14 (1789076474) [18185.195133] Lustre: lustre-MDT0000-mdc-ffff9f0358135800: Connection to lustre-MDT0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [18200.578898] LustreError: MGC192.168.201.142@tcp: Connection to MGS (at 192.168.201.142@tcp) was lost; in progress operations using this service will fail [18200.615941] Lustre: Evicted from MGS (at 192.168.201.142@tcp) after server handle changed from 0x911bb912c06f697c to 0x911bb912c0789745 [18200.642790] Lustre: MGC192.168.201.142@tcp: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [18204.868219] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9f037b425c00 x1875978970871680/t12884908675(12884908675) o101->lustre-MDT0000-mdc-ffff9f0358135800@192.168.201.142@tcp:12/10 lens 968/608 e 0 to 0 dl 1789076536 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [18205.374695] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9f0381007480 x1875978977680768/t12884924352(12884924352) o101->lustre-MDT0000-mdc-ffff9f0358135800@192.168.201.142@tcp:12/10 lens 968/608 e 0 to 0 dl 1789076536 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18205.413664] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 22 previous similar messages [18206.375333] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9f03466fad80 x1875978977723520/t12884924424(12884924424) o101->lustre-MDT0000-mdc-ffff9f0358135800@192.168.201.142@tcp:12/10 lens 968/608 e 0 to 0 dl 1789076537 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18206.397312] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 45 previous similar messages [18206.770516] Lustre: lustre-MDT0000-mdc-ffff9f0358135800: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [18226.088628] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 17:42:19 (1789076539) [18243.514362] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 17:42:37 (1789076557) [18262.390391] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 17:42:56 (1789076576) [18264.906514] Lustre: DEBUG MARKER: SKIP: sanity test_160d needs >= 2 MDTs [18267.766497] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 17:43:00 (1789076580) [18287.781259] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 17:43:21 (1789076601) [18296.492899] Lustre: DEBUG MARKER: 1789076609: creating first dirs [18351.232951] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 17:44:24 (1789076664) [18392.822984] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 17:45:05 (1789076705) [18430.459405] Lustre: lustre-MDT0000-mdc-ffff9f0358135800: Connection to lustre-MDT0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [18445.801133] LustreError: MGC192.168.201.142@tcp: Connection to MGS (at 192.168.201.142@tcp) was lost; in progress operations using this service will fail [18445.815110] Lustre: Evicted from MGS (at 192.168.201.142@tcp) after server handle changed from 0x911bb912c0789745 to 0x911bb912c078a990 [18445.835044] Lustre: MGC192.168.201.142@tcp: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [18461.309188] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9f0358cf7100 x1875978977673472/t12884924333(12884924333) o101->lustre-MDT0000-mdc-ffff9f0358135800@192.168.201.142@tcp:12/10 lens 968/608 e 0 to 0 dl 1789076792 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18461.334589] LustreError: 234010:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [18462.403696] Lustre: lustre-MDT0000-mdc-ffff9f0358135800: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [18476.928802] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 17:46:31 (1789076791) [18504.415756] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 17:46:58 (1789076818) [18504.917457] Lustre: Mounted lustre-client [18509.378926] LustreError: 291504:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0358135800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [18509.405036] LustreError: 291504:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [18509.557955] Lustre: Unmounted lustre-client [18517.810060] Lustre: Mounted lustre-client [18522.649539] LustreError: 292027:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0358ddf800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [18522.668078] LustreError: 292027:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [18522.762805] Lustre: Unmounted lustre-client [18524.550792] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 17:47:18 (1789076838) [18548.649711] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 17:47:41 (1789076861) [18572.087680] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 17:48:05 (1789076885) [18597.888670] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 17:48:31 (1789076911) [20738.538399] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 18:24:11 (1789079051) [20775.798909] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 18:24:49 (1789079089) [20778.186674] Lustre: DEBUG MARKER: SKIP: sanity test_160p ldiskfs only test [20780.174664] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 18:24:54 (1789079094) [20793.363895] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 18:25:06 (1789079106) [20831.300936] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 18:25:44 (1789079144) [20948.582751] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 18:27:41 (1789079261) [20966.039428] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 18:27:59 (1789079279) [20967.867961] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [20969.751967] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 18:28:03 (1789079283) [20994.844880] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 18:28:28 (1789079308) [21039.198221] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 18:29:12 (1789079352) [21041.441687] Lustre: DEBUG MARKER: SKIP: sanity test_161b skipping remote directory test [21043.665919] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 18:29:17 (1789079357) [21066.066217] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 18:29:39 (1789079379) [21070.362343] LustreError: 335429:0:(namei.c:1578:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [21072.977337] LustreError: 335429:0:(namei.c:1578:ll_create_node()) cfs_fail_timeout interrupted [21083.130731] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 18:29:57 (1789079397) [21092.349603] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 18:30:06 (1789079406) [21093.742347] Lustre: DEBUG MARKER: SKIP: sanity test_162b needs >= 2 MDTs [21095.792585] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 18:30:09 (1789079409) [21149.447240] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 18:31:03 (1789079463) [21159.920187] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [21194.113945] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 18:31:47 (1789079507) [21231.604458] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [21242.279734] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [21251.915397] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 18:32:45 (1789079565) [21287.928304] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [21297.883777] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [21308.025818] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 18:33:41 (1789079621) [21364.718736] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [21372.432167] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [21381.092331] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 18:34:55 (1789079695) [21383.438604] Lustre: DEBUG MARKER: SKIP: sanity test_165e needs >= 2 MDTs [21385.753881] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 18:34:59 (1789079699) [21395.432043] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [21413.706081] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [21422.628822] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 18:35:35 (1789079735) [21467.139188] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection to lustre-OST0000 (at 192.168.201.142@tcp) was lost; in progress operations using this service will wait for recovery to complete [21489.707961] Lustre: lustre-OST0000-osc-ffff9f0358081000: Connection restored to 192.168.201.142@tcp (at 192.168.201.142@tcp) [21497.486956] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 18:36:51 (1789079811) [21499.765757] Lustre: DEBUG MARKER: creating a 10 Mb file [21586.174682] Lustre: DEBUG MARKER: starting reads [21588.696975] Lustre: DEBUG MARKER: truncating the file [21591.102908] Lustre: DEBUG MARKER: killing dd [21593.053749] Lustre: DEBUG MARKER: removing the temporary file [21600.574262] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 18:38:34 (1789079914) [21600.778826] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [21600.959612] Lustre: shutting down debug daemon thread... [21600.995423] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [21601.061270] Lustre: shutting down debug daemon thread... [21608.189811] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 18:38:42 (1789079922) [21636.441560] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 18:39:10 (1789079950) [21636.636089] LustreError: 349005:0:(file.c:482:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [21639.664402] LustreError: 349005:0:(file.c:482:ll_file_release()) cfs_fail_timeout id 50e awake [21639.676662] LustreError: dumping log to /tmp/lustre-log.1789079955.349005 [21647.706833] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 18:39:21 (1789079961) [21650.223430] LustreError: 349587:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0358081000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [21650.240673] LustreError: 349587:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [21650.323077] Lustre: *** cfs_fail_loc=60e, val=0*** [21650.327145] Lustre: Unmounted lustre-client [21659.153696] Lustre: Mounted lustre-client [21661.447139] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 18:39:35 (1789079975) [21663.069937] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [21665.409814] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 18:39:39 (1789079979) [21688.210642] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 18:40:02 (1789080002) [21715.876489] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 18:40:29 (1789080029) [21812.151214] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 18:42:06 (1789080126) [21918.705381] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 18:43:52 (1789080232) [21920.790720] Lustre: DEBUG MARKER: SKIP: sanity test_182b needs >= 2 MDTs [21922.750525] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 18:43:56 (1789080236) [21932.483803] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 18:44:06 (1789080246) [21945.153892] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 18:44:18 (1789080258) [21953.084461] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 18:44:27 (1789080267) [22010.654867] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 18:45:23 (1789080323) [22024.934963] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 18:45:37 (1789080337) [22038.709773] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 18:45:52 (1789080352) [22048.499323] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 18:46:01 (1789080361) [22057.818869] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 18:46:11 (1789080371) [22067.719627] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 18:46:21 (1789080381) [22079.423273] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 18:46:33 (1789080393) [22088.384974] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 18:46:41 (1789080401) [22096.522398] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 18:46:50 (1789080410) [22130.623568] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 18:47:24 (1789080444) [22149.578911] Lustre: DEBUG MARKER: == sanity test complete, duration 21883 sec ============== 18:47:43 (1789080463) [22152.055673] Lustre: DEBUG MARKER: === sanity: start cleanup 18:47:45 (1789080465) === [22192.440300] Lustre: DEBUG MARKER: === sanity: finish cleanup 18:48:26 (1789080506) === [22196.877419] LustreError: 367585:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9f0347246000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [22196.887766] LustreError: 367585:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [22196.989402] Lustre: Unmounted lustre-client [22231.292784] Key type lgssc unregistered [22231.774535] LNet: 368067:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [22231.782725] LNetError: 368067:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [22231.799072] LNet: Removed LNI 192.168.201.42@tcp [22232.468293] Key type .llcrypt unregistered [22232.472103] Key type ._llcrypt unregistered