Error message during a iozone test: "fsync: giving up on dirty . . ."

From: Mark Millard <marklmi_at_yahoo.com>
Date: Thu, 17 Oct 2024 01:30:50 UTC
After doing an iozone test run with some basic monitoring
( top use, ls -lodTt /tmp/iozone.* ), I later noticed that
the console was displaying message(s). dmesg -a dispalyed
them as well:

fsync: giving up on dirty (error = 35) 0xffffa00087390a50: type VCHR state VSTATE_CONSTRUCTED op 0xffff000000cb5458
    usecount 1, writecount 0, refcount 31 seqc users 0 rdev 0xffffa00087271400
    hold count flags ()
    flags ()
    v_object 0xffffa0008e01de70 ref 0 pages 2185 cleanbuf 28 dirtybuf 1
    lock type mntfs: EXCL by thread 0xffff000145b3a900 (pid 17261, iozone, tid 100423)
 with exclusive waiters pending

Unfortunately, this was based on my personal build, not an
official FreeBSD build. I do not know if it is repeatable
in either type of context.

# uname -apKU
FreeBSD aarch64-main-pbase 15.0-CURRENT FreeBSD 15.0-CURRENT #9 main-n272664-149e1af6ae49-dirty: Sat Oct  5 20:13:13 PDT 2024     root@aarch64-main-pbase:/usr/obj/BUILDs/main-CA76-nodbg-clang/usr/main-src/arm64.aarch64/sys/GENERIC-NODBG-CA76 arm64 aarch64 1500024 1500024

The context was UFS, no ZFS pool in use.

The system was a Windows Dev Kit 2023 using a USB3 media: a
U.2 Optane via an adaptor.

For reference:

# iozone -w -i 0 -l 128 -r 4k -s 1g
Iozone: Performance Test of File I/O
        Version $Revision: 3.506 $
Compiled for 64 bit mode.
Build: freebsd  
Contributors:William Norcott, Don Capps, Isom Crawford, Kirby Collins
            Al Slater, Scott Rhine, Mike Wisner, Ken Goss
            Steve Landherr, Brad Smith, Mark Kelly, Dr. Alain CYR,
            Randy Dunlap, Mark Montague, Dan Million, Gavin Brebner,
            Jean-Marc Zucconi, Jeff Blomberg, Benny Halevy, Dave Boone,
            Erik Habbinga, Kris Strecker, Walter Wong, Joshua Root,
            Fabrice Bacchella, Zhenghua Xue, Qin Li, Darren Sawyer,
            Vangel Bojaxhi, Ben England, Vikentsi Lapa,
            Alexey Skidanov, Sudhir Kumar.

Run began: Wed Oct 16 17:09:54 2024

Setting no_unlink
Record Size 4 kB
File size set to 1048576 kB
Command line used: iozone -w -i 0 -l 128 -r 4k -s 1g
Output is in kBytes/sec
Time Resolution = 0.000001 seconds.
Processor cache size set to 1024 kBytes.
Processor cache line size set to 32 bytes.
File stride size set to 17 * record size.
Min process = 128  Max process = 128  Throughput test with 128 processes
Each process writes a 1048576 kByte file in 4 kByte records

Children see throughput for 128 initial writers =  209938.09 kB/sec
Parent sees throughput for 128 initial writers =  130875.72 kB/sec
Min throughput per process =     863.04 kB/sec  Max throughput per process =    4826.54 kB/sec
Avg throughput per process =    1640.14 kB/sec
Min xfer =  524736.00 kB

Children see throughput for 128 rewriters =  214463.62 kB/sec
Parent sees throughput for 128 rewriters =  214422.18 kB/sec
Min throughput per process =     805.30 kB/sec  Max throughput per process =    1983.41 kB/sec
Avg throughput per process =    1675.50 kB/sec
Min xfer =  425788.00 kB



iozone test complete.


I do not know the relative timing vs. the message, but a:

# ls -lodTt /tmp/* 
load: 3.24  cmd: ls 17508 [ufs] 35.14r 0.00u 0.00s 0% 3056k
#0 0xffff0000004fad98 at mi_switch+0xd8
#1 0xffff0000004baafc at sleeplk+0xfc
#2 0xffff0000004b951c at lockmgr_slock_hard+0x27c
#3 0xffff00000082b474 at ffs_lock+0x64
#4 0xffff0000006007c8 at _vn_lock+0x58
#5 0xffff0000005e80b8 at vget_finish+0x28
#6 0xffff0000005ceae4 at cache_fplookup_final_child+0x54
#7 0xffff0000005cc680 at cache_fplookup+0x4c0
#8 0xffff0000005d8534 at namei+0xd4
#9 0xffff0000005f9154 at kern_statat+0xa4
#10 0xffff0000005f976c at sys_fstatat+0x2c
#11 0xffff0000008c00c4 at do_el0_sync+0x634
#12 0xffff00000089a1ac at handle_el0_sync+0x4c
load: 10.95  cmd: ls 17508 [ufs] 61.42r 0.00u 0.00s 0% 3064k
#0 0xffff0000004fad98 at mi_switch+0xd8
#1 0xffff0000004baafc at sleeplk+0xfc
#2 0xffff0000004b951c at lockmgr_slock_hard+0x27c
#3 0xffff00000082b474 at ffs_lock+0x64
#4 0xffff0000006007c8 at _vn_lock+0x58
#5 0xffff0000005e80b8 at vget_finish+0x28
#6 0xffff0000005ceae4 at cache_fplookup_final_child+0x54
#7 0xffff0000005cc680 at cache_fplookup+0x4c0
#8 0xffff0000005d8534 at namei+0xd4
#9 0xffff0000005f9154 at kern_statat+0xa4
#10 0xffff0000005f976c at sys_fstatat+0x2c
#11 0xffff0000008c00c4 at do_el0_sync+0x634
#12 0xffff00000089a1ac at handle_el0_sync+0x4c
^C

seemed to have been unable to make progress during the "rewriters"
activity.


===
Mark Millard
marklmi at yahoo.com