Normal view

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

Last Week on My Mac: Checking code can take longer now

By: hoakley
4 May 2025 at 15:00

Many of you have commented that you too find that apps and command tools can now take surprisingly long to launch. Although my previous analyses have demonstrated how those can often be attributed to security checks being made on components including frameworks and dylibs, there remains some dispute over the nature of those checks. Although I believe there’s convincing evidence that those checks are prolonged to recompute hashes and CDHashes, others are adamant that they are in fact ‘malware scans’. This article considers new evidence.

Inspecting and analysing the log during the launch of large apps isn’t the best way of getting a clear view of what happens when macOS runs its security checks. There’s a great deal going on at the time, with multiple security checks being performed for TCC, LaunchServices and RunningBoard in dialog, sandboxes and containers to set up, and iCloud services to connect. Last week I’ve been tackling this more methodically, and here use two launches of a simple command tool to give clearer insights into what’s going on when macOS runs its security checks.

Methods

The command tool in question is my blowhole, just over 200 KB of simple code to write a message to the log, hence directly telling us when it’s run. It has its signing certificate embedded into its Mach-O binary, and is notarized. However, because it’s a single binary and not an app bundle, its notarization ticket is stapled to its installer package, and not to the tool itself.

The two runs I analyse here are:

  • On a Mac Studio M1 Max running macOS Ventura 13.4.1 at 14:32 on 4 July 2023. blowhole had already been installed on that Mac, but the copy being run was in a previously unknown location, ~/Documents, which normally forces macOS to perform more extensive security checks, including an XProtect scan and notarization checks, but not as thorough as when in quarantine.
  • On a Mac mini M4 Pro running macOS Sequoia 15.4.1 at 20:07 on 2 May 2025. Although blowhole had been installed and run some weeks previously, it hadn’t been run since then, and was expected to attract more extensive security checks, including an XProtect scan and notarization checks, but not as thorough as when in quarantine.

The first of those was collected using Ulbow, and the second by LogUI. Excerpts giving milestone entries are given in the Appendix at the end. In the diagrams below, each milestone is given with time in seconds elapsed since the first mention of the binary.

Ventura

First mention of the tool to be run comes from AppleMobileFileIntegrity (AMFI), which leads immediately to its daemon amfid starting its assessment of the binary, with the entry SecTrustEvaluateIfNecessary to inspect the signature and the CDHashes it contains. As this takes a mere 0.003 seconds, and the next stage starts 0.01 seconds after amfid entered the path to the binary, all that could have done was confirm the integrity of the signature, its requirements, and that its hashes were already cached.

syspolicyd then records the start of the Gatekeeper process assessment, and initiates the Gatekeeper scan, first starting checks on the notarization ticket, then starting the XProtect scan while ticket checking proceeds. Of those, the XProtect scan completes first, returning its results to syspolicyd at 0.054 seconds after the start.

Ticket checking involves an explicit connection to iCloud using CloudKit, with abundant log entries. The CloudKit Ticket Store is found to be reachable, and the ticket checked for the CDHashes obtained earlier from the tool’s signature.

With both checks completed satisfactorily, at 0.192 seconds the Gatekeeper scan is declared complete, syspolicyd evaluates its result, and is almost ready for the tool to run. Before that can happen, details of the executable are entered into provenance tracking. syspolicyd confirms the evaluation allows the tool to run, and AppleSystemPolicy records the evaluation result.

Sequoia

The sequence here is very similar to that in Ventura, with some significant differences, marked in the emphasised items in the diagram above.

First, there’s a substantial delay of 0.063 seconds between amfid entering the binary’s path and the start of the Gatekeeper process assessment. This started with entries from amfid recording SecTrustEvaluateIfNecessary and trustd SecKeyVerifySignature, indicating that more took place here than in Ventura. However, there’s no evidence of any external signature checks being made, and it’s most likely that the binary’s hashes weren’t cached, so required recomputation to verify them. The delay is woefully inadequate for any form of malware scan to have taken place at this stage.

When XprotectService reports that XProtect is performing the malware scan, it additionally reports the location of the XProtect rules being used. That’s because Sequoia introduced a new location used for those data files, in /var/protected/xprotect/XProtect.bundle/Contents/Resources/XProtect.yara as recorded here.

Next, the XProtect scan here takes 0.126 seconds, rather than 0.030 seconds in Ventura. This is the result of the huge growth in the number and complexity of the Yara rules used for this scan over the last two years. The Ventura scan was performed using version 2168 of those rules, with a Yara file of 147 KB size and around 218 rules. By version 5296 used in the Sequoia scan, file size had risen to 947 KB with about 381 rules.

