Reading view

There are new articles available, click to refresh the page.

Can you trust times shown in the log?

Next to the order of entries in the log, their date and time stamps are one of the most important pieces of information they contain. In some cases, such as when you’re using the log to estimate performance, their accuracy is vital. This article reports the results from tests to validate the times given in log records provided by the log show command, and in my free log browsers LogUI and Ulbow.

Clock date and time

Dates and times given in log extracts invariably match those of the Mac’s system clock, the only catch here being adjustments for time zone and DST. The latter can become confusing if you look at the log when DST is changed, or from a different time zone. To cope with that you can use the --timezone local option in log show to express all times with uniform adjustment. Ulbow doesn’t use that, but LogUI does now synchronise all time and date stamps to the current time zone and DST.

Time differences

The log is an excellent tool for measuring time and performance, either using regular entries or Signposts that are intended for the purpose. Writing an entry into the log incurs minimal overhead, and is simple to perform from any code or script. If your favourite scripting language doesn’t give direct access to writing entries, then you can use my free command tool blowhole to do so. If you want to assess processes in macOS, then it’s usually straightforward to identify appropriate milestones that mark events and use those to calculate the period. These all depend on the times reported in log entries being sufficiently accurate.

Gold standard

Since Mac OS X, every Mac has had a high-precision internal clock within it (prior to that Time Manager could resolve times down to the microsecond but no further). This increments monotonically in ‘ticks’, an unsigned 64-bit integer, starting from an arbitrary value, and is referred to as Mach Absolute Time (MAT).

Intel Macs increment their ‘tick’ count once every nanosecond, so the difference between two readings of the clock represents the time interval in nanoseconds. Life isn’t as simple with Apple silicon Macs, as they tick three times every 125 nanoseconds, or once every 41.67 nanoseconds. Apple’s latest documentation on MAT, its units and use, comes in a Technical Q&A dated 2005.

Once correctly converted into nanoseconds, MAT is the closest available measurement of time to a gold standard.

I suspect that log entries are originally given a raw MAT as their time, and that can be made available using the log show command, or in Ulbow, as that uses log show to obtain log entries. LogUI reads the log directly, through the OSLog API in macOS, which currently doesn’t provide MAT values, instead giving a lower resolution Date value.

This validation therefore compares time intervals given by Ulbow from log entry timestamps, and those given in LogUI, against MAT intervals obtained in Ulbow. To increase the challenge, log entries used are from blowhole writing 25 log entries as fast as it can, a worst case scenario as that writes 2-3 entries each microsecond.

Comparisons

Log extracts obtained using log show in Ulbow and those estimated by LogUI were compared, and their timestamps were found to be identical.

On an Apple silicon Mac (M4 Pro), entries written by blowhole had raw MAT values that recorded intervals of 9 or 10 ticks between them, after the first three were made 73 and 15 ticks apart. From the third of the series of 25 log entries there was a strong linear relationship between recorded MAT in nanoseconds elapsed and loop number, as shown in the chart below.

The gradient of the regressed line shows that blowhole‘s log entries occurred at intervals of just under 405 nanoseconds.

Because LogUI (and regular timestamps in log show and Ulbow) only resolve to microseconds, the matching plot for LogUI’s times against loop number is stepped.

The gradient of this regression line is 0.4, indicating that the intervals occurred at 400 nanoseconds, almost identical to that found for the MAT.

Plotting times measured by LogUI (which also represents those for Ulbow and log show, as they’re identical) against that of MAT shows a good linear relationship with a gradient of just under 1.009, indicating that timestamps in log show, Ulbow and LogUI are accurate and reliable estimates of MAT.

Differences between pairs of time estimates obtained from MAT and LogUI ranged from -83 to +792 nanoseconds, with a median of +370 and quartiles of +83 to +583 nanoseconds.

Conclusion

  • Times given for log entries in LogUI, Ulbow and log show are reliable estimates of MAT to within +0.8 microseconds.
  • When nanosecond resolution is needed, the machTimestamp field from log show or Ulbow should be used, and converted into nanoseconds.

LogUI build 52 handles time zones and microseconds better

Last week’s deep dive into the precision of times in the log concluded that, with the data currently available, the highest they can aspire to are microseconds, 10^-6 seconds, and not the nanoseconds given in the last build of LogUI. The aims of this new build are to deliver correctly rounded microsecond time resolution, and to adopt consistency in time zones and DST corrections.

I described in detail yesterday how I arrived at conversion of log entry dates to yield the time in microseconds. Here I’ll consider how to treat time zones correctly.

When you enter a start time in LogUI, this is assumed to be given in the local time set on your Mac, including both its time zone and any DST correction. LogUI already takes those into account, and performs any necessary adjustments.

Now that I have completely overhauled how LogUI converts the date stored for each log entry, I have changed behaviour in comparison with the default option of the log show command, and Ulbow that accepts its timestamps without question. The best way to see that is to observe log entries when the Mac’s time zone is changed.

Ulbow, and by default the log show command, uses date and time stamps adjusted for the time zone and DST setting at the time each entry is written to the log. You should therefore be prepared to see abrupt discontinuities in its timestamps. This condensed sequence of log entries from Ulbow shows what happens when you change time zone from New York to the UK during DST:
10:50:00.729672-0400 com.apple.Settings /AppleInternal/Library/BuildRoots/ … obfuscated() obfuscate output: …
10:50:00.729687-0400 com.apple.xpc.alarm Setting timer for "com.apple. …
15:50:00.730675+0100 === system wallclock time adjusted
15:50:00.730733+0100 com.apple.mobiletimer.logging … rescheduling 0 alarms
15:50:00.730754+0100 com.apple.xpc.alarm Setting timer for "com.apple.mdmclient.timer.ManualCertRenewalCheck" in 86080 seconds.

Instead, LogUI adjusts all log entries to the current time zone for consistency in reading:
15:50:00.729672+0100 com.apple.Settings /AppleInternal/Library/BuildRoots/ … obfuscated() obfuscate output: …
15:50:00.729687+0100 com.apple.xpc.alarm Setting timer for "com.apple. …
15:50:00.730675+0100 Boundary === system wallclock time adjusted
15:50:00.730733+0100 com.apple.mobiletimer.logging … rescheduling 0 alarms
15:50:00.730754+0100 com.apple.xpc.alarm Setting timer for "com.apple.mdmclient.timer.ManualCertRenewalCheck" in 86080 seconds.

