Take advantage of Xcode’s hidden diagnostics to debug multi-threaded application code

PreviewMarkdown’s Thumbnailer component, an App Extension which generates Finder icon thumbnail previews of Markdown documents, recently started showing some odd behaviour. Tracking down the cause provided some interesting insights into writing macOS software for a multi-threaded environment.

Thumbnailer-rendered thumbnails

What was the issue? Sometime Thumbnailer wouldn’t generate a thumbnail. Instead, the file would be presented with a generic icon or an editor-specific one. I saw the issue first with the Big Sur developer beta release and with macOS 10.15.6. I figured it was a problem with how Finder was caching thumbnail data. Since it didn’t happen with every file — and even then you could get an icon if you adjusted the icon size — I decided it wasn’t urgent and put it to one side to look at later.

Then a customer mentioned it, and since the issue had not gone away with subsequent 11.x and 10.15.x releases, I decided it was time to take a closer look.

macOS’ QuickLook manager has a way to clear the thumbnail cache, but that doesn’t really work on Catalina or above. Logging out does, but that revealed caching was not the issue. And so I looked at the crash logs. Thumbnailer was falling over at certain times with addressing issues or virtual memory faults, usually on threads other than the main one. The crashes were occurring when Finder asking Thumbnailer for one or more icon images.

How to generate icon thumbnails

To recap on how Thumbnailer works. It’s implemented as sub-class of AppKit’s QLThumbnailProvider. When Finder is presented with a Markdown file, it instantiates my sub-class and calls its required provideThumbnail() function. Finder passes in a reference to the file it needs an icon for. My function uses that reference to read the file and render its Markdown content. Eventually it calls a handler function that Finder also passes into the provideThumbnail() call.

The handler receives a closure, which it subsequently calls to draw the Markdown render from Thumbnailer into the current graphics context.

And, bingo, your Finder window shows a thumbnail preview of your Markdown file.

Unless, that is, the above sequence fails at some point. In which case you get a generic doc icon.

Tracking down the failure is tricky because everything happens asynchronously — and several layers deep at that. I don’t know when my Thumbnailer code will be called. I can call the supplied handler function promptly, but I don’t know when the closure I pass to it will be executed. This means I can’t sit and watch the log in Xcode tell me what’s going on at any one time. Nor can I set breakpoints to pause the code and observe its state at that point.

If you know what a closure is, you can skip to the next paragraph. A closure is a block of code that can be passed to a function and called at any time. Unlike a reference to a function, a closure bundles (‘closes over’ in the jargon) all the data it will process. In passing a closure, you are essentially saying, ‘At some point I want you to run this code and for it to work with this data.’ Closures are common in languages like JavaScript where you’re typically writing code that will be called in response to some event over which you have no control, but are now found in pretty much any language where asynchronous operation is likely.

I should have mentioned that Finder, if it sees multiple Markdown files at once, will spin up multiple threads, one per file up to a limit, and call Thumbnailer’s provideThumbnail() function from each one.

Xcode’s ‘hidden’ diagnostic tools

Xcode provides some useful Instruments for tracking down memory issues such as leaks, and to track memory allocations, and you can attach them to apps called asynchronously, like Thumbnailer. The other thing you can do is enable various thread and memory diagnostics in your code’s build scheme — accessed from Xcode’s Product menu. These are compiled into your app, but can provide a host of extra information in crash logs. You don’t want to include these in shipping builds — they add way too much latency, which can itself lead to failures — but they do provide useful guidance when you’re reviewing logs.

Xcode’s app debugging instruments can help you track down really tricky issues

I discovered these tools by searching the online Xcode user manual, but by then I had already refactored my code so that I was using an autorelease pool to ensure the many NSAttributedStrings being generated in the rendering process were correctly being disposed of. I figured this was probably unnecessary, but you never know. I also shifted almost the entirety of my provideThumbnail()‘s code into the declaration of the closure I pass back to the handler. As I added each one, I didn’t see much improvement: 98% of icons were being rendered correctly, the remainder were not. And it wasn’t the same files every time.

Don’t ignore — though it’s easy to miss — Xcode’s runtime diagnostic options

Clearly memory wasn’t really the issue — what about threading? I don’t have a lot of experience here beyond using macOS’ Grand Central Dispatch (GCD) in another app to ensure Internet-delivered log messages are presented on screen in the order in which they arrive. The combination of the extra information from Xcode’s compiled-in diagnostics and my research led me to realise what I was seeing was a classic race condition: thread A was changing data while thread B was still using it.

Here’s a basic example:

  1. Thread B checks a string is not empty.
  2. Thread A clears the string.
  3. Thread B, thinking it has a valid string, tries to read character x… and crashes because x is no longer there (A cleared it).

By now I had also applied GCD to ensure the closures run on the main thread because a lot of Cocoa, especially UI-related code, expects that to be the case.

Race tracked

However, the revelation about possible race conditions led me to refactor the code so that within the closure only local variables are mutated and the closed over variables are only ever read, never written. Thumbnailer of necessity stores globally some values read in from your user preferences, which can change between runs. So I moved that code into the sub-class’ initialization code.

What I was originally doing wasn’t wrong. If the code hadn’t had to contend with being called by an arbitrary thread — in a user-launched app, for instance — it would have been just fine. It just wasn’t when called by the system.

With the new version of Thumbnailer, any given thread can read data common to all threads but never write it. All writing is done with variables local to the thread (or to rather the closure that thread is processing).

So far, so good. And I’ve even been able to remove the code which forces everything onto the main thread so that thumbnails can be rendered in parallel rather than one after the other. This is particularly good when Finder has to generate a lot of thumbnails at once.

The moral of the story, then, is that just because you’re not writing code with threading in mind, doesn’t mean you can pay no mind to threading.

Other learnings include:

  • Always check the crash logs in cases when code can fail silently, usually because it was executed asynchronously and has no UI component. NSLog() statements will get lost, as will print() calls.
  • Find out about Xcode diagnostic tools: not only Instruments but also the Address and Thread runtime sanitizers — they can provide valuable guidance.

A new version of PreviewMarkdown is in pre-release testing. It has a new feature too — watch this space for more details and news of when it’s available. You can get the current version from the Mac App Store.

Further Reading

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s