MacOS Catalina: Slow by Design?

Here's some shell script to use a random file name and have friendlier output.

  RAND_FILE="/tmp/test-$RANDOM.sh";
  time_helper() { /usr/bin/time $RAND_FILE 2>&1 | tail -1 | awk '{print $1}'; }  # this just returns the real run time
  echo $'#!/bin/sh\necho Hello' $RANDOM > $RAND_FILE && chmod a+x  $RAND_FILE;
  echo "Testing $RAND_FILE";
  echo "execution time #1: $(time_helper) seconds";
  echo "execution time #2: $(time_helper) seconds";

Introducing a network delay makes the effect much more obvious. Normally I see a delay of about 0.1 seconds, but after using the XCode network link conditioner (pf rules) to add 500ms latency to everything the delay shoots way up to ~2 seconds.

example output:

  Testing /tmp/test-24411.sh
  execution time #1: 2.32 seconds
  execution time #2: 0.00 seconds

with developer tools checked both executions report "0.0 seconds".

Huh this is crazy. 2 seconds is way slow and this shouldn't involve any network activity. Seems like a real problem.

He/she added an artificial network latency/delay into the config, just like they describe. That is the reason for the delay. It is made artificially long on purpose.

I tried just blocking "api.apple-cloudkit.com" with /etc/hosts. This reduces the delay but doesn't eliminate it. A connection attempt is still made every time. (I don't recommend making this change permanent. Just give your terminal app the "Developers Tools" permission instead)

After blocking that domain I can see that tccd and syspolicyd are logging some error messages to the console related to the failed connection. I don't recommend blocking because my guess is that'll put syspolicyd/tccd in some unexpected state and they'll repeatedly keep trying to make requests.

Try this for watching security related console log messages:

  sudo log stream --debug --info --predicate "processImagePath contains 'tccd' OR processImagePath contains 'syspolicyd' OR processImagePath Contains[c] 'taskgated' OR processImagePath contains 'trustd' OR eventMessage Contains[c] 'malware' OR senderImagePath Contains[c] 'security' "

syspolicyd explicitly logs when it makes the network request.

   syspolicyd: cloudkit record fetch: https://api.apple-cloudkit.com/database/1/com.apple.gk.ticket-delivery/production/public/records/lookup, 2/2/23de35......

(you need to enable private logging to see that url)

Enabling private logging is fairly annoying these days, unfortunately. (Interestingly, if macOS thinks you're AppleInternal, it will make it just as annoying to disable private logging…)

It’s not an unreasonable delay on a slow 3g hotspot. It’s problematic to have the performance tied to the network speed and suffer an overall slow performance because your network happens to be slow.

wait a sec...I recognize that name. I only know how to enable private logging thanks to your detailed and informative blog post! Seriously, it's one of the favorite macOS things I've read in a while. I loved the step by step walk through using gdb you showed.

Though just today I saw that apparently an enterprise policy config can enable private logging in 10.15.3+ without having to disable SIP. https://georgegarside.com/blog/macos/sierra-console-private/

For reference for others: this is the blog post by OP on enabling private logging in Catalina. check it out! https://saagarjha.com/blog/2019/09/29/making-os-log-public-o...

Have I written anything that is contradicts that? I simply pointed out that in the example the delay was artificial, and it was definitely due to network, not due to something other than network, as the comment suggested.

I’m glad you appreciated it, but I think it also happened to be some of the fastest-to-deteriorate advice I’ve given :) I should go back and revisit this, as on my system I have it currently stuck in a state where it unconditionally enables private data logging at boot (which mean my crash logs have personal information in them unless I remember to turn it off with the workaround I’ve been using until now…)