If you’re using log show, you can add the --timezone local option to adopt the same behaviour.

This also solves the dilemma when you’re browsing the log through a time zone change, for example when the clock has gone forward to DST, or the reverse. In LogUI the rule is simple: enter the current time, and all log entries will be adjusted to and shown in that single time zone.

I’ve previously explained some of the confusion that can arise with DST changes, in the autumn/fall, and again in the Spring. Hopefully LogUI won’t lead to any confusion now.

LogUI 1.0 build 52 is now available from here: logui152
and from its Product Page.

Enjoy!

Never work with children, animals or time: nailing the nanosecond

Quite unintentionally, last week became a saga about time, and a good demonstration of how you should do your utmost to avoid working with it. This all started with an irksome problem in my new log browser LogUI.

LogUI departs from my previous log browsers in accessing log entries through the macOS API added in Catalina. When it first arrived, I found it opaque, and its documentation too incomplete to support coding a competitive browser at that time. Since then I have revisited this on several occasions, and each time retreated to using the log show command to obtain log extracts. As far as time is concerned, that presents me with two alternatives: a formatted string containing a date and timestamp down to the microsecond (10^-6 second), and a Mach timestamp giving the ‘ticks’ from an arbitrary start time.

Although the latter can only give relative time, the timestamp provided suffices for most purposes, and comes already formatted as
2025-05-25 07:51:05.200099+0100
for example.

Milliseconds

When you use the macOS API, date and time don’t come formatted, but are supplied as a Date, an opaque structure that can be formatted using a DateFormatter
let dateFormatter = DateFormatter()
dateFormatter.dateFormat = "yyyy-MM-dd HH:mm:ss.SSSZ"
let dateString = dateFormatter.string(from: date)

to provide
2025-05-24 13:46:12.683+0100

That only gives time down to the millisecond (10^-3 second), which is inadequate for many purposes. But changing the formatting string to "yyyy-MM-dd HH:mm:ss.SSSSSSZ"
just returns
2025-05-24 13:46:12.683000+0100
with zeroed microseconds. As I can’t find any documentation that states the expected time resolution of Dates, it’s unclear whether this is a bug or feature, but either way a different approach is needed to resolve time beyond milliseconds.

Nanoseconds

The only method I can see to recover higher precision in the macOS API is using DateComponents to provide nanoseconds (10^-9 second).
Calendar.current.component(.nanosecond, from: date)
returns an integer ready to format into a string using
nanosecStr = String(format: "%09d", nanoSeconds)
to give all nine digits.

Inserting that into a formatted date is a quick and simple way to construct what we want,
2025-05-24 13:46:12.683746842+0100
down to the nanosecond.

It’s only when you come to examine more closely whether the numbers returned as nanoseconds match changes seen in Mach timestamp, that you realise they’re a fiction, and what’s given as nanoseconds is in fact microseconds with numerical decoration.

Microseconds

The answer then is to round what’s given as nanoseconds to the nearest microsecond, which then matches what’s shown in Mach timestamps
let nanoSeconds = Int((Double(Calendar.current.component(.nanosecond, from: date))/1000.0).rounded())
and that can be converted into a string using
nanosecStr = String(format: "%06d", nanoSeconds)

Rather than manually format the rest of the date and timestamp, you can splice microseconds into the @ position of the format string
"yyyy-MM-dd HH:mm:ss.@Z"
turning
2025-05-24 13:46:12.@+0100
into
2025-05-24 13:46:12.683747+0100

Unfortunately, that’s too simple. If you test that method using times, you’ll discover disconcerting anomalies arising from the fact that seconds and microseconds are rounded differently. This is reflected in a sequence such as
2025-05-24 13:46:12.994142+0100
2025-05-24 13:46:13.999865+0100
2025-05-24 13:46:13.000183+0100

where the second rounds up to the next second even though the microseconds component hasn’t yet rounded up. The only way to address that is to format all the individual components in the string using DateComponents. And that leaves a further problem: how to get the time zone in standard format like +0100?

Time zones

Current time zone is available as an opaque TimeZone structure, obtained as
TimeZone.current
Note that this doesn’t need to be obtained individually for each Date, as its components are obtained using current Calendar settings, not those at the time the Date was set in that log entry. This should have the beneficial side-effect of unifying times to the same time zone and DST setting.

But that doesn’t offer it in a format like +0100, so that has to be calculated and formatted as
let timeZone = (TimeZone.current.secondsFromGMT())/36
let tzStr = String(format: "%+05d", timeZone)

Solution

