hoakley Macs, Technology

Inside the Content Caching server: performance and troubleshooting

If you haven’t got it yet, anyone running more than one Mac should be using the macOS Content Caching server to minimise the quantity of downloads for macOS updates and other content which their Macs consume. I’ve already provided an overview of how to turn it on and configure a basic service. This article goes deeper to discover more about how it works, how you can monitor its performance and effectiveness, and how to troubleshoot it.

When you have a Content Caching server running on your network, other Macs connect to it when downloading Apple-provided updates and content, including files in iCloud, as set in its options in the Sharing pane. Clients, including Macs, iOS and iPadOS devices, need no configuration: once the service is turned on, the next time that they start up, they’ll automatically connect to it, and from then on, whenever they download cached content, it will be obtained from that server.

Content currently cached includes:

  • macOS updates normally obtained through Software Update or the command tool softwareupdate;
  • Internet Recovery images from macOS 10.13.5 onwards, which might include those for M1 Macs, when obtained in recoveryOS;
  • apps and their updates supplied through the Mac and iOS App Stores;
  • GarageBand downloadable content;
  • iCloud documents and data, including Photos libraries;
  • Apple Books
  • downloadable components for Xcode.

Apple’s list is here.

Apple provides quite extensive configuration options for the server, both in the Sharing pane and at the command line through AssetCacheManagerUtil. These cater for larger and more complex networks; for most small systems, they’re not required. man AssetCacheManagerUtil provides full details, as it does for associated tools AssetCacheLocatorUtil and AssetCacheTetheratorUtil. Apple provides a very helpful explanatory article which includes important recommendations for those using more complex setups. You can also configure the server by editing its Property List direct: Apple explains that here.

Performance

When the Content Caching server is running on a Mac, performance information is delivered through AssetCacheManagerUtil status and in Activity Monitor. The latter adds a new tab Cache, which provides summary statistics for the local cache.

cachingserver1

This includes the total size of data served for the last hour, 24 hours, 7 days, and 30 days. To view those graphically, the time period for the charts at the foot can be changed by using it as a popup menu.

cachingserver2

cachingserver3

As you’ll see from the last 30 days, this includes the macOS 11.4 update, for which almost 30 GB still had to be downloaded from Apple’s servers, while just over 20 GB was served from its cache. Apple explains the exact meaning of each category in this article.

There are some simple but important lessons to be learned here. Among them is how to perform a set of macOS updates most efficiently. Remember that when the server itself is updating, it can’t provide its service, and that updates delivered to M1 models are different. My server is hosted on an iMac Pro which is hardly ever shut down, and seldom restarted, ensuring almost constant availability. When possible, I prefer to download and install macOS updates on that server first. Only when it has restarted fully, and made the service available again, will I update my other Macs, so that they can make best use of the local cache.

My maximum cache size is set to 1 TB, as it enjoys fairly free run of an external 2 TB SSD. However, the server appears to remove some older downloads even though there’s no pressure on space, currently with only 130 GB used, including 5 GB iCloud. When you want to update multiple Macs, it’s generally best to do so reasonably soon after the first update, or clients may find the server has to download the whole update again.

The Content Caching server doesn’t deliver all the updates you may obtain from Apple. Manual downloads, for instance those obtained through Apple Developer accounts, are unlikely to pass through the cache. When enabled, iCloud content can be a good way of reducing both download size and delays, but in other use it may make little difference. Watch the figures shown in Activity Monitor to check how useful the additional service is proving.

Troubleshooting

The Content Caching server doesn’t maintain its own private log, but writes messages to the Unified log. To browse those, filter log show or Console output using the predicate
subsystem == "com.apple.AssetCache"
This is also extremely simple to use in my free log browsers Ulbow and Consolation 3. In normal use, the sub-system writes messages only sparingly, and it’s quite reasonable to view several hours of its entries if you wish. The rest of this article explains what you’re likely to find, to help you to troubleshoot problems with the server.

Every five minutes, the server writes a status and statistics summary, such as
Since server start at 2021-06-13 09:07:05.427: 173.5 MB returned to clients, 0 bytes to peers, 0 bytes to children; 2.6 MB stored from Internet, 0 bytes from peers, 0 bytes from parents; 48.6 MB imported.

Transactions, each prefaced by an ID for that transaction, consist of PUT and GET requests which respectively send data from the client, and fetch data from the server for a client. These start with an entry such as
#kVxKEjR0ANsK Received GET request by "cloudd/985" for /hXJqwZ4BbGIYuHECo_gP [icloud:…]
or
#VGIjGj/jbvU9 Received PUT request by "cloudd/985" to store /osfuyTsBegV6Zx1p4H05 [icloud:…]
where the initial # is the transaction ID.

