How do we measure time? Technically, by the oscillations of a cesium atom. This film tells a human story behind an element from the periodic table: cesium.

A series of short films about how the elements of the periodic table shape our lives.

By international disagreement, last Sunday morning the UK, along with Europe, set its clocks back an hour from British Summer Time to good old GMT, and this coming Sunday it’s the turn of most of the US to do the same. Unless you’re in Hawaii or Arizona (excluding the Navajo Nation), which apparently don’t take part in this bizarre ritual. This is marginally better than ancient Greece, where adjacent cities kept separate and discoordinated calendars even though their sundials might have remained in sync.

While Macs should take this all in their stride, there’s one feature that twice every year throws its hands up in horror leaving you to work around it, the log show command. Whatever you’re doing in the small hours when the clocks go back or forward, don’t try accessing log entries written during those couple of hours or you could be sadly disappointed.

When clocks go forward in the Spring, log show just skips an hour, leaving a void in the fabric of time. But when they go back, a whole hour occurs twice, and wreaks havoc with the log. That’s another time feature subject to general disagreement, when to change to and from summer or daylight saving time. In the UK and Europe, that’s undertaken at 01:00 UTC (or, in the UK, GMT), while in the US it’s at 02:00 local time. It’s surely confusing enough that clocks change simultaneously across the whole of Europe, but to know when those in a US state are due to change you also have to know the local time before they change.

To see how bad this is, after the dust had settled on the system clocks of two of my Macs last Sunday, I dared to look with two log browsers, Ulbow that relies on the log show command, and LogUI that has better sense and calls the OSLog API direct.

Accessing the log using Ulbow, there was no problem around 02:00 or 01:00 GMT (if you must, UTC), when you might have expected the clock change to have had greatest impact. On both Macs running here at the time, it was exactly 01:49:02 GMT or BST that the log fell over. Calling for a single second of the log at that moment elicited over 300,000 entries on one Mac, and just short of four million on the other.

Whatever logoclysm strikes at that moment is over in the twinkling of an eye. Step back a second or two and you’ll see normal log entries reported in the previous time (here, BST +0100), and step forward to see everything orderly and in new time (GMT +0000). Use LogUI instead of Ulbow, though, and you can’t even tell when local time was adjusted, as that app expresses all times according to the prevailing setting at the time you read the log.

There is a seldom-used option for the log show command in -timezone local, which displays all times in the current local time. Yet the default is for log entries to be “displayed in the timezone at the time the entry was written to source archive or file”, as explained in man log. In some circumstances that may make entries more readable, but at least twice a year it causes chaos, and I’m puzzled why log show still makes that its default.

Although Apple doesn’t document it, I suspect that the Unified log, like other time-reliant subsystems in macOS, relies on Mach ticks since a clock datum. Because those are strictly monotonic, they can’t go backwards and cause the confusion seen here, unless of course you disable network time syncing and manually set your Mac’s clock to a time in the past (and even that is appearance rather than reversal). That used to occur on old Macs whose system clock relied on a small internal battery with a limited life. When that battery expired, the system date and time reverted to the datum of 1 January 1970, at the time the mark of a Mac that needed its battery replaced.

If you’re in the US, I wish you a smooth transition when your clocks go back this weekend, and hope you don’t need to access any entries in the log for the hour that time is out of joint.

Time is central to any log, and with the high performance of the Unified log it’s fundamental. It’s also one of its most confusing aspects, particularly when you add time zones, seasonal clock changes, and clock synchronisation.

Clock ticks

I believe each log entry includes the Mach absolute time (MAT) when that entry was made, and those form the log’s internal timebase. However, Apple doesn’t document that, there are alternatives such as Mach continuous time, and times exposed in the public OSLog API are limited to opaque Date structures rather than MAT. In contrast, the log show command can return a numeric field named machTimestamp that does appear to contain the MAT of that log entry.