Size of the binary being scanned also affects scan time, although in an unexpected way. A great many of the Yara rules used include upper limits to file size, so those larger than a few MB are subject to few rules, probably intentionally. Thus, larger binary files are likely to complete their XProtect scan in shorter time than expected, and maybe more quickly than smaller binaries.

As a result of these two delays, Gatekeeper’s XProtect results aren’t reported until 0.247 seconds have elapsed since the start, already over 0.05 seconds longer than the whole process in Ventura. However, in this case there’s no mention of provenance tracking, and the blowhole tool is finally run after 0.3 seconds, taking just over 150% of the time in Ventura.

Summary of security checks

  • Trust evaluation and signature verification, to confirm hashes and CDHashes if not cached;
  • Gatekeeper scan, including simultaneous ticket check and XProtect malware scan;
  • CDHash ticket check online using CloudKit with iCloud Ticket Store;
  • XProtect malware scan against Yara rules;
  • Gatekeeper evaluation for syspolicyd to allow or not;
  • Result registered with the kernel;
  • Command tool run.

Note that there’s no evidence of any OCSP checks being made with the certificate authority to determine whether certificates have been revoked. Additional time will be required if hashes and CDHashes are to be recomputed, and as a result of increased Yara rules.

Appendix: Log Milestones

Times are given in seconds, adjusted to a start of 0.0. The Ventura extract was obtained with log privacy disabled.

Ventura 13.4.1 2023-07-04 14:32:40 on Mac Studio M1 Max

XProtect version 2168, Yara file 147 KB, 218 rules
0.000000 AppleMobileFileIntegrity Checking in with amfid for DER co.eclecticlight.blowhole
0.001395 amfid Entering OSX path for /Users/howardoakley/Documents/blowhole
0.010608 syspolicyd GK process assessment: /Users/howardoakley/Documents/blowhole <-- (/bin/zsh, /System/Applications/Utilities/Terminal.app/Contents/MacOS/Terminal)
0.022891 syspolicyd GK performScan: PST: (path: /Users/howardoakley/Documents/blowhole), (team: (null)), (id: (null)), (bundle_id: (null))
0.023291 syspolicyd looking up ticket: {length = 20, bytes = 0xe0cad936293cea0807ec2e5193bed5f3f02dc019}, 2, 1
0.023316 syspolicyd cloudkit record fetch: https://api.apple-cloudkit.com/database/1/com.apple.gk.ticket-delivery/production/public/records/lookup, 2/2/e0cad936293cea0807ec2e5193bed5f3f02dc019
0.023554 XprotectService Xprotect is performing a direct malware and dylib scan: /Users/howardoakley/Documents/blowhole
0.053971 syspolicyd GK Xprotect results: PST: (path: /Users/howardoakley/Documents/blowhole), (team: (null)), (id: (null)), (bundle_id: (null)), {
XProtectMalwareType = 0;
XProtectSignatureVersion = 4321574501753746074;
}, version: 4321574501753746074
0.170283 syspolicyd CKTicketStore network reachability: 1, Wed Jun 21 19:33:35 2023
0.191576 syspolicyd GK scan complete: PST: (path: /Users/howardoakley/Documents/blowhole), (team: (null)), (id: (null)), (bundle_id: (null)), 4, 4, 0
0.191797 syspolicyd GK evaluateScanResult: 2, PST: (path: /Users/howardoakley/Documents/blowhole), (team: QWY4LRW926), (id: co.eclecticlight.blowhole), (bundle_id: NOT_A_BUNDLE), 0, 0, 1, 0, 4, 4, 0
0.191996 syspolicyd Putting executable into provenance with metadata: TA(917fa0aed8a1a838, 0)
0.191999 syspolicyd Putting process into provenance tracking with metadata: 1410, TA(917fa0aed8a1a838, 0)
0.192054 syspolicyd GK eval - was allowed: 1, show prompt: 0
0.192090 AppleSystemPolicy evaluation result: 17, allowed, cache, 1688477560
0.195467 blowhole Blowhole snorted!

Sequoia 15.4.1 2025-05-02 20:07:00 on Mac mini M4 Pro

