I’m concerned that Time Machine is taking so long to back up my laptop to my file server, that it may be the sign of a problem with my file server. The first step in investigating a problem like this is to get data. I think I have found a way to get useful log data about Time Machine backups, using the log show command or the Consolation3 application. I’d like to share how I do it.

My Mac laptop runs macOS 10.13 High Sierra. I back it up using Time Machine to two destinations: a hard drive connected directly, and to a file server via my home network. (The file server runs the FreeNAS OS and has a ZFS filesystem, but those details are not germane to getting log data.) Time Machine starts a backup every hour or so, and it alternates destinations each time. Obviously, backups are faster if not much has changed on the origin laptop, and are slower if a lot has changed. But setting that aside, I could clearly observe that backups to the hard drive finished in a few minutes, while backups to the file server seemed to take several hours.

In past versions of macOS, I would look in the macOS Console application . But the behaviour of Console was different in macOS High Sierra than in previous macOS versions. The search patterns I used before didn’t work here.

Some we searching brought me to a lovely utility, The Time Machine Mechanic, T2M2 for short, at the Eclectic Light Company. This utility reads the macOS log messages which Time Machine writes as it goes, and comes up with a simple summary of whether Time Machine is working well or having problems.

T2M2 worked for me some of the time, but often it failed with an “error 65”. I traced this to a problem with “metadata” in the log system on my mac. I wrote about this an an earlier blog, Resolving “log archive metadata is missing” and “error number 65”. T2M2 didn’t have the capability of working around this problem.

So I turned to T2M2’s big sister, Consolation3. Consolation3 reads the same log messages from Time Machine, but leaves them a bit more visible in their complexity. This is what Consolation3’s main window looks like, when showing a day’s worth of Time Machine log messages. (I have redacted some of my system names with grey rectangles; those details don’t matter here.)

This let me get past the “error number 65” problem with the log metadata. The trick is to set the Period value to 0, and set a useful Start date and time, and an End date and time which is in the future. (You might also want to set End to some fixed time in the past, if you are researching past behaviour.)

The problem I had next is that Consolation3 showed me too much. I wanted a few messages which would summarise each Time Machine session: when it started, when it ended, and if it took hours, what were the steps and how long did they take. Instead, I was buried in lots of detailed log entries from Time Machine. A day’s activity resulted in about 300 messages for 7 backup sessions.

For example, the log message,
Failed to remove attribute 'com.apple.backupd.SnapshotVolumeFSEventStoreUUID' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
happens several time at each backup attempt to each destination, and doesn’t seem relevant to the high-level picture.

However, some messages were clearly useful. For example, these messages marked the start and finish of a backup session. The difference between their timestamps let me calculate how long the session took:
2020-07-31 13:08:03.896669-0700 localhost backupd[81888]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Starting automatic backup
…[50 log entries omitted]…
2020-07-31 17:07:06.344209-0700 localhost backupd[81888]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Backup completed successfully.

So, how can we filter out just the useful messages from the stream? The answer lies in the Filter section of the Consolation3 UI. Click the pattern radio button. In the first and third lines, set pattern and operator and text as shown below. In the second line, set logical to AND . It is essentially this:

subsystem == com.apple.TimeMachine
AND
eventMessage MATCHES Starting.*|Not starting(?! scheduled Time Machine backup: Backup already running).*|Backing up to.*|Mounting.*|Copied [0-9]*.*|.*Backup c[a-z]+ed.*|.*recovery system|Post-backup thinning.*|Backup failed.*|Failed to eject.*

This is what it looks like in the Consolation3 UI (again, with certain parts of the messages redacted in grey):

Now, there are about 5-15 log entries for each backup session. There are few enough log entries to reveal the overview of the session, and sufficient log entries to show which major parts of the session took how much time.

This leaves me able to see overviews of my backup sessions. It is now easy to quantify how long backup sessions take to the attached disk, and how long they take to the file server. The next challenge will be to understand why steps take longer to the file server. That is a topic for a different blog post.

