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 == "com.apple.DiskArbitration.diskarbitrationd"
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.

8Comments

Add yours

1

Walt on March 24, 2023 at 8:20 am

Thanks for another interesting article Howard. I would be more interested in why macOS versions starting with Big Sur take tens of seconds (~15-17) to unmount an external disk compared to macOS Catalina where the time was almost immediate and seemed not more than a few seconds.

LikeLiked by 1 person
- 2
  
  Duncan on March 24, 2023 at 11:01 am
  
  I have an older Mac running 10.9 (Mavericks) for non-critical tasks, with a Thunderbolt-2 SATA drive dock attached. When I insert a 2.5″ SSD it mounts almost instantaneously, and unmounts almost as quickly. I’d love to see that kind of responsiveness with my current desktop Mac running Monterey.
  
  But then, reading this article, I understand how newer versions of MacOS are performing far more housekeeping tasks than the old Mavericks machine. It’s unfortunate from a user’s standpoint that newer machines, while more sophisticated and capable, can’t maintain all the ‘snappiness’ of the older ones, considering the concomitant advances of technology, but I guess that’s the price of (some elements of) progress.
  
  (I’d also love to see the engine compartments in cars as uncluttered as pre-1970s models, but nostalgia glosses over how unsafe those cars were relative to today’s cocoons and how many creature comforts they lacked.)
  
  LikeLiked by 1 person
  - 3
    
    hoakley on March 24, 2023 at 6:32 pm
    
    Thank you. Yes, there are trade-offs. Trim is an issue I will try unsuccessfully to address here tomorrow morning.
    Howard.
    
    LikeLike
- 4
  
  hoakley on March 24, 2023 at 6:28 pm
  
  Thank you.
  That’s not my experience with an external SSD with a single general-purpose APFS volume.
  Is your disk a Time Machine backup, or an external bootable disk? SSD or hard disk?
  Howard.
  
  LikeLike
5

nuxnix on March 24, 2023 at 8:49 am

I have noticed my Time Machine drive takes a very long time – several tens of seconds – to become visible after a restart. Will now investigate. Thanks for the article.

And cd/dvd/Blu-ray via external drives is another area where I find myself having to disconnect the external drive completely before the mounting of these removable media works. Once one works I can eject and load another just fine but ifone fails no subsequent cd/dvd/Blu-ray will work without physical disconnection

LikeLiked by 1 person
- 6
  
  hoakley on March 24, 2023 at 6:31 pm
  
  If it’s an APFS Time Machine backup store, then it may well be unmounting its snapshots, particularly if the disk has many backups stored on it.
  Is the optical drive you’re using a recent model? I’ve been using a couple of Blu-ray burners here, and haven’t seen that problem, but those are recent models.
  Howard.
  
  LikeLike
7

Bill Smith on March 24, 2023 at 11:59 am

This, opposed to a similar Reddit discussion on the same topic; “My stupid disk takes forever on my M1/M2, Apple better fix broke dick Ventura.”

LikeLiked by 1 person
- 8
  
  hoakley on March 24, 2023 at 6:32 pm
  
  Thank you.
  Howard.
  
  LikeLike

Share this:

Like this:

Related