A typical GET request might proceed thus (transaction IDs omitted, and entries truncated):
Received GET request by "cloudd/985" for /hXJqwZ4BbGIYuHECo_gP [icloud:…]
ECAssetHandler[0x7fce2a526870]: Asset /hXJqwZ4BbGIYuHECo_gP [icloud:…], path /Volumes/ThunderBay4/Library/Application Support/Apple/AssetCache/Data/D7AC92D4-B442-41B7-A65E-4E5186C44427, cached length 945757, MD5 (null), last-modified Mon, 05 Aug 2019 14:04:54 GMT, extents [0,945757]
ECAssetHandler[0x7fce2a526870]: Request has immutable range header = bytes=0-945756
ECAssetRequestor[0x7fce2a747700]: Skipping outgoing If-Modified-Since range request for URL https://eu-irl-00001.s3.dualstack.eu-west-1.amazonaws.com:443/…
ECResponse[0x7fce2a41f1c0]: Info loaded: response code = 304, reason code = 9, file length = 945757, reader = 0x7fce2a553680
ECAssetHandler[0x7fce2a526870]: Opened extent [0,945757] for reading at offset 0 (offset into file = 0)
Served all 945 KB of 945 KB; 945 KB from cache, 0 bytes stored from Internet, 0 bytes from peers, 0 bytes from parents
ECCacheReader[0x7fce2a553680]: canceled at offset = 945757
ECAssetHandler[0x7fce2a526870]: Removed reader 0x7fce2a553680 at 945757/945757, readers [], requestors [], will cancel 0 requestors >= 0 for asset /hXJqwZ4BbGIYuHECo_gP [icloud:…]

A PUT request might run:
Received PUT request by "cloudd/985" to store /osfuyTsBegV6Zx1p4H05 [icloud:…]
ECAssetHandler[0x7fce2a526870]: Asset /osfuyTsBegV6Zx1p4H05 [icloud:…], path /Volumes/ThunderBay4/Library/Application Support/Apple/AssetCache/Data/2834B20D-19DE-48BA-B7C6-28E756A50BC8, extents none
ECCacheManager: space requested 18 KB, current cache size 131.76 GB (limit 1.02 TB) for asset /osfuyTsBegV6Zx1p4H05 [icloud:…]
ECCacheManager: Purging asset /EcGzA78Bd5f0spwCo_rL [icloud:…] guid 8FCE9AC8-D886-4952-8A9C-F6D0617AAD18 size 203 bytes (actual 203 bytes) created 2021-02-12 20:35:34.297 last accessed 2021-02-13 10:11:11.399
ECCacheManager: Purging asset /50vrW0EBd5f0p4YCo_dF [icloud:…] guid 45754E78-4641-4AFF-AC3E-EF1747156B00 size 396 bytes (actual 396 bytes) created 2021-02-12 20:35:36.271 last accessed 2021-02-13 10:11:12.768
Removed 599 bytes in 2 assets (including 599 bytes in 2 personal [icloud] assets) from the cache to make room for a new asset
ECAssetUploader[0x7fce2a547a30]: PUTing 18703 bytes to URL https://eu-irl-00001.s3.dualstack.eu-west-1.amazonaws.com:443/…
enqueued 18703 bytes in 0.012 sec
ECAssetUploader[0x7fce2a547a30]: Upload response code 200
ECCacheWriter[0x7fce2a549b60]: Import ready: response code = 200, reason code=12
ECAssetHandler[0x7fce2a526870]: Opened extent [0,0w18703] for writing at offset 0 (offset into file = 0)
ECResponse[0x7fce2a440a90]: Import done: response code = 200, reason code = 12, writer = 0x7fce2a549b60
Imported all 18 KB of 18 KB
ECCacheWriter[0x7fce2a549b60]: canceled at offset = 18703

Other transactions you’re likely to come across are affinity requests, configuration and registration. The latter are useful, as they should include a statement of the public IP address and whether there are any other known caching servers:
Request for configuration from http://suconfig.apple.com/resource/registration/v1/config.plist succeeded
Cleanup succeeded.
Registering with local address: 192.168.63.3 (1000 Mbit/sec wired); port 52613; local subnet range only: 192.168.63.0-192.168.63.255; version: 243; on AC power: yes; cache size: ~1 TB; capabilities: im,ns,pc,qp,sc,ur; portable: no
Request for registration from https://lcdn-registration.apple.com/lcdn/register succeeded
Got back public IP 81.134.66.123
This server knows about 0 other caching servers.

Clients appear to configure and register roughly every hour.

Note that it isn’t possible to discover what items have been served, or what’s in the cache at any time. This is presumably to protect users’ privacy. However, log entries are generally informative, and careful study of them should lead you to diagnose most problems.