Input/Output: MacOS Sonoma 14.4b3 CIRCUITPY Slow Write Performance

[eightycc]

CircuitPython version

All CP versions are affected.

Code/REPL

n/a

Behavior

Writes to the CIRCUITPY filesystem when mounted by USB MSC on MacOS Sonoma 14.4 beta 2 and above are 400 to 800 times slower than with previous releases of MacOS.

Description

Previously, MacOS Sonoma 14.0 introduced a regression in its MSDOS filesystem support that caused a number of issues that are documented in issue #8449. The root cause of the issue was in Sonoma's new MSDOS filesystem user-space support that replaced the earlier kernel extension support. The new user-space support delays writing filesystem metadata (in this case FAT table and root directory) for tens of seconds after writes to a file, causing a variety of undesirable outcomes.

Apple subsequently fixed this behavior in 14.4 beta 2 by completely re-writing all metadata (the equivalent of a sync) after every few blocks written. This has the undesirable effects of slowing writes by 400 to 800 times and introducing unnecessary wear to the flash memory.

It is possible to reproduce poor write performance using a USB stick. All of these tests were performed with a 16G stick. The test writes 512 blocks of 512 bytes of zeroes.

dd if=/dev/zero of=/Volumes/NO\ NAME/test.dat bs=512 count=512

Performance jumps ~400x to 800x when the filesystem size exceeds 1G.

Filesystem Size	Filesystem	Time(Sec.)
4M	FAT12	26.981
8M	FAT12	28.780
15M	FAT16	29.019
16M	FAT16	29.139
32M	FAT16	29.669
64M	FAT16	29.414
128M	FAT16	50.138
256M	FAT32	39.641
512M	FAT32	40.786
1G	FAT32	42.938
2G	FAT32	0.050
4G	FAT32	0.046
8G	FAT32	0.101
16G	FAT32	0.109

For convenience I made the test sticks on Linux. It should be possible to do the same with Disk Utilities on MacOS.

Partitioned with fdisk creating a primary partition of the desired size, for example:

rabeles@ub2004:~$ sudo fdisk /dev/sdd

Welcome to fdisk (util-linux 2.37.2).
Changes will remain in memory only, until you decide to write them.
Be careful before using the write command.

Command (m for help): d
Selected partition 1
Partition 1 has been deleted.

Command (m for help): n
Partition type
   p   primary (0 primary, 0 extended, 4 free)
   e   extended (container for logical partitions)
Select (default p): p
Partition number (1-4, default 1): 
First sector (2048-30892031, default 2048): 
Last sector, +/-sectors or +/-size{K,M,G,T,P} (2048-30892031, default 30892031): +1026M

Created a new partition 1 of type 'Linux' and of size 1 GiB.
Partition #1 contains a vfat signature.

Do you want to remove the signature? [Y]es/[N]o: yes

The signature will be removed by a write command.

Command (m for help): t
Selected partition 1
Hex code or alias (type L to list all): 06
Changed type of partition 'Linux' to 'FAT16'.

Command (m for help): p
Disk /dev/sdd: 14.73 GiB, 15816720384 bytes, 30892032 sectors
Disk model: Cruzer Blade    
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x00000000

Device     Boot Start     End Sectors Size Id Type
/dev/sdd1        2048 2103295 2101248   1G  6 FAT16

Filesystem/RAID signature on partition 1 will be wiped.

Command (m for help): w
The partition table has been altered.
Calling ioctl() to re-read partition table.
Syncing disks.

Then create the filesystem:

rabeles@ub2004:~$ sudo mkfs.vfat -F32 /dev/sdd1
mkfs.fat 4.2 (2021-01-31)

Additional information

No response

[lurch]

The test writes 512 blocks of 512 bytes of zeroes.

Is it worth benchmarking different blocksizes? e.g. bs=1024 count=256 and bs=2048 count=128

[eightycc]

Is it worth benchmarking different blocksizes?

It's a good thought. I did benchmark with larger block sizes, and the timings improve as you would expect but are still more than 2 orders of magnitude slower than they should be. For example, bs=1024 count=256 takes 15.571 seconds for a rate of 16K bytes/second.

[sperok]

The code attached will automatically remount a CIRCUITPY device as synchronous, likely minimizing risk of data corruption #8449 and some of the perceived performance of delayed writes. It is human readable XML, uncommented. Install once, runs unattended, persists across Mac reboots and unlimited insertions/removals on any number of devices.

This is a launch daemon property list configured to watch /Volumes for change events without polling. An embedded bash script examines all mounted CIRCUITPY devices on change. Devices mounted synchronous or read-only are not touched. Any other CIRCUITPY device is unmounted and mounted "synchronous,noasync"

To use:

1. Download the file and rename it, removing the .txt extension.
2. $ sudo cp tech.auli.cato.plist /Library/LaunchDaemons/tech.auli.cato.plist
3. $ sudo launchctl load -w /Library/LaunchDaemons/tech.auli.cato.plist

Monitor insertions using Apple's log utility:

5. $ log stream --predicate 'process == "logger"'

tech.auli.cato.plist.txt

[eightycc]

The excellent workaround for #8449 by @sperok will work with Sonoma 14.3 and earlier. The reason that the workaround worked was that re-mounting the device caused the older MSDOS filesystem kext to be loaded.

Unfortunately, Apple has changed mount behavior in Sonoma 14.4 beta 4 so that it continues to use the faulty user space MSDOS filesystem driver across a re-mount.

[sperok]

bummer. wouldn't breaking "synchronous,noasync" behavior qualify as a bug? Can this be reported to Apple?

[eightycc]

wouldn't breaking "synchronous,noasync" behavior qualify as a bug?

@sperok Of course, but that's not exactly what's going on.

Apropos #8449 mount flags are a red herring. I tested various combinations of flags on a remount, and found they had no effect. I later found that this was because re-mounting with any combination of flags caused Sonoma to pull in older kext code that worked properly vs. Sonoma's new user space driver. "Properly" in this context is that it did not delay metadata writes.

We've been reporting the issue to Apple since last October. They responded to my report with "Potential fix identified - For a future OS update" and at about the same time changed behavior in Sonoma 14.4 beta like this:

• Modified their MSDOS user space driver to re-write all metadata (FAT tables and root directory in our case) after every few data block writes on all MSDOS filesystems (FAT12, FAT16, and FAT32) 1G or smaller in size. This results in the performance degradation noted in this issue.
• Modified MSDOS filesystem mount behavior so that a re-mount does not bring in the older, bug-free kext.

So, Apple has resolved #8449 but has left us with a performance problem for which we have no workaround. Hopefully another round of problem reports to Apple will get the performance issue solved, too.

Original Apple feedback for #8449 is FB13226668, feedback for this issue is FB13628505.

[sperok]

Thanks for the detailed explanation. I've now gone back through #8449 and read the entire history, happy to learn "Tracing shows meta-data updates now follow a data write within a few hundred milliseconds."

[dhalbert]

The default autoreload waiting time is 0.75 seconds after the most recent write.

[romkey]

macOS Sonoma 14.4 beta 4 is out and still exhibits this behavior

[UnexpectedMaker]

Hey @romkey, have you had a chance to try beta 14.4 5 yet?

[romkey]

@UnexpectedMaker yes, just tested it in fact! Sadly no change, still slow but at least it also still works.

Other Apple beta OS's are on their release candidates now but macOS 14.4 still isn't, so we may have a couple more betas before it's released.

[UnexpectedMaker]

@romkey Thanks for checking. I'm not going to hold me breath about a fix coming in 14.4 ;)

[romkey]

macOS 14.4RC out today, no change (if anything it feels even slower but I didn't actually time it)

[UnexpectedMaker]

Ahh CR@P - Well, thanks for the update :)

[dhalbert]

I was going to file a Feedback, and made up a USB stick with four partitions (16MB, 512MB, 1GB, 2GB) using gparted. Upon plugging this in to a Mac running 14.4 beta 5, one partition mounted quickly, one mounted slowly, and two never mounted after a couple of minutes. It looks like macOS was trying to set up the .fseventsd and .Spotlight-V100 directories, but maybe was doing so extremely slowly. So I gave up on that as a simple test to submit.

I will try for a simpler report about single small-sized partitions on USB sticks after some further experimentation.

[eightycc]

@dhalbert

I was going to file a Feedback, and made up a USB stick with four partitions (16MB, 512MB, 1GB, 2GB) using gparted.

It's a bit of a pain, but you'll need to test with one partition at a time.

[romkey]

The manual remount workaround still works for me (macOS 14.4RC). Doing this gets me fast writes to CIRCUITPY

Using a Matrix Portal S3 here. Before testing I ran

import storage
storage.erase_filesystem()

ran it again after copying files and before manually remounting.

