A week ago, I reported significant discrepancies in the reported timestamps of entries in Sierra’s new log system. In investigating Time Machine backups, I can now give a better idea of the magnitude of that variation, and I think that I can explain how it is generated.

I obtained entries from the same log in macOS Sierra 10.12.3, using Consolation (hence the log show command), at 34, 39, 42, and 61 minutes after the events occurred. The original entries read:
08:09:44.383430 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Forcing deep traversal on source: "Macintosh HD" (device: /dev/disk2 mount: '/' fsUUID: BE50387F-1302-31FB-B567-68F50F8ADE7A eventDBUUID: FDAC9A01-ECB1-4AFA-8F58-B018F81CF569)
08:09:44.400219 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Deep event scan at path:/ reason:must scan subdirs|require scan|
08:09:44.400344 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Running event scan
08:09:44.400449 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] periodic consistency scan for '/'

The total drift over the 27 minutes between the first and last log excerpts was 0.005332 seconds in every case, with the timestamps becoming progressively earlier as they were read later. For example, the first log item Forcing deep traversal on source: was reported as occurring at the following times:
08:09:44.383430
08:09:44.382003
08:09:44.380641
08:09:44.378099

These demonstrate a systematic and progressive error in the reported timing of log events over the first hour after they occurred. If the rate of change remains constant, it would indicate that, an hour after an index event occurred and was entered into the log, the timestamp would show that event as having occurred at least 0.01 seconds earlier than it actually did.

Because this drift appears to be identical across different log entries, it does not alter the order in which events are reported to have occurred.

For the great majority of purposes, this drift in reported log timestamps is of little or no significance. However, anyone using log entries for forensic purposes must take it into account when trying to relate log entries to the times of external events.

This demonstrates that the new log database does not store datestamps as absolute times, but as tick counts of the system clock. When the log show command converts those into seconds, it uses the difference between the tick count at the time that it is run, and that recorded in the log. As the system clock undergoes slight drift between the time that an event occurred and the time that its tick count is converted into a timestamp by log show, that drift will result in systematic change in the reported timestamps of all log entries. However, the actual tick counts of those entries do not change.

If you really wanted to obtain the most accurate timestamp conversions for log entries, you should recalibrate your Mac against a reference time source immediately before running the log show command (or using it by proxy in Consolation).

Hopefully this solves that particular mystery.