XProtect version 5296, Yara file 947 KB, 381 rules
0.000 amfid Entering OSX path for /usr/local/bin/blowhole
0.063 syspolicyd GK process assessment: <private> <-- (<private>, <private>)
0.081 syspolicyd GK performScan: PST: (path: cc151acaee5bc8cd), (team: (null)), (id: (null)), (bundle_id: (null))
0.082 syspolicyd looking up ticket: <private>, 2, 1
0.082 syspolicyd cloudkit record fetch: <private>, <private>
0.121 XprotectService Xprotect is performing a direct malware and dylib scan: <private>
0.125 XprotectService Using XProtect rules location: /var/protected/xprotect/XProtect.bundle/Contents/Resources/XProtect.yara
0.247 syspolicyd GK Xprotect results: PST: (path: cc151acaee5bc8cd), (team: (null)), (id: (null)), (bundle_id: (null)), XPScan: 0,1089725382763820427,2025-05-02 19:07:00 +0000,(null),(null),file:///usr/local/bin/blowhole
0.283 syspolicyd CKTicketStore network reachability: 1, Fri May 2 17:21:52 2025
0.293 syspolicyd GK scan complete: PST: (path: cc151acaee5bc8cd), (team: (null)), (id: (null)), (bundle_id: (null)), 4, 4, 0
0.295 syspolicyd GK evaluateScanResult: 2, PST: (path: cc151acaee5bc8cd), (team: QWY4LRW926), (id: co.eclecticlight.blowhole), (bundle_id: NOT_A_BUNDLE), 0, 0, 1, 0, 4, 4, 0
0.296 syspolicyd GK eval - was allowed: 1, show prompt: 0
0.296 kernel evaluation result: 5, exec, allowed, cache, 1746212820, 4, 4, f1f7b76465d358b, 1746212820, /usr/local/bin/blowhole
0.303 blowhole Blowhole snorted!

For comparison, Catalina’s log entries are remarkably similar too.

Last Week on My Mac: Gone to launch

By: hoakley
27 April 2025 at 15:00

I looked in the macOS cupboard last week and opened yet another can of worms, in those Macs that take many seconds or even minutes to launch some apps. In common with many other thorny problems, there’s little consensus about many of the details, other than this mostly affecting Intel Macs running macOS Big Sur or later, although I have seen reports of similar problems in M1 Macs.

Although some have apparently found solutions, such as Jeff Johnson’s recommendation to disable SIP, the only consistent answer appears to be moving the app to another location and moving it back again. Even that’s only a temporary measure, and sooner or later those apps will launch slowly again.

Last week I thought I might have a chance to get to the bottom of the problem, when Kristian kindly sent me some log extracts from his Mac’s slow launches, and patterns started to emerge. But like every other good can of worms, the deeper I dig into the can, the more worms there are. This article is a convenient opportunity to reveal some of those.

What takes time?

Looking at three test launches of Pages, greatest differences were seen in the time taken to check the many frameworks in the app bundle, shown in purple in the bar chart below.

In the slow launch provided by Kristian, total time was just over 4 seconds, within which checking frameworks took 3.2 seconds, 80% of launch time. A similarly slow launch in my test VM took just over 3 seconds, with 2.5 seconds on frameworks, while a fast launch completed in just over half a second, with less than 0.1 seconds spent in framework checks.

Cache misses and SIP

What I didn’t mention in those log extracts was the role of cache misses in framework checks in the slower launches. At that stage, it looked as if differences were down to whether each framework had to be checked from scratch as its previous assessment couldn’t be found in cached security checks.

I have therefore repeated the VM tests in two further conditions, with SIP disabled, and with Gatekeeper/XProtect checks disabled.

When launched after a restart, with SIP fully disabled, Pages did indeed launch quickly, in a total time of 0.34 seconds with less than 0.05 seconds checking frameworks. However, disabling Gatekeeper resulted in a total launch time that was only slightly quicker than normal at 2.4 seconds, and 1.8 seconds checking frameworks.

Behaviour with SIP turned off was odd, in that no Gatekeeper process assessment was recorded, and there was no mention of any cache misses for framework checks. In contrast, when Gatekeeper was turned off, there was a Gatekeeper process assessment using a previous code evaluation, and cache misses were recorded for all the frameworks checked. My previous experience with disabling Gatekeeper is that its checks still take place and are logged normally, but their results are ignored, so that wasn’t as paradoxical as it might appear.

Calibre

Pages is an atypical example, being an App Store app signed by Apple, so I then turned to the other log record provided by Kristian, from Calibre. This is remarkable for having 68 frameworks, and took a total of 4.6 seconds to launch on his Mac, with nearly 4.4 seconds of that spent checking those frameworks, all of which were cache misses and reported with constraint violations by amfid.

When I tried repeating this in my test VM and with SIP or Gatekeeper disabled, results became far more complicated, so I have summarised them in a table.