root@JohnsMacStudio ~ # time cp tmptest/* /Volumes/CIRCUITPY
cp tmptest/* /Volumes/CIRCUITPY  0.00s user 0.01s system 0% cpu 16.597 total
root@JohnsMacStudio ~ # umount /Volumes/CIRCUITPY ; mkdir /Volumes/CIRCUITPY ; mount -t msdos /dev/disk4s1 /Volumes/CIRCUITPY
root@JohnsMacStudio ~ # time cp tmptest/* /Volumes/CIRCUITPY
cp tmptest/* /Volumes/CIRCUITPY  0.00s user 0.01s system 1% cpu 0.436 total

tmptest has 21 2KB files in it

First mount line is from automatic mounting second is the manual remount - note the lack of fskit in the second

/dev/disk4s1 on /Volumes/CIRCUITPY (msdos, local, nodev, nosuid, noowners, noatime, fskit)
/dev/disk4s1 on /Volumes/CIRCUITPY (msdos, local, noowners)

I haven't been able to find a mount option to tell it not to use fskit - tried nofskit and no-fskit (-o fskit also doesn't work to force fskit)

[romkey]

I noticed this because I was trying to get a simple shell script working that demonstrates the problem using disk images, but I keep seeing fast writes with it. Not sure what's going on here as it appears to be using fskit

Its mount output looks like this /dev/disk10s1 on /Volumes/TESTDISK (msdos, local, nodev, nosuid, noowners, noatime, fskit, mounted by romkey)

When I manually copy the files it generates to an automatically mounted CIRCUITPY the copies are very slow. When I copy them in the script or by hand to the disk image it mounts, the copies are very fast. Maybe writing to a disk image is just so fast that even with all the extra writes it still appears instantaneous? I'll try to do some testing later with much larger files and see if I can see a difference in timing.

Here's the script:

#!/bin/bash

# disk image size: M for MB, G for GB
SIZE=6M

if [[ "`id -u`" == "0" ]]; then
    echo "Do not run this script as root"
    exit -1
fi

if [[ -e disk.img ]]; then
    echo "Refusing to delete disk.img, rm by hand and rerun if okay"
    exit -1
fi

echo "creating empty disk image of size $SIZE"

truncate -s $SIZE disk.img
DISK=`diskutil image attach --noMount disk.img`

echo "attached image as disk $DISK"
echo "about to run diskutil eraseDisk 'ms-dos'  TESTDISK $DISK"
echo "this will put an empty filesystem on $DISK and mount it as /Volumes/TESTDISK"
echo
echo "failsafe check - press return to continue, ^C to exit"
read

# you can force FAT12 by specifying it after "msdos" here
# but the disk must be 32MB or less
diskutil eraseDisk 'ms-dos'  TESTDISK $DISK

mkdir tmptest

for i in {0..20}
do
    truncate -s 2049 tmptest/$i
done

time cp tmptest/* /Volumes/TESTDISK

echo "to clean up"
echo "  rm -rf tmptest disk.img"
echo "  umount /Volumes/TESTDISK"

[romkey]

The general public release of macOS 14.4 is out today. As expected, the slow writes are still an issue.

The good news is that it still fixes the original issue and it's still possible to write to smaller filesystems without using any workarounds. So @dhalbert it's safe to update the blog post to tell people to update to 14.4.

Hopefully 14.5 beta will be out soon and we can begin the testing/optimism/disappointment/surprise cycle anew.

[UnexpectedMaker]

Yeah, I finally updated my M2Max Studio to Sonoma today because of the 14.4 release - been on Ventura since I bought it specifically because of this CP issue.

[romkey]

macOS Sonoma 14.4.1 is out, bug fix release, no change in this behavior

[dhalbert]

The (first?) macOS 14.5 beta is out. I upgraded, and realized I should have taken a baseline before upgrading. @romkey have you tried that beta yet? Thanks.

[eightycc]

This problem may also affect ExFAT. See this discussion at AppleInsider: https://forums.appleinsider.com/discussion/235967

[romkey]

@dhalbert sorry for the slow response, been deep in some other stuff. Comparing a 14.4.1 Mac with a 14.5 beta Mac, the 14.5 beta Mac is faster but still very slow (38 seconds to copy 24 files on 14.4.1, 18 seconds to copy the same files on 14.5 beta)

[romkey]

Just tested the first developer beta of macOS 15 Sequoia with an Unexpected Maker Bling board and it's still slow. From the command line, roughly one second per file (tried with three different sets of files) for modestly sized files (like Python source code). Larger files took > 1s/file

The good news is it does work, so they didn't totally break it this time (yet)! Ejecting is also still very slow.

With 24 files:

With 7 files:

[dhalbert]

@romkey Thank you for testing! Do you alreadyhave a Feedaback issue open with Apple about this? I would like to come up with a simple portable test that shows what @eightycc 's OP in this issue shows: slow on 1GB or smaller, much faster above. I tried a multi-volume USB stick but that failed in various ways. It seems difficult to create a disk image of a small size natively on macOS. I just want to make it as easy as possible for them to reproduce the issue.

[romkey]

@dhalbert I haven't opened an issue yet, really should.

I tried putting together a demo of the problem a few months ago and had some issues with it. I'll see if I can find what I had and share it.