Over the past several months, a handful of people had been complaining that Mercurial's test harness was executing much slower on Macs. But this slowdown seemingly wasn't occurring on Linux or Windows. And not every Mac user experienced the slowness!
Before jetting off to the Mercurial 4.8 developer meetup in Stockholm a few weeks ago, I sat down with a relatively fresh 6+6 core MacBook Pro and experienced the problem firsthand: on my 4+4 core i7-6700K running Linux, the Mercurial test harness completes in ~12 minutes, but on this MacBook Pro, it was executing in ~38 minutes! On paper, this result doesn't make any sense because there's no way that the MacBook Pro should be ~3x slower than that desktop machine.
Looking at Activity Monitor when running the test harness with 12 tests in parallel revealed something odd: the system was spending ~75% of overall CPU time inside the kernel! When reducing the number of tests that ran in parallel, the percentage of CPU time spent in the kernel decreased and the overall test harness execution time also decreased. This kind of behavior is usually a sign of something very inefficient in kernel land.
I sample profiled all processes on the system when running the Mercurial
test harness. Aggregate thread stacks revealed a common pattern:
readdir() being in the stack.
Upon closer examination of the stacks,
readdir() calls into
apfs_vnop_readdir(), which calls into some functions with
btree in their name, which call into
lck_mtx_lock_grab_mutex() and various other functions with
lck_mtx in their name. And the caller of most
to be Python 2.7's module importing mechanism (notably
APFS refers to the Apple File System, which is a filesystem that Apple introduced in 2017 and is the default filesystem for new versions of macOS and iOS. If upgrading an old Mac to a new macOS, its HFS+ filesystems would be automatically converted to APFS.
While the source code for APFS is not available for me to confirm, the
profiling results showing excessive time spent in
lck_mtx_lock_grab_mutex() combined with the fact that execution time
decreases when the parallel process count decreases leads me to the
conclusion that APFS obtains a global kernel lock during read-only
operations such as
readdir(). In other words, APFS slows down when
attempting to perform parallel read-only I/O.
This isn't the first time I've encountered such behavior in a filesystem: last year I blogged about very similar behavior in AUFS, which was making Firefox CI significantly slower.
Because Python 2.7's module importing mechanism was triggering the
slowness by calling
posted to python-dev
about the problem, as I thought it was important to notify the larger
Python community. After all, this is a generic problem that affects
the performance of starting any Python process when running on APFS.
i.e. if your build system invokes many Python processes in parallel,
you could be impacted by this. As part of obtaining data for that post, I
discovered that Python 3.7 does not call
readdir() as part of
module importing and therefore doesn't exhibit a severe slowdown. (Python's
module importing code was rewritten significantly in Python 3 and the fix
was likely introduced well before Python 3.7.)
I've produced a gist that can reproduce the problem.
The script essentially performs a recursive directory walk. It exercises
heavily and is essentially a benchmark of the filesystem and filesystem
cache's ability to return file metadata.
When you tell it to walk a very large directory tree - say a Firefox version control checkout (which has over 250,000 files) - the excessive time spent in the kernel is very apparent on macOS 10.13 High Sierra:
$ time ./slow-readdir.py -l 12 ~/src/firefox ran 12 walks across 12 processes in 172.209s real 2m52.470s user 1m54.053s sys 23m42.808s $ time ./slow-readdir.py -l 12 -j 1 ~/src/firefox ran 12 walks across 1 processes in 523.440s real 8m43.740s user 1m13.397s sys 3m50.687s $ time ./slow-readdir.py -l 18 -j 18 ~/src/firefox ran 18 walks across 18 processes in 210.487s real 3m30.731s user 2m40.216s sys 33m34.406s
On the same machine upgraded to macOS 10.14 Mojave, we see a bit of a speedup!:
$ time ./slow-readdir.py -l 12 ~/src/firefox ran 12 walks across 12 processes in 97.833s real 1m37.981s user 1m40.272s sys 10m49.091s $ time ./slow-readdir.py -l 12 -j 1 ~/src/firefox ran 12 walks across 1 processes in 461.415s real 7m41.657s user 1m05.830s sys 3m47.041s $ time ./slow-readdir.py -l 18 -j 18 ~/src/firefox ran 18 walks across 18 processes in 140.474s real 2m20.727s user 3m01.048s sys 17m56.228s
Contrast with my i7-6700K Linux machine backed by EXT4:
$ time ./slow-readdir.py -l 8 ~/src/firefox ran 8 walks across 8 processes in 6.018s real 0m6.191s user 0m29.670s sys 0m17.838s $ time ./slow-readdir.py -l 8 -j 1 ~/src/firefox ran 8 walks across 1 processes in 33.958s real 0m34.164s user 0m17.136s sys 0m13.369s $ time ./slow-readdir.py -l 12 -j 12 ~/src/firefox ran 12 walks across 12 processes in 25.465s real 0m25.640s user 1m4.801s sys 1m20.488s
It is apparent that macOS 10.14 Mojave has received performance work relative to macOS 10.13! Overall kernel CPU time when performing parallel directory walks has decreased substantially - to ~50% of original on some invocations! Stacks seem to reveal new code for lock acquisition, so this might indicate generic improvements to the kernel's locking mechanism rather than APFS specific changes. Changes to file metadata caching could also be responsible for performance changes. Although it is difficult to tell without access to the APFS source code. Despite those improvements, APFS is still spending a lot of CPU time in the kernel. And the kernel CPU time is still comparatively very high compared to Linux/EXT4, even for single process operation.
At this time, I haven't conducted a comprehensive analysis of APFS to
determine what other filesystem operations seem to acquire global kernel
locks: all I know is
readdir() does. A casual analysis of profiled
stacks when running Mercurial's test harness against Python 3.7 seems
apfs_* functions still on the stack a lot and that seemingly
indicates more APFS slowness under parallel I/O load. But HFS+ exhibited
similar problems (it appeared HFS+ used a single I/O thread inside the
kernel for many operations, making I/O on macOS pretty bad), so I'm
not sure if these could be considered regressions the way
new behavior is.
I've reported this issue to Apple at https://bugreport.apple.com/web/?problemID=45648013. I'm told that issues get more attention from Apple when there are many duplicates of the same issue. So please reference this issue if you file your own report.
Now that I've elaborated on the technical details, I'd like to add some personal commentary. While this post is about APFS, this issue of global kernel locks during common I/O operations is not unique to APFS. I already referenced similar issues in AUFS. And I've encountered similar behaviors with Btrfs (although I can't recall exactly which operations). And NTFS has its own bag of problems.
This seeming pattern of global kernel locks for common filesystem operations and slow filesystems is really rubbing me the wrong way. Modern NVMe SSDs are capable of reading and writing well over 2 gigabytes per second and performing hundreds of thousands of I/O operations per second. We even have Intel soon producing persistent solid state storage that plugs into DIMM slots because it is that friggin fast.
Today's storage hardware is capable of ludicrous performance. It is fast enough that you will likely saturate multiple CPU cores processing the read or written data coming from and going to storage - especially if you are using higher-level, non-JITed (read: slower) programming languages (like Python). There has also been a trend that systems are growing more CPU cores faster than they are instructions per second per core. And SSDs only achieve these ridiculous IOPS numbers if many I/O operations are queued and can be more efficiently dispatched within the storage device. What this all means is that it probably makes sense to use parallel I/O across multiple threads in order to extract all potential performance from your persistent storage layer.
It's also worth noting that we now have solid state storage that outperforms (in some dimensions) what DRAM from ~20 years ago was capable of. Put another way I/O APIs and even some filesystems were designed in an era when its RAM was slower than what today's persistent storage is capable of! While I'm no filesystems or kernel expert, it does seem a bit silly to be using APIs and filesystems designed for an era when storage was multiple orders of magnitude slower and systems only had a single CPU core.
My takeaway is I can't help but feel that systems-level software (including the kernel) is severely limiting the performance potential of modern storage devices. If we have e.g. global kernel locks when performing common I/O operations, there's no chance we'll come close to harnessing the full potential of today's storage hardware. Furthermore, the behavior of filesystems is woefully under documented and software developers have little solid advice for how to achieve optimal I/O performance. As someone who cares about performance, I want to squeeze every iota of potential out of hardware. But the lack of documentation telling me which operations acquire locks, which strategies are best for say reading or writing 10,000 files using N threads, etc makes this extremely difficult. And even if this documentation existed, because of differences in behavior across filesystems and operating systems and the difficulty in programmatically determining the characteristics of filesystems at run time, it is practically impossible to design a one size fits all approach to high performance I/O.
The filesystem is a powerful concept. I want to agree and use the everything is a file philosophy. Unfortunately, filesystems don't appear to be scaling very well to support the potential of modern day storage technology. We're probably at the point where commodity priced solid state storage is far more capable than today's software for the majority of applications. Storage hardware manufacturers will keep producing faster and faster storage and their marketing teams will keep convincing us that we need to buy it. But until software catches up, chances are most of us won't come close to realizing the true potential of modern storage hardware. And that's even true for specialized applications that do employ tricks taking hundreds or thousands of person hours to implement in order to eek out every iota of performance potential. The average software developer and application using filesystems as they were designed to be used has little to no chance of coming close to utilizing the performance potential of modern storage devices. That's really a shame.