How does an Apple silicon Mac mount a Thunderbolt disk?

External storage is the most popular peripheral for Macs, if for no other reason than to keep backups. Each time your Mac starts up, or you connect its external disk, your Mac has to mount that disk and all its volumes. Some users find that process takes a long time, although it’s hard to discover why. This article explains how an Apple silicon Mac mounts a Thunderbolt 3 SSD, based on full log records, enabling you to diagnose mounting problems.

For the purposes of this walkthrough, an external Thunderbolt 3 disk was plugged directly into one of the ports on a Mac Studio M1 Max running macOS Ventura 13.2.1. Times are given in seconds relative to a start of 0.0.

When mounted, the top-level disk became disk4, with a standard hidden EFI partition at disk4s1, and its single APFS container at disk4s2, and as disk5, making the sole APFS volume disk5s1.

The initial hardware phase starts with entries from IOAccessoryManager’s opening entry
0.000000 IOAccessoryManager IOPort::addTransport(): [Port-USB-C@4] Adding transport...

After a long torrent of entries mostly from IOAccessoryManager, cable connection is recognised and powered on
0.055389 AppleSynopsysUSB40XHCI usb-drd3-port-ss@03200000: AppleUSB40XHCITypeCPort::cableChangeOccurred: USB3 mode change, powering off
0.055409 AppleSynopsysUSB40XHCI usb-drd3-port-ss@03200000: AppleUSB40XHCITypeCPort::cableChangeOccurred: cable connected, powering on
0.055444 AppleUSBXHCI usb-drd3-port-hs@03100000: AppleUSB20XHCITypeCPort::cableChangeOccurred: cable connected, powering on

Next the physical layer of Thunderbolt is turned on, and reported
1.159502 AppleThunderboltNHI 2691438900us AppleThunderboltNHIType5(3)::setPhyState - PHY is on
1.159507 AppleThunderboltNHI 2691438900us AppleThunderboltNHIType5(3)::setPhyState - PHY is on

The Thunderbolt PCI downstream and upstream paths are activated and their bandwidth checked
2.884983 AppleThunderboltPCIUpAdapter 2693164380us Thunderbolt PCI - activating downstream path - SRC [3:0x0:0x3] DST [3:0x1:0x8] - req_bandwidth = 1
2.885015 AppleThunderboltPCIUpAdapter 2693164380us Thunderbolt PCI - activating downstream path - SRC [3:0x0:0x3] DST [3:0x1:0x8] - req_bandwidth = 1
2.885027 AppleThunderboltPCIUpAdapter 2693164424us Thunderbolt PCI - activating upstream path - SRC [3:0x1:0x8] DST [3:0x0:0x3] - req_bandwidth = 1
2.885032 AppleThunderboltPCIUpAdapter 2693164424us Thunderbolt PCI - activating upstream path - SRC [3:0x1:0x8] DST [3:0x0:0x3] - req_bandwidth = 1

where SRC is source, and DST is destination.

It takes another couple of seconds of intense entries from diskarbitrationd before APFS springs into action. This starts with a declaration of the number and size of buffers to be used, following which I’ll concentrate on the APFS volume disk5s1, and its container disk4s2
4.994774 apfs cryptoAlloc:650: Using 64 buffers with size 16384, 512 buffers size 65536

Disks are created by diskarbitrationd, then APFS starts its probe
4.999629 diskarbitrationd created disk, id = /dev/disk4.
5.003346 diskarbitrationd created disk, id = /dev/disk4s2.
5.016652 apfs nx_checkpoint_find_valid_checkpoint:556: disk4s2 probe of external device... skipping recent sanity checks.
5.016657 apfs nx_checkpoint_find_valid_checkpoint:560: disk4s2 Marking container for reconciliation.
5.016661 apfs nx_mount:1548: disk4s2 checkpoint search: largest xid 278107, best xid 278107 @ 170
5.016672 apfs nx_mount:1575: disk4s2 stable checkpoint indices: desc 169 data 10214

Successful NVMe initialisation follows
5.019666 IONVMeFamily virtual bool IONVMeController::start(IOService *)::849:Successfully initialized NVMe drive

