Log messages during normal macOS startup have changed recently. If you try using any previous guides to the logs with Sierra 10.12.5, you will struggle to find your way around them. This article provides the latest information available, so that you can use a log browsing tool such as my free Consolation (from Downloads above) to tackle startup and related problems.
Make a logarchive
The best way to investigate any startup is to make a logarchive covering the last thirty seconds or so prior to previous shutdown (especially if this was a restart), and the first couple of minutes after the startup itself.
Although logarchive format is currently proprietary, and consists of a bundle within which are large numbers of nested folders, Consolation 2.2, Console, and Terminal’s log
command all work with logarchives. They preserve all log entries indefinitely, and are much better than trying to work with a live system log.
Leave your Mac for a couple of minutes after startup, then open Consolation 2.2, set a Period of, say, 3 or 4 minutes – long enough to capture the whole startup, then click on the Write logarchive button to create and save the logarchive to disk.
Finding the startup time
Prior to Sierra 10.12.4 or 10.12.5, the first entry in the log contained the banner text BOOT_TIME
. If you try searching the logs in 10.12.5 for that, you will be disappointed: it has gone. Instead, you will see the last entry prior to the previous shutdown, typically
=== system wallclock time adjusted
then at least ten seconds later, the new startup banner
=== system boot:
followed by the UUID of the startup event.
Use the time of that banner as the start time for subsequent log searches.
Early hardware and kernel phase
Following the banner, you will see a succession of messages from the kernel, including
PMAP: PCID enabled
PMAP: Supervisor Mode Execute Protection enabled
PMAP: Supervisor Mode Access Protection enabled
then a statement of the kernel version:
Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64
Then follows a series of messages about AppleACPIPlatform
.
Available processor cores will then be enabled, followed by security policies. Networking initialisation starts, and if you have a Fusion Drive you should see messages about CoreStorage, such as
(CoreStorage) Composite Disk alg="bloomclock" unit_nbytes=131072
After that, traditional BSD disk messages appear, such as:
BSD root: disk2
, major 1, minor 8
Your startup volume will then have its HFS+ filesystem mounted:
(HFS) hfs: mounted Macintosh HD on device b(1, 8)
Messages from processes other than the kernel now start appearing. These clean out temporary items, and start up security systems next. The clock is then adjusted again:
=== system wallclock time adjusted
and that may be repeated shortly afterwards.
Main startup phase
Just over two seconds after startup, in-memory log records start, being announced with
=== log class: in-memory begins
configd
then creates a series of activities, and loads system configurations for InterfaceNamer, ISPreference, ApplicationFirewall, KernelEventMonitor, LinkConfiguration, PreferencesMonitor, EAPOLController, IPConfiguration, CaptiveNetworkSupport, IPMonitor, PPPController, and com.apple.print.notification. The wired Ethernet port is then named in BSD style as en0.
macOS then checks to see if this startup follows a kernel panic, and left a panic dump. This should be accomplished over three messages, such as
Attempting to extract kernel core if it exists
Path /private/var/tmp/kernel_panics/ exists, next check permissions
HandleKernelCore(): SadMac partition not found
Many of the messages during this phase come from Open Directory, and some from securityd
. These are followed by a heavy burden of mDNSResponder messages, and later DNS configuration. The kernel returns, working through its list of items in input/output using IOHIDFamily. It reappears later too, to configure the GPU.
After more than four seconds, CoreAudio features are started up. Kernel extensions, LaunchAgents and LaunchDaemons are also being run up throughout this phase of startup. Most will result in at least one log message, such as
(com.bombich.ccchelper) Created Activity ID: 0x8000000000000368, Description: SecTrustEvaluateIfNecessary
Unfortunately many of the kernel extensions are not individually identified in messages:
(kextd) Created Activity ID: 0x8000000000000433, Description: SecTrustEvaluateIfNecessary
for example.
coreduetd
then performs its Admission Checks, which work out energy budgets using Joules, and creates entries in its pooltable.
Various Bluetooth initialisations have been made by this stage, nearly five seconds after startup, and one important log entry lists all paired devices, starting with
hostControllerOnline - Number of Paired devices = 7, List of Paired devices = (
Centralized Task Scheduling (CTS) appears just over 5 seconds after startup, with initial messages of
User Active
FullWake:cpu disk net aud vid
resuming activities on transition
Time Change: Registered for time change notifications
after which XPC Activities begin.
CTS then loads the Duet Activity Scheduler (DAS) with activities for it to dispatch. I will examine those in a later article.
While activities are being loaded up, Bluetooth Wireless Proximity starts up its daemon, announced by
STARTED WIPROX DAEMON
Once all the DAS activities are loaded up by CTS, the DAS daemon starts with the announcement
_DASDaemon started
following which all its activities are scored, and it starts dispatching them to CTS to be run.
The local Ethernet link is finally brought up nearly 7 seconds after startup, with a duplicated announcement of
Link up on en0, 100-Megabit, Full-duplex, Symmetric flow-control, Debug [796d,0301,0de1,0300,45e1,0000]
There are many audio and IP configuration entries which follow. Eventually, the Network Time Protocol daemon appears with
ntpd 4.2.8p6@1.3265 Fri Feb 5 17:38:17 UTC 2016 (124.60.2~6): Starting
More than 14 seconds after startup, the display is detected and configured, and WindowServer starts to prepare the login window.
With tens of thousands of entries being made in Sierra’s unified log in the first few minutes after starting up, navigating them can be difficult. The waypoints given above should help you, although you will also need to use specific search predicates if you are not going to be overwhelmed with irrelevant information.