The first complication with time is that MAT differs between Intel and Apple silicon Macs. While each increment in MAT represents one nanosecond in Intel Macs, in Apple silicon chips MAT ticks occur three times every 125 nanoseconds, or once every 41.67 ns. These are monotonic, in that they always move forward, so every subsequent tick count is greater than (or equal to) the previous ones, unlike wallclock time.

I have looked in detail at how this is reflected in times shown in the log when accessed by different methods, including that now used by LogUI. In practice, this means that the finest resolution of time in LogUI is 1 microsecond, which should suffice for almost every purpose.

Wallclock time

While MAT can be useful for measuring differences in time with great precision, it doesn’t tell you the time in terms of real-world clocks, or wallclock time. Conversion between those relies on data stored in opaque timesync files stored alongside log files. Those are used to provide a wallclock time for each log entry when it’s obtained either through the log show command, or the opaque Date structure in the OSLog API that LogUI relies on. It’s here we encounter all the complexities of the wallclock, such as time zones, seasonal time corrections, and corrections to synchronise with global time references.

Times shown in log entries also need to match those set in the log browser. In practice that leaves two options for times shown in log entries: express them in the local time when they were saved to the log, or in the local time when they’re extracted from the log. By default, the log show command adopts the former, as does Ulbow because it gets its log entries using that command tool, but LogUI converts all times to local time when the log extract is obtained. log show does have an option --timezone local to synchronise entries to current local time, but that’s seldom used.

Wallclock adjustment

The only time measure that remains unaffected by system wallclock time adjustments is MAT. No matter how a wallclock time is expressed, though, there will always be a hiatus and the risk of duplicate times being given, for example with consecutive entries of
08:26:16.140474+0100
08:26:10.043353+0100 === system wallclock time adjusted
08:26:10.044335+0100

If you’re using the log to measure time, and those measurements span a wallclock adjustment, you will need to make a manual adjustment to allow for that.

Time zone and season

When times of log entries are expressed using the local time applicable when those entries were written, changes in time zone and seasonal adjustments become confusing. For example, these entries were written when the wallclock was advanced by one hour in accordance with the start of British Summer Time:
2020-03-29 01:09:22.489149+0000 361080253974026
2020-03-29 01:09:22.489160+0000 361080253985232
2020-03-29 02:09:22.522734+0100 361080253990360 === system wallclock time adjusted
2020-03-29 02:09:22.522749+0100 361080254005593
2020-03-29 02:09:22.522913+0100 361080254170158
In each case, the wallclock date and time are given first, followed by the MAT (from an Intel Mac), demonstrating that the hiatus of one hour doesn’t affect the latter.

According to convention, Summer time adjustments across Europe are made at 01:00:00 +0000 (UTC). So in the Spring, clocks are put forward from 01:00:00 regular time to 02:00:00 Summer time. In North America, changes are made at 02:00:00 local, and usually on different days. Because of the way that macOS manages time, changes to the system clock will inevitably occur shortly after the officially set time, in that case nearly ten minutes later.

To avoid this confusion, LogUI expresses wallclock and control times using local time when those entries are extracted from the log. In that case, you’d see
2020-03-29 02:09:22.489149+0100
2020-03-29 02:09:22.489160+0100
2020-03-29 02:09:22.522734+0100 === system wallclock time adjusted
2020-03-29 02:09:22.522749+0100
2020-03-29 02:09:22.522913+0100
as you would obtain that log extract when British Summer Time was already in force.

Converting from Date values stored in log files to strings expressed in local time isn’t something an app would want to repeat constantly, for example on the fly when scrolling through a list of 50,000 entries. LogUI therefore converts each time into text when it fetches those log entries. If you then save the log extract in JSON format, those times remain in that local form, and aren’t converted again if you open that file in a different time zone or seasonal time correction. If you want to retain times in their original format, so they’ll be converted into a later time zone, for example, save the log as a logarchive, to ensure that each time will be converted into text using the local time applicable when the extract is fetched from that logarchive. That should affect few users, and only in unusual situations.