diskarbitrationd continues creating the required disks, then probes them, including a check with fsck
5.020040 diskarbitrationd created disk, id = /dev/disk5.
5.020881 diskarbitrationd created disk, id = /dev/disk5s1.
5.028795 diskarbitrationd probed disk, id = /dev/disk5s1, with apfs, ongoing.
5.057195 diskarbitrationd fsck status 0 /dev/rdisk5s1
5.057636 diskarbitrationd probed disk, id = /dev/disk5s1, with apfs, success.

APFS then starts work with the container
5.074789 apfs dev_init:296: disk5 device accelerated crypto: 0 (compiled @ Feb 8 2023 20:39:28)
5.074796 apfs dev_init:299: disk5 device_handle block size 4096 block count 937633356 features 16 external solidstate
5.074957 apfs nx_mount:1219: disk5 initializing cache w/hash_size 8192 and cache size 32768
5.278753 apfs nx_mount:1548: disk5 checkpoint search: largest xid 278107, best xid 278107 @ 170
5.278775 apfs nx_mount:1575: disk5 stable checkpoint indices: desc 169 data 10214
5.278789 apfs spaceman_metazone_init:171: disk5 metazone for device 0 of size 8111692 blocks (encrypted: 0-4055846 unencrypted: 4055846-8111692)
5.278791 apfs spaceman_datazone_init:600: disk5 allocation zone on dev 0 for allocations of 1 blocks starting at paddr 112132096

(spaceman is the APFS Space Manager.)

Finally, APFS turns its attention to the volume, first checking whether there’s anything to recover in it
5.279334 apfs er_state_obj_get_for_recovery:7575: disk5s1 No ER state object for volume OWCenvoyPro4tb - rolling is not happening, nothing to recover.

Then the volume is mounted, and that’s declared successful by diskarbitrationd
5.279340 apfs apfs_log_mount_unmount:1980: disk5s1 mounting volume OWCenvoyPro4tb, requested by: mount_apfs (pid 2448); parent: mount (pid 2446)
5.279439 apfs handle_mount:725: disk5s1 vol-uuid: A15DC1BA-6195-4154-BD39-7090A4ED04DC block size: 4096 block count: 937633356 (unencrypted; flags: 0x1; features: 1.0.2)
5.280672 apfs handle_mount:738: disk5s1 setting dev block size to 4096 from 512
5.280677 apfs nx_volume_group_update:7895: disk5s1 Volume OWCenvoyPro4tb role 0 Not a System or data volume
5.281551 diskarbitrationd mounted disk, id = /dev/disk5s1, success.

At the end of this, if you have the time to wait for it, there’s a crock of pure gold. First, APFS reports the result of scanning free blocks using Space Manager without performing any trimming
5.415022 apfs spaceman_scan_free_blocks:3311: disk5 scan took 0.136184 s (no trims)

Then Space Manager spends nearly 4.5 seconds trimming the single APFS container on the external SSD
10.020991 apfs spaceman_scan_free_blocks:3293: disk5 scan took 4.605944 s, trims took 4.418881 s
10.021030 apfs spaceman_scan_free_blocks:3295: disk5 825947426 blocks free in 209547 extents
10.021042 apfs spaceman_scan_free_blocks:3303: disk5 825947426 blocks trimmed in 209547 extents (21 us/trim, 47420 trims/s)
10.021054 apfs spaceman_scan_free_blocks:3306: disk5 trim distribution 1:124790 2+:24695 4+:29277 16+:16527 64+:12303 256+:1955

Mounting this Thunderbolt 3 SSD thus took a little over 5 seconds, with an additional 4.5 seconds trimming it afterwards. If you’re not sure whether an external SSD is being trimmed properly, this seems a good way to find out.

If you want to follow this in the comfort of your own Mac, I suggest two useful predicates:
senderImagePath contains "IOAccessoryManager"
to view the hardware initialisation steps at the start, and
senderImagePath contains "apfs" || subsystem == ""
for the mounting and trimming at the end.

I will add these as a log package to the next version of Mints, to make them more generally accessible without having to use predicates in Ulbow.