Note: the original version of this article relied heavily on information which hasn’t proved helpful after all. As a result, many of its interpretations appear to have been incorrect, or equally misleading. I pride myself in providing accurate and reliable information, and have therefore rewritten it without such reliance. I apologise unreservedly for my previous errors, and will try to provide increasingly detailed and accurate accounts of this as I get more reliable information in the future.
This account confines itself to the checks which are performed once the XNU kernel has loaded, after the phase conventionally known (inaccurately) as ‘firmware’.
On an M1 Pro Mac which started to boot at around 00 to 01 seconds on the system clock, the first 7-8 seconds of that process is omitted from the log, and consists of the Boot ROM, LLB and iBoot phases. The first log entries from the kernel are
08.289794 === system boot: [UUID]
13.742101 kprintf initialized
with a further gap of more than 5 seconds between them, during which there’s further unrecorded activity. What’s then announced comes from the kernel:
13.742296 Darwin Kernel Version 21.2.0: Sun Nov 28 20:28:41 PST 2021; root:xnu-8019.61.5~1/RELEASE_ARM64_T6000
13.818102 iBoot version: iBoot-7429.61.2
To be able to access LocalPolicy, the kernel needs to load its validation tool for Image4 files, which is does next
13.989331 Darwin Image4 Validator Version 4.2.0: Tue Nov 30 21:45:44 PST 2021; root:AppleImage4-157.60.2~361/AppleImage4/RELEASE_ARM64E
After that, security policy is loaded:
13.989783 AppleMobileFileIntegrity AMFI: UDID enforcement enabled
13.989801 calling mpo_policy_init for AMFI
13.989810 Security policy loaded: Apple Mobile File Integrity (AMFI)
13.989817 calling mpo_policy_init for Sandbox
13.989905 Security policy loaded: Seatbelt sandbox policy (Sandbox)
13.989966 calling mpo_policy_init for Quarantine
13.989970 Security policy loaded: Quarantine policy (Quarantine)
Next comes starting the Secure Enclave key store:
14.065805 AppleSEPKeyStore:319:0: starting (BUILT: Nov 30 2021 21:31:02)
During this period, other parts of the chip are starting up and initialising. There are often copious log entries from each as it does.
So far, all this has been run on a single core. It’s now time to start all the others, which is performed by a series of calls to
cpu_start, beginning with the first E processor
14.568080 ml_processor_register>cpu_id 0x0 cluster_id 0 cpu_number 0 is type 1
14.568126 cpu_start() cpu: 0
That’s repeated until all ten cores are up and running. On the M1 Pro/Max, these are listed in three clusters:
- cluster 0 contains the two E cores, type 1, numbers 0 and 1;
- cluster 1 contains the first four P cores, type 2, numbers 2-5;
- cluster 2 contains the remaining four P cores, type 2, numbers 6-9.
The original M1 chip has just two clusters:
- cluster 0 contains the four E cores, type 1, numbers 0-3;
- cluster 1 contains the four P cores, type 2, numbers 4-7.
Gatekeeper is then enabled
14.644687 AppleSystemPolicy GK status: enabled
14.644688 AppleSystemPolicy Per file changetime scans: enabled
The kernel is now ready to access disk storage, so loads the APFS file system
14.779543 apfs apfs_module_start:2568: load: com.apple.filesystems.apfs, v1933.61.1, apfs-1933.61.1, 2021/11/30
The next task is to locate the boot volume, ready to mount its snapshot
14.827815 AppleFileSystemDriver AppleFileSystemDriver: publishing boot-uuid-media=disk3s1 (Macintosh HD)
14.828281 Got boot device = IOService:/AppleARMPE/arm-io/AppleT600xIO/ans@8F400000/AppleASCWrapV4/iop-ans-nub/RTBuddyV2/RTBuddyService/AppleANS3NVMeController/NS_01@1/IOBlockStorageDriver/APPLE SSD AP2048R Media/IOGUIDPartitionScheme/Container@2/AppleAPFSContainerScheme/AppleAPFSMedia/AppleAPFSContainer/Macintosh HD@1
followed by the longstanding announcement of the BSD root
14.828295 BSD root: disk3s1
14.828300 , major 1, minor 13
Only now, nearly 15 seconds after its start, does the Mac get to root from the boot snapshot
14.898802 apfs apfs_vfsop_mount:2118: disk3 Promoter has been locked
14.899252 apfs apfs_vfsop_mount:2188: disk3s1 Rooting from snapshot with xid 183952.
14.899261 apfs apfs_log_mount_unmount:1828: disk3s1 mounting volume Macintosh HD, requested by: kernel_task (pid 0); parent: kernel_task (pid 0)
14.899386 apfs handle_snapshot_mount:885: disk3s1 mounting snapshot w/snap_xid 183952 and sblock oid 0x23263e
The first task with that snapshot is to validate its seal
14.901008 apfs is_root_hash_authentication_required_osx:369: disk3s1 Release kext with internal build: 0, ARV disabled: 0, booting xid: 0
14.901013 apfs is_root_hash_authentication_required:478: disk3s1 root volume, root hash authentication is required
14.901018 apfs authenticate_root_hash:546: disk3s1 successfully validated on-disk root hash
Next comes the Recovery volume within that boot container
14.910181 trying to find and mount BaseSystem dmg as root volume
14.910188 attempting kernel mount for recovery volume...
14.915623 apfs er_state_obj_get_for_recovery:6381: disk3s3 No ER state object for volume Recovery - rolling is not happening, nothing to recover.
14.915679 apfs handle_mount:654: disk3s3 vol-uuid: 4CDE4B2A-F463-49AA-AC77-D4DD774F4832 block size: 4096 block count: 487113810 (unencrypted; flags: 0x1; features: 1.0.2)
14.916518 apfs handle_mount:667: disk3s3 setting dev block size to 4096 from 512
14.916525 apfs nx_volume_group_update:7709: disk3s3 Volume Recovery role 4 Not a System or data volume
14.916803 mounted recovery volume
Other volumes mounted include VM, Preboot and Update
15.095112 apfs apfs_log_mount_unmount:1828: disk3s6 mounting volume VM, requested by: apfs_boot_util (pid 2); parent: launchd (pid 1)
15.097235 apfs apfs_log_mount_unmount:1828: disk3s2 mounting volume Preboot, requested by: apfs_boot_util (pid 2); parent: launchd (pid 1)
15.102171 apfs apfs_log_mount_unmount:1828: disk3s4 mounting volume Update, requested by: apfs_boot_util (pid 2); parent: launchd (pid 1)
Additionally, volumes in the Apple_APFS_ISC container are mounted as required
15.122871 apfs apfs_log_mount_unmount:1828: disk1s2 mounting volume xART, requested by: apfs_boot_util (pid 2); parent: launchd (pid 1)
15.125391 apfs apfs_log_mount_unmount:1828: disk1s1 mounting volume iSCPreboot, requested by: apfs_boot_util (pid 2); parent: launchd (pid 1)
15.128037 apfs apfs_log_mount_unmount:1828: disk1s3 mounting volume Hardware, requested by: apfs_boot_util (pid 2); parent: launchd (pid 1)
The end of the kernel-run phase comes almost 20 seconds after the start. From then on, processes other than the kernel fill much of the log. The first of these loads the Wi-Fi firmware
19.928393 wifiFirmwareLoader wifiFirmwareLoader Sandboxing init issue, couldn't find profile in default paths, attempting default compiled profile
Immediately after that, the system clock is adjusted, and there’s a hiatus when that occurs, here setting the clock back by 3.3 seconds
13.614115 === system wallclock time adjusted
The next task is to validate the Boot Kernel Collection and any auxiliary collection, using
13.642280 kernelmanagerd Starting userland kernel management subsystem (KernelManagement_executables-262.60.4)
14.121399 kernelmanagerd Disabling kext auditing: We are on Apple Silicon
14.137320 kernelmanagerd Initializing with settings:
14.139417 kernelmanagerd finding bundles in repositories:
kernelmanagerd then validates each of the Boot Kernel Collection with a log entry such as
14.164688 kernelmanagerd validating extension at /System/Library/DriverExtensions/com.apple.DriverKit-AppleUSBFTDI.dext
and many more.
Once that’s ready to load as a collection, that’s reported
14.207370 kernelmanagerd Preparing collection load into kernel
Each is acknowledged as it is loaded
14.316533 kernelmanagerd Received kext load notification: com.apple.kpi.bsd
and many more
kernelmanagerd has finished, the kernel shuts it down, and no more kernel extensions can be loaded
29.313999 Kext loading now disabled.
29.314006 Kext unloading now disabled.
29.314009 Kext autounloading now disabled.
29.314011 Kernel requests now disabled.
29.314448 kernelmanagerd Kernel requested shutdown. Goodbye!
macOS is now fully loaded and running at last, almost 30 seconds after the start.