Two common events which you will see in your logs are waking up from sleep, and making a backup using Time Machine. These are useful landmarks in your logs, and important events which need to run correctly, making them worth understanding.

Waking up

Problems and crashes which occur when waking the system up from sleep can be impossible to diagnose and fix without using the logs. Although you will see additional messages, these are the key stages which you are likely to encounter.

07/07/2016 11:46:42.000 kernel[0]: STEX : setPowerState : 0, (0 = sleep , 1 = pause, 2 = wake)
07/07/2016 11:46:42.000 kernel[0]: STEX : Going to sleep, outstanding IO = 0
07/07/2016 11:46:42.000 kernel[0]: STEX : setPowerState done
Oddly the first events logged when you start waking your Mac up are usually those indicating that it is going back to sleep.

07/07/2016 10:44:16.000 kernel[0]: AppleThunderboltNHIType2::waitForOk2Go2Sx - intel_rp = 1 dlla_reporting_supported = 1
07/07/2016 11:46:42.000 kernel[0]: AppleThunderboltNHIType2::waitForOk2Go2Sx - retries = 30000
Those are normally followed by a couple of odd reports from the Thunderbolt subsystem. Note that the first is out of time sequence: this should not happen, but now appears quite normal.

07/07/2016 11:46:42.000 kernel[0]: Wake reason: XHC1
07/07/2016 11:46:42.000 kernel[0]: Previous sleep cause: 5
07/07/2016 11:46:42.000 syslogd[60]: ASL Sender Statistics
07/07/2016 11:46:42.000 kernel[0]: AppleThunderboltNHIType2::prePCIWake - power up complete - took 2 us
07/07/2016 11:46:42.000 kernel[0]: ARPT: 40601.606994: wl0: leaveModulePoweredForOffloads: Wi-Fi will stay on.
07/07/2016 11:46:42.000 kernel[0]: ARPT: 40601.607012: AirPort_Brcm43xx::syncPowerState: WWEN[disabled]
This is the start of the wake-up sequence proper, giving the cause for the sleep, then preparing communications links.

07/07/2016 11:46:42.000 kernel[0]: AppleThunderboltGenericHAL::earlyWake - complete - took 809 milliseconds
07/07/2016 11:46:42.000 kernel[0]: STEX : setPowerState : 2, (0 = sleep , 1 = pause, 2 = wake)
07/07/2016 11:46:42.000 kernel[0]: STEX : Power on device
07/07/2016 11:46:42.000 kernel[0]: STEX : Machine Model : iMac17,1
07/07/2016 11:46:42.000 kernel[0]: STEX : fw is READY to do handshake
07/07/2016 11:46:42.000 kernel[0]: STEX : Sending Host Model Name : iMac17,1
07/07/2016 11:46:42.000 kernel[0]: STEX : Sending Host Build Version : 15F34
07/07/2016 11:46:42.000 kernel[0]: [ PCI configuration begin ]
07/07/2016 11:46:42.000 kernel[0]: [ PCI configuration end, bridges 16, devices 17 ]
07/07/2016 11:46:43.000 kernel[0]: [IOBluetoothHCIController][WakeUpDisplay] -- took 1048849 microseconds to call activityTickle()
07/07/2016 11:46:43.000 kernel[0]: full wake promotion (reason 1) 1050 ms
07/07/2016 11:46:43.051 CommCenter[335]: Telling CSI to exit low power.
07/07/2016 11:46:43.000 kernel[0]: STEX : scatch Data = 0
The Power State is now set to be ‘wake’, and the Mac is fully powered up again.

07/07/2016 11:46:43.000 kernel[0]: Ethernet [AppleBCM5701Ethernet]: Link up on en0, 100-Megabit, Full-duplex, Symmetric flow-control, Debug [796d,2301,0de1,0300,45e1,0000]
07/07/2016 11:46:46.409 ntpd[244]: wake time set +2.234229 s
This is the Ethernet network connection being restored. These settings should match those attained at the last startup.