It is straightforward to transform these settings for the Consolation3 app into a command you can use in the macOS shell. Look at the text between the “Get log” button, and the log messages window. It begins: ["show", …. Triple-click on the word “show”. Both lines get selected. Copy this text, and paste into a text editor. It turns out there is more text than was visible. It is a sequence of quoted strings, separated by commas, within square brackets. Turn this text into a shell command, by deleting the square brackets and the commas. Change the word “json” to “syslog“. Insert the word log and a space at the beginning. It will now look something like this:

log "show" "--predicate" "subsystem == \"com.apple.TimeMachine\" AND eventMessage MATCHES \"Starting.*|Not starting(?! scheduled Time Machine backup: Backup already running).*|Backing up to.*|Mounting.*|Copied [0-9]*.*|.*Backup c[a-z]+ed.*|.*recovery system|Post-backup thinning.*|Backup failed.*|Failed to eject.*\" " "--style" "syslog" "--info" "--signpost" "--start" "2020-07-31 00:03:00" "--end" "2020-08-31 00:00:00"

Paste this string into a shell (using the Terminal app). The result is something like this:

% log "show" "--predicate" "subsystem == \"com.apple.TimeMachine\" AND eventMessage MATCHES \"Starting.*|Not starting(?! scheduled Time Machine backup: Backup already running).*|Backing up to.*|Mounting.*|Copied [0-9]*.*|.*Backup c[a-z]+ed.*|.*recovery system|Post-backup thinning.*|Backup failed.*|Failed to eject.*\" " "--style" "syslog" "--info" "--signpost" "--start" "2020-07-31 00:03:00" "--end" "2020-08-31 00:00:00"
log: warning: The log archive contains partial or missing metadata
log: warning: The log archive contains partial or missing metadata
log: warning: The log archive contains partial or missing metadata
Filtering the log data using "subsystem == "com.apple.TimeMachine" AND eventMessage MATCHES "Starting.*|Not starting(?! scheduled Time Machine backup: Backup already running).*|Backing up to.*|Mounting.*|Copied [0-9]*.*|.*Backup c[a-z]+ed.*|.*recovery system|Post-backup thinning.*|Backup failed.*|Failed to eject.*""
Skipping debug messages, pass --debug to include.
Timestamp                       (process)[PID]    
2020-07-31 00:16:13.434696-0700  localhost backupd[78944]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Starting automatic backup
2020-07-31 00:16:43.312688-0700  localhost backupd[78944]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Backing up to /dev/disk2s2: /Volumes/Time Machine Backups/Backups.backupdb
…[lines omitted for brevity]…

You can use your normal shell-hacking skills to modify this command for your own purposes. Note that you can remove the quotes from any of these strings which have no spaces and no asterisks in them. If you want to get all the messages to the present, you can leave out --end and the following date. Here’s a simpler command:

% log show --predicate "subsystem == \"com.apple.TimeMachine\" AND eventMessage MATCHES \"Starting.*|Not starting(?! scheduled Time Machine backup: Backup already running).*|Backing up to.*|Mounting.*|Copied [0-9]*.*|.*Backup c[a-z]+ed.*|.*recovery system|Post-backup thinning.*|Backup failed.*|Failed to eject.*\" " --style syslog --info --signpost --start "2020-07-31 00:03:00"

Use the shell’s man log command to find out more about what you can do with the log command. You can learn more about the underlying macOS Unified Log system in a series of blog posts at the Eclectic Light Company.

The quoted string after MATCHES is a regular expression. Here is a breakdown of what each part of the regular expression aims to match. (I won’t try to explain regular expression syntax, but there are many resources to learn that.) The backslash-escaped quotes (\") surround the regular expression. The vertical bars ( | ) separate alternative patterns to match.

Starting.*: Displays messages about starting backups.
Not starting(?! scheduled Time Machine backup: Backup already running).*: Displays messages about not starting backups, except that the (?! scheduled…) expression rejects messages about “not starting” because “Backup already running”.
Backing up to.*: Messages starting “Backing up to” usually contain a path which shows the destination of the backup: local disk, or file server.
Mounting.*: I’m not sure. I must have had a reason for displaying messages starting, “Mounting”, but Time Machine hasn’t logged any for me recently.
Copied [0-9]*.*: Displays a hourly progress report message, useful for showing incremental progress on a long backup.
.*Backup c[a-z]+ed.*: Displays both “Backup cancelled” and “Backup completed successfully” messages.
.*recovery system and Post-backup thinning.*: Work on the “recovery system” and on “post-backup thinning” takes a bit of time between data copying and backup completion. These messages give start times for these tasks.
Backup failed.* and Failed to eject.*: Display messages about the end of failed backup sessions.

Are you trying to diagnose Time Machine backup problems also? I hope these filters in Consolation3 and in log show are helpful for you.

No Comments »