Time Machine 16: Reading a normal backup in Catalina using Mints

Normally, if you’re having problems with Time Machine backups my free utility T2M2 will provide sufficient information to make a diagnosis and work out how to fix it. When it doesn’t, or you just need to look at bit deeper, the new Time Machine log window in Mints should prove far easier to use than Ulbow, or Consolation. This article takes you through what you should see when you use Mints in Catalina.

Mints makes this as simple as possible: click on the Time Machine Log Window button to open a new window. At the top, set the Period to -1 hour from the current time, which has been set for you when the window opened. Then click on the Get log button.

tmmints01

After a few moments, the log view will fill with mainly grey entries. If you like, you can hide those by unticking the Other item in the second row. You may find those Other log entries contain valuable clues when a backup doesn’t work out right, but for error-free backups they only clutter with distracting detail.

After a long preamble of entries in grey, the backup sequence starts with DAS in blue:
DuetAS '0:com.apple.backupd-auto:DB230F' CurrentScore: 0.901436, ThresholdScore: 0.758907 DecisionToRun:1
this hands over to CTS-XPC in green:
CTS-XPC DAS told us to run com.apple.backupd-auto
which in turn changes the TMPowerState to 2 (in red):
TimeMach TMPowerState: 2
this exchange may repeat, before you see the start of the backup in red:
TimeMach Starting automatic backup

tmmints02

TM first looks for sparsebundles for the host UUIDs or MAC address, and confirms the mountpoint of the backup destination:
TimeMach Mountpoint '/Volumes/ThunderBay2HFS'is still valid
then announces the start of the backup
TimeMach Backing up to ThunderBay2HFS (/dev/disk1s2): /Volumes/ThunderBay2HFS
this gives the volume containing the backup store, first using device format as disk1s2, then its mountpoint.

The first part of the sequence is to perform age-based thinning of snapshots, with entries like
TimeMach Starting age based thinning of Time Machine local snapshots on disk '/System/Volumes/Data'

Once completed, the stable snapshot is made and mounted, and the reference snapshot is mounted:
TimeMach Created Time Machine local snapshot with name 'com.apple.TimeMachine.2020-07-15-154511.local' on disk '/Volumes/External1'
TimeMach Declared stable snapshot: com.apple.TimeMachine.2020-07-15-154511.local
TimeMach Mounted stable snapshot: com.apple.TimeMachine.2020-07-15-154511.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac Pro/2020-07-15-154511/External1 source: External1
TimeMach Mounted reference snapshot: com.apple.TimeMachine.2020-07-15-144512.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac Pro/2020-07-15-144512/External1 source: External1

For each volume to be backed up, TM decides on a strategy. Here’s the normal approach for a data volume:
TimeMach Possible strategies for "External1" (device: /dev/disk12s1 mount: '/Volumes/External1' fsUUID: 0BE9EA2C-8D68-4E79-A394-2AC11449A79A eventDBUUID: 2614919D-E7BC-4147-941F-33E6A8B2B311) (<EventMarker 2020-07-15 13:45:16 +0000 7162257446477253288 2614919D-E7BC-4147-941F-33E6A8B2B311 549134>): first backup, deep scan, FSEvents, snapshot diffing,
TimeMach Using FSEvents for source: "External1" (device: /dev/disk12s1 mount: '/Volumes/External1' fsUUID: 0BE9EA2C-8D68-4E79-A394-2AC11449A79A eventDBUUID: 2614919D-E7BC-4147-941F-33E6A8B2B311)

which is followed by details of building the list of items to be backed up.

For the Recovery volume, a deep scan is performed:
TimeMach Possible strategies for "Recovery" (device: /dev/disk5s3 mount: '/Volumes/Recovery' fsUUID: 7BAC426A-65E5-40AD-910D-493C2147870D eventDBUUID: (null)) (<EventMarker 2020-07-15 13:45:17 +0000 0 (null) 0>): first backup, deep scan,
TimeMach Deep scan required for source: "Recovery" (device: /dev/disk5s3 mount: '/Volumes/Recovery' fsUUID: 7BAC426A-65E5-40AD-910D-493C2147870D eventDBUUID: (null))

This is perfectly normal – this isn’t what used to be a ‘deep traversal scan’ when there were problems working out what needed to be backed up.

Then the items to be backed up are copied across, in this case next to nothing.
TimeMach Copied 1 items (Zero KB) from volume External1. Linked 4. Moved 0
TimeMach Found 0 perfect clone families, 0 partial clone families. Shared space Zero KB (0 bytes).
TimeMach Saved clone family cache for 'External1' at /Volumes/ThunderBay2HFS/Backups.backupdb/Howard’s iMac Pro/2020-07-15-154512.inProgress/CDEAC764-E352-47D1-848B-9AEDE8C3C376/.0BE9EA2C-8D68-4E79-A394-2AC11449A79A.clonedb

after which the snapshots are unmounted
TimeMach Unmounted local snapshot: com.apple.TimeMachine.2020-07-15-154511.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac Pro/2020-07-15-154511/External1 source: External1
TimeMach Unmounted local snapshot: com.apple.TimeMachine.2020-07-15-144512.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac Pro/2020-07-15-144512/External1 source: External1

The latest snapshot is then marked as the reference, and the backup itself is complete.
TimeMach Marked as reference snapshot: com.apple.TimeMachine.2020-07-15-154511.local
TimeMach Completed backup: 2020-07-15-154512

Finally, old backups are thinned:
TimeMach Thinning 2 backups using age-based thinning, expected free space: 1.81 TB actual free space: 1.81 TB trigger 100 GB thin 166.67 GB dates: (
"2020-07-14-144716",
"2020-07-15-134546"
)

and the whole backup is declared successful
TimeMach Backup completed successfully.

tmmints03

You’ll next see DAS rescoring the activities it’s scheduling
DuetAS Rescoring all 174 activities [<private>]
until the whole cycle starts again.

This sequence is summarised in the following diagram, for Catalina:

TMbackup1015full

In El Capitan and Sierra, this was far simpler:

TMbackupHFS

I hope that Mints makes it much easier to see how this works, and where any problems arise.