MacKuba

Kuba Suder's blog on Mac & iOS development

Performance

App ClipsAppKitExtensionsFoundationLocationLoggingMacMapsPerformancePhotosPrivacySafariSwiftSwiftUIUIKitWatchKitWWDC 14WWDC 16WWDC 18WWDC 19WWDC 20

View as index

Measuring Performance Using Logging

Categories: Foundation, Logging, Performance, WWDC 18 0 comments Watch the video

Signposts – a new feature of the os_log API

Useful for debugging performance issues

Integrated with Instruments, which can visualize activity over time using signposts

Signposts allow you to mark the beginning and end of a piece of work and mark it with some kind of label

import os.signpost

let refreshLog = OSLog(subsystem: "…", category: "…")

os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
// …do actual work…
os_signpost(.end, log: refreshLog, name: "Fetch Asset")

Ranges of signposts with different names can overlap – e.g. you can have one signpost covering the whole process and smaller signposts covering specific single tasks that it consists of:

os_signpost(.begin, log: log, name: "Load Data")

os_signpost(.begin, log: log, name: "Fetch Asset")
// …
os_signpost(.end, log: log, name: "Fetch Asset")

os_signpost(.begin, log: log, name: "Parse JSON")
// …
os_signpost(.end, log: log, name: "Parse JSON")

os_signpost(.end, log: log, name: "Load Data")

If you run multiple tasks of the same kind, to let the system differentiate between them and know which begin matches which end, you can add a “signpost ID”:

os_signpost(.begin, log: log, name: "Load Data")

for asset in assets {
    let spid = OSSignpostID(log: log)

    os_signpost(.begin, log: refreshLog, name: "Fetch Asset", signpostID: spid)
    // …do actual work…
    os_signpost(.end, log: refreshLog, name: "Fetch Asset", signpostID: spid)
}

os_signpost(.end, log: log, name: "Load Data")

You can also pass your model object when generating the signpost ID – then it will always use the same signpost ID for the same object, and you don't have to store the signpost object, just your model:

let spid = OSSignpostID(log: log, object: asset)

There is also an option of passing an additional string argument to begin/end to provide some context (e.g. to differentiate between different possible ways to finish an activity, like success/failure)

The string also accepts format arguments like os_log:

os_signpost(.begin, log: log, name: "Compute Physics",
    "Calculating %{public}s: %d %d %d %d", description, x1, y2, x2, y2)

Apart from marking the beginning and end, you can also mark specific points in time during the process using the .event signpost type:

os_signpost(.event, log: log, name: "Fetch Asset",
    "Received chunk of data, size %d", size)

Signposts are very optimized internally, they’re built to minimize the time spent when logging, same as the whole os_log API

This means you can emit a lot of signposts even in a very tight window, when investigating a performance bottleneck

If you still really want to enable or disable some signpost logs based on some conditions, you can swap your logger object with OSLog.disabled:

let refreshLog: OSLog

if ProcessInfo.processInfo.environment.keys.contains("SIGNPOSTS_REFRESH") {
    refreshLog = OSLog(…)
} else {
    refreshLog = .disabled
}

To conditionally disable some expensive code that is only useful for debugging, you can check the signpostsEnabled property:

if refreshLog.signpostsEnabled {
    let information = collectInfo()
    os_signpost(…, information)
}

All APIs are also available in C & ObjC:

#include <os/signpost.h>

os_signpost_interval_begin()
os_signpost_interval_end()
os_signpost_event_emit()
os_signpost_id_t
OS_LOG_DISABLED

Use formatter %{xcode:size-in-bytes}u to let Xcode & Instruments know that the logged value is a byte size of some data

→ This is one of so called “Engineering types” – find more in the Instruments Help menu, in the Instruments developer guide

Instruments:

Use the “os_signpost” instrument to profile using signposts

After recording some data, you can see the signpost names in the sidebar on the left and signpost ranges with the optional begin/end comments marked on the chart

In the bottom pane you can see count and duration statistics, grouped by category, signpost, id and comment

Clicking the arrow button next to a specific message row shows you a list of all instances of this specific message (selecting them highlights them on the timeline)

For metadata like logged byte sizes of downloads, you can choose “Summary: Metadata Statistics” to see total/min/max/avg of each type of value

Live streaming signpost logs to Instruments (“Immediate mode”) adds some overhead, so if you want to avoid that while debugging some performance-critical code, click and hold the Record button to access recording options and change mode to “Last n seconds”

Points of interest:

Points of interest is a special log category of OSLog

It’s meant for logging important actions taken by the user, like opening some specific screen

Normal os_log logs and signpost logs logged to this category appear in a special separate Instruments timeline, which lets you visualize what was happening in the app at the moment when something happened on other charts like CPU usage

Custom Instruments packages:

You can now build your custom Instruments packages, defined as an XML file in a separate target, which appear as a new kind of template when starting Instruments

This lets you process and present collected signpost data in a different way that makes sense for the specific problem you’re analyzing