Key points

• The Unified log appears to record times in Mach absolute time, and convert those to wallclock format when accessed.
• By default, the log show command, and apps like Ulbow that use it, give the wallclock time adjusted to local time when each log entry is written. That can result in confusing time sequences.
• LogUI expresses all times in local time when log entries are extracted from the log. That makes its handling of time independent of seasonal changes, and more consistent.
• Periodic wallclock adjustments affect all wallclock times, and may need to be allowed for when measuring times from log entries.

The greatest challenge in using the Unified log is how to navigate its many thousands of entries, to find those you want to read. Success depends on the combination of two aids: time and waypoints (or landmarks).

Time

No matter how you obtain log extracts, you need to know when to look for those entries. The more precisely you can work out the time of interest, the quicker and easier it will be to locate the entries you’re interested in. While the log command offers alternatives, LogUI works throughout using the local time applicable when you access the log, allowing for your current time zone and any seasonal adjustment to it, when accessing the live log in that Mac.

However, the underlying times given in log extracts are those recorded by the Mac or device whose log you’re accessing. If its system clock was five minutes slow when those entries were written to its log, then you need to allow for that. For example, when I first started my Mac yesterday its clock might have been 1 minute slow. An event that occurred at 10:56 yesterday by the room clock would therefore appear in the log entries for 10:55.

One important time you can discover is the boot time of the Mac. Mints offers a Boot button to retrieve boot times over the last 24 hours. If the logs were written by a different Mac or device, then you’ll need to search for the time of that last boot. Fortunately the first two log entries are easily recognised:
11:41:37.562774+0100 === system boot: D3CEA9B4-F045-434D-8D12-C6E794A02F14
11:41:42.758780+0100 kprintf initialized
The long gap between the first two entries is accounted for by the firmware phase of the boot process. If necessary you can search for a message containing === (three equals signs). Mints provides the time of the first of those for each boot, and its UUID.

There are two occasions when time can become confusing, when clock corrections are applied, and when clocks are moved forward or back to add or remove summer or seasonal time changes. Fortunately the latter only change twice each year, although when they do, you really don’t want to see what happened in the log, and those changes aren’t even applied at a predictable time.

Clock corrections, like kernel boot, are readily found by the === text in their message. They normally happen in pairs, with the first correction the larger, and the second often far smaller. Here’s an example seen in consecutive log entries:
08:26:16.140474+0100 /usr/libexec/sandboxd[80] ==> com.apple.sandboxd
08:26:10.043353+0100 === system wallclock time adjusted
08:26:10.044335+0100 Sandbox: distnoted(72) deny(1) file-read-metadata /private
08:26:10.044601+0100 2 duplicate reports for Sandbox: distnoted(72) deny(1) file-read-metadata /private
08:26:10.044606+0100 Sandbox: distnoted(72) deny(1) file-read-metadata /Library
08:26:10.089204+0100 === system wallclock time adjusted
08:26:10.091850+0100 started normally

The first adjustment dropped the clock back by 6.1 seconds, from 08:26:16.140474 to 08:26:10.043353. This means that you’ll see times of 08:26:12 both before the correction and afterwards. The second adjustment, from 08:26:10.044606 to 08:26:10.089204, was far smaller at 0.045 seconds, and at least went in the right direction.

The most substantial clock corrections are made shortly after booting. Although macOS does make them later, the size of those should be smaller.

Waypoints

Even working with times resolved to the second, those can still leave you browsing thousands of log entries. To locate more precisely you need details of one or more entries that will be sufficiently distinctive to focus in on a few dozen. These are waypoints for navigation.

LogUI provides three methods for locating these waypoints:

• using a search predicate to determine which log entries are extracted from the log;
• applying search text to filter out all entries that don’t contain a term;
• searching a rich text export of the log extract.

Predicates