07/07/2016 11:46:55.000 kernel[0]: STEX : handshake with FW successfully, Device#1
07/07/2016 11:46:55.000 kernel[0]: STEX : setPowerState done
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40612.719489: AirPort_Brcm43xx::powerChange: System Wake - Full Wake/ Dark Wake / Maintenance wake
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220074: IOPMPowerSource Information: onWake, SleepType: Normal Sleep,
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220122: AirPort_Brcm43xx::platformWoWEnable: WWEN[disable]
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220776: ChangeVCO => vco:960, xtalF:40, frac: 98, ndivMode: 3, ndivint: 24
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220780: Data written into the PLL_CNTRL_ADDR2: 00000c31
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220816: Data written into the PLL_CNTRL_ADDR3 (Fractional): 0000100e
07/07/2016 11:46:56.000 kernel[0]: [HID] [ATC] AppleDeviceManagementHIDEventService::processWakeReason Wake reason: Button (0x03)
07/07/2016 11:46:56.000 kernel[0]: [HID] [ATC] AppleDeviceManagementHIDEventService::processWakeReason Wake reason: Host (0x01)
07/07/2016 11:46:56.000 kernel[0]: ARPT: 40613.613462: AirPort_Brcm43xx::syncPowerState: WWEN[disabled]
07/07/2016 11:46:56.000 kernel[0]: PM response took 394 ms (73, powerd)
07/07/2016 11:46:56.257 sharingd[356]: 11:46:56.256 : Starting AirDrop server for user 501 on wake
All remaining subsystems are woken up and ready for use. Your logs should resume normal entries.

You may also see custom processes being launched by launchd. In this vanilla configuration of El Capitan 10.11.5, there are no such customisations. If yours does launch additional processes, then you will need to check those for errors, which could (and often are) be the cause of your problems.

Time Machine backup

When awake and connected to the backup store, this should occur every hour. If you are using your Mac at the time, these log entries may become interspersed with messages relating to your other activities, but you can normally recognise this sequence as it happens in the background.

07/07/2016 07:47:17.053 com.apple.backupd[7985]: Starting automatic backup
07/07/2016 07:47:17.268 com.apple.backupd[7985]: Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
07/07/2016 07:47:18.834 com.apple.backupd[7985]: Will copy (304.1 MB) from Macintosh HD
07/07/2016 07:47:18.834 com.apple.backupd[7985]: Found 239 files (304.1 MB) needing backup
07/07/2016 07:47:18.863 com.apple.backupd[7985]: 14.63 GB required (including padding), 3.23 TB available
Time Machine’s backupd process announces that it is starting a timed backup, which volume it is going to back up to, then works out what needs to be backed up. It gives details of the number of files and space required to do this, and tells you how much free space remains on the backup volume before the backup is made.

07/07/2016 07:51:01.273 com.apple.backupd[7985]: Copied 360 items (304 MB) from volume Macintosh HD. Linked 9332.
07/07/2016 07:51:08.237 com.apple.backupd[7985]: Created new backup: 2016-07-07-075106
Once the backup is complete, it reports what it did actually back up, and tells you the name of that backup. The backup consists of a combination of new files, here 360 in all, and links from existing files, here over nine thousand. These should be similar to the number it first identified, but may not be exactly the same. This also tells you which volume the files were copied from. The time of creation of the new backup given here, less the starting time above, tells you how long the backup took – in this case, less than 4 minutes in all.

07/07/2016 07:51:09.000 kernel[0]: hfs: mounted Recovery HD on device disk0s3
07/07/2016 07:51:09.957 mds[83]: (Volume.Normal:2464) volume:0x7fc7ca8bf000 ********** Bootstrapped Creating a default store:0 SpotLoc:(null) SpotVerLoc:(null) occlude:0 /Volumes/Recovery HD
07/07/2016 07:51:10.004 fseventsd[65]: Logging disabled completely for device:1: /Volumes/Recovery HD
The Recovery partition is then mounted.

07/07/2016 07:51:10.048 com.apple.backupd[7985]: Starting post-backup thinning
07/07/2016 07:51:10.000 kernel[0]: hfs: unmount initiated on Recovery HD on device disk0s3
07/07/2016 07:54:15.363 com.apple.backupd[7985]: Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2016-07-06-065322 (27.1 MB)
07/07/2016 07:54:15.363 com.apple.backupd[7985]: Post-backup thinning complete: 1 expired backups removed
backupd then performs housekeeping on the backups, removing any expired backups to reclaim space. The Recovery partition is also unmounted again.

07/07/2016 07:54:19.280 com.apple.backupd[7985]: Backup completed successfully.
Successful completion occurred.

So reading logs is not as daunting as you might think, is it?