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.