The complete solution is thus:
let timeZone = (TimeZone.current.secondsFromGMT())/36
let tzStr = String(format: "%+05d", timeZone)
let dateComponents = Calendar.current.dateComponents([.year, .month, .day, .hour, .minute, .second, .nanosecond, from: date)
let yearStr = String(format: "%04d", dateComponents.year ?? 0)
let monthStr = String(format: "%02d", dateComponents.month ?? 0)
let dayStr = String(format: "%02d", dateComponents.day ?? 0)
let hourStr = String(format: "%02d", dateComponents.hour ?? 0)
let minuteStr = String(format: "%02d", dateComponents.minute ?? 0)
let secondStr = String(format: "%02d", dateComponents.second ?? 0)
let nanoSeconds = Int((Double(dateComponents.nanosecond ?? 0)/1000.0).rounded())
let nanosecStr = String(format: "%06d", nanoSeconds)

then concatenate those together with punctuation marks as separators to deliver the string
2025-05-24 13:46:12.683746+0100

If you’re coding in Swift, you might instead consider using Date.FormatStyle, although its documentation only refers to handling milliseconds, so I suspect that might turn out to be another wild goose chase.

If you know of a better way of handling this explicitly, don’t hesitate to let my code therapist know.

A Dance to the Music of Time in Intel and Apple silicon logs

Now we’ve got LogUI to give us the times of log entries down to the nearest nanosecond, it’s time to see whether that’s any improvement over other tools. Given that Mach Absolute Time resolves to nanoseconds (10^-9 seconds) in Intel Macs, and just under 42 nanoseconds in Apple silicon Macs, can we now resolve times of events better than when using microseconds (10^-6 seconds)?

Methods

To test this out, I used my command tool blowhole that can run a tight loop writing entries in the log as fast as possible. To do this, it uses the code
for index in 1...number {
os_log("%d", log: Blowhole.gen_log, type: type, index)
}

I then wrote loops of 20 to the log of an iMac Pro (Intel Xeon W CPU), M3 Pro and M4 Pro, and extracted the resulting log entries using LogUI with its new nanosecond times.

Results

Plotting these times against loop number resulted in unexpected patterns.

In this graph, results from the iMac Pro are shown in black, those from the M3 Pro in blue, and the M4 Pro in red. Although less well-ordered in the first to fourth loops, from the fifth loop onwards there were linear relationships between time of log entries and loop number. Linear regression equations are shown in the legend, and demonstrate:

  • on the iMac Pro each loop takes 1.0 x 10^-6 seconds, i.e. 1 μs;
  • on the M3 Pro each loop takes 5.6 x 10^-7 seconds, i.e. 0.6 μs;
  • on the M4 Pro each loop takes 4.6 x 10^-7 seconds, i.e. 0.5 μs.

which perhaps isn’t surprising.

However, the patterns of individual points are quite different. Apart from loops 4 and 5, subsequent loops on the iMac Pro are evenly spaced in time. Those on the Apple silicon chips are grouped in pairs or, for loops 14-16 on the M4 Pro, in a triplet, where two or three loops are assigned the same time in the log.

Looking at time differences, a clear pattern emerges, that log times are incremented in steps of 954 ns. For the iMac Pro, each loop occurs one step later, while for the M3 Pro and M4 Pro steps between pairs and triplets are also 954 ns. In a few cases, the step difference is slightly greater at around 1192 ns instead of 954 ns. Apple silicon chips are faster on average because each step includes two or more loops, while the iMac Pro only manages one loop per step.

Explanation

If log entry times had been given in microseconds rather than nanoseconds, the same patterns would have been seen. But without the additional precision in their times, it wouldn’t have been clear that multiple log entries were being written with identical times, down to the nanosecond.

One likely explanation is that macOS only writes log entries approximately every microsecond, and the entry time recorded for each is that of that writing. Writing log entries must occur asynchronously for the M3 Pro and M4 Pro to be able to send pairs or triplets to be written, rather than having to wait for each writing process to complete.

Thus, the time resolution of log entries is approximately 1 μs, or 954 or 1192 ns to be more precise, and that’s the same regardless of whether macOS is running on a recent Intel Mac or the latest Apple silicon chips. Although a time resolution of 1 μs is sufficient for general purposes, if you want to dig deeper, as I have done here, access to the finer resolution provided in nanosecond times is essential.

Conclusions

  • Times written in log entries are incremented every 954 or 1192 ns on both Intel and Apple silicon.
  • Faster Apple silicon chips can write more than one entry in the same time increment.
  • Although expressing the time of log entries in microseconds is sufficient for general purposes, using nanoseconds can confirm which have occurred simultaneously.

The Music of Time

So what is a Dance to the Music of Time? It’s one of Nicolas Poussin’s most brilliant paintings, that inspired a series of twelve novels written by Anthony Powell. While I wouldn’t attempt to summarise those, here’s the painting to enjoy.

poussindancemusictime
Nicolas Poussin (1594–1665), A Dance to the Music of Time (c 1634-6), oil on canvas, 82.5 × 104 cm, The Wallace Collection, London. Wikimedia Commons.

Poussin’s Dance to the Music of Time (c 1634-6) shows four young people dancing, who are currently believed to be Poverty (male at the back, facing away), Labour (closest to Time and looking at him), Wealth (in golden skirt and sandals, also looking at Time), and Pleasure (blue and red clothes) who fixes the viewer with a very knowing smile. Opposite Pleasure is a small herm of Janus, whose two faces look to the past and the future. Father Time at the right is playing his lyre to provide the music, and an infant seated by him holds a sandglass, to measure time periods. Above them in the heavens, Aurora (goddess of the dawn) precedes Apollo’s sun chariot, on which the large ring represents the Zodiac, thus the passage of the months. Behind the chariot are the Horai, the four seasons of the year.

Resolve time better in LogUI build 48

Macs keep time exceedingly precisely, although there are important differences here between Intel and Apple silicon models. Their most precise record of time is given in Mach Absolute Time (MAT), the number of ‘ticks’ since an arbitrary start. In Intel Macs, each tick occurs every nanosecond (10^-9 second), providing high resolution, but ticks are less frequent in Apple silicon chips, occurring once every 41.666… nanoseconds instead.

You can test this on an Apple silicon Mac using my free utility Mints, which has a convenient button to display Mach timebase information. Run Mints in native mode, the default as it’s a Universal App, and it reports the Arm values; force it to launch as an app translated by Rosetta, and it will give the same timebase as an Intel Mac.

time01

time02

Although entries in the log are recorded in MAT’s high resolution, most methods of accessing log entries lose much of that precision. The datestamps provided by the log show command, for example, round time to the nearest microsecond (10^-6 second), although it’s capable of delivering a field in MAT’s nanoseconds. The bundled Console app is similar, but lacks any option to display MAT. My Ulbow app can display both datestamps with microseconds and MAT, but until now LogUI has been limited to displaying only time in milliseconds (10^-3 second).

To put these into context, in each microsecond the P core in the CPU of an M4 chip can complete execution of over 1,000 instructions, and in a millisecond that becomes more than a million instructions.

LogUI has been constrained by the formatted output available using Date and DateFormatter in the macOS API, which appear to be incapable of generating time any more precisely than milliseconds. After several earlier unsuccessful attempts, I’m now able to obtain time in nanoseconds, using Calendar and DateComponents in the API. For example, to obtain a formatted string containing the nanosecond component of a Date variable named date:
let nanoSeconds = Calendar.current.component(.nanosecond, from: date)
let nsTime = String(format: "%09d", nanoSeconds)

The string nsTime can then be spliced into a formatted date string.

I have incorporated this into a new build of LogUI, which also has extended information about the log display in its Help book. LogUI 1.0 build 48 is now available from here: logui148
and from its Product Page.

Tomorrow I’ll consider whether these more precise times are of use, and what we can learn from them.

Use Writing Tools to understand the log in LogUI build 46

I’ll be the first to admit that I’m sceptical of AI, and seldom use ChatGPT or Writing Tools. One of the conditions imposed by the magazines that I write for is that none of my contributions use AI in any way, either to research topics or to manipulate the text. Besides, I’d far rather all the mistakes I make are mine, and not introduced by AI. But I am impressed by Writing Tools, and think you might find them useful when trying to extract information from and understand the log, when using LogUI.

I’m therefore delighted to announce a new build of LogUI that gives access to summarisation features in Writing Tools to analyse and clarify log entries.

Most obviously, this build reworks the interface by promoting the button commands to its toolbar. From the left, these are:

  • Get log extract (circular arrows).
  • Gloss (magnifying glass on document page).
  • Save as Rich Text (downward arrow and box).

Following those is the popup menu to select the field to be used for search, and at the right end the Search box itself.

A more subtle change is aimed at making it less confusing when using multiple windows and search criteria on log extracts from the same time. The title shown in each window now appends any search term in use. That’s shown in the window, and in the Window menu, but isn’t included in the default file name if you save the extract in Rich Text.

Currently, LogUI supports two ways of moving log extracts to other apps: you can save the whole extract as a formatted Rich Text file, or copy the most important fields in selected entries as text. Build 46 adds a third as the bridge to Writing Tools, in what I term a gloss. This is generally used for words added to a text, either in between its lines or in the margin, that explain words in the main body of that text, and can be gathered together in a glossary. In LogUI this functions as a special pasteboard and plain text editor, the Gloss window.

The message field of some log entries is very large, containing a lot of information some of which may be of importance. The example I use here gives the registration details of an app being launched through RunningBoard. To copy those into a Gloss, select that log entry and click on the Gloss button in the toolbar. The contents of the selected message field(s) are then displayed in the Gloss window, a basic text editor, where you can manually format them if you wish, copy and paste the contents into a text document in another app. This works fully on all Macs running macOS 14.6 or later.

As this window contains a SwiftUI TextEditor view, you can also use Writing Tools on any selection you make within its text (Apple silicon Macs only). Select all using Command-A, hover the pointer over the selected text and you’ll see the Writing Tools blue button appear to the left of the window. Click on that, or use the contextual menu on the selected text, and you can now apply any of those Writing Tools to the contents.

If you try to use a Writing Tool that can’t cope with the text contents, you’ll see the error Writing Tools Unavailable.

In that case, open the contextual menu and try a different tool that can cope. Some log messages don’t contain much English, and in those cases Writing Tools might try another language such as German before reporting that the language isn’t recognised or supported.

Text in that Gloss window persists, and is saved into LogUI’s preferences. Only one Gloss window is available, and it contains the text from those entries selected the last time you clicked on the Gloss button. When you do that, the new gloss replaces the old. If you want to save the previous gloss, copy and paste it before clicking on the Gloss button.

Writing Tools can’t interpret log entries or diagnose problems from the log, but its summaries can make complex lists more comprehensible, and sometimes provide additional information that can be helpful. Always check its output against the original, as it can make mistakes.

To illustrate how this might help, here are examples taken from an original RunningBoard registration for the Pages app, starting
'app<application.com.apple.iWork.Pages.6871230.6871236(501)>' Constructed job description:
<dictionary: 0x910d117a0> { count = 23, transaction: 0, voucher = 0x0, contents =
"Platform" => <int64: 0x94ab1b6b9872cd77>: 1
"ProcessType" => <string: 0x910c2dc20> { length = 3, contents = "App" }
"EnableTransactions" => <bool: 0x1fb02aba0>: false

and running on for many more lines after those.

Writing Tools’ Summary reads:
The job description for the Pages application is provided. It includes details about the platform, process type, environment variables, and more. The description also specifies the program arguments and the path to the Pages executable.

Key Points start:

  • Application Name: com.apple.iWork.Pages
  • Application Bundle Identifier: com.apple.iWork.Pages
  • Application Platform: 1
  • Session Types: “Aqua”, “LoginWindow”
  • Initial Task Role: 2
  • Environment Variables: Includes variables like `__CF_USER_TEXT_ENCODING`, `TMPDIR`, `SHELL`, `HOME`, `SSH_AUTH_SOCK`, `LOGNAME`.
  • User Information: USER: hoakley, HOME: /Users/hoakley

List starts:

  • The job description is for a constructed application.
  • The application is identified as ‘app<application.com.apple.iWork.Pages.6871230.6871236(501)>’.
  • The application is running on a platform with an ID of 1.
  • The process type is “App”.
  • Transactions are not enabled for the application.
  • The application is managed by “com.apple.runningboard”.
  • The bundle identifier for the application is “com.apple.iWork.Pages”.
  • The application is part of a resource coalition with an ID of “app<application.com.apple.iWork.Pages.6871230.6871236(501)>”.
  • Pointer authentication is disabled for the application.

I think the first item there is a minor misreading, as I would understand that the text reports that a job description has been constructed for the application, not that the application is somehow constructed. However, other items listed appear to be faithful to the contents of the original message.

In some cases I have seen Writing Tools spell out an abbreviation, and in most it lays out the contents of long lists and dictionaries more accessibly. Try it out and see what you think.

LogUI 1.0 build 46 is now available from here: logui146
and from its Product Page.

Enjoy!

Reducing noise by searching LogUI’s views

App architectures can enable or constrain. My previous log browsers, Consolation and Ulbow, have been document-based, so each window represents a different log extract. As there seemed little reason to open two document windows on a single extract from the log, I’ve normally tweaked and fiddled with each window to display the entries I want to browse, an inevitable compromise that usually leaves me scrolling through thousands of entries.

LogUI is lighter in weight and not based on documents, merely windows and views. Although they’re backed by the data of a log extract, there’s no reason that you shouldn’t open several windows on the same data if that makes analysis easier. And it does, particularly when used with Search. Here’s an example.

Over the last couple of weeks, I’ve been looking at many log extracts covering app launch, one of the busiest events in macOS. In the first few seconds following a double-click to run an app, the log can accumulate well over 25,000 entries. No matter how experienced you are in dealing with them, or how efficiently you can look for milestones marking progress, it can take hours to read the launch process thoroughly in the log. This is partly because of the sheer volume of entries, but most of all because so many subsystems in macOS are involved. Any given period of tens of milliseconds can have long volleys in TCC, interspersed with a series of RunningBoard assertions, and occasional progress reports from LaunchServices. They’ll suddenly be interrupted by DAS dispatching an unrelated background activity, Wi-Fi updates, and other everyday tasks.

Try this instead.

Watch your Mac’s clock until it’s about to change minute. Just as the seconds count changes to 00, double-click the app and take your hands away from mouse/trackpad and keyboard. Once the clock reaches 10 seconds, assuming the app launch is complete, quit that app and start up LogUI. Its new window should show the time when you launched the app, so ensure its time period is correct, say anything between 5 and 30 seconds, and allow it to collect up to the 5-10 seconds required. When that’s ready, click on its Get Log button and check that it contains all the entries you require. Open second, third, fourth, and fifth windows likewise, with the same start times and settings. Once they’re all open, Get Log in each of them, and check that the number of entries is identical, indicating that each has the same log entries.

In my case, launching Pages brought over 40,000 log entries in the first 5 seconds, ending with the app running and prompting me to open a document. Even if you speed-read those at one entry every second, that would take you nearly 12 hours to work through. Let’s reduce that to a few minutes to see each of its important phases.

In a second window, type sendaction: into the Search box at the top right and press Return. That will find all entries marking the clicks/taps you triggered the launch with.

There are two paired entries 0.237 seconds apart, representing my double-tap. So we now know that we can safely ignore everything in the log that happened before the time 11:55:00.767. Leave that window open with just those entries showing, as a reminder.

Normally the first subsystem on the scene to handle those actions is LaunchServices. In the third window, change the search field 🔍 popup menu to Subsystems, type launchservices in the Search box, and press Return.

Sure enough, from a time of 00.779 seconds, only 0.012 seconds after the second tap, LaunchServices reports that it’s getting ready to launch Pages through RunningBoard, and constructs its EnvironmentDictionary for the purpose. This is the cue to move onto the fourth window, where we set the popup menu to Subsystems again, enter runningboard into the Search box, and press Return.

This details the launch request being handled by RunningBoard, which a few moments later constructs and reports an extensive job description for Pages. Another early arrival during the launch process is TCC to check the new app’s privacy access. In the fifth window, set Subsystems again, and search on tcc.

So far we’ve ignored another group of subsystems and processes that are more interesting than the drudgery of TCC, security. For a first look at how this is checked, switch the popup to Processes and search for amfid, the service for Apple Mobile File Integrity (AMFI) checking.

This shows its check entering first the path to the main executable at 00.805 seconds, two immediate security checks being called, then entering the path for one of the frameworks inside the Pages app bundle 0.05 seconds later. We can readily trace each framework check through the rest of the launch process in this view.

A more general summary of security checking milestones is provided by com.apple.syspolicy.exec, so switch the popup to Subsystems, and search on syspolicy.

This reveals how syspolicyd called a Gatekeeper process assessment on Pages, showed that the code had already been evaluated (despite it not having been run previously in this session), and allowed the launch to proceed without any further checks like an XProtect scan being made.

Finally, for a permanent record of this launch, in any of the windows click on the Save button to write all 41,712 log entries to a Rich Text file. That turned out to be 9.3 MB in size, so I’m glad I’m not still trawling through that trying to make sense of its contents.

To do this, LogUI will require a little more memory: in this case, working with five windows, each with over 40,000 log entries, LogUI took 520 MB. I think the convenience is worth that small cost, but I am going to return to Xcode to see if that can’t be managed better and reduced in size.

At the moment, LogUI doesn’t use any tricks to share a single log extract across different windows, and I’m wondering why and how that could be improved. One approach might be to obtain a single log extract as a Project, from which you can open individual windows for different searches. Although that shouldn’t be difficult to code, it would make LogUI more complex to use, and limit the flexibility of each window. Please try this out yourselves and let me know what you think. For now, I’m surprised at how useful search can be across several open windows.

Search your log extracts with LogUI build 42

The biggest shortcoming of the first versions of LogUI has been their lack of search or find. If you needed to look for anything, the best approach was to save an extract as Rich Text and search through that. I’m delighted to offer a solution in LogUI 1.0 build 42.

Ulbow already supports Find for its log extracts, but that just searches the text contents regardless of which field the text appears in. Sometimes that works well, but if you want to look for specific field entries it’s highly inefficient. When working with its Lists, SwiftUI is different, and its regular Search doesn’t just find text, but only displays those items in the list that contain the text in a given field.

What I’ve attempted to do here is follow the SwiftUI model, so search returns only those log entries that contain the search text, but provide support for searching four different fields:

  • the contents of the message,
  • the process name responsible,
  • the name of the sender,
  • the subsystem.

All searches are performed as case-insensitive for simplicity and speed.

The best way to see how this works is to try it.

Here I’ve simply obtained a 20 second period of recent log, with Max entries set to accommodate them, a total of over 13,000 entries, far too many to search through manually.

I left the search field, in the popup menu next to the magnifying glass symbol 🔍, set to Messages, then typed cfprefsd into the search box at the top right, and pressed the Return key to initiate the search. This returns all the entries in that log excerpt that contain the text cfprefsd in their message field.

SwiftUI can perform live incremental search, so that as you type characters into the search box, the search is performed. While that can be impressive on shorter lists, and minimises the number of characters you have to type in for a useful result, it’s costly when performed on large lists, and with log extracts can be quite distracting. If you want to see live search in action, I’ve used that in AppexIndexer, where it only has to deal with a few hundred rows at a time.

I then select one of those.

Having found all those entries containing cfprefsd in the messages, I switch the popup menu to Processes and press the Return key again. If the search box has lost the focus, the Mac will ‘beep’, so all you do is click on the search box and press Return to perform the search.

Now the window contains all those log entries containing cfprefsd in their process name. Note how the previously selected entry is still highlighted: selections in log entries should be preserved throughout searches.

For the final search I set the popup menu to Senders, and press the Return key.

This time there are no log entries that meet the search criterion, and the window informs you of that.

To return to the full log extract at any time, empty the search box, perhaps using its 🅧 tool, and press Return.

When you save a log extract in the midst of searching, the file should still contain the whole of the extract, not just what’s currently visible in the search. You should be able to copy only selected entries from a search, though.

As it stands, LogUI now has a toolbar containing the search box and two rows of settings and controls below that. I’m open to suggestions as to how that could be changed or reordered, ideally to reduce it to two rows without increasing minimum window width.

LogUI 1.0 build 42 is now available from here: logui142
and from its Product Page.

I hope you find it useful and more productive.

A primer on predicates for LogUI

All good log browsers provide tools to narrow down the log entries they display. Without those, it would be easy to waste all day wandering through tens of thousands of entries. One common tool provided by macOS, directly and in the log command tool, is filtering using predicates. Although LogUI provides easy access to simple predicates, to get the best from them, it’s worth digging a little deeper, as I do here.

Instant predicates

LogUI’s instant predicates filter log entries according to any of four basic predicate types:

  • subsystem, such as com.apple.sharing, the field shown in yellow in log extracts;
  • eventMessage, the text message listed in white/black at the end of each entry;
  • processImagePath, such as mediaanalysisd, shown in blue, the name of the process making that entry;
  • senderImagePath, such as libxpc.dylib, shown in red, the name of the process sending that entry.

These are quick to enter in the text box to the right of the popup menu in the window’s toolbar, but in many circumstances can prove too broad, and need narrowing down further. In other situations, you want to browse entries from two subsystems, or using a combination of criteria. The best way to do that is to write a short predicate. For single use, you can do that in the one-off predicate editor using the Set button.

When you want to reuse that, you can add it to the predicate popup menu using Settings Predicate (currently a bit kludgy).

Predicates

macOS can use predicates in other situations, most commonly for Spotlight search. If you’re interested in those, see Apple’s Predicate Programming Guide. Here I’ll describe predicates as they’re more commonly used to filter log entries, as they’re usually much simpler.

Each simple predicate consist of three parts:

  • the name of one of the fields in a log entry, such as subsystem or eventMessage. This sets where the filter looks in each entry;
  • an operator, which might be == for ‘equals’ exactly, or for text is commonly CONTAINS[c] for case-insensitive contains;
  • text or a numeric value to look for, such as “error” or 513. Only those entries equalling or containing (or whatever the operator means) this in the specified field will then be returned from the log and displayed.

Here are some basic examples.

eventMessage CONTAINS[c] "error"
entries will only be those with the text error in their message field.

subsystem == "com.apple.duetactivityscheduler"
entries will all have that text, ignoring case, but only that text, as the name of their subsystem.

subsystem CONTAINS[c] "com.apple.xpc"
entries will have any subsystem containing that text, which also includes com.apple.xpc.activity.

Fields

Although you can use any of the fields shown in LogUI (and some that aren’t), the most commonly used are, in order as they are shown in LogUI’s window:

  • eventType (red) – matches the type of event, such as logEvent (1024), traceEvent (768), activityCreateEvent (513), or activityTransitionEvent (514). Can be given as characters (case-sensitive) without quotation marks, or using the digits given in parentheses. Use these only with the operators == or !=, as they are treated as numbers rather than text.
  • category (green) – this matches the category, and varies according to subsystem. This is given as text in quotation marks, and is normally lower-case.
  • messageType (white/black) – matches the type of message for logEvent and traceEvent, and includes default (0), release (0), info (1), debug (2), error (16), and fault (17). Can be given as characters (case-sensitive) without quotation marks, or digits as shown in parentheses. Use these only with the operators == or !=, as they are treated as numbers rather than text.
  • senderImagePath (red) – this matches the text pattern in the name of the sender, which might be the name of a library, extension, or executable.
  • processImagePath (blue) – this matches the text pattern in the name of the process that originated the event.
  • subsystem (yellow) – this matches the subsystem specifier, e.g. com.apple.TimeMachine, given as text in quotation marks. You may find it best to use CONTAINS[c] rather than ==, to allow for differences in case and extended subsystem specifiers.
  • eventMessage (white/black) – for this, you specify a text pattern, or text, within the message, given as text in quotation marks.

Operators

The following comparisons and other operators are available:

  • == (two equals signs) for equality
  • != or <> for inequality
  • >= or => for greater than or equal to
  • <= or =< for less than or equal to
  • > for greater than
  • < for less than
  • AND or && for logical and
  • OR or || for logical or
  • NOT or ! for logical not
  • BEGINSWITH, CONTAINS, ENDSWITH, LIKE, MATCHES for string comparisons, using regex expressions when desired; strings can be compared with case insensitivity and diacritic insensitivity by appending [cd] to the operator, e.g. CONTAINS[c] means case-insensitive comparison
  • FALSE, TRUE, NULL have their expected literal meanings.

There are others as well, but you’ll seldom use them to filter log entries.

Building complex predicates

To see the scheduling and dispatch of background activities by DAS-CTS, you need to look at log extracts showing both their entries. Use the predicate
subsystem == "com.apple.duetactivityscheduler" OR subsystem CONTAINS "com.apple.xpc"
to do that. The first part of it includes those entries from DAS, and the second includes those for XPC and its relatives that run CTS. Using an OR between the two parts combines both sets of entries in the one extract.

To see the reports posted by XProtect Remediator, you need to look at those entries made by its subsystem that have the right category, using the predicate
subsystem == "com.apple.XProtectFramework.PluginAPI" AND category == "XPEvent.structured"
Using the AND operator ensures that the only entries shown come from that one subsystem, and they are given just that category.

Time Machine involves a combination of different subsystems and messages. To get a good overview of relevant entries, you can use
subsystem == "com.apple.TimeMachine" OR
(subsystem == "com.apple.duetactivityscheduler" AND eventMessage CONTAINS[c] "Rescoring all") OR
(subsystem == "com.apple.xpc.activity" AND eventMessage CONTAINS[c] "com.apple.backupd-auto") OR
eventMessage CONTAINS[c] "backup" OR
eventMessage CONTAINS[c] "Time Machine" OR eventMessage CONTAINS[c] "TimeMachine"

I’ve broken this down into separate lines, but you shouldn’t do that in the predicate. Taking it line by line it becomes simpler to understand. Use parentheses () to group each part of the predicate carefully as shown.

You can see other examples in the Help book for my free utility Mints: the Further Information pages towards the end give each of the predicates that Mints uses for its log extracts.

Quick summary

  • [field name] [operator] [text or numeric value]
  • common field names: senderImagePath, processImagePath, subsystem, eventMessage
  • common operators: ==, CONTAINS[c]
  • filter info: “text”
  • combine filters using AND, OR.

LogUI build 37 now has more power for browsing the log

By anyone’s standards, the macOS log contains a great many entries, and being able to filter out the noise is essential. This is accomplished by applying predicates to determine which entries are extracted and shown in a log browser like LogUI. However, using predicates requires knowledge about the log and its entries, and forms the greatest barrier for most users. This new version of LogUI improves features to help you use predicates to make the log more accessible.

This all happens in the toolbar of its browser window.

The section at the left of the lower row of tools now provides two methods to apply your own predicates: a one-off predicate editor, and an editor for custom entries in its popup menu.

One-off predicates

Click on the Set button to open the one-off predicate editor.

Here you can compose and paste in your own custom predicates that will extract only the log entries that you’re interested in. In this example, only entries whose subsystem is com.apple.duetactivityscheduler, or contains com.apple.xpc, will be gathered and displayed. Those tell you what’s going on with DAS and CTS scheduling and dispatch of background activities.

LogUI keeps that one-off predicate, even after a restart, as it’s automatically written to its preference file.

Once you’ve clicked Save, selecting the [ … ] item in the predicate menu will apply that predicate to each log extract you obtain.

There’s also an additional standard predicate using the senderImagePath.

Custom menu predicates

Predicates listed in that menu below blowhole are custom predicates saved to LogUI’s preferences using its new Predicate tab in its Settings. This editor is very basic at the moment, and its use a little awkward. This is because SwiftUI much prefers menu contents to be static, so adding items to the predicate menu doesn’t go down too well. This editor allows you to add one predicate at a time, in plain text format.

Click on the Append button here and there’ll be a new predicate named XProtect Remediator with the predicate shown. You can only add one new predicate, then need to quit the app before adding another. I’m sorry that’s so laborious, but once you have set up your custom predicates you can return to using LogUI fully.

The Settings General pane now contains a button to Reset Predicates back to their defaults.

Predicates

A basic predicate is composed of a log field name, like subsystem, followed by an operator such as == (equals) or CONTAINS[c] (case-insensitive contains), and a filter term, usually a string like "com.apple.xpc". So the predicate
subsystem CONTAINS[c] "com.apple.xpc"
will return all log entries with their subsystem containing the text com.apple.xpc. You can combine those basic elements into a more selective predicate using combinators such as AND and OR, so
subsystem == "com.apple.duetactivityscheduler" OR subsystem CONTAINS|c] "com.apple.xpc"
returns entries with a subsystem of precisely com.apple.duetactivityscheduler together with those whose subsystem contains the text com.apple.xpc.

Some years ago I wrote a primer here, and you’ll find some useful predicates in the Further Information section in the Help book for Mints. I’ll be writing more here to help you get the best out of LogUI.

There are a couple of oddities with predicates. SwiftUI tends to like using typographic double-quotation marks, but the macOS predicate builder doesn’t accept them as a substitute for straight marks. So LogUI changes all styled marks to straight ones automatically for you, to ensure those shouldn’t cause a problem. However, when it encounters errors it can behave erratically; while I’m trying to make this more robust, I apologise in advance if using a broken predicate upsets LogUI. It’s worth being careful to check your predicates before trying to use them.

LogUI version 1.0 build 37 is now available from here: logui137

My next task is to improve editing and saving predicates to its preferences, to make them accessible as menu customisations.

LogUI log browser build 31 has better filters

This week’s new features in my lightweight log browser LogUI tackle two important areas: initial checks to confirm that the app can access the log, and improving the filtering of log entries using predicates.

LogUI has three key requirements:

  • that the Mac is running macOS 14.6 or later, as enforced by macOS;
  • that it’s run from an admin account, as that has the privileges required to access the log;
  • that there are log records it can access in the path /var/db/diagnostics, as without those it hasn’t got anything to work with.

LogUI 1.0 build 31 now contains code to check the latter two, run soon after launch. If either fails, you’ll see an informative alert, and the app will quit when you click to dismiss that.

LogUI now has internal features to support a wide range of filters that can be applied when fetching log entries. These are an essential means of reducing the number of entries displayed, and of focussing your attention on what’s important.

This is reflected in its Settings, which now refer to Text rather than a Subsystem. The window toolbar now has a Predicate popup menu, and its text box is labelled text rather than Subsystem.

This menu offers the following options:

  • none, which applies no filtering and displays all log entries;
  • subsystem, which uses the text entered as the name of the subsystem whose entries are to be displayed, as in the previous builds;
  • eventMessage, which shows only those log entries whose message contains the text entered;
  • processImagePath, which shows only entries whose process name (or path) contains the text entered;
  • [Edit], which in future will open an on-the-fly predicate editor, but currently doesn’t filter;
  • TimeMachineBasic to blowhole, which use set predicates to display log entries for those features. The first two are different levels of detail for Time Machine backups, error finds entries with that word in their message, kernel finds entries with the kernel as their process, and blowhole finds entries made by my command tool for writing entries in the log.

Text entered is not case-sensitive.

Although it’s currently possible to change and extend those, that involves delicate surgery to LogUI’s preferences Property List, and I don’t intend you to hack that just yet. The next features will provide a proper editor in LogUI’s Settings, and the on-the-fly editor accessed through this menu.

Otherwise LogUI should work just the same as the last build. These new features are documented in its Help book, a separate copy of which is supplied in its Zip archive.

LogUI 1.0 build 31 is now available from here: logui131
and I will shortly be giving it an entry in my log browser Product Page, to make it easier to access. I’m also looking at building an auto-update mechanism into it.

Please let me know how you get on with this, and whether it proves useful to you. Enjoy!

Browse your Mac’s log with LogUI

If you ever need to understand what’s going on in your Mac, reading its log is essential. However much you might stare at Activity Monitor, read source code or disassemble components of macOS, what you can see in the log tells you what has really happened. Whether it’s a bug or an unexpected event, it’s the only way to look back and discover what went on.

For most, Console isn’t the right tool. It only offers the options of viewing its live stream, or making an archive of the whole log and wading through that when you need to look at an event in the past. Although my log browser Ulbow gives much better access, for many it’s still a daunting task. I’ve now switched almost entirely to using my new lightweight log browser, LogUI, and here explain how you can use it. Although it’s currently an early release with limited features, you should find it ideal for getting started.

LogUI 1.0 build 27 is available from here: logui127

This comes as a Zip archive, so unZip it, and move the LogUI app to another folder before running it for the first time; your main Applications folder is fine, and almost anywhere will do nicely. Alongside it is a copy of the PDF Help file that’s also inside the app, so you can refer to it when you’re not running LogUI. As the two are identical, you can trash the separate copy if you’re happy to use that inside the app.

Before opening LogUI, generate an event that you can examine in the log. One starter might be launching an app. Try to do this when your Mac is otherwise quiet and unoccupied: if Activity Monitor shows it’s busy with lots of background tasks, then the log could be filling with noise, when what you want most is peace. For the sake of simplicity, time this on an even minute, and make a mental note of that time to the second.

As soon as you’ve done that, open LogUI and you’ll be greeted by its window, with its toolbar ready for you to set up and get your first log extract. That should be set as follows:

  • Start to the current date, hour and minutes. As those are set to the time you open the window, they should already be close to the time of the event. Just after the stepper control is the seconds setting. If the event occurred a moment after the seconds changed to 00, that makes a convenient time to start your log extract.
  • Period set to around 5 seconds. This value can be floating point decimal, so might be 2.5 seconds for a smaller log extract.
  • Max entries set to 1000 to start with.
  • Show Signposts not ticked.
  • Full Fields ticked.
  • Subsystem empty.

Then click on Get Log to see the log extract for that period.

In my case, a five second period overfilled the 1000 I had set in Max entries. Scrolling to the foot of the extract showed that had been reached in less than two seconds, so I increased Max entries to 10000 and clicked Get Log again.

There are now over 5,000 entries in the extract, but they scroll smoothly enough to let me look around them.

The best way of reducing the number of entries to make them more understandable is to add a Subsystem as a filter. In this case, as I’ve launched an app, I can get most useful information from LaunchServices, by entering
com.apple.launchservices
into Subsystem. I also reduce the number of fields shown by unticking the Full Fields box, letting me concentrate on the messages. You can toggle Full Fields without having to get log entries again, as it only affects the fields within those entries that are shown in the window. Then click on Get Log again.

Scrolling down through the 358 entries remaining, I quickly reach one with a message field reading
LAUNCH: translocate to <private> from <private>
Although we could do without the privacy censorship here, it’s easy to work out that the app I just launched underwent app translocation, and that’s confirmed a little further down when LaunchServices gives its full path.

If you want a copy of the text from one or more selected entries, use the Copy command (Command-C), then paste it into any text editor. That doesn’t copy all the fields, only those you’re most likely to need elsewhere. For a full copy of that log extract, with colours indicating the fields, click on the Save as RTF button. As with LogUI’s window title, saved files are given default file names containing the start time of that log extract to help you keep them in good order.

This is the same log extract seen in my rich text editor DelightEd.

Finally, open LogUI’s Settings to enter the defaults you want its windows to open with. These match controls in its toolbar. The last of those, Light Mode, enables you to run the whole app in Light Mode if you prefer. For that to work, your Mac will also need to be in Light Mode, and you should tick that box, close the Settings window and quit the app. When you next open it, it should operate in Light Mode. Other changes made to Settings don’t need you to quit the app for them to take effect.

Enjoy!

预言在应验:五年前所讨论的未来人机交互的新范式_6.ylog

从 2024 年的今天,回望 2019 年的 Apple 和 Ive 团队,我们会发现有些变化和趋势似乎是早已注定的。在过往的观察和分析中,我们所预言的事情正在成为现实和主流。常言道以史为镜可以知兴替,今天再看当时的 Apple 和 Ive 团队,关于产品的演进思路和设计策略的变化都早有端倪,也能预见在 AI 席卷的浪潮下,Apple 将会如何应对。

在这一期,你会听到:

—- 二十年前的专利文件:通体透光的 iPhone

—- 国产厂商和 Apple 在设计上的差异

—- 成功的设计:AirPods 只是剪掉线的 EarPods

—- 塑料手机的设计巅峰:iPhone 5c

—- 刘海与机器视觉:早早布局的 AI 伏笔

—- 未来十年的人机交互:人和人之间怎么交互?

—- 设计策略上的「S型曲线」体现在哪里?

—- 产品路径上迷路的 iPad

—- 光洁的划痕:是矫情还是哲学?

—- 史上最佳手机壳:iPhone 5c 的多彩硅胶壳

—- 拟物化的残党,现在理解扁平化的先进性了吗?

|相关图片|

首款 Unibody 设计于 2008 年 10 月发布
截图来自:Designed by Apple in California

查看更多图片和设计讨论:Mac Pro 2019

|拓展阅读|

如何评价 iPhone X 的工业设计?

交互的王,时代的狂!万字详解灵动岛的今生来世!

十年轮回?经典进化!工业设计师深入解读 iPhone12!

从技术寿命 S 曲线,看阳极氧化铝的设计

抽象的产品,用户「界面」的设计

如何看待 Evans Hankey 从 Apple 设计团队离职?

注定会离职的 Jonathan Ive 和科技产品的设计趋势

|登场人物|

苏志斌:工业设计师,车联网智能硬件产品经理 / 联创,《设以观复》作者

王汉洋:AI 行业从业者,多档播客主播,《拯救东北1910》《山有虎》作者

|相关链接|

若你所使用的播客客户端未能完整显示插图,或遇网络问题未能正常播放,请访问:

荒野楼阁 WildloG 的地址:https://suithink.me/zlink/podcast/

阅读设计相关的各类文章:https://suithink.me/zlink/idea/

|其他社交网络媒体|

苏志斌 @ 知乎|SUiTHiNK @ 即刻 / 微博

苏志斌SUiTHiNK @ Bilibili / YouTube / 小红书

|联络邮箱|

suithink.su@gmail.com

欢迎在 小宇宙、Spotify、YouTube、Apple Podcast 收听本节目,期待你的留言。

❌