WWDC 14
Fix Bugs Faster Using Activity Tracing
⚠️ 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