Rows in this table record results from each of six launches of the current release of Calibre. The first is that obtained by Kristian on his Mac, the remainder are all obtained from a 4-core VM running macOS 14.7.5 on a Mac mini M4 Pro. Those were:

  • first run after installation, with the quarantine flag set;
  • second run a minute or so after that first run, without a restart;
  • third run after closing the VM and starting it up again;
  • after downgrading security to permissive by disabling SIP completely;
  • after disabling Gatekeeper/XProtect checks, but still at Full Security, with SIP enabled.

Total launch time is measured from the initial click in the Finder to the app loading its preferences. Time checking frameworks is measured from the start of the first check called by amfid on one of Calibre’s frameworks, to the completion of the its check on the last framework. XProtect scan is measured between the announcement of the start of Gatekeeper’s XProtect scan, and its completion.

The fastest launch by far was in the second run, when none of the checks were performed, there were hardly any log entries from security subsystems or processes, and it completed in 0.158 seconds. The slowest was the first run, when the XProtect scan took over 6 seconds, and accounted for 77% of the total launch time of almost 8 seconds.

Remaining results fall into two groups: Kristian’s original slow launch, with almost 4.4 seconds taken checking frameworks, all of them being recorded as cache misses, and the three VM tests. The latter were remarkable as launch time was uniform at just over 0.5 seconds, and a fifth of the time spent checking frameworks. That occurred because macOS proceeded to run the app before checking of frameworks was complete. In those three tests, no cache misses were recorded, and time was independent of whether a previous Gatekeeper assessment was used. Two of them even included brief local checks against the app’s notarization ticket.

Neither disabling SIP nor disabling Gatekeeper had any effect on the time taken to check frameworks, nor on the total time taken to launch the app.

Diagnosing slow launches

I have given details of my results because, if there’s one thing they demonstrate, it’s the complexity of determining app launch times. In Pages, much of the delay seems to result from cache misses slowing framework checks, and disabling SIP restored rapid launching, as Jeff Johnson reported. In Calibre, launches proceed without waiting for framework checks to complete, and disabling SIP doesn’t result in any acceleration.

This reflects the complexity of app launch. I’ve here concentrated on security checks, as they have been most commonly blamed for this problem. Other processes that have to be completed during launch include:

  • LaunchServices registration and coordination
  • RunningBoard registration and resource management
  • TCC privacy controls
  • sandbox and container preparation
  • iCloud connection
  • checks for app updates
  • all other app initialisations

several of which can involve their own security checks.

Although most of those are well recorded in log entries, disentangling them when watching Activity Monitor or in spindumps is more demanding, and there’s ample opportunity to gain false impressions.

But none of these tests or logs represent what happens in the slowest of launches that can take several minutes. Even the 8 seconds total launch time taken on Calibre’s first run pales in comparison to the 300 seconds that some report. There’s a difference of two orders of magnitude, suggesting that really long launch times are different from all the observations and measurements here. There must be something seriously wrong for an app to take several minutes to launch. Investigating that is also a great challenge.

Tackling slow launching

Results above demonstrate how subtle factors can result in fairly modest apps launching in anything from less than 0.2 to almost 8 seconds. If an app regularly takes several seconds to launch, and that irks you, try pre-warming it first. Longer times are more likely to occur after a Mac has been started up from cold, and apps usually launch fastest when they’ve already been run in the same session. Even if your Mac doesn’t have sufficient memory to leave that app running, that could make subsequent launches quicker.

If an app not infrequently takes more than 30 seconds to launch, then finding the cause becomes more important, and if it takes several minutes, you really need to investigate further.

Capturing an excerpt of the whole log for several minutes isn’t going to help, but will just overwhelm you with many MB of inscrutable data. If you know your way around spindumps, you may find them helpful, although they too can only cover brief periods of time. There are some basic steps you can take that can also help you diagnose and address performance problems more generally:

  • Measure launch time carefully and record it. Counting icon bounces in the Dock is better than nothing, and gives you an objective measure of time to launch.
  • Try in Safe mode. That disables most customising software, and any improvement in launch times points the finger at extensions, startup items and other software you have installed.
  • Create a new user and see if that account has the same problems. This can detect user-specific customisations that might be the cause.
  • Build an external bootable SSD with a ‘clean’ system, install the app(s) there, start up from it, and see whether it still launches as slowly. You can also try this using a more recent version of macOS, to see whether that helps.

The best way to preserve a record of what happened during a slow launch is to wait until the app is running properly, then perform a sysdiagnose, as that saves much of the log in a logarchive. You can initiate that in the Options … popup menu in Activity Monitor, or by pressing Command-Option-Control Shift-. (period or full stop). That logarchive can be browsed using Ulbow or even Console, but not (yet) LogUI.

I’m also keen to look at log records from one of these much slower launches. If you’re interested in cooperating, please comment below or send me an email (see the About page).

❌
❌