generic/095 failing in ext4 and xfs

generic/095 failing in ext4 and xfs

[Luis Henriques]

Hi!

I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
Here's what I'm getting:

# cat results/generic/095.out.bad 
QA output created by 095
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
fio: pid=4090, got signal=11
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
fio: pid=4086, got signal=11
Silence is golden

This was for ext4 but the output for xfs is similar.  Since fio is getting
killed I suspect this may be an issue with this tool.  Thus I'm sending
this to both fio and fstests mailing-lists.

I'm using a 5.15-rc3 kernel and fio-3.28.  Is anyone else seeing something
similar?

Cheers,
--
Luís

Re: generic/095 failing in ext4 and xfs

[Theodore Ts'o]

On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> Hi!
> 
> I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> Here's what I'm getting:
> 
> This was for ext4 but the output for xfs is similar.  Since fio is getting
> killed I suspect this may be an issue with this tool.  Thus I'm sending
> this to both fio and fstests mailing-lists.
> 
> I'm using a 5.15-rc3 kernel and fio-3.28.  Is anyone else seeing something
> similar?

Hmm, it's not failing for me.

ext4/4k: 1 tests, 3 seconds
  generic/095  Pass     2s
Totals: 1 tests, 0 skipped, 0 failures, 0 errors, 2s

root@kvm-xfstests:~# uname -a
Linux kvm-xfstests 5.15.0-rc3-xfstests #355 SMP Fri Oct 1 14:44:55 EDT 2021 x86_64 GNU/Linux
root@kvm-xfstests:~# ver
blktests        62ec9d6 (Tue, 1 Jun 2021 10:08:38 -0700)
e2fsprogs       v1.46.4-5-g4cda2545-orphan_file (Sun, 22 Aug 2021 10:07:15 -0400)
fio             fio-3.27 (Wed, 26 May 2021 10:10:32 -0600)
fsverity        v1.4 (Mon, 14 Jun 2021 16:14:52 -0700)
ima-evm-utils   v1.3.2 (Wed, 28 Oct 2020 13:18:08 -0400)
nvme-cli        v1.14-61-gf729e93 (Fri, 25 Jun 2021 10:21:17 -0600)
quota           v4.05-40-g25f16b1 (Tue, 16 Mar 2021 17:57:19 +0100)
util-linux      v2.37 (Tue, 1 Jun 2021 09:52:10 +0200)
xfsprogs        v5.12.0 (Fri, 21 May 2021 15:53:24 -0400)
xfstests        linux-v3.8-3301-ga8b2de63 (Wed, 1 Sep 2021 12:07:48 -0400)
xfstests-bld    8c07d08 (Fri, 27 Aug 2021 22:11:13 -0400)

I'm using fio 3.27, though.

					- Ted

Re: generic/095 failing in ext4 and xfs

[Jens Axboe]

On 10/1/21 11:11 AM, Luis Henriques wrote:
> Hi!
> 
> I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> Here's what I'm getting:
> 
> # cat results/generic/095.out.bad 
> QA output created by 095
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> fio: pid=4090, got signal=11
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> fio: pid=4086, got signal=11
> Silence is golden
> 
> This was for ext4 but the output for xfs is similar.  Since fio is getting
> killed I suspect this may be an issue with this tool.  Thus I'm sending
> this to both fio and fstests mailing-lists.
> 
> I'm using a 5.15-rc3 kernel and fio-3.28.  Is anyone else seeing something
> similar?

Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
you give that a go? If that does work, would be great if you could try
and bisect it.

-- 
Jens Axboe

Re: generic/095 failing in ext4 and xfs

[Theodore Ts'o]

On Fri, Oct 01, 2021 at 02:46:09PM -0600, Jens Axboe wrote:
> 
> Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
> you give that a go? If that does work, would be great if you could try
> and bisect it.

I just tried fio 3.28, and it worked for me.  So I don't think it's
fio.

Luis, could it be related to a  kernel config option?

Here's the kernel config that I'm using.  Can you try copying the
attached file to your .config, and then run "make olddefconfig", and
then rebuild your kernel, and see if that works for you?  If so, then
we'll try to narrow down which kernel config is making the difference.

The other potential difference is that my test appliance is currently
built using Debian 10 ("Buster").  There can be glibc or other
userspace dependencies which make be making a difference, but that
seems unlikely given that generic/095 is a pretty old test, and it's
not trying to use anything new/exotic like io_uring.

      	     	    	       	      	     - Ted

CONFIG_LOCALVERSION="-xfstests"
CONFIG_SYSVIPC=y
CONFIG_POSIX_MQUEUE=y
CONFIG_NO_HZ=y
CONFIG_HIGH_RES_TIMERS=y
CONFIG_IKCONFIG=y
CONFIG_IKCONFIG_PROC=y
CONFIG_CGROUPS=y
CONFIG_MEMCG=y
CONFIG_BLK_CGROUP=y
CONFIG_CGROUP_SCHED=y
CONFIG_CGROUP_PIDS=y
CONFIG_CGROUP_RDMA=y
CONFIG_CGROUP_FREEZER=y
CONFIG_CPUSETS=y
CONFIG_CGROUP_DEVICE=y
CONFIG_CGROUP_CPUACCT=y
CONFIG_CGROUP_PERF=y
CONFIG_CGROUP_BPF=y
CONFIG_USER_NS=y
CONFIG_BLK_DEV_INITRD=y
CONFIG_BPF_SYSCALL=y
# CONFIG_COMPAT_BRK is not set
CONFIG_SLAB=y
CONFIG_SMP=y
CONFIG_X86_X2APIC=y
# CONFIG_X86_EXTENDED_PLATFORM is not set
CONFIG_HYPERVISOR_GUEST=y
CONFIG_PARAVIRT=y
CONFIG_PARAVIRT_SPINLOCKS=y
CONFIG_PARAVIRT_TIME_ACCOUNTING=y
CONFIG_MCORE2=y
CONFIG_NR_CPUS=48
# CONFIG_X86_MCE_AMD is not set
# CONFIG_MICROCODE is not set
CONFIG_NUMA=y
# CONFIG_AMD_NUMA is not set
CONFIG_X86_PMEM_LEGACY=y
CONFIG_X86_CHECK_BIOS_CORRUPTION=y
CONFIG_EFI=y
CONFIG_EFI_STUB=y
CONFIG_HZ_300=y
CONFIG_KEXEC=y
# CONFIG_SUSPEND is not set
# CONFIG_ACPI_REV_OVERRIDE_POSSIBLE is not set
# CONFIG_ACPI_TABLE_UPGRADE is not set
# CONFIG_PCI_MMCONFIG is not set
CONFIG_IA32_EMULATION=y
# CONFIG_DMIID is not set
CONFIG_EFI_VARS=y
CONFIG_JUMP_LABEL=y
CONFIG_MEMORY_HOTPLUG=y
CONFIG_MEMORY_HOTREMOVE=y
CONFIG_ZONE_DEVICE=y
CONFIG_NET=y
CONFIG_PACKET=y
CONFIG_PACKET_DIAG=y
CONFIG_UNIX=y
CONFIG_UNIX_DIAG=y
CONFIG_INET=y
CONFIG_SYN_COOKIES=y
CONFIG_INET_UDP_DIAG=y
CONFIG_NETLINK_DIAG=y
# CONFIG_WIRELESS is not set
CONFIG_NET_9P=y
CONFIG_NET_9P_VIRTIO=y
CONFIG_PCI=y
CONFIG_PCI_MSI=y
CONFIG_DEVTMPFS=y
CONFIG_MTD=y
CONFIG_MTD_BLOCK2MTD=y
CONFIG_MTD_UBI=y
CONFIG_BLK_DEV_LOOP=y
CONFIG_VIRTIO_BLK=y
CONFIG_BLK_DEV_NVME=y
CONFIG_SCSI=y
# CONFIG_SCSI_PROC_FS is not set
CONFIG_BLK_DEV_SD=y
CONFIG_SCSI_VIRTIO=y
CONFIG_MD=y
CONFIG_BLK_DEV_DM=y
CONFIG_DM_SNAPSHOT=y
CONFIG_DM_THIN_PROVISIONING=y
CONFIG_DM_ZERO=y
CONFIG_DM_FLAKEY=y
CONFIG_NETDEVICES=y
CONFIG_VIRTIO_NET=y
# CONFIG_ETHERNET is not set
# CONFIG_WLAN is not set
# CONFIG_INPUT_MOUSE is not set
# CONFIG_SERIO_SERPORT is not set
# CONFIG_LEGACY_PTYS is not set
CONFIG_SERIAL_8250=y
# CONFIG_SERIAL_8250_DEPRECATED_OPTIONS is not set
CONFIG_SERIAL_8250_CONSOLE=y
CONFIG_SERIAL_8250_NR_UARTS=32
CONFIG_SERIAL_8250_RUNTIME_UARTS=32
# CONFIG_HW_RANDOM_INTEL is not set
# CONFIG_HW_RANDOM_AMD is not set
# CONFIG_HW_RANDOM_VIA is not set
CONFIG_HW_RANDOM_VIRTIO=y
CONFIG_RANDOM_TRUST_CPU=y
# CONFIG_HWMON is not set
# CONFIG_X86_PKG_TEMP_THERMAL is not set
# CONFIG_HID is not set
# CONFIG_USB_SUPPORT is not set
CONFIG_RTC_CLASS=y
# CONFIG_RTC_DRV_CMOS is not set
CONFIG_VIRT_DRIVERS=y
CONFIG_VIRTIO_PCI=y
CONFIG_VIRTIO_BALLOON=y
# CONFIG_X86_PLATFORM_DEVICES is not set
# CONFIG_IOMMU_SUPPORT is not set
CONFIG_EXT2_FS=y
CONFIG_EXT2_FS_XATTR=y
CONFIG_EXT2_FS_POSIX_ACL=y
CONFIG_EXT2_FS_SECURITY=y
CONFIG_EXT4_FS=y
CONFIG_EXT4_FS_POSIX_ACL=y
CONFIG_EXT4_FS_SECURITY=y
CONFIG_EXT4_DEBUG=y
CONFIG_JBD2_DEBUG=y
CONFIG_REISERFS_FS=y
CONFIG_REISERFS_FS_XATTR=y
CONFIG_REISERFS_FS_POSIX_ACL=y
CONFIG_REISERFS_FS_SECURITY=y
CONFIG_JFS_FS=y
CONFIG_JFS_POSIX_ACL=y
CONFIG_JFS_SECURITY=y
CONFIG_XFS_FS=y
CONFIG_XFS_QUOTA=y
CONFIG_XFS_POSIX_ACL=y
CONFIG_XFS_RT=y
CONFIG_OCFS2_FS=y
CONFIG_BTRFS_FS=y
CONFIG_BTRFS_FS_POSIX_ACL=y
CONFIG_BTRFS_DEBUG=y
CONFIG_BTRFS_ASSERT=y
CONFIG_NILFS2_FS=y
CONFIG_F2FS_FS=y
CONFIG_F2FS_FS_SECURITY=y
CONFIG_F2FS_CHECK_FS=y
CONFIG_FS_DAX=y
CONFIG_FS_ENCRYPTION=y
CONFIG_FS_VERITY=y
CONFIG_FS_VERITY_BUILTIN_SIGNATURES=y
CONFIG_QUOTA_NETLINK_INTERFACE=y
# CONFIG_PRINT_QUOTA_WARNING is not set
CONFIG_QFMT_V2=y
CONFIG_AUTOFS4_FS=y
CONFIG_FUSE_FS=y
CONFIG_VIRTIO_FS=y
CONFIG_OVERLAY_FS=y
CONFIG_UDF_FS=y
CONFIG_MSDOS_FS=y
CONFIG_VFAT_FS=y
CONFIG_FAT_DEFAULT_UTF8=y
CONFIG_NTFS_FS=y
CONFIG_NTFS_RW=y
CONFIG_PROC_KCORE=y
CONFIG_PROC_CHILDREN=y
CONFIG_TMPFS=y
CONFIG_TMPFS_POSIX_ACL=y
CONFIG_CONFIGFS_FS=y
CONFIG_UBIFS_FS=y
CONFIG_NFS_FS=y
CONFIG_NFS_V3_ACL=y
CONFIG_NFS_V4=y
CONFIG_NFSD=y
CONFIG_NFSD_V3_ACL=y
CONFIG_NFSD_V4=y
CONFIG_9P_FS=y
CONFIG_NLS_DEFAULT="utf8"
CONFIG_NLS_CODEPAGE_437=y
CONFIG_NLS_ASCII=y
CONFIG_NLS_ISO8859_1=y
CONFIG_NLS_UTF8=y
CONFIG_UNICODE=y
CONFIG_SECURITY=y
CONFIG_FORTIFY_SOURCE=y
CONFIG_INTEGRITY_SIGNATURE=y
CONFIG_IMA=y
CONFIG_IMA_WRITE_POLICY=y
CONFIG_IMA_APPRAISE=y
CONFIG_EVM=y
# CONFIG_CRYPTO_MANAGER_DISABLE_TESTS is not set
CONFIG_CRYPTO_ADIANTUM=y
CONFIG_CRYPTO_ESSIV=y
CONFIG_CRYPTO_CRC32C_INTEL=y
CONFIG_CRYPTO_CRC32_PCLMUL=y
CONFIG_CRYPTO_AES_NI_INTEL=y
# CONFIG_CRYPTO_HW is not set
CONFIG_PRINTK_TIME=y
CONFIG_DYNAMIC_DEBUG=y
CONFIG_DEBUG_INFO=y
CONFIG_DEBUG_INFO_REDUCED=y
CONFIG_DEBUG_SECTION_MISMATCH=y
CONFIG_MAGIC_SYSRQ=y
CONFIG_DEBUG_KERNEL=y
CONFIG_DEBUG_PAGEALLOC=y
CONFIG_DEBUG_WX=y
CONFIG_DEBUG_OBJECTS=y
CONFIG_DEBUG_KMEMLEAK=y
CONFIG_DEBUG_KMEMLEAK_DEFAULT_OFF=y
CONFIG_PANIC_TIMEOUT=5
CONFIG_HARDLOCKUP_DETECTOR=y
CONFIG_WQ_WATCHDOG=y
CONFIG_PROVE_LOCKING=y
CONFIG_LOCK_STAT=y
CONFIG_DEBUG_ATOMIC_SLEEP=y
CONFIG_DEBUG_LIST=y
CONFIG_DEBUG_SG=y
CONFIG_RCU_EQS_DEBUG=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_PROFILER=y
CONFIG_FTRACE_SYSCALLS=y
CONFIG_TRACER_SNAPSHOT=y
CONFIG_BLK_DEV_IO_TRACE=y
# CONFIG_STRICT_DEVMEM is not set
CONFIG_FAULT_INJECTION=y
CONFIG_FAIL_MAKE_REQUEST=y
CONFIG_FAULT_INJECTION_DEBUG_FS=y

Re: generic/095 failing in ext4 and xfs

[Luis Henriques]

"Theodore Ts'o" <tytso@mit.edu> writes:

> On Fri, Oct 01, 2021 at 02:46:09PM -0600, Jens Axboe wrote:
>> 
>> Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
>> you give that a go? If that does work, would be great if you could try
>> and bisect it.
>
> I just tried fio 3.28, and it worked for me.  So I don't think it's
> fio.

Awesome, thank you both for checking it out.  So, it's definitely
something in my test environment.

> Luis, could it be related to a  kernel config option?

Yeah, it could be.  I've tested this on a rolling release (openSUSE TW),
so it's definitely quite different from Debian 10.  It may take me a bit
to figure out what's going on, but I'll start with this kernel config and
report back any finding.

Again, thank you both for confirming it's working on your side.

Cheers,
-- 
Luis

>
> Here's the kernel config that I'm using.  Can you try copying the
> attached file to your .config, and then run "make olddefconfig", and
> then rebuild your kernel, and see if that works for you?  If so, then
> we'll try to narrow down which kernel config is making the difference.
>
> The other potential difference is that my test appliance is currently
> built using Debian 10 ("Buster").  There can be glibc or other
> userspace dependencies which make be making a difference, but that
> seems unlikely given that generic/095 is a pretty old test, and it's
> not trying to use anything new/exotic like io_uring.
>
>       	     	    	       	      	     - Ted
>
> CONFIG_LOCALVERSION="-xfstests"
> CONFIG_SYSVIPC=y
> CONFIG_POSIX_MQUEUE=y
> CONFIG_NO_HZ=y
> CONFIG_HIGH_RES_TIMERS=y
> CONFIG_IKCONFIG=y
> CONFIG_IKCONFIG_PROC=y
> CONFIG_CGROUPS=y
> CONFIG_MEMCG=y
> CONFIG_BLK_CGROUP=y
> CONFIG_CGROUP_SCHED=y
> CONFIG_CGROUP_PIDS=y
> CONFIG_CGROUP_RDMA=y
> CONFIG_CGROUP_FREEZER=y
> CONFIG_CPUSETS=y
> CONFIG_CGROUP_DEVICE=y
> CONFIG_CGROUP_CPUACCT=y
> CONFIG_CGROUP_PERF=y
> CONFIG_CGROUP_BPF=y
> CONFIG_USER_NS=y
> CONFIG_BLK_DEV_INITRD=y
> CONFIG_BPF_SYSCALL=y
> # CONFIG_COMPAT_BRK is not set
> CONFIG_SLAB=y
> CONFIG_SMP=y
> CONFIG_X86_X2APIC=y
> # CONFIG_X86_EXTENDED_PLATFORM is not set
> CONFIG_HYPERVISOR_GUEST=y
> CONFIG_PARAVIRT=y
> CONFIG_PARAVIRT_SPINLOCKS=y
> CONFIG_PARAVIRT_TIME_ACCOUNTING=y
> CONFIG_MCORE2=y
> CONFIG_NR_CPUS=48
> # CONFIG_X86_MCE_AMD is not set
> # CONFIG_MICROCODE is not set
> CONFIG_NUMA=y
> # CONFIG_AMD_NUMA is not set
> CONFIG_X86_PMEM_LEGACY=y
> CONFIG_X86_CHECK_BIOS_CORRUPTION=y
> CONFIG_EFI=y
> CONFIG_EFI_STUB=y
> CONFIG_HZ_300=y
> CONFIG_KEXEC=y
> # CONFIG_SUSPEND is not set
> # CONFIG_ACPI_REV_OVERRIDE_POSSIBLE is not set
> # CONFIG_ACPI_TABLE_UPGRADE is not set
> # CONFIG_PCI_MMCONFIG is not set
> CONFIG_IA32_EMULATION=y
> # CONFIG_DMIID is not set
> CONFIG_EFI_VARS=y
> CONFIG_JUMP_LABEL=y
> CONFIG_MEMORY_HOTPLUG=y
> CONFIG_MEMORY_HOTREMOVE=y
> CONFIG_ZONE_DEVICE=y
> CONFIG_NET=y
> CONFIG_PACKET=y
> CONFIG_PACKET_DIAG=y
> CONFIG_UNIX=y
> CONFIG_UNIX_DIAG=y
> CONFIG_INET=y
> CONFIG_SYN_COOKIES=y
> CONFIG_INET_UDP_DIAG=y
> CONFIG_NETLINK_DIAG=y
> # CONFIG_WIRELESS is not set
> CONFIG_NET_9P=y
> CONFIG_NET_9P_VIRTIO=y
> CONFIG_PCI=y
> CONFIG_PCI_MSI=y
> CONFIG_DEVTMPFS=y
> CONFIG_MTD=y
> CONFIG_MTD_BLOCK2MTD=y
> CONFIG_MTD_UBI=y
> CONFIG_BLK_DEV_LOOP=y
> CONFIG_VIRTIO_BLK=y
> CONFIG_BLK_DEV_NVME=y
> CONFIG_SCSI=y
> # CONFIG_SCSI_PROC_FS is not set
> CONFIG_BLK_DEV_SD=y
> CONFIG_SCSI_VIRTIO=y
> CONFIG_MD=y
> CONFIG_BLK_DEV_DM=y
> CONFIG_DM_SNAPSHOT=y
> CONFIG_DM_THIN_PROVISIONING=y
> CONFIG_DM_ZERO=y
> CONFIG_DM_FLAKEY=y
> CONFIG_NETDEVICES=y
> CONFIG_VIRTIO_NET=y
> # CONFIG_ETHERNET is not set
> # CONFIG_WLAN is not set
> # CONFIG_INPUT_MOUSE is not set
> # CONFIG_SERIO_SERPORT is not set
> # CONFIG_LEGACY_PTYS is not set
> CONFIG_SERIAL_8250=y
> # CONFIG_SERIAL_8250_DEPRECATED_OPTIONS is not set
> CONFIG_SERIAL_8250_CONSOLE=y
> CONFIG_SERIAL_8250_NR_UARTS=32
> CONFIG_SERIAL_8250_RUNTIME_UARTS=32
> # CONFIG_HW_RANDOM_INTEL is not set
> # CONFIG_HW_RANDOM_AMD is not set
> # CONFIG_HW_RANDOM_VIA is not set
> CONFIG_HW_RANDOM_VIRTIO=y
> CONFIG_RANDOM_TRUST_CPU=y
> # CONFIG_HWMON is not set
> # CONFIG_X86_PKG_TEMP_THERMAL is not set
> # CONFIG_HID is not set
> # CONFIG_USB_SUPPORT is not set
> CONFIG_RTC_CLASS=y
> # CONFIG_RTC_DRV_CMOS is not set
> CONFIG_VIRT_DRIVERS=y
> CONFIG_VIRTIO_PCI=y
> CONFIG_VIRTIO_BALLOON=y
> # CONFIG_X86_PLATFORM_DEVICES is not set
> # CONFIG_IOMMU_SUPPORT is not set
> CONFIG_EXT2_FS=y
> CONFIG_EXT2_FS_XATTR=y
> CONFIG_EXT2_FS_POSIX_ACL=y
> CONFIG_EXT2_FS_SECURITY=y
> CONFIG_EXT4_FS=y
> CONFIG_EXT4_FS_POSIX_ACL=y
> CONFIG_EXT4_FS_SECURITY=y
> CONFIG_EXT4_DEBUG=y
> CONFIG_JBD2_DEBUG=y
> CONFIG_REISERFS_FS=y
> CONFIG_REISERFS_FS_XATTR=y
> CONFIG_REISERFS_FS_POSIX_ACL=y
> CONFIG_REISERFS_FS_SECURITY=y
> CONFIG_JFS_FS=y
> CONFIG_JFS_POSIX_ACL=y
> CONFIG_JFS_SECURITY=y
> CONFIG_XFS_FS=y
> CONFIG_XFS_QUOTA=y
> CONFIG_XFS_POSIX_ACL=y
> CONFIG_XFS_RT=y
> CONFIG_OCFS2_FS=y
> CONFIG_BTRFS_FS=y
> CONFIG_BTRFS_FS_POSIX_ACL=y
> CONFIG_BTRFS_DEBUG=y
> CONFIG_BTRFS_ASSERT=y
> CONFIG_NILFS2_FS=y
> CONFIG_F2FS_FS=y
> CONFIG_F2FS_FS_SECURITY=y
> CONFIG_F2FS_CHECK_FS=y
> CONFIG_FS_DAX=y
> CONFIG_FS_ENCRYPTION=y
> CONFIG_FS_VERITY=y
> CONFIG_FS_VERITY_BUILTIN_SIGNATURES=y
> CONFIG_QUOTA_NETLINK_INTERFACE=y
> # CONFIG_PRINT_QUOTA_WARNING is not set
> CONFIG_QFMT_V2=y
> CONFIG_AUTOFS4_FS=y
> CONFIG_FUSE_FS=y
> CONFIG_VIRTIO_FS=y
> CONFIG_OVERLAY_FS=y
> CONFIG_UDF_FS=y
> CONFIG_MSDOS_FS=y
> CONFIG_VFAT_FS=y
> CONFIG_FAT_DEFAULT_UTF8=y
> CONFIG_NTFS_FS=y
> CONFIG_NTFS_RW=y
> CONFIG_PROC_KCORE=y
> CONFIG_PROC_CHILDREN=y
> CONFIG_TMPFS=y
> CONFIG_TMPFS_POSIX_ACL=y
> CONFIG_CONFIGFS_FS=y
> CONFIG_UBIFS_FS=y
> CONFIG_NFS_FS=y
> CONFIG_NFS_V3_ACL=y
> CONFIG_NFS_V4=y
> CONFIG_NFSD=y
> CONFIG_NFSD_V3_ACL=y
> CONFIG_NFSD_V4=y
> CONFIG_9P_FS=y
> CONFIG_NLS_DEFAULT="utf8"
> CONFIG_NLS_CODEPAGE_437=y
> CONFIG_NLS_ASCII=y
> CONFIG_NLS_ISO8859_1=y
> CONFIG_NLS_UTF8=y
> CONFIG_UNICODE=y
> CONFIG_SECURITY=y
> CONFIG_FORTIFY_SOURCE=y
> CONFIG_INTEGRITY_SIGNATURE=y
> CONFIG_IMA=y
> CONFIG_IMA_WRITE_POLICY=y
> CONFIG_IMA_APPRAISE=y
> CONFIG_EVM=y
> # CONFIG_CRYPTO_MANAGER_DISABLE_TESTS is not set
> CONFIG_CRYPTO_ADIANTUM=y
> CONFIG_CRYPTO_ESSIV=y
> CONFIG_CRYPTO_CRC32C_INTEL=y
> CONFIG_CRYPTO_CRC32_PCLMUL=y
> CONFIG_CRYPTO_AES_NI_INTEL=y
> # CONFIG_CRYPTO_HW is not set
> CONFIG_PRINTK_TIME=y
> CONFIG_DYNAMIC_DEBUG=y
> CONFIG_DEBUG_INFO=y
> CONFIG_DEBUG_INFO_REDUCED=y
> CONFIG_DEBUG_SECTION_MISMATCH=y
> CONFIG_MAGIC_SYSRQ=y
> CONFIG_DEBUG_KERNEL=y
> CONFIG_DEBUG_PAGEALLOC=y
> CONFIG_DEBUG_WX=y
> CONFIG_DEBUG_OBJECTS=y
> CONFIG_DEBUG_KMEMLEAK=y
> CONFIG_DEBUG_KMEMLEAK_DEFAULT_OFF=y
> CONFIG_PANIC_TIMEOUT=5
> CONFIG_HARDLOCKUP_DETECTOR=y
> CONFIG_WQ_WATCHDOG=y
> CONFIG_PROVE_LOCKING=y
> CONFIG_LOCK_STAT=y
> CONFIG_DEBUG_ATOMIC_SLEEP=y
> CONFIG_DEBUG_LIST=y
> CONFIG_DEBUG_SG=y
> CONFIG_RCU_EQS_DEBUG=y
> CONFIG_FUNCTION_TRACER=y
> CONFIG_FUNCTION_PROFILER=y
> CONFIG_FTRACE_SYSCALLS=y
> CONFIG_TRACER_SNAPSHOT=y
> CONFIG_BLK_DEV_IO_TRACE=y
> # CONFIG_STRICT_DEVMEM is not set
> CONFIG_FAULT_INJECTION=y
> CONFIG_FAIL_MAKE_REQUEST=y
> CONFIG_FAULT_INJECTION_DEBUG_FS=y

Re: generic/095 failing in ext4 and xfs

[Jens Axboe]

On 10/2/21 4:16 AM, Luis Henriques wrote:
> "Theodore Ts'o" <tytso@mit.edu> writes:
> 
>> On Fri, Oct 01, 2021 at 02:46:09PM -0600, Jens Axboe wrote:
>>>
>>> Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
>>> you give that a go? If that does work, would be great if you could try
>>> and bisect it.
>>
>> I just tried fio 3.28, and it worked for me.  So I don't think it's
>> fio.
> 
> Awesome, thank you both for checking it out.  So, it's definitely
> something in my test environment.
> 
>> Luis, could it be related to a  kernel config option?
> 
> Yeah, it could be.  I've tested this on a rolling release (openSUSE TW),
> so it's definitely quite different from Debian 10.  It may take me a bit
> to figure out what's going on, but I'll start with this kernel config and
> report back any finding.
> 
> Again, thank you both for confirming it's working on your side.

Do you have a core file from fio? Would be interesting to get a
backtrace from it.

In terms of why it's failing, a guess would be that your device is using 4k
sectors and the test is trying to do 1k aligned dio. That would fail, but
it should not cause fio to crash...

-- 
Jens Axboe

Re: generic/095 failing in ext4 and xfs

[Luis Henriques]

On Sat, Oct 02, 2021 at 08:59:57AM -0600, Jens Axboe wrote:
> On 10/2/21 4:16 AM, Luis Henriques wrote:
> > "Theodore Ts'o" <tytso@mit.edu> writes:
> > 
> >> On Fri, Oct 01, 2021 at 02:46:09PM -0600, Jens Axboe wrote:
> >>>
> >>> Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
> >>> you give that a go? If that does work, would be great if you could try
> >>> and bisect it.
> >>
> >> I just tried fio 3.28, and it worked for me.  So I don't think it's
> >> fio.
> > 
> > Awesome, thank you both for checking it out.  So, it's definitely
> > something in my test environment.
> > 
> >> Luis, could it be related to a  kernel config option?
> > 
> > Yeah, it could be.  I've tested this on a rolling release (openSUSE TW),
> > so it's definitely quite different from Debian 10.  It may take me a bit
> > to figure out what's going on, but I'll start with this kernel config and
> > report back any finding.
> > 
> > Again, thank you both for confirming it's working on your side.
> 
> Do you have a core file from fio? Would be interesting to get a
> backtrace from it.

Ok, not a lot of progress from my end yet, but here's some info gathered
with gdb from the core file:

#0  0x000056505966b361 in io_completed (td=0x7f2b0c5437a0, io_u_ptr=0x7ffec2403e48, icd=0x7ffec2403e60) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2012
#1  0x000056505966b922 in ios_completed (icd=0x7ffec2403e60, td=0x7f2b0c5437a0) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2086
#2  io_u_queued_complete (td=0x7f2b0c5437a0, min_evts=<optimized out>) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2145
#3  0x0000565059680e88 in do_io (td=0x7f2b0c5437a0, bytes_done=0x7ffec2404070) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:1176
#4  0x000056505968a8ee in thread_main (data=data@entry=0x56505ae43510) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:1870
#5  0x000056505968ca48 in run_threads (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2460
#6  0x000056505968cb55 in fio_backend (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2597
#7  fio_backend (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2558
#8  0x000056505962fd97 in main (argc=4, argv=0x7ffec240c448, envp=<optimized out>) at /usr/src/debug/fio-3.28-1.1.x86_64/fio.c:60

And here's the io_completed() code where the crash occurs:

   2007                 if (io_u->resid) {
   2008                         io_u->xfer_buflen = io_u->resid;
   2009                         io_u->xfer_buf += bytes;
   2010                         io_u->offset += bytes;
   2011                         td->ts.short_io_u[io_u->ddir]++;
   2012                         if (io_u->offset < io_u->file->real_file_size) {
   2013                                 requeue_io_u(td, io_u_ptr);
   2014                                 return;
   2015                         }
   2016                 }

> In terms of why it's failing, a guess would be that your device is using 4k
> sectors and the test is trying to do 1k aligned dio. That would fail, but
> it should not cause fio to crash...
> 
> -- 
> Jens Axboe
> 

Cheers,
--
Luís

Re: generic/095 failing in ext4 and xfs

[Luis Henriques]

On Mon, Oct 04, 2021 at 11:08:29AM +0100, Luis Henriques wrote:
> On Sat, Oct 02, 2021 at 08:59:57AM -0600, Jens Axboe wrote:
> > On 10/2/21 4:16 AM, Luis Henriques wrote:
> > > "Theodore Ts'o" <tytso@mit.edu> writes:
> > > 
> > >> On Fri, Oct 01, 2021 at 02:46:09PM -0600, Jens Axboe wrote:
> > >>>
> > >>> Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
> > >>> you give that a go? If that does work, would be great if you could try
> > >>> and bisect it.
> > >>
> > >> I just tried fio 3.28, and it worked for me.  So I don't think it's
> > >> fio.
> > > 
> > > Awesome, thank you both for checking it out.  So, it's definitely
> > > something in my test environment.
> > > 
> > >> Luis, could it be related to a  kernel config option?
> > > 
> > > Yeah, it could be.  I've tested this on a rolling release (openSUSE TW),
> > > so it's definitely quite different from Debian 10.  It may take me a bit
> > > to figure out what's going on, but I'll start with this kernel config and
> > > report back any finding.
> > > 
> > > Again, thank you both for confirming it's working on your side.
> > 
> > Do you have a core file from fio? Would be interesting to get a
> > backtrace from it.
> 
> Ok, not a lot of progress from my end yet, but here's some info gathered
> with gdb from the core file:
> 
> #0  0x000056505966b361 in io_completed (td=0x7f2b0c5437a0, io_u_ptr=0x7ffec2403e48, icd=0x7ffec2403e60) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2012
> #1  0x000056505966b922 in ios_completed (icd=0x7ffec2403e60, td=0x7f2b0c5437a0) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2086
> #2  io_u_queued_complete (td=0x7f2b0c5437a0, min_evts=<optimized out>) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2145
> #3  0x0000565059680e88 in do_io (td=0x7f2b0c5437a0, bytes_done=0x7ffec2404070) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:1176
> #4  0x000056505968a8ee in thread_main (data=data@entry=0x56505ae43510) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:1870
> #5  0x000056505968ca48 in run_threads (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2460
> #6  0x000056505968cb55 in fio_backend (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2597
> #7  fio_backend (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2558
> #8  0x000056505962fd97 in main (argc=4, argv=0x7ffec240c448, envp=<optimized out>) at /usr/src/debug/fio-3.28-1.1.x86_64/fio.c:60
> 
> And here's the io_completed() code where the crash occurs:
> 
>    2007                 if (io_u->resid) {
>    2008                         io_u->xfer_buflen = io_u->resid;
>    2009                         io_u->xfer_buf += bytes;
>    2010                         io_u->offset += bytes;
>    2011                         td->ts.short_io_u[io_u->ddir]++;
>    2012                         if (io_u->offset < io_u->file->real_file_size) {
>    2013                                 requeue_io_u(td, io_u_ptr);
>    2014                                 return;
>    2015                         }
>    2016                 }

I forgot to include the kernel log.  The page cache error seems relevant,
and, as I said before, I'm seeing it both on ext4 and xfs:

[   38.014790] fio[762]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
[   38.016320] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
[   38.016839] Page cache invalidation failure on direct I/O.  Possible data corruption due to collision with buffered I/O!
[   38.019520] fio[760]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
[   38.020543] File: /mnt/scratch/file1 PID: 754 Comm: fio
[   38.022056] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
[   38.052142] fio[761]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
[   38.053545] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
[   38.058111] fio[759]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
[   38.059511] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
[   38.065638] fio[758]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
[   38.067055] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026

> > In terms of why it's failing, a guess would be that your device is using 4k
> > sectors and the test is trying to do 1k aligned dio. That would fail, but
> > it should not cause fio to crash...
> > 
> > -- 
> > Jens Axboe
> > 

Cheers,
--
Luís

Re: generic/095 failing in ext4 and xfs

[Luis Henriques]

On Mon, Oct 04, 2021 at 11:15:59AM +0100, Luis Henriques wrote:
> On Mon, Oct 04, 2021 at 11:08:29AM +0100, Luis Henriques wrote:
> > On Sat, Oct 02, 2021 at 08:59:57AM -0600, Jens Axboe wrote:
> > > On 10/2/21 4:16 AM, Luis Henriques wrote:
> > > > "Theodore Ts'o" <tytso@mit.edu> writes:
> > > > 
> > > >> On Fri, Oct 01, 2021 at 02:46:09PM -0600, Jens Axboe wrote:
> > > >>>
> > > >>> Hmm, do older versions fail? I see Ted suggested that 3.27 doesn't, can
> > > >>> you give that a go? If that does work, would be great if you could try
> > > >>> and bisect it.
> > > >>
> > > >> I just tried fio 3.28, and it worked for me.  So I don't think it's
> > > >> fio.
> > > > 
> > > > Awesome, thank you both for checking it out.  So, it's definitely
> > > > something in my test environment.
> > > > 
> > > >> Luis, could it be related to a  kernel config option?
> > > > 
> > > > Yeah, it could be.  I've tested this on a rolling release (openSUSE TW),
> > > > so it's definitely quite different from Debian 10.  It may take me a bit
> > > > to figure out what's going on, but I'll start with this kernel config and
> > > > report back any finding.
> > > > 
> > > > Again, thank you both for confirming it's working on your side.
> > > 
> > > Do you have a core file from fio? Would be interesting to get a
> > > backtrace from it.
> > 
> > Ok, not a lot of progress from my end yet, but here's some info gathered
> > with gdb from the core file:
> > 
> > #0  0x000056505966b361 in io_completed (td=0x7f2b0c5437a0, io_u_ptr=0x7ffec2403e48, icd=0x7ffec2403e60) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2012
> > #1  0x000056505966b922 in ios_completed (icd=0x7ffec2403e60, td=0x7f2b0c5437a0) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2086
> > #2  io_u_queued_complete (td=0x7f2b0c5437a0, min_evts=<optimized out>) at /usr/src/debug/fio-3.28-1.1.x86_64/io_u.c:2145
> > #3  0x0000565059680e88 in do_io (td=0x7f2b0c5437a0, bytes_done=0x7ffec2404070) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:1176
> > #4  0x000056505968a8ee in thread_main (data=data@entry=0x56505ae43510) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:1870
> > #5  0x000056505968ca48 in run_threads (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2460
> > #6  0x000056505968cb55 in fio_backend (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2597
> > #7  fio_backend (sk_out=0x0) at /usr/src/debug/fio-3.28-1.1.x86_64/backend.c:2558
> > #8  0x000056505962fd97 in main (argc=4, argv=0x7ffec240c448, envp=<optimized out>) at /usr/src/debug/fio-3.28-1.1.x86_64/fio.c:60
> > 
> > And here's the io_completed() code where the crash occurs:
> > 
> >    2007                 if (io_u->resid) {
> >    2008                         io_u->xfer_buflen = io_u->resid;
> >    2009                         io_u->xfer_buf += bytes;
> >    2010                         io_u->offset += bytes;
> >    2011                         td->ts.short_io_u[io_u->ddir]++;
> >    2012                         if (io_u->offset < io_u->file->real_file_size) {
> >    2013                                 requeue_io_u(td, io_u_ptr);
> >    2014                                 return;
> >    2015                         }
> >    2016                 }
> 
> I forgot to include the kernel log.  The page cache error seems relevant,
> and, as I said before, I'm seeing it both on ext4 and xfs:
> 
> [   38.014790] fio[762]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
> [   38.016320] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
> [   38.016839] Page cache invalidation failure on direct I/O.  Possible data corruption due to collision with buffered I/O!
> [   38.019520] fio[760]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
> [   38.020543] File: /mnt/scratch/file1 PID: 754 Comm: fio
> [   38.022056] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
> [   38.052142] fio[761]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
> [   38.053545] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
> [   38.058111] fio[759]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
> [   38.059511] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026
> [   38.065638] fio[758]: segfault at 30 ip 000056505966b361 sp 00007ffec2403df0 error 4 in fio[56505962e000+84000]
> [   38.067055] Code: c1 48 85 c0 74 2e 48 89 45 68 48 8b 45 40 48 63 55 2c 4c 01 4d 60 4c 01 c8 48 89 45 40 49 83 84 d4 70 5d 02 00 01 48 8b 55 20 <48> 3b 42 30 0f 82 75 026

Ok, I may have narrowed it a bit more.  The disks being used in my testing
were zram-based (I know, I should have mentioned it before :-/ ).  If I use
file-based disks the test passes and I see no crashes in fio.

Cheers,
--
Luís

Re: generic/095 failing in ext4 and xfs

[Theodore Ts'o]

On Mon, Oct 04, 2021 at 01:17:02PM +0100, Luis Henriques wrote:
> 
> Ok, I may have narrowed it a bit more.  The disks being used in my testing
> were zram-based (I know, I should have mentioned it before :-/ ).  If I use
> file-based disks the test passes and I see no crashes in fio.

What was the last kernel version where it didn't crash for you?   5.14?

And maybe we need to have a test which explicitly uses zram, since I
suspect many/most of the fs developers who are running fstests aren't
using zram....

						- Ted

Re: generic/095 failing in ext4 and xfs

[Luis Henriques]

(sorry for the delay in my replies)

On Mon, Oct 04, 2021 at 12:18:24PM -0400, Theodore Ts'o wrote:
> On Mon, Oct 04, 2021 at 01:17:02PM +0100, Luis Henriques wrote:
> > 
> > Ok, I may have narrowed it a bit more.  The disks being used in my testing
> > were zram-based (I know, I should have mentioned it before :-/ ).  If I use
> > file-based disks the test passes and I see no crashes in fio.
> 
> What was the last kernel version where it didn't crash for you?   5.14?

No, this is not a regression.  I tried to go as far as 5.0 and I still get
the exact same behaviour.  Also, I've tried fio 3.24 and it still
crashes.

So, this definitely looks like a zram issue.  I've added the maintainers
to the CC list in case they have any ideas.

> And maybe we need to have a test which explicitly uses zram, since I
> suspect many/most of the fs developers who are running fstests aren't
> using zram....
> 
> 						- Ted

Cheers,
--
Luís

[PATCH] fio: make sure io_u->file isn't NULL before using it

[Luís Henriques]

While running fstests generic/095 against ext4 on a zram device I started
seeing fio crashing.  Fix it by making sure io_u->file isn't NULL before
accessing it.

Signed-off-by: Luís Henriques <lhenriques@suse.de>
---
 io_u.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/io_u.c b/io_u.c
index 5289b5d1d9c6..b8e715d4118c 100644
--- a/io_u.c
+++ b/io_u.c
@@ -2009,7 +2009,8 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
 			io_u->xfer_buf += bytes;
 			io_u->offset += bytes;
 			td->ts.short_io_u[io_u->ddir]++;
-			if (io_u->offset < io_u->file->real_file_size) {
+			if (io_u->file &&
+			    (io_u->offset < io_u->file->real_file_size)) {
 				requeue_io_u(td, io_u_ptr);
 				return;
 			}

Re: [PATCH] fio: make sure io_u->file isn't NULL before using it

[Jens Axboe]

On 10/11/21 4:27 AM, Luís Henriques wrote:
> While running fstests generic/095 against ext4 on a zram device I started
> seeing fio crashing.  Fix it by making sure io_u->file isn't NULL before
> accessing it.
> 
> Signed-off-by: Luís Henriques <lhenriques@suse.de>
> ---
>  io_u.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/io_u.c b/io_u.c
> index 5289b5d1d9c6..b8e715d4118c 100644
> --- a/io_u.c
> +++ b/io_u.c
> @@ -2009,7 +2009,8 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
>  			io_u->xfer_buf += bytes;
>  			io_u->offset += bytes;
>  			td->ts.short_io_u[io_u->ddir]++;
> -			if (io_u->offset < io_u->file->real_file_size) {
> +			if (io_u->file &&
> +			    (io_u->offset < io_u->file->real_file_size)) {
>  				requeue_io_u(td, io_u_ptr);
>  				return;
>  			}

This will prevent the crash, but I'm wondering why io_u-> == NULL for this case.
It really should be a valid file.

Can you let me know exactly how you're reproducing this? Then I'll give it
a whirl too.

-- 
Jens Axboe

Re: [PATCH] fio: make sure io_u->file isn't NULL before using it

[Luís Henriques]

On Mon, Oct 11, 2021 at 06:58:52AM -0600, Jens Axboe wrote:
> On 10/11/21 4:27 AM, Luís Henriques wrote:
> > While running fstests generic/095 against ext4 on a zram device I started
> > seeing fio crashing.  Fix it by making sure io_u->file isn't NULL before
> > accessing it.
> > 
> > Signed-off-by: Luís Henriques <lhenriques@suse.de>
> > ---
> >  io_u.c | 3 ++-
> >  1 file changed, 2 insertions(+), 1 deletion(-)
> > 
> > diff --git a/io_u.c b/io_u.c
> > index 5289b5d1d9c6..b8e715d4118c 100644
> > --- a/io_u.c
> > +++ b/io_u.c
> > @@ -2009,7 +2009,8 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
> >  			io_u->xfer_buf += bytes;
> >  			io_u->offset += bytes;
> >  			td->ts.short_io_u[io_u->ddir]++;
> > -			if (io_u->offset < io_u->file->real_file_size) {
> > +			if (io_u->file &&
> > +			    (io_u->offset < io_u->file->real_file_size)) {
> >  				requeue_io_u(td, io_u_ptr);
> >  				return;
> >  			}
> 
> This will prevent the crash, but I'm wondering why io_u-> == NULL for this case.
> It really should be a valid file.
> 
> Can you let me know exactly how you're reproducing this? Then I'll give it
> a whirl too.

Sure, here's my recipe for reproducing this bug:

 # modprobe zram num_devices=2
 # echo 1G > /sys/block/zram0/disksize 
 # echo 1G > /sys/block/zram1/disksize 
 # mkfs.ext4 /dev/zram0
 # mkfs.ext4 /dev/zram1

 # ./check generic/095

Cheers,
--
Luís

Re: [PATCH] fio: make sure io_u->file isn't NULL before using it

[Jens Axboe]

On 10/11/21 7:44 AM, Luís Henriques wrote:
> On Mon, Oct 11, 2021 at 06:58:52AM -0600, Jens Axboe wrote:
>> On 10/11/21 4:27 AM, Luís Henriques wrote:
>>> While running fstests generic/095 against ext4 on a zram device I started
>>> seeing fio crashing.  Fix it by making sure io_u->file isn't NULL before
>>> accessing it.
>>>
>>> Signed-off-by: Luís Henriques <lhenriques@suse.de>
>>> ---
>>>  io_u.c | 3 ++-
>>>  1 file changed, 2 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/io_u.c b/io_u.c
>>> index 5289b5d1d9c6..b8e715d4118c 100644
>>> --- a/io_u.c
>>> +++ b/io_u.c
>>> @@ -2009,7 +2009,8 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
>>>  			io_u->xfer_buf += bytes;
>>>  			io_u->offset += bytes;
>>>  			td->ts.short_io_u[io_u->ddir]++;
>>> -			if (io_u->offset < io_u->file->real_file_size) {
>>> +			if (io_u->file &&
>>> +			    (io_u->offset < io_u->file->real_file_size)) {
>>>  				requeue_io_u(td, io_u_ptr);
>>>  				return;
>>>  			}
>>
>> This will prevent the crash, but I'm wondering why io_u-> == NULL for this case.
>> It really should be a valid file.
>>
>> Can you let me know exactly how you're reproducing this? Then I'll give it
>> a whirl too.
> 
> Sure, here's my recipe for reproducing this bug:
> 
>  # modprobe zram num_devices=2
>  # echo 1G > /sys/block/zram0/disksize 
>  # echo 1G > /sys/block/zram1/disksize 
>  # mkfs.ext4 /dev/zram0
>  # mkfs.ext4 /dev/zram1
> 
>  # ./check generic/095

I know you fixed the issue in the test by now, but any chance you can try
this one and see if it correctly reports full residual instead of trying
to requeue and crash?


diff --git a/io_u.c b/io_u.c
index 5289b5d1d9c6..586a4befdce0 100644
--- a/io_u.c
+++ b/io_u.c
@@ -2004,7 +2004,7 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
 		 * Make sure we notice short IO from here, and requeue them
 		 * appropriately!
 		 */
-		if (io_u->resid) {
+		if (bytes && io_u->resid) {
 			io_u->xfer_buflen = io_u->resid;
 			io_u->xfer_buf += bytes;
 			io_u->offset += bytes;

-- 
Jens Axboe

Re: [PATCH] fio: make sure io_u->file isn't NULL before using it

[Luís Henriques]

[-- Attachment #1: Type: text/plain, Size: 2622 bytes --]

On Mon, Oct 11, 2021 at 09:15:47AM -0600, Jens Axboe wrote:
> On 10/11/21 7:44 AM, Luís Henriques wrote:
> > On Mon, Oct 11, 2021 at 06:58:52AM -0600, Jens Axboe wrote:
> >> On 10/11/21 4:27 AM, Luís Henriques wrote:
> >>> While running fstests generic/095 against ext4 on a zram device I started
> >>> seeing fio crashing.  Fix it by making sure io_u->file isn't NULL before
> >>> accessing it.
> >>>
> >>> Signed-off-by: Luís Henriques <lhenriques@suse.de>
> >>> ---
> >>>  io_u.c | 3 ++-
> >>>  1 file changed, 2 insertions(+), 1 deletion(-)
> >>>
> >>> diff --git a/io_u.c b/io_u.c
> >>> index 5289b5d1d9c6..b8e715d4118c 100644
> >>> --- a/io_u.c
> >>> +++ b/io_u.c
> >>> @@ -2009,7 +2009,8 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
> >>>  			io_u->xfer_buf += bytes;
> >>>  			io_u->offset += bytes;
> >>>  			td->ts.short_io_u[io_u->ddir]++;
> >>> -			if (io_u->offset < io_u->file->real_file_size) {
> >>> +			if (io_u->file &&
> >>> +			    (io_u->offset < io_u->file->real_file_size)) {
> >>>  				requeue_io_u(td, io_u_ptr);
> >>>  				return;
> >>>  			}
> >>
> >> This will prevent the crash, but I'm wondering why io_u-> == NULL for this case.
> >> It really should be a valid file.
> >>
> >> Can you let me know exactly how you're reproducing this? Then I'll give it
> >> a whirl too.
> > 
> > Sure, here's my recipe for reproducing this bug:
> > 
> >  # modprobe zram num_devices=2
> >  # echo 1G > /sys/block/zram0/disksize 
> >  # echo 1G > /sys/block/zram1/disksize 
> >  # mkfs.ext4 /dev/zram0
> >  # mkfs.ext4 /dev/zram1
> > 
> >  # ./check generic/095
> 
> I know you fixed the issue in the test by now, but any chance you can try
> this one and see if it correctly reports full residual instead of trying
> to requeue and crash?

Sure!  So, I patched fio with this change and executed the generic/095
test twice: one run without the test fix, another with the test fix.  I
can confirm that fio didn't crash in any of the runs, but I'm not sure how
to check if it's correctly reporting residual.

I'm attaching the test logs (for the failure run) in case that helps.

Cheers,
--
Luís


> 
> diff --git a/io_u.c b/io_u.c
> index 5289b5d1d9c6..586a4befdce0 100644
> --- a/io_u.c
> +++ b/io_u.c
> @@ -2004,7 +2004,7 @@ static void io_completed(struct thread_data *td, struct io_u **io_u_ptr,
>  		 * Make sure we notice short IO from here, and requeue them
>  		 * appropriately!
>  		 */
> -		if (io_u->resid) {
> +		if (bytes && io_u->resid) {
>  			io_u->xfer_buflen = io_u->resid;
>  			io_u->xfer_buf += bytes;
>  			io_u->offset += bytes;
> 
> -- 
> Jens Axboe
> 

[-- Attachment #2: 095.full --]
[-- Type: text/plain, Size: 55020 bytes --]

fio --bs=8k --iodepth=16 --iodepth_batch=8 --randrepeat=1 --size=1m --directory=/tmp/mnt/scratch --numjobs=5 --name=job1 --ioengine=sync --bs=1k --direct=1 --rw=randread --filename=file1:file2 --name=job2 --ioengine=libaio --rw=randwrite --direct=1 --filename=file1:file2 --name=job3 --bs=1k --ioengine=posixaio --rw=randwrite --direct=1 --filename=file1:file2 --name=job4 --ioengine=splice --direct=1 --rw=randwrite --filename=file1:file2 --name=job5 --bs=1k --ioengine=sync --rw=randread --filename=file1:file2 --name=job6 --ioengine=posixaio --rw=randwrite --filename=file1:file2 --name=job7 --ioengine=splice --rw=randwrite --filename=file1:file2 --name=job8 --ioengine=mmap --rw=randwrite --bs=1k --filename=file1:file2 --name=job9 --ioengine=mmap --rw=randwrite --direct=1 --bs=4096 --filename=file1:file2 
Discarding device blocks:      0/262144\b\b\b\b\b\b\b\b\b\b\b\b\b             \b\b\b\b\b\b\b\b\b\b\b\b\bdone                            
Creating filesystem with 262144 4k blocks and 65536 inodes
Filesystem UUID: e77d8742-2325-4f0c-a67c-9900cb195663
Superblock backups stored on blocks: 
	32768, 98304, 163840, 229376

Allocating group tables: 0/8\b\b\b   \b\b\bdone                            
Writing inode tables: 0/8\b\b\b   \b\b\bdone                            
Creating journal (8192 blocks): done
Writing superblocks and filesystem accounting information: 0/8\b\b\b   \b\b\bdone

job1: (g=0): rw=randread, bs=(R) 1024B-1024B, (W) 1024B-1024B, (T) 1024B-1024B, ioengine=sync, iodepth=16
...
job2: (g=0): rw=randwrite, bs=(R) 8192B-8192B, (W) 8192B-8192B, (T) 8192B-8192B, ioengine=libaio, iodepth=16
...
job3: (g=0): rw=randwrite, bs=(R) 1024B-1024B, (W) 1024B-1024B, (T) 1024B-1024B, ioengine=posixaio, iodepth=16
...
job4: (g=0): rw=randwrite, bs=(R) 8192B-8192B, (W) 8192B-8192B, (T) 8192B-8192B, ioengine=splice, iodepth=16
...
job5: (g=0): rw=randread, bs=(R) 1024B-1024B, (W) 1024B-1024B, (T) 1024B-1024B, ioengine=sync, iodepth=16
...
job6: (g=0): rw=randwrite, bs=(R) 8192B-8192B, (W) 8192B-8192B, (T) 8192B-8192B, ioengine=posixaio, iodepth=16
...
job7: (g=0): rw=randwrite, bs=(R) 8192B-8192B, (W) 8192B-8192B, (T) 8192B-8192B, ioengine=splice, iodepth=16
...
job8: (g=0): rw=randwrite, bs=(R) 1024B-1024B, (W) 1024B-1024B, (T) 1024B-1024B, ioengine=mmap, iodepth=16
...
job9: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=mmap, iodepth=16
...
fio-3.28-57-g63b8-dirty
Starting 45 processes
job1: Laying out IO files (2 files / total 1MiB)
fio: pid=2364, got signal=6
fio: pid=2367, got signal=6
fio: pid=2368, got signal=6

job1: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2354: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=2, majf=0, minf=29
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=50.0%, 4=50.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job1: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2355: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=3, majf=3, minf=27
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=50.0%, 4=50.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job1: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2356: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=6, majf=6, minf=26
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=50.0%, 4=50.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job1: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2357: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=1, majf=0, minf=29
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=50.0%, 4=50.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job1: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2358: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=8, majf=8, minf=24
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=50.0%, 4=50.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job2: (groupid=0, jobs=1): err= 0: pid=2359: Mon Oct 11 16:33:05 2021
  write: IOPS=1600, BW=12.5MiB/s (13.1MB/s)(1024KiB/80msec); 0 zone resets
    slat (usec): min=25, max=37322, avg=2684.09, stdev=7381.40
    clat (usec): min=4, max=12289, avg=3860.08, stdev=3161.06
     lat (usec): min=77, max=47504, avg=6544.27, stdev=9652.17
    clat percentiles (usec):
     |  1.00th=[   82],  5.00th=[  652], 10.00th=[ 1221], 20.00th=[ 1598],
     | 30.00th=[ 1713], 40.00th=[ 1778], 50.00th=[ 2343], 60.00th=[ 3359],
     | 70.00th=[ 3949], 80.00th=[ 6980], 90.00th=[ 8586], 95.00th=[10814],
     | 99.00th=[11994], 99.50th=[12256], 99.90th=[12256], 99.95th=[12256],
     | 99.99th=[12256]
  lat (usec)   : 10=0.78%, 100=0.78%, 250=0.78%, 500=0.78%, 750=3.12%
  lat (usec)   : 1000=2.34%
  lat (msec)   : 2=38.28%, 4=24.22%, 10=21.88%, 20=7.03%
  cpu          : usr=0.00%, sys=13.92%, ctx=61, majf=3, minf=19
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=6.2%, 16=93.8%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=98.2%, 8=1.8%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=99.1%, 8=0.0%, 16=0.9%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job2: (groupid=0, jobs=1): err= 0: pid=2360: Mon Oct 11 16:33:05 2021
  write: IOPS=2206, BW=17.2MiB/s (18.1MB/s)(1024KiB/58msec); 0 zone resets
    slat (usec): min=19, max=22227, avg=1293.17, stdev=4243.34
    clat (nsec): min=1744, max=13937k, avg=2624525.45, stdev=3543041.64
     lat (usec): min=55, max=22739, avg=3917.79, stdev=5242.31
    clat percentiles (usec):
     |  1.00th=[   57],  5.00th=[  233], 10.00th=[  437], 20.00th=[  545],
     | 30.00th=[  570], 40.00th=[  594], 50.00th=[  627], 60.00th=[  889],
     | 70.00th=[ 2671], 80.00th=[ 3556], 90.00th=[ 9503], 95.00th=[11469],
     | 99.00th=[12649], 99.50th=[13960], 99.90th=[13960], 99.95th=[13960],
     | 99.99th=[13960]
  lat (usec)   : 2=0.78%, 100=0.78%, 250=3.91%, 500=5.47%, 750=46.88%
  lat (usec)   : 1000=3.91%
  lat (msec)   : 2=4.69%, 4=14.06%, 10=12.50%, 20=7.03%
  cpu          : usr=8.77%, sys=0.00%, ctx=33, majf=1, minf=21
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=6.2%, 16=93.8%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=98.2%, 8=1.8%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=99.1%, 8=0.0%, 16=0.9%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job2: (groupid=0, jobs=1): err= 0: pid=2361: Mon Oct 11 16:33:05 2021
  write: IOPS=1662, BW=13.0MiB/s (13.6MB/s)(1024KiB/77msec); 0 zone resets
    slat (usec): min=21, max=31476, avg=2285.17, stdev=6451.78
    clat (nsec): min=1461, max=8546.3k, avg=3394454.86, stdev=2584376.00
     lat (usec): min=30, max=38816, avg=5679.71, stdev=7944.51
    clat percentiles (usec):
     |  1.00th=[   33],  5.00th=[  243], 10.00th=[  938], 20.00th=[ 1336],
     | 30.00th=[ 1762], 40.00th=[ 2114], 50.00th=[ 2278], 60.00th=[ 2573],
     | 70.00th=[ 5080], 80.00th=[ 5932], 90.00th=[ 7963], 95.00th=[ 8291],
     | 99.00th=[ 8586], 99.50th=[ 8586], 99.90th=[ 8586], 99.95th=[ 8586],
     | 99.99th=[ 8586]
  lat (usec)   : 2=0.78%, 50=0.78%, 100=1.56%, 250=2.34%, 500=1.56%
  lat (usec)   : 1000=3.91%
  lat (msec)   : 2=24.22%, 4=34.38%, 10=30.47%
  cpu          : usr=0.00%, sys=6.58%, ctx=77, majf=1, minf=21
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=6.2%, 16=93.8%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=98.2%, 8=1.8%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=99.1%, 8=0.0%, 16=0.9%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job2: (groupid=0, jobs=1): err= 0: pid=2362: Mon Oct 11 16:33:05 2021
  write: IOPS=1684, BW=13.2MiB/s (13.8MB/s)(1024KiB/76msec); 0 zone resets
    slat (usec): min=18, max=34986, avg=2547.30, stdev=6865.46
    clat (nsec): min=1454, max=12139k, avg=3714736.58, stdev=3282289.17
     lat (usec): min=26, max=45556, avg=6262.11, stdev=9137.41
    clat percentiles (usec):
     |  1.00th=[   28],  5.00th=[  190], 10.00th=[  343], 20.00th=[  465],
     | 30.00th=[ 1942], 40.00th=[ 2245], 50.00th=[ 2409], 60.00th=[ 2802],
     | 70.00th=[ 3916], 80.00th=[ 6783], 90.00th=[ 8455], 95.00th=[11207],
     | 99.00th=[11994], 99.50th=[12125], 99.90th=[12125], 99.95th=[12125],
     | 99.99th=[12125]
  lat (usec)   : 2=0.78%, 50=0.78%, 100=0.78%, 250=4.69%, 500=13.28%
  lat (msec)   : 2=13.28%, 4=36.72%, 10=22.66%, 20=7.03%
  cpu          : usr=0.00%, sys=5.33%, ctx=90, majf=3, minf=19
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=6.2%, 16=93.8%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=98.2%, 8=1.8%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=99.1%, 8=0.0%, 16=0.9%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job2: (groupid=0, jobs=1): err= 0: pid=2363: Mon Oct 11 16:33:05 2021
  write: IOPS=1662, BW=13.0MiB/s (13.6MB/s)(1024KiB/77msec); 0 zone resets
    slat (usec): min=20, max=36554, avg=2615.40, stdev=7062.59
    clat (nsec): min=1561, max=13205k, avg=3852028.32, stdev=3205515.13
     lat (usec): min=36, max=47273, avg=6467.50, stdev=9399.31
    clat percentiles (usec):
     |  1.00th=[   38],  5.00th=[  343], 10.00th=[ 1020], 20.00th=[ 1500],
     | 30.00th=[ 1663], 40.00th=[ 1975], 50.00th=[ 2769], 60.00th=[ 3359],
     | 70.00th=[ 4424], 80.00th=[ 6259], 90.00th=[ 8160], 95.00th=[11207],
     | 99.00th=[13173], 99.50th=[13173], 99.90th=[13173], 99.95th=[13173],
     | 99.99th=[13173]
  lat (usec)   : 2=0.78%, 50=0.78%, 100=0.78%, 250=1.56%, 500=3.12%
  lat (usec)   : 750=0.78%, 1000=1.56%
  lat (msec)   : 2=31.25%, 4=28.91%, 10=23.44%, 20=7.03%
  cpu          : usr=0.00%, sys=6.58%, ctx=81, majf=1, minf=21
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=6.2%, 16=93.8%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=98.2%, 8=1.8%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=99.1%, 8=0.0%, 16=0.9%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job3: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2364: Mon Oct 11 16:33:05 2021
  lat (msec)   : 10=18.75%
  cpu          : usr=0.00%, sys=0.00%, ctx=0, majf=0, minf=0
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=50.0%, 16=50.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=5.3%, 4=84.2%, 8=5.3%, 16=5.3%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,16,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job3: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2365: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=2, majf=1, minf=27
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=50.0%, 16=50.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=5.6%, 4=94.4%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,16,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job3: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2366: Mon Oct 11 16:33:05 2021
  cpu          : usr=0.00%, sys=0.00%, ctx=5, majf=3, minf=27
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=50.0%, 16=50.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=5.6%, 4=94.4%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,16,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job3: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2367: Mon Oct 11 16:33:05 2021
  lat (usec)   : 1000=18.75%
  cpu          : usr=0.00%, sys=0.00%, ctx=0, majf=0, minf=0
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=50.0%, 16=50.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=5.3%, 4=84.2%, 8=5.3%, 16=5.3%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,16,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job3: (groupid=0, jobs=1): err=22 (file:io_u.c:1845, func=io_u error, error=Invalid argument): pid=2368: Mon Oct 11 16:33:05 2021
  lat (msec)   : 4=18.75%
  cpu          : usr=0.00%, sys=0.00%, ctx=0, majf=0, minf=0
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=50.0%, 16=50.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=5.3%, 4=84.2%, 8=5.3%, 16=5.3%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,16,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job4: (groupid=0, jobs=1): err= 0: pid=2369: Mon Oct 11 16:33:05 2021
  write: IOPS=1641, BW=12.8MiB/s (13.4MB/s)(1024KiB/78msec); 0 zone resets
    clat (usec): min=32, max=18196, avg=511.89, stdev=1705.10
     lat (usec): min=32, max=18196, avg=512.09, stdev=1705.10
    clat percentiles (usec):
     |  1.00th=[   34],  5.00th=[   36], 10.00th=[   40], 20.00th=[   61],
     | 30.00th=[   73], 40.00th=[   88], 50.00th=[  149], 60.00th=[  176],
     | 70.00th=[  285], 80.00th=[  494], 90.00th=[  955], 95.00th=[ 2245],
     | 99.00th=[ 3851], 99.50th=[18220], 99.90th=[18220], 99.95th=[18220],
     | 99.99th=[18220]
  lat (usec)   : 50=14.06%, 100=28.91%, 250=25.00%, 500=12.50%, 750=7.81%
  lat (usec)   : 1000=3.12%
  lat (msec)   : 2=3.12%, 4=4.69%, 20=0.78%
  cpu          : usr=0.00%, sys=12.99%, ctx=83, majf=5, minf=16
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job4: (groupid=0, jobs=1): err= 0: pid=2370: Mon Oct 11 16:33:05 2021
  write: IOPS=2064, BW=16.1MiB/s (16.9MB/s)(1024KiB/62msec); 0 zone resets
    clat (usec): min=25, max=16986, avg=470.55, stdev=1703.89
     lat (usec): min=25, max=16986, avg=470.70, stdev=1703.90
    clat percentiles (usec):
     |  1.00th=[   26],  5.00th=[   33], 10.00th=[   34], 20.00th=[   38],
     | 30.00th=[   41], 40.00th=[   45], 50.00th=[   47], 60.00th=[   55],
     | 70.00th=[   76], 80.00th=[  363], 90.00th=[  947], 95.00th=[ 2147],
     | 99.00th=[ 5604], 99.50th=[16909], 99.90th=[16909], 99.95th=[16909],
     | 99.99th=[16909]
  lat (usec)   : 50=56.25%, 100=16.41%, 250=6.25%, 500=8.59%, 750=0.78%
  lat (usec)   : 1000=2.34%
  lat (msec)   : 2=3.12%, 4=3.91%, 10=1.56%, 20=0.78%
  cpu          : usr=0.00%, sys=9.84%, ctx=45, majf=2, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job4: (groupid=0, jobs=1): err= 0: pid=2371: Mon Oct 11 16:33:05 2021
  write: IOPS=1729, BW=13.5MiB/s (14.2MB/s)(1024KiB/74msec); 0 zone resets
    clat (usec): min=30, max=18586, avg=476.04, stdev=1774.05
     lat (usec): min=31, max=18586, avg=476.26, stdev=1774.05
    clat percentiles (usec):
     |  1.00th=[   32],  5.00th=[   33], 10.00th=[   33], 20.00th=[   34],
     | 30.00th=[   56], 40.00th=[   89], 50.00th=[   93], 60.00th=[  163],
     | 70.00th=[  206], 80.00th=[  343], 90.00th=[  840], 95.00th=[ 1614],
     | 99.00th=[ 5407], 99.50th=[18482], 99.90th=[18482], 99.95th=[18482],
     | 99.99th=[18482]
  lat (usec)   : 50=25.00%, 100=27.34%, 250=20.31%, 500=14.06%, 750=3.12%
  lat (usec)   : 1000=2.34%
  lat (msec)   : 2=3.12%, 4=2.34%, 10=1.56%, 20=0.78%
  cpu          : usr=0.00%, sys=13.70%, ctx=49, majf=2, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job4: (groupid=0, jobs=1): err= 0: pid=2372: Mon Oct 11 16:33:05 2021
  write: IOPS=1706, BW=13.3MiB/s (14.0MB/s)(1024KiB/75msec); 0 zone resets
    clat (usec): min=32, max=17596, avg=565.07, stdev=1719.54
     lat (usec): min=32, max=17596, avg=565.27, stdev=1719.57
    clat percentiles (usec):
     |  1.00th=[   34],  5.00th=[   36], 10.00th=[   39], 20.00th=[   67],
     | 30.00th=[   78], 40.00th=[  104], 50.00th=[  130], 60.00th=[  180],
     | 70.00th=[  289], 80.00th=[  379], 90.00th=[ 1303], 95.00th=[ 2966],
     | 99.00th=[ 4228], 99.50th=[17695], 99.90th=[17695], 99.95th=[17695],
     | 99.99th=[17695]
  lat (usec)   : 50=15.62%, 100=23.44%, 250=26.56%, 500=16.41%, 750=3.91%
  lat (usec)   : 1000=2.34%
  lat (msec)   : 2=5.47%, 4=3.91%, 10=1.56%, 20=0.78%
  cpu          : usr=6.76%, sys=8.11%, ctx=102, majf=0, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job4: (groupid=0, jobs=1): err= 0: pid=2373: Mon Oct 11 16:33:05 2021
  write: IOPS=1620, BW=12.7MiB/s (13.3MB/s)(1024KiB/79msec); 0 zone resets
    clat (usec): min=35, max=6962, avg=520.71, stdev=1210.46
     lat (usec): min=35, max=6962, avg=520.98, stdev=1210.49
    clat percentiles (usec):
     |  1.00th=[   39],  5.00th=[   42], 10.00th=[   65], 20.00th=[   86],
     | 30.00th=[  100], 40.00th=[  118], 50.00th=[  151], 60.00th=[  172],
     | 70.00th=[  221], 80.00th=[  326], 90.00th=[ 1156], 95.00th=[ 3163],
     | 99.00th=[ 6849], 99.50th=[ 6980], 99.90th=[ 6980], 99.95th=[ 6980],
     | 99.99th=[ 6980]
  lat (usec)   : 50=8.59%, 100=20.31%, 250=45.31%, 500=12.50%, 750=1.56%
  lat (usec)   : 1000=1.56%
  lat (msec)   : 2=2.34%, 4=4.69%, 10=3.12%
  cpu          : usr=0.00%, sys=19.23%, ctx=113, majf=6, minf=15
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job5: (groupid=0, jobs=1): err= 0: pid=2374: Mon Oct 11 16:33:05 2021
  read: IOPS=85.3k, BW=83.3MiB/s (87.4MB/s)(1024KiB/12msec)
    clat (nsec): min=582, max=104452, avg=965.48, stdev=3594.28
     lat (nsec): min=622, max=104492, avg=1006.11, stdev=3595.08
    clat percentiles (nsec):
     |  1.00th=[   588],  5.00th=[   604], 10.00th=[   620], 20.00th=[   652],
     | 30.00th=[   684], 40.00th=[   700], 50.00th=[   716], 60.00th=[   732],
     | 70.00th=[   748], 80.00th=[   772], 90.00th=[   812], 95.00th=[   900],
     | 99.00th=[  4048], 99.50th=[  5280], 99.90th=[ 46336], 99.95th=[104960],
     | 99.99th=[104960]
  lat (nsec)   : 750=69.43%, 1000=26.46%
  lat (usec)   : 2=0.68%, 4=2.34%, 10=0.78%, 20=0.10%, 50=0.10%
  lat (usec)   : 250=0.10%
  cpu          : usr=9.09%, sys=0.00%, ctx=9, majf=6, minf=16
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1024,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job5: (groupid=0, jobs=1): err= 0: pid=2375: Mon Oct 11 16:33:05 2021
  read: IOPS=73.1k, BW=71.4MiB/s (74.9MB/s)(1024KiB/14msec)
    clat (nsec): min=562, max=17276, avg=759.74, stdev=815.84
     lat (nsec): min=603, max=17596, avg=799.78, stdev=822.30
    clat percentiles (nsec):
     |  1.00th=[  588],  5.00th=[  596], 10.00th=[  604], 20.00th=[  620],
     | 30.00th=[  644], 40.00th=[  660], 50.00th=[  684], 60.00th=[  700],
     | 70.00th=[  724], 80.00th=[  748], 90.00th=[  788], 95.00th=[  820],
     | 99.00th=[ 2768], 99.50th=[ 4896], 99.90th=[16064], 99.95th=[17280],
     | 99.99th=[17280]
  lat (nsec)   : 750=81.25%, 1000=16.70%
  lat (usec)   : 2=0.68%, 4=0.68%, 10=0.49%, 20=0.20%
  cpu          : usr=0.00%, sys=7.69%, ctx=4, majf=3, minf=18
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1024,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job5: (groupid=0, jobs=1): err= 0: pid=2376: Mon Oct 11 16:33:05 2021
  read: IOPS=93.1k, BW=90.9MiB/s (95.3MB/s)(1024KiB/11msec)
    clat (nsec): min=594, max=14728, avg=1045.56, stdev=1284.62
     lat (nsec): min=630, max=14769, avg=1086.76, stdev=1293.48
    clat percentiles (nsec):
     |  1.00th=[  604],  5.00th=[  620], 10.00th=[  636], 20.00th=[  660],
     | 30.00th=[  684], 40.00th=[  700], 50.00th=[  716], 60.00th=[  732],
     | 70.00th=[  756], 80.00th=[  788], 90.00th=[ 1064], 95.00th=[ 3568],
     | 99.00th=[ 5664], 99.50th=[ 8256], 99.90th=[14144], 99.95th=[14784],
     | 99.99th=[14784]
  lat (nsec)   : 750=67.48%, 1000=22.27%
  lat (usec)   : 2=1.95%, 4=5.76%, 10=2.15%, 20=0.39%
  cpu          : usr=10.00%, sys=0.00%, ctx=6, majf=5, minf=16
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1024,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job5: (groupid=0, jobs=1): err= 0: pid=2377: Mon Oct 11 16:33:05 2021
  read: IOPS=85.3k, BW=83.3MiB/s (87.4MB/s)(1024KiB/12msec)
    clat (nsec): min=641, max=16976, avg=878.51, stdev=857.12
     lat (nsec): min=681, max=17021, avg=923.44, stdev=864.64
    clat percentiles (nsec):
     |  1.00th=[  652],  5.00th=[  668], 10.00th=[  684], 20.00th=[  700],
     | 30.00th=[  724], 40.00th=[  748], 50.00th=[  772], 60.00th=[  788],
     | 70.00th=[  804], 80.00th=[  828], 90.00th=[  868], 95.00th=[  908],
     | 99.00th=[ 4320], 99.50th=[ 5024], 99.90th=[14784], 99.95th=[17024],
     | 99.99th=[17024]
  lat (nsec)   : 750=39.75%, 1000=57.13%
  lat (usec)   : 2=0.49%, 4=1.37%, 10=1.07%, 20=0.20%
  cpu          : usr=9.09%, sys=0.00%, ctx=9, majf=8, minf=14
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1024,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job5: (groupid=0, jobs=1): err= 0: pid=2378: Mon Oct 11 16:33:05 2021
  read: IOPS=68.3k, BW=66.7MiB/s (69.9MB/s)(1024KiB/15msec)
    clat (nsec): min=642, max=27395, avg=978.34, stdev=1424.98
     lat (nsec): min=679, max=27933, avg=1023.85, stdev=1434.63
    clat percentiles (nsec):
     |  1.00th=[  652],  5.00th=[  668], 10.00th=[  676], 20.00th=[  700],
     | 30.00th=[  732], 40.00th=[  756], 50.00th=[  772], 60.00th=[  796],
     | 70.00th=[  812], 80.00th=[  844], 90.00th=[  892], 95.00th=[ 1096],
     | 99.00th=[ 6048], 99.50th=[ 8640], 99.90th=[19328], 99.95th=[27520],
     | 99.99th=[27520]
  lat (nsec)   : 750=37.30%, 1000=57.23%
  lat (usec)   : 2=2.15%, 4=1.07%, 10=1.86%, 20=0.29%, 50=0.10%
  cpu          : usr=7.14%, sys=0.00%, ctx=9, majf=8, minf=14
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=1024,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job6: (groupid=0, jobs=1): err= 0: pid=2379: Mon Oct 11 16:33:05 2021
  write: IOPS=1855, BW=14.5MiB/s (15.2MB/s)(1024KiB/69msec); 0 zone resets
    slat (nsec): min=141, max=75144, avg=1565.61, stdev=7509.80
    clat (usec): min=8, max=33482, avg=6816.01, stdev=8391.68
     lat (usec): min=9, max=33483, avg=6817.58, stdev=8392.09
    clat percentiles (usec):
     |  1.00th=[   10],  5.00th=[   19], 10.00th=[   38], 20.00th=[  147],
     | 30.00th=[ 1467], 40.00th=[ 2180], 50.00th=[ 3556], 60.00th=[ 5014],
     | 70.00th=[ 7504], 80.00th=[13435], 90.00th=[17695], 95.00th=[28967],
     | 99.00th=[33162], 99.50th=[33424], 99.90th=[33424], 99.95th=[33424],
     | 99.99th=[33424]
  lat (usec)   : 10=3.12%, 20=2.34%, 50=5.47%, 100=7.03%, 250=3.91%
  lat (usec)   : 500=1.56%, 750=1.56%, 1000=0.78%
  lat (msec)   : 2=12.50%, 4=14.84%, 10=25.00%, 20=12.50%, 50=9.38%
  cpu          : usr=0.00%, sys=0.00%, ctx=74, majf=2, minf=27
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=62.5%, 16=37.5%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=96.1%, 8=3.4%, 16=0.6%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job6: (groupid=0, jobs=1): err= 0: pid=2380: Mon Oct 11 16:33:05 2021
  write: IOPS=2560, BW=20.0MiB/s (21.0MB/s)(1024KiB/50msec); 0 zone resets
    slat (nsec): min=203, max=148143, avg=2370.61, stdev=13430.86
    clat (usec): min=6, max=25433, avg=4766.72, stdev=7242.47
     lat (usec): min=6, max=25434, avg=4769.09, stdev=7244.42
    clat percentiles (usec):
     |  1.00th=[    7],  5.00th=[   20], 10.00th=[   22], 20.00th=[   40],
     | 30.00th=[  235], 40.00th=[ 1045], 50.00th=[ 1385], 60.00th=[ 2966],
     | 70.00th=[ 4555], 80.00th=[ 6718], 90.00th=[22414], 95.00th=[22938],
     | 99.00th=[23462], 99.50th=[25560], 99.90th=[25560], 99.95th=[25560],
     | 99.99th=[25560]
  lat (usec)   : 10=2.34%, 20=4.69%, 50=16.41%, 100=2.34%, 250=4.69%
  lat (usec)   : 500=1.56%, 750=0.78%, 1000=4.69%
  lat (msec)   : 2=15.62%, 4=10.16%, 10=23.44%, 20=1.56%, 50=11.72%
  cpu          : usr=2.04%, sys=0.00%, ctx=41, majf=1, minf=28
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=43.8%, 16=56.2%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=95.5%, 8=3.4%, 16=1.1%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job6: (groupid=0, jobs=1): err= 0: pid=2381: Mon Oct 11 16:33:05 2021
  write: IOPS=1910, BW=14.9MiB/s (15.7MB/s)(1024KiB/67msec); 0 zone resets
    slat (nsec): min=145, max=63825, avg=1455.53, stdev=6646.46
    clat (usec): min=7, max=26472, avg=6863.34, stdev=7084.59
     lat (usec): min=8, max=26473, avg=6864.79, stdev=7085.53
    clat percentiles (usec):
     |  1.00th=[    9],  5.00th=[   23], 10.00th=[   46], 20.00th=[  285],
     | 30.00th=[ 1287], 40.00th=[ 2278], 50.00th=[ 4686], 60.00th=[ 6783],
     | 70.00th=[11469], 80.00th=[13435], 90.00th=[17433], 95.00th=[19792],
     | 99.00th=[24511], 99.50th=[26346], 99.90th=[26346], 99.95th=[26346],
     | 99.99th=[26346]
  lat (usec)   : 10=1.56%, 20=3.12%, 50=7.03%, 100=5.47%, 250=1.56%
  lat (usec)   : 500=3.12%, 750=3.91%, 1000=3.12%
  lat (msec)   : 2=7.81%, 4=11.72%, 10=19.53%, 20=27.34%, 50=4.69%
  cpu          : usr=0.00%, sys=0.00%, ctx=135, majf=5, minf=25
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=50.0%, 16=50.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=98.4%, 8=1.1%, 16=0.5%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job6: (groupid=0, jobs=1): err= 0: pid=2382: Mon Oct 11 16:33:05 2021
  write: IOPS=4266, BW=33.3MiB/s (35.0MB/s)(1024KiB/30msec); 0 zone resets
    slat (nsec): min=133, max=106117, avg=2044.11, stdev=9968.18
    clat (usec): min=7, max=11660, avg=3046.86, stdev=3452.44
     lat (usec): min=7, max=11662, avg=3048.91, stdev=3452.70
    clat percentiles (usec):
     |  1.00th=[    9],  5.00th=[   22], 10.00th=[   34], 20.00th=[   91],
     | 30.00th=[  619], 40.00th=[  930], 50.00th=[ 2057], 60.00th=[ 2737],
     | 70.00th=[ 3851], 80.00th=[ 5407], 90.00th=[10814], 95.00th=[11600],
     | 99.00th=[11600], 99.50th=[11600], 99.90th=[11600], 99.95th=[11600],
     | 99.99th=[11600]
  lat (usec)   : 10=1.56%, 20=2.34%, 50=10.94%, 100=5.47%, 250=7.03%
  lat (usec)   : 750=11.72%, 1000=1.56%
  lat (msec)   : 2=7.81%, 4=26.56%, 10=14.06%, 20=10.94%
  cpu          : usr=0.00%, sys=0.00%, ctx=37, majf=3, minf=26
  IO depths    : 1=0.0%, 2=6.2%, 4=6.2%, 8=75.0%, 16=12.5%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=93.5%, 8=3.9%, 16=2.6%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job6: (groupid=0, jobs=1): err= 0: pid=2383: Mon Oct 11 16:33:05 2021
  write: IOPS=3200, BW=25.0MiB/s (26.2MB/s)(1024KiB/40msec); 0 zone resets
    slat (nsec): min=244, max=66266, avg=2227.13, stdev=7105.77
    clat (usec): min=7, max=24308, avg=3503.31, stdev=6587.20
     lat (usec): min=11, max=24309, avg=3505.53, stdev=6587.27
    clat percentiles (usec):
     |  1.00th=[   11],  5.00th=[   19], 10.00th=[   34], 20.00th=[  139],
     | 30.00th=[  155], 40.00th=[  273], 50.00th=[  725], 60.00th=[  889],
     | 70.00th=[ 1385], 80.00th=[ 5473], 90.00th=[18482], 95.00th=[19006],
     | 99.00th=[24249], 99.50th=[24249], 99.90th=[24249], 99.95th=[24249],
     | 99.99th=[24249]
  lat (usec)   : 10=0.78%, 20=4.69%, 50=7.03%, 100=5.47%, 250=21.88%
  lat (usec)   : 500=4.69%, 750=10.94%, 1000=8.59%
  lat (msec)   : 2=13.28%, 10=9.38%, 20=9.38%, 50=3.91%
  cpu          : usr=2.56%, sys=0.00%, ctx=26, majf=2, minf=25
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=68.8%, 16=31.2%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=93.1%, 8=5.0%, 16=1.9%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job7: (groupid=0, jobs=1): err= 0: pid=2384: Mon Oct 11 16:33:05 2021
  write: IOPS=3121, BW=24.4MiB/s (25.6MB/s)(1024KiB/41msec); 0 zone resets
    clat (usec): min=3, max=14454, avg=233.47, stdev=1499.03
     lat (usec): min=3, max=14454, avg=233.55, stdev=1499.06
    clat percentiles (usec):
     |  1.00th=[    4],  5.00th=[    4], 10.00th=[    4], 20.00th=[    4],
     | 30.00th=[    5], 40.00th=[    5], 50.00th=[    5], 60.00th=[    5],
     | 70.00th=[    5], 80.00th=[    5], 90.00th=[    6], 95.00th=[  122],
     | 99.00th=[ 8455], 99.50th=[14484], 99.90th=[14484], 99.95th=[14484],
     | 99.99th=[14484]
  lat (usec)   : 4=22.66%, 10=71.09%, 50=0.78%, 250=0.78%, 750=0.78%
  lat (msec)   : 2=1.56%, 4=0.78%, 10=0.78%, 20=0.78%
  cpu          : usr=0.00%, sys=0.00%, ctx=13, majf=1, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job7: (groupid=0, jobs=1): err= 0: pid=2385: Mon Oct 11 16:33:05 2021
  write: IOPS=3200, BW=25.0MiB/s (26.2MB/s)(1024KiB/40msec); 0 zone resets
    clat (usec): min=3, max=11767, avg=214.75, stdev=1229.67
     lat (usec): min=3, max=11767, avg=214.82, stdev=1229.69
    clat percentiles (usec):
     |  1.00th=[    4],  5.00th=[    4], 10.00th=[    4], 20.00th=[    4],
     | 30.00th=[    5], 40.00th=[    5], 50.00th=[    5], 60.00th=[    5],
     | 70.00th=[    6], 80.00th=[    8], 90.00th=[   10], 95.00th=[  130],
     | 99.00th=[ 5014], 99.50th=[11731], 99.90th=[11731], 99.95th=[11731],
     | 99.99th=[11731]
  lat (usec)   : 4=21.88%, 10=69.53%, 20=0.78%, 50=1.56%, 100=0.78%
  lat (usec)   : 250=0.78%, 750=0.78%
  lat (msec)   : 2=0.78%, 4=0.78%, 10=1.56%, 20=0.78%
  cpu          : usr=0.00%, sys=0.00%, ctx=12, majf=2, minf=19
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job7: (groupid=0, jobs=1): err= 0: pid=2386: Mon Oct 11 16:33:05 2021
  write: IOPS=2976, BW=23.3MiB/s (24.4MB/s)(1024KiB/43msec); 0 zone resets
    clat (usec): min=3, max=12613, avg=270.36, stdev=1358.23
     lat (usec): min=3, max=12613, avg=270.44, stdev=1358.28
    clat percentiles (usec):
     |  1.00th=[    4],  5.00th=[    4], 10.00th=[    4], 20.00th=[    5],
     | 30.00th=[    5], 40.00th=[    5], 50.00th=[    5], 60.00th=[    5],
     | 70.00th=[    6], 80.00th=[    8], 90.00th=[   10], 95.00th=[ 1188],
     | 99.00th=[ 6063], 99.50th=[12649], 99.90th=[12649], 99.95th=[12649],
     | 99.99th=[12649]
  lat (usec)   : 4=10.94%, 10=79.69%, 20=1.56%, 50=0.78%, 250=0.78%
  lat (usec)   : 750=0.78%
  lat (msec)   : 2=0.78%, 4=2.34%, 10=1.56%, 20=0.78%
  cpu          : usr=0.00%, sys=0.00%, ctx=16, majf=5, minf=16
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job7: (groupid=0, jobs=1): err= 0: pid=2387: Mon Oct 11 16:33:05 2021
  write: IOPS=1600, BW=12.5MiB/s (13.1MB/s)(1024KiB/80msec); 0 zone resets
    clat (usec): min=3, max=13691, avg=554.03, stdev=1567.65
     lat (usec): min=3, max=13691, avg=554.20, stdev=1567.66
    clat percentiles (usec):
     |  1.00th=[    5],  5.00th=[    7], 10.00th=[    7], 20.00th=[   10],
     | 30.00th=[   77], 40.00th=[   99], 50.00th=[  135], 60.00th=[  174],
     | 70.00th=[  208], 80.00th=[  392], 90.00th=[ 1057], 95.00th=[ 2802],
     | 99.00th=[ 7111], 99.50th=[13698], 99.90th=[13698], 99.95th=[13698],
     | 99.99th=[13698]
  lat (usec)   : 4=0.78%, 10=20.31%, 20=2.34%, 50=1.56%, 100=17.97%
  lat (usec)   : 250=30.47%, 500=9.38%, 750=3.91%, 1000=2.34%
  lat (msec)   : 2=3.91%, 4=3.91%, 10=2.34%, 20=0.78%
  cpu          : usr=1.27%, sys=2.53%, ctx=125, majf=4, minf=18
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job7: (groupid=0, jobs=1): err= 0: pid=2388: Mon Oct 11 16:33:05 2021
  write: IOPS=2976, BW=23.3MiB/s (24.4MB/s)(1024KiB/43msec); 0 zone resets
    clat (usec): min=3, max=11465, avg=238.97, stdev=1232.98
     lat (usec): min=3, max=11465, avg=239.06, stdev=1233.02
    clat percentiles (usec):
     |  1.00th=[    4],  5.00th=[    4], 10.00th=[    4], 20.00th=[    5],
     | 30.00th=[    5], 40.00th=[    5], 50.00th=[    5], 60.00th=[    5],
     | 70.00th=[    5], 80.00th=[    6], 90.00th=[   10], 95.00th=[  619],
     | 99.00th=[ 5342], 99.50th=[11469], 99.90th=[11469], 99.95th=[11469],
     | 99.99th=[11469]
  lat (usec)   : 4=10.94%, 10=81.25%, 20=0.78%, 500=0.78%, 750=1.56%
  lat (msec)   : 2=0.78%, 4=1.56%, 10=1.56%, 20=0.78%
  cpu          : usr=0.00%, sys=0.00%, ctx=18, majf=5, minf=17
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,128,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job8: (groupid=0, jobs=1): err= 0: pid=2389: Mon Oct 11 16:33:05 2021
  write: IOPS=29.3k, BW=28.6MiB/s (30.0MB/s)(1024KiB/35msec); 0 zone resets
    clat (nsec): min=52, max=4005.3k, avg=21454.89, stdev=228411.55
     lat (nsec): min=87, max=4005.4k, avg=21563.28, stdev=228409.29
    clat percentiles (nsec):
     |  1.00th=[     59],  5.00th=[     90], 10.00th=[    112],
     | 20.00th=[    181], 30.00th=[    217], 40.00th=[    282],
     | 50.00th=[   1304], 60.00th=[   1496], 70.00th=[   3216],
     | 80.00th=[   3536], 90.00th=[   5152], 95.00th=[  11584],
     | 99.00th=[ 272384], 99.50th=[1482752], 99.90th=[3620864],
     | 99.95th=[4014080], 99.99th=[4014080]
  lat (nsec)   : 100=7.71%, 250=29.88%, 500=5.47%, 750=0.39%, 1000=0.20%
  lat (usec)   : 2=21.19%, 4=20.41%, 10=7.81%, 20=4.88%, 50=0.49%
  lat (usec)   : 100=0.20%, 250=0.29%, 500=0.39%, 750=0.10%
  lat (msec)   : 2=0.20%, 4=0.29%, 10=0.10%
  cpu          : usr=8.82%, sys=0.00%, ctx=28, majf=582, minf=19
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,1024,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job8: (groupid=0, jobs=1): err= 0: pid=2390: Mon Oct 11 16:33:05 2021
  write: IOPS=29.3k, BW=28.6MiB/s (30.0MB/s)(1024KiB/35msec); 0 zone resets
    clat (nsec): min=50, max=3672.6k, avg=21308.01, stdev=213632.75
     lat (nsec): min=85, max=3672.7k, avg=21416.38, stdev=213630.86
    clat percentiles (nsec):
     |  1.00th=[     56],  5.00th=[     75], 10.00th=[    104],
     | 20.00th=[    177], 30.00th=[    211], 40.00th=[    378],
     | 50.00th=[   1304], 60.00th=[   2928], 70.00th=[   3248],
     | 80.00th=[   3632], 90.00th=[   5472], 95.00th=[  11840],
     | 99.00th=[ 296960], 99.50th=[1515520], 99.90th=[2932736],
     | 99.95th=[3686400], 99.99th=[3686400]
  lat (nsec)   : 100=9.38%, 250=26.95%, 500=5.37%, 750=0.39%
  lat (usec)   : 2=16.70%, 4=25.68%, 10=8.89%, 20=4.69%, 50=0.88%
  lat (usec)   : 500=0.20%, 750=0.20%
  lat (msec)   : 2=0.20%, 4=0.49%
  cpu          : usr=8.82%, sys=0.00%, ctx=20, majf=599, minf=19
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,1024,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job8: (groupid=0, jobs=1): err= 0: pid=2391: Mon Oct 11 16:33:05 2021
  write: IOPS=41.0k, BW=40.0MiB/s (41.9MB/s)(1024KiB/25msec); 0 zone resets
    clat (nsec): min=49, max=2654.1k, avg=8722.09, stdev=117739.66
     lat (nsec): min=84, max=2654.2k, avg=8769.59, stdev=117739.76
    clat percentiles (nsec):
     |  1.00th=[     51],  5.00th=[     58], 10.00th=[     74],
     | 20.00th=[     96], 30.00th=[    114], 40.00th=[    147],
     | 50.00th=[    205], 60.00th=[   1224], 70.00th=[   1320],
     | 80.00th=[   1432], 90.00th=[   1848], 95.00th=[   2416],
     | 99.00th=[  10048], 99.50th=[ 411648], 99.90th=[1990656],
     | 99.95th=[2637824], 99.99th=[2637824]
  lat (nsec)   : 50=0.20%, 100=22.07%, 250=28.81%, 500=2.25%, 750=0.10%
  lat (usec)   : 2=38.09%, 4=4.88%, 10=2.54%, 20=0.29%, 50=0.10%
  lat (usec)   : 500=0.29%, 750=0.10%
  lat (msec)   : 2=0.20%, 4=0.10%
  cpu          : usr=4.17%, sys=0.00%, ctx=13, majf=477, minf=21
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,1024,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job8: (groupid=0, jobs=1): err= 0: pid=2392: Mon Oct 11 16:33:05 2021
  write: IOPS=33.0k, BW=32.3MiB/s (33.8MB/s)(1024KiB/31msec); 0 zone resets
    clat (nsec): min=53, max=3093.6k, avg=17587.87, stdev=179151.15
     lat (nsec): min=91, max=3093.7k, avg=17708.65, stdev=179151.47
    clat percentiles (nsec):
     |  1.00th=[     56],  5.00th=[     59], 10.00th=[     80],
     | 20.00th=[    181], 30.00th=[    241], 40.00th=[    282],
     | 50.00th=[   1240], 60.00th=[   3216], 70.00th=[   3504],
     | 80.00th=[   3792], 90.00th=[   5472], 95.00th=[  11072],
     | 99.00th=[ 189440], 99.50th=[ 937984], 99.90th=[2736128],
     | 99.95th=[3096576], 99.99th=[3096576]
  lat (nsec)   : 100=12.40%, 250=20.12%, 500=15.14%, 750=0.39%
  lat (usec)   : 2=9.67%, 4=24.22%, 10=10.84%, 20=5.47%, 50=0.68%
  lat (usec)   : 250=0.20%, 500=0.10%, 750=0.10%, 1000=0.20%
  lat (msec)   : 2=0.10%, 4=0.39%
  cpu          : usr=0.00%, sys=13.33%, ctx=18, majf=531, minf=21
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,1024,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job8: (groupid=0, jobs=1): err= 0: pid=2393: Mon Oct 11 16:33:05 2021
  write: IOPS=39.4k, BW=38.5MiB/s (40.3MB/s)(1024KiB/26msec); 0 zone resets
    clat (nsec): min=50, max=3405.8k, avg=9250.34, stdev=122881.30
     lat (nsec): min=85, max=3405.8k, avg=9331.42, stdev=122880.20
    clat percentiles (nsec):
     |  1.00th=[     55],  5.00th=[     59], 10.00th=[     70],
     | 20.00th=[     85], 30.00th=[     99], 40.00th=[    117],
     | 50.00th=[    215], 60.00th=[   1272], 70.00th=[   1416],
     | 80.00th=[   1576], 90.00th=[   4576], 95.00th=[   5472],
     | 99.00th=[  34560], 99.50th=[ 399360], 99.90th=[1155072],
     | 99.95th=[3391488], 99.99th=[3391488]
  lat (nsec)   : 100=30.66%, 250=20.41%, 500=4.69%, 750=0.49%
  lat (usec)   : 2=27.73%, 4=3.81%, 10=9.47%, 20=1.46%, 50=0.49%
  lat (usec)   : 250=0.10%, 500=0.20%, 750=0.10%, 1000=0.10%
  lat (msec)   : 2=0.20%, 4=0.10%
  cpu          : usr=8.00%, sys=0.00%, ctx=18, majf=450, minf=20
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,1024,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job9: (groupid=0, jobs=1): err= 5 (file:engines/mmap.c:257, func=msync, error=Input/output error): pid=2394: Mon Oct 11 16:33:05 2021
  write: IOPS=7757, BW=30.1MiB/s (31.5MB/s)(1016KiB/33msec); 0 zone resets
    clat (usec): min=23, max=3399, avg=49.62, stdev=216.57
     lat (usec): min=23, max=3399, avg=49.70, stdev=216.57
    clat percentiles (usec):
     |  1.00th=[   24],  5.00th=[   24], 10.00th=[   25], 20.00th=[   26],
     | 30.00th=[   27], 40.00th=[   28], 50.00th=[   30], 60.00th=[   31],
     | 70.00th=[   32], 80.00th=[   35], 90.00th=[   37], 95.00th=[   49],
     | 99.00th=[  388], 99.50th=[  578], 99.90th=[ 3392], 99.95th=[ 3392],
     | 99.99th=[ 3392]
  lat (usec)   : 50=94.92%, 100=1.56%, 250=1.17%, 500=0.78%, 750=0.39%
  lat (msec)   : 4=0.39%
  cpu          : usr=0.00%, sys=25.00%, ctx=20, majf=256, minf=26
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,256,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=2, first_error=5/<Input/output error>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job9: (groupid=0, jobs=1): err= 0: pid=2395: Mon Oct 11 16:33:05 2021
  write: IOPS=14.2k, BW=55.6MiB/s (58.3MB/s)(1024KiB/18msec); 0 zone resets
    clat (usec): min=24, max=2564, avg=60.04, stdev=225.97
     lat (usec): min=24, max=2564, avg=60.14, stdev=225.97
    clat percentiles (usec):
     |  1.00th=[   25],  5.00th=[   26], 10.00th=[   26], 20.00th=[   28],
     | 30.00th=[   30], 40.00th=[   32], 50.00th=[   32], 60.00th=[   34],
     | 70.00th=[   35], 80.00th=[   39], 90.00th=[   44], 95.00th=[   50],
     | 99.00th=[  742], 99.50th=[ 2409], 99.90th=[ 2573], 99.95th=[ 2573],
     | 99.99th=[ 2573]
  lat (usec)   : 50=94.92%, 100=2.34%, 250=0.39%, 500=0.78%, 750=0.78%
  lat (msec)   : 4=0.78%
  cpu          : usr=0.00%, sys=47.06%, ctx=27, majf=261, minf=16
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,256,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=0, first_error=0/<Success>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job9: (groupid=0, jobs=1): err= 5 (file:engines/mmap.c:257, func=msync, error=Input/output error): pid=2396: Mon Oct 11 16:33:05 2021
  write: IOPS=12.2k, BW=47.4MiB/s (49.7MB/s)(1020KiB/21msec); 0 zone resets
    clat (usec): min=25, max=4368, avg=70.05, stdev=295.82
     lat (usec): min=25, max=4368, avg=70.18, stdev=295.83
    clat percentiles (usec):
     |  1.00th=[   26],  5.00th=[   27], 10.00th=[   28], 20.00th=[   31],
     | 30.00th=[   32], 40.00th=[   34], 50.00th=[   36], 60.00th=[   38],
     | 70.00th=[   40], 80.00th=[   44], 90.00th=[   74], 95.00th=[   88],
     | 99.00th=[  857], 99.50th=[ 1680], 99.90th=[ 4359], 99.95th=[ 4359],
     | 99.99th=[ 4359]
  lat (usec)   : 50=82.81%, 100=14.45%, 250=0.78%, 750=0.39%, 1000=0.39%
  lat (msec)   : 2=0.39%, 10=0.39%
  cpu          : usr=15.00%, sys=35.00%, ctx=18, majf=264, minf=23
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,256,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=1, first_error=5/<Input/output error>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job9: (groupid=0, jobs=1): err= 5 (file:engines/mmap.c:257, func=msync, error=Input/output error): pid=2397: Mon Oct 11 16:33:05 2021
  write: IOPS=7529, BW=29.1MiB/s (30.5MB/s)(1012KiB/34msec); 0 zone resets
    clat (usec): min=23, max=3350, avg=66.34, stdev=234.18
     lat (usec): min=23, max=3350, avg=66.48, stdev=234.18
    clat percentiles (usec):
     |  1.00th=[   25],  5.00th=[   26], 10.00th=[   26], 20.00th=[   28],
     | 30.00th=[   31], 40.00th=[   32], 50.00th=[   35], 60.00th=[   38],
     | 70.00th=[   42], 80.00th=[   47], 90.00th=[   53], 95.00th=[   78],
     | 99.00th=[ 1029], 99.50th=[ 1172], 99.90th=[ 3359], 99.95th=[ 3359],
     | 99.99th=[ 3359]
  lat (usec)   : 50=86.72%, 100=7.81%, 250=1.17%, 500=1.56%, 750=0.39%
  lat (msec)   : 2=0.78%, 4=0.39%
  cpu          : usr=0.00%, sys=30.30%, ctx=19, majf=256, minf=26
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,256,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=3, first_error=5/<Input/output error>
     latency   : target=0, window=0, percentile=100.00%, depth=16
job9: (groupid=0, jobs=1): err= 5 (file:engines/mmap.c:257, func=msync, error=Input/output error): pid=2398: Mon Oct 11 16:33:05 2021
  write: IOPS=5953, BW=23.0MiB/s (24.1MB/s)(1012KiB/43msec); 0 zone resets
    clat (usec): min=25, max=4743, avg=85.07, stdev=312.28
     lat (usec): min=25, max=4743, avg=85.33, stdev=312.27
    clat percentiles (usec):
     |  1.00th=[   27],  5.00th=[   28], 10.00th=[   29], 20.00th=[   35],
     | 30.00th=[   37], 40.00th=[   44], 50.00th=[   49], 60.00th=[   55],
     | 70.00th=[   60], 80.00th=[   65], 90.00th=[   80], 95.00th=[  141],
     | 99.00th=[  881], 99.50th=[ 1090], 99.90th=[ 4752], 99.95th=[ 4752],
     | 99.99th=[ 4752]
  lat (usec)   : 50=50.78%, 100=42.19%, 250=2.73%, 500=1.17%, 750=0.78%
  lat (usec)   : 1000=0.39%
  lat (msec)   : 2=0.39%, 10=0.39%
  cpu          : usr=7.14%, sys=21.43%, ctx=34, majf=257, minf=28
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,256,0,0 short=0,0,0,0 dropped=0,0,0,0
     errors    : total=3, first_error=5/<Input/output error>
     latency   : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
   READ: bw=333MiB/s (350MB/s), 66.7MiB/s-90.9MiB/s (69.9MB/s-95.3MB/s), io=5120KiB (5243kB), run=11-15msec
  WRITE: bw=375MiB/s (393MB/s), 12.5MiB/s-55.6MiB/s (13.1MB/s-58.3MB/s), io=30.0MiB (31.4MB), run=18-80msec

Disk stats (read/write):
  zram1: ios=549/3114, merge=0/0, ticks=0/40, in_queue=40, util=29.07%
fio: file hash not empty on exit

[-- Attachment #3: 095.out.bad --]
[-- Type: text/plain, Size: 2494 bytes --]

QA output created by 095
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=275456, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=416768, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=233472, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=247808, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
fio: io_u_queue.h:37: io_u_qpush: Assertion '0' failed.
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
fio: io_u_queue.h:37: io_u_qpush: Assertion '0' failed.
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=43008, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=114688, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=241664, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=115712, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=370688, buflen=1024
fio: io_u_queue.h:37: io_u_qpush: Assertion '0' failed.
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
fio: pid=2364, got signal=6
fio: pid=2367, got signal=6
fio: pid=2368, got signal=6
fio: file hash not empty on exit
Silence is golden

Re: generic/095 failing in ext4 and xfs

[Zorro Lang]

On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> Hi!
> 
> I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> Here's what I'm getting:
> 
> # cat results/generic/095.out.bad 
> QA output created by 095
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> fio: pid=4090, got signal=11
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> fio: pid=4086, got signal=11

I *guess* it might be caused by a striped storage(fs) of you?

Thanks,
Zorro

> Silence is golden
> 
> This was for ext4 but the output for xfs is similar.  Since fio is getting
> killed I suspect this may be an issue with this tool.  Thus I'm sending
> this to both fio and fstests mailing-lists.
> 
> I'm using a 5.15-rc3 kernel and fio-3.28.  Is anyone else seeing something
> similar?
> 
> Cheers,
> --
> Luís
> 

Re: generic/095 failing in ext4 and xfs

[Luís Henriques]

On Sun, Oct 10, 2021 at 04:31:25PM +0800, Zorro Lang wrote:
> On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> > Hi!
> > 
> > I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> > Here's what I'm getting:
> > 
> > # cat results/generic/095.out.bad 
> > QA output created by 095
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> > fio: pid=4090, got signal=11
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> > fio: pid=4086, got signal=11
> 
> I *guess* it might be caused by a striped storage(fs) of you?

I'm not sure I understand what you mean by that.  As I mentioned somewhere
else in this thread, I'm using zram devices for testing.  If I change the
test to use file-backed storage device instead, it passes without any
issues.

Cheers,
--
Luís

> 
> Thanks,
> Zorro
> 
> > Silence is golden
> > 
> > This was for ext4 but the output for xfs is similar.  Since fio is getting
> > killed I suspect this may be an issue with this tool.  Thus I'm sending
> > this to both fio and fstests mailing-lists.
> > 
> > I'm using a 5.15-rc3 kernel and fio-3.28.  Is anyone else seeing something
> > similar?
> > 
> > Cheers,
> > --
> > Luís
> > 
> 

Re: generic/095 failing in ext4 and xfs

[Ming Lei]

On Mon, Oct 11, 2021 at 10:09:30AM +0100, Luís Henriques wrote:
> On Sun, Oct 10, 2021 at 04:31:25PM +0800, Zorro Lang wrote:
> > On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> > > Hi!
> > > 
> > > I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> > > Here's what I'm getting:
> > > 
> > > # cat results/generic/095.out.bad 
> > > QA output created by 095
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> > > fio: pid=4090, got signal=11
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> > > fio: pid=4086, got signal=11

The issue should be from generic/095 test itself, which run dio with bs=1k,
but logical block size is 4k. I guess the test may work after you change
bs to 4k in generic/095.


Thanks,
Ming

Re: generic/095 failing in ext4 and xfs

[Luís Henriques]

On Mon, Oct 11, 2021 at 05:31:44PM +0800, Ming Lei wrote:
> On Mon, Oct 11, 2021 at 10:09:30AM +0100, Luís Henriques wrote:
> > On Sun, Oct 10, 2021 at 04:31:25PM +0800, Zorro Lang wrote:
> > > On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> > > > Hi!
> > > > 
> > > > I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> > > > Here's what I'm getting:
> > > > 
> > > > # cat results/generic/095.out.bad 
> > > > QA output created by 095
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> > > > fio: pid=4090, got signal=11
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> > > > fio: pid=4086, got signal=11
> 
> The issue should be from generic/095 test itself, which run dio with bs=1k,
> but logical block size is 4k. I guess the test may work after you change
> bs to 4k in generic/095.

Ah, I see what you mean.  Ok, I've used the patch bellow and the test now
passes.  The patch changes the block size only for the DIO jobs, there are
other jobs where bs=1k is still used.  Do you think other jobs should be
changed as well?

Cheers,
--
Luís

From 7e304a3dc11b7761700aff853078ef7171dd5d6e Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Lu=C3=ADs=20Henriques?= <lhenriques@suse.de>
Date: Mon, 11 Oct 2021 11:08:47 +0100
Subject: [PATCH] generic/095: use device blocksize instead of 1k for DIO
 operations
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

This test fails for ext4 and xfs when using zram.  As pointed out by others
(Zorro and Ming), the test shouldn't use 1k for dio.

Signed-off-by: Luís Henriques <lhenriques@suse.de>
---
 tests/generic/095 | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/tests/generic/095 b/tests/generic/095
index c4693917b3e1..47d18e1a6f63 100755
--- a/tests/generic/095
+++ b/tests/generic/095
@@ -23,6 +23,7 @@ iodepth_batch=$((8 * LOAD_FACTOR))
 numjobs=$((5 * LOAD_FACTOR))
 fio_config=$tmp.fio
 fio_out=$tmp.fio.out
+blksz=$(_get_block_size $SCRATCH_MNT)
 cat >$fio_config <<EOF
 [global]
 bs=8k
@@ -34,7 +35,7 @@ directory=$SCRATCH_MNT
 numjobs=$numjobs
 [job1]
 ioengine=sync
-bs=1k
+bs=$blksz
 direct=1
 rw=randread
 filename=file1:file2
@@ -44,7 +45,7 @@ rw=randwrite
 direct=1
 filename=file1:file2
 [job3]
-bs=1k
+bs=$blksz
 ioengine=posixaio
 rw=randwrite
 direct=1

Re: generic/095 failing in ext4 and xfs

[Ming Lei]

On Mon, Oct 11, 2021 at 11:16:09AM +0100, Luís Henriques wrote:
> On Mon, Oct 11, 2021 at 05:31:44PM +0800, Ming Lei wrote:
> > On Mon, Oct 11, 2021 at 10:09:30AM +0100, Luís Henriques wrote:
> > > On Sun, Oct 10, 2021 at 04:31:25PM +0800, Zorro Lang wrote:
> > > > On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> > > > > Hi!
> > > > > 
> > > > > I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> > > > > Here's what I'm getting:
> > > > > 
> > > > > # cat results/generic/095.out.bad 
> > > > > QA output created by 095
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> > > > > fio: pid=4090, got signal=11
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> > > > > fio: pid=4086, got signal=11
> > 
> > The issue should be from generic/095 test itself, which run dio with bs=1k,
> > but logical block size is 4k. I guess the test may work after you change
> > bs to 4k in generic/095.
> 
> Ah, I see what you mean.  Ok, I've used the patch bellow and the test now
> passes.  The patch changes the block size only for the DIO jobs, there are
> other jobs where bs=1k is still used.  Do you think other jobs should be
> changed as well?

Only DIO job need aligned bs parameter. 


thanks,
Ming

Re: generic/095 failing in ext4 and xfs

[Luís Henriques]

On Mon, Oct 11, 2021 at 07:13:57PM +0800, Ming Lei wrote:
> On Mon, Oct 11, 2021 at 11:16:09AM +0100, Luís Henriques wrote:
> > On Mon, Oct 11, 2021 at 05:31:44PM +0800, Ming Lei wrote:
> > > On Mon, Oct 11, 2021 at 10:09:30AM +0100, Luís Henriques wrote:
> > > > On Sun, Oct 10, 2021 at 04:31:25PM +0800, Zorro Lang wrote:
> > > > > On Fri, Oct 01, 2021 at 06:11:49PM +0100, Luis Henriques wrote:
> > > > > > Hi!
> > > > > > 
> > > > > > I'm seeing generic/095 failing both with ext4 and xfs (but not on btrfs).
> > > > > > Here's what I'm getting:
> > > > > > 
> > > > > > # cat results/generic/095.out.bad 
> > > > > > QA output created by 095
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=51200, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=133120, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=92160, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=158720, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=513024, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=33792, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file2: Invalid argument: write offset=449536, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=45056, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=30720, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=222208, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: read offset=342016, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=177152, buflen=1024
> > > > > > fio: pid=4090, got signal=11
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=43008, buflen=1024
> > > > > > fio: io_u error on file /tmp/mnt/scratch/file1: Invalid argument: write offset=308224, buflen=1024
> > > > > > fio: pid=4086, got signal=11
> > > 
> > > The issue should be from generic/095 test itself, which run dio with bs=1k,
> > > but logical block size is 4k. I guess the test may work after you change
> > > bs to 4k in generic/095.
> > 
> > Ah, I see what you mean.  Ok, I've used the patch bellow and the test now
> > passes.  The patch changes the block size only for the DIO jobs, there are
> > other jobs where bs=1k is still used.  Do you think other jobs should be
> > changed as well?
> 
> Only DIO job need aligned bs parameter. 

Awesome, thanks for confirming.

Cheers,
--
Luís

Re: generic/095 failing in ext4 and xfs

[Theodore Ts'o]

On Mon, Oct 11, 2021 at 11:16:09AM +0100, Luís Henriques wrote:
> 
> Ah, I see what you mean.  Ok, I've used the patch bellow and the test now
> passes.  The patch changes the block size only for the DIO jobs, there are
> other jobs where bs=1k is still used.  Do you think other jobs should be
> changed as well?

When you try to submit this to fstests, what I'd suggest is to use
_min_dio_alignment (defined in common/rc) to set the block size for
DIO in the fio jobs.

Cheers,

					- Ted

Re: generic/095 failing in ext4 and xfs

[Luís Henriques]

On Mon, Oct 11, 2021 at 08:44:54AM -0400, Theodore Ts'o wrote:
> On Mon, Oct 11, 2021 at 11:16:09AM +0100, Luís Henriques wrote:
> > 
> > Ah, I see what you mean.  Ok, I've used the patch bellow and the test now
> > passes.  The patch changes the block size only for the DIO jobs, there are
> > other jobs where bs=1k is still used.  Do you think other jobs should be
> > changed as well?
> 
> When you try to submit this to fstests, what I'd suggest is to use
> _min_dio_alignment (defined in common/rc) to set the block size for
> DIO in the fio jobs.

Ok, will do.  Thanks.

Cheers,
--
Luís