MacKuba

Kuba Suder's blog on Mac & iOS development

WWDC 14

App ClipsAppKitExtensionsFoundationLocationLoggingMacMapsPerformancePhotosPrivacySafariSwiftSwiftUIUIKitWatchKitWWDC 14WWDC 16WWDC 18WWDC 19WWDC 20

View as index

Fix Bugs Faster Using Activity Tracing

Categories: Foundation, Logging 0 comments Watch the video

⚠️ The APIs mentioned in this talk seem to be somewhat abandoned – they were never made available to Swift, some things have been deprecated or have stopped working.


Apple has been adding a lot of tools for asynchronous development, like XPC, GCD, NSOperation

However, splitting work between different threads and especially between different processes makes it difficult to debug and diagnose issues

A single call to a system API might result in multiple system daemons calling each other to execute this single activity

Current logging mechanisms are insufficient, because they lack context showing how you got to the place where something happens

When something goes wrong in one of the systems involved, the whole activity fails, but it’s not clear where to look for the problem

Goals of this new tool:

  • reduce the time guessing what happened where, how did it get there and why
  • understand interaction of multiple actions over time
  • it should be lightweight and easy to use

Activities

Activity = a set of work triggered by a specific action, going across multiple systems cooperating to realize a specific goal

There’s a new system daemon diagnosticd that handles the activity tracing for all processes

Each activity has an identifier (AID) automatically propagated across the system

Activities are automatically created by UIKit and AppKit for UI actions

When you e.g. press a button in the UI, AppKit or UIKit automatically creates a new activity with some unique name, calls os_activity_start() on it, calls your IBAction handler, and then calls os_activity_end() at the end

You can also create activities explicitly:

os_activity_initiate("Activity Name", flags, ^{ … });
  • name must be a constant string
  • another variant available without a block
  • included in <os/activity.h>

Detached activity (OS_ACTIVITY_FLAG_DETACHED) = a new activity that’s not a subactivity of the current one, but a completely independent activity

Breadcrumbs

Breadcrumb = a user-facing or user-initiated action that triggered an activity, e.g. “Send an email”

A way to label activities meaningful to you

Adding a breadcrumb:

os_activity_set_breadcrumb("composing email");
  • name must be a constant string
  • only supported in the main process binary, not in libraries or plugins

⚠️ Replaced later with os_activity_label_useraction, only for activities started from IBActions

Trace messages:

Trace message = a single log in a given system as a part of an activity

New API to add trace messages to the current activity

Messages are stored in an in-memory ring buffer

Different behavior for production code and debugging

os_trace("Something happened at level %d", index);
  • only scalar format types allowed (ints, longs etc.)
  • strings and characters are *not* supported for privacy, security and performance reasons
  • included in <os/trace.h>
os_debug_trace("Open socket %d total time %f", sock, time);
  • version for debug logging
  • only actually logged if you’re in the debug mode, ignored in release mode
  • records more information – increased buffer size
  • you can enable debug mode at launch by setting env variable OS_ACTIVITY_MODE=debug

If you want to pass some additional data with a trace message, you can use os_trace_with_payload:

os_trace_with_payload("Interface: %ld", index, ^(xpc_object_t dict) {
    xpc_dictionary_set_string(dict, "interface_name", ifname);
});
  • blocks are only called and have their data recorded if the activity logs are being currently live streamed to a log viewing tool
  • uses XPC to deliver data to diagnosticd
  • you can enable stream mode with an env variable OS_ACTIVITY_MODE=stream

⚠️ Replaced later with os_log

Crash logs now include information about the current activity at the moment of the crash (name, running time etc.), the last few breadcrumbs, and recent trace messages from that activity (!)

⚠️ They don’t anymore :(

Logging errors into trace messages:

os_trace_error("Interface %ld failed with error %d", ifindex, errno);
  • soft errors, something that went wrong
os_trace_fault("Invalid state %d - will likely crash", state);
  • fatal errors, this shouldn’t happen, about to crash
  • sends trace messages from the process’s local buffer to diagnosticd

Limits:

  • format string cannot exceed 100 characters
  • formatted trace message string also has a limit, will truncate if exceeded
  • up to 7 parameters allowed
  • process ring buffer size depends on the platform and debug/release mode

Debugger: thread info includes current activity info and last trace messages

ostraceutil command line tool – live streaming of activity trace from a process (by name or pid)

⚠️ Replaced later with log

Tip: think about privacy when adding trace messages – never trace identifying information about a user or device