These are best used when the time period of your extract needs to be relatively long, so would return a large number of entries. For example, if you can only narrow the time down to several minutes, and are looking for the time that a specific app was launched, you can look for that app’s job description when it’s created and written to the log by RunningBoard.*

Over a period of two minutes, RunningBoard might write thousands of entries in the log, so looking for your app’s job description among them would be time-consuming. Set the start time and period to cover the whole of the time you want to search, then set a predicate for the subsystem com.apple.runningboard.

When LogUI fetches that log extract, there might still be over 2,000 entries, so now is the time to apply search text to filter those further.

Search filter

To filter those 2,000 entries and show only those containing job descriptions created by RunningBoard, enter the text constructed job in LogUI’s search box, with its menu set to Messages, and press Return. You’ll now see that list reduced to just a handful, and looking through them you can discover exactly when your waypoint occurred.

My example for this article starts with a period of just 2 minutes, in which there were more than 100,000 log entries.

Using the com.apple.runningboard predicate whittled those down to 13,443 entries.

Searching within those for constructed job left me with just 8 entries to look through.

Search rich text

Sometimes you can’t devise the right combination of predicate and search filter to discover what you’re looking for, which might be an error reported in a subsystem or a process that you can’t identify. One good way forward is to narrow your log extract as much as you can, then save the extract as Rich Text, open that in a suitable editor, and search through it for the word error. That will discover every log entry containing the word error anywhere, rather than confining it to the message text.

Using time and waypoints

Armed with your waypoint and the exact time of its entry in the log, you can now set that as the start time, set a period of a couple of seconds, and get a full log extract containing all the detail you might need. This should give you further clues to allow you to move through time using predicates and search filters to discover what happened. This is much quicker and less frustrating than trying to scan through thousands of log entries in search of vague clues.

Key points

• Use time and waypoints to find log entries.
• Mints’ Boot button gives times of each boot in the last 24 hours.
• Reduce the number of log entries returned using a predicate.
• Narrow those down using a search filter.
• Search all text by exporting the log extract as Rich Text.

* Sadly, the days of being able to access freely RunningBoard’s informative job descriptions in the log are over. As of macOS Tahoe, all you’ll see is the dreaded <private> of censorship. If you want to examine these now, you’ll have to remove log privacy protection first. Thanks, Apple, for providing such useful tools then rendering them next to useless.

我好久都没睡好了，值得记录一下。

从半年前手术开始，接连着出差、二次手术、年前的忙、过年的烦、年后的忙，一直到前几天的连续熬夜和通宵工作，我真的很长一段时间里都没有这么深的睡眠了。

前几天为了最后出方案，熬了两个通宵，公司内部的野心和追求都令我感到很失望，复杂的情绪交融在一起，非常难过。但最后还是用我的方式，引导大家选择了我想要的那个。尽管看上去我在力推另一个方案，但是人呐，对于自己没有概念的事情，靠嘴说是没有用的，对于他们来说，打出高中低来，选中间的，是他们能理解的方式。更好的那个，谈不上多超前，仅仅只是不值得而已。算了，以后总会有机会。

昨晚九点半，终于把所有设计文件、模型和工艺文件、USDZ 文件分别发送到了各个下一环节手中。接下来，不用我熬夜，轮到我监督他们干活交东西了。算是阶段性的胜利吧。

心情一好，我就看了半部《无间道3》。

前段时间跟筱烨一起看《无限超越班》，心里的戏瘾就痒痒，但是现在没有机会上舞台了，就上 Netflix 找了无间道三部曲开始看。之前分两周陆续看完了前两部，昨晚难得松懈一下，一口气看了半部三。

为了帮我补熬夜的气血，筱烨给我买了两次西洋参。第一盒前几天喝完了，前天又到了一盒，昨晚睡前温热地喝了一杯。

大概是工作的疲惫 + 阶段胜利的松懈 + 看电影的愉悦 + 西洋参补的气，一起让我睡了一顿好觉吧？