Profiling performance by os_signpost and customized instruments package in MEGA iOS

MEGA
13 min readJan 24, 2024

By Harry Yan, iOS Team Lead, Mobile, MEGA

In the world of iOS development, understanding the performance and behavior of your app is crucial for delivering a smooth and responsive user experience. Apple provides various tools and APIs to help developers achieve this, and one such powerful tool is os_signpost. In this post, we'll dive into what os_signpost is and how you can use it to gather valuable insights with a customized instrument package into your app's performance.

Os_signpost

os_signpost is an instrumentation framework introduced by Apple to allow developers to mark specific points in their code with meaningful log entries. These log entries, known as signposts, help us track the execution flow and performance of our app as it runs. Unlike traditional logging, which focuses on text-based messages, os_signpost is designed to provide a detailed timeline of your app's execution in a structured and efficient manner.

Signposts are categorised into three types:

  1. Event Signposts: Used to mark significant events during the execution of your app, such as loading a resource or completing a network request.
  2. Interval Signposts: Used to measure the duration of an activity between two points in time. This is particularly useful for tracking performance bottlenecks.
  3. Signpost Breadcrumbs: These are lightweight signposts used to track frequent and short-lived events.

Integrate signpost

There are two different APIs to integrate the SignPost: OSSignposter and os_signpost. Here is the code:

  1. Subsystem: An identifier string, in reverse DNS notation, that represents the app subsystem that’s logging information, such as com.your_company.your_subsystem_name. The logging system uses this information to categorize and filter related log messages and to group related logging settings.
  2. Category: A category within the specified subsystem. The system uses this value to categorise and filter related log messages and to group related logging settings within the subsystem. A category’s logging settings override those of the containing subsystem.

For example, let signposter = OSSignposter(subsystem: "com.mega.timeline", category: "TimelineThumbnailLoading") .

Apple recommends to use OSSignposter which supports iOS 15 and above. However, it doesn't work well with the customised instrument package, so we still choose os_signpost.

After integrating os_signpost code in your project, you will see the customized signposts like the below:

Customized instruments package

The above example can help us get customised events or intervals list on instrument, but couldn’t provide custom UI on the graph part. To help engineers identify issues quickly, we need to introduce the Customised instruments package here.

Customised instruments package can provide us with better data sampling and visualisation, such as customised colors, graphs, and table lists. Here are examples:

The red bars on the 1st screenshot represent cancelled tasks, and the green ones are completed tasks. These visible graphs can help us easily check whether our task cancellation works or not. The bottom list is also customised and shows image names, statuses, and duration. The 2nd screenshot shows each downloaded image size and the total size loaded. The green means the image size is smaller than 10KB, otherwise shown in red.

Create your instrument package

Go to File → New → Project, and then choose Instruments package:

Schema structure

Apple will create an XML file for us like below, which explains the basic structure such as schema definitions, modeler declarations, instrument definitions, and embed templates. We only focus on schema and instrument definitions at the moment, and will introduce 2 important schema tags: <os-signpost-interval-schema> and <os-signpost-point-schema> and <instrument>.

<os-signpost-interval-schema>

  • <id>: A unique value we’ll use later to reference our schema from the instrument UI description.
  • <title>: A value presented near the graph view in instruments UI.
  • <subsystem>, <category>, <name>: These will be used for identifying our signpost calls, they have to match the ones we used for creating the os_log subsystem handle in our app’s code.
  • <start-pattern>, <end-pattern>: This format will be applied to the string parameter we passed to begin or end calls. For example:

// XML
<start-pattern>
<message>"Name:" ?handle ",Begin:" ?begin</message>
</start-pattern>
<end-pattern>
<message>"Name:" ?handle ",End:" ?end ",Concept:" ?concept</message>
</end-pattern>

// Swift
MEGASignpost.timelineThumbnails.begin(name: "Load Single Thumbnail", format: "Name:%{public}@,Begin:%{public}@", arguments: [photo.base64Handle, "Begin"])

The format in the code must be matched with <message> content; otherwise, we can’t see messages on the instrument. Strings starting with the question mark, ‘handle’, and ‘begin’, are the names of the variables holding the data we pass from the app side. This is the first place we meet CLIPS expression. CLIPS is a language Apple uses for data processing in instruments.

  • <column>: At the end of the schema we have a bunch of ‘column’ tags describing data columns available for our package. There are four variables in the above example: ?handle, ?begin, ?end and ?concept. So, we need to define four columns:

<column>
<mnemonic>handle</mnemonic>
<title>Image Handle</title>
<type>string</type>
<expression>?handle</expression>
</column>
<column>
<mnemonic>begin-status</mnemonic>
<title>Begin Status</title>
<type>string</type>
<expression>?begin</expression>
</column>
<column>
<mnemonic>end-status</mnemonic>
<title>End Status</title>
<type>string</type>
<expression>?end</expression>
</column>
<column>
<mnemonic>concept</mnemonic>
<title>Concept</title>
<type>event-concept</type>
<expression>?concept</expression>
</column>

mnemonic is a unique column reference, expression tag contains CLIPS expression which result will be used as a column value. Event-concept is used as an adjective to describe another type. You can find more details here.

Instrument definitions

Instrument UI is divided into two main parts: A graph on the top and a table with data on the bottom. First of all, you need to define a table like this:


<create-table>
<id>timeline-thumbnail-size-interval-table</id>
<schema-ref>mega-timeline-thumbnail-size-interval</schema-ref>
</create-table>

The table needs to refer to the schema (provides data) we defined before. Then we can define the graph and list:

<!-- Define graph to draw for your Instrument (optional) -->
<graph>
<title>Thumbnail Status Graph</title>

<lane>
<title>timeline-thumbnail-size-interval</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>

<plot-template>
<instance-by>handle</instance-by>
<label-format>Thumbnail:%s</label-format>
<value-from>handle</value-from>
<color-from>concept</color-from>
<label-from>end-status</label-from>
<qualified-by>handle</qualified-by>
</plot-template>
</lane>
</graph>

<!-- Define at least one detail view for your Instrument -->
<list>
<title>Timeline Thumbnail Size Interval</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>
<column>handle</column>
<column>begin-status</column>
<column>end-status</column>
<column>concept</column>
<column>start</column>
<column>duration</column>
</list>

<lane> tag defines the graph on the instrument, and <plot-template> will create slices for each value in “instance-by”, and you can find more info here.

Profile tasks performance

MEGA adopted Swift concurrency 2 years ago and has been using structured/unstructured tasks heavily in our code base, especially in the Photos feature(Timeline and Album). Proper task cancellation (cancel and release them) becomes an important topic.

In our code base, we usually rely on 2 different ways to cancel them: Manual cancellation in deinit/viewWillDisappear methods or waiting for the operating system to release them like .task method provided by SwiftUI from iOS 15.

After writing/refactoring the code, we need to verify whether our cancellation works or not. Here is an example:

The above code implements thumbnail loading for the Photo feature including Timeline, Album, and Media discovery. The task cancellation code is defined in the TaskModifier.swift file. Theoretically, the catch block will be called when cancelling loading tasks. For example, the user scrolls the photos page fast and we should cancel those loading tasks when related photocells are invisible.

public struct ThrowingTaskModifier: ViewModifier {
private var priority: TaskPriority
private var action: @Sendable () async throws -> Void

public init(
priority: TaskPriority,
action: @escaping @Sendable () async throws -> Void
) {
self.priority = priority
self.action = action
}

@State private var task: Task<Void, any Error>?

private func cancelTask() {
task?.cancel()
task = nil
}

public func body(content: Content) -> some View {
content
.task(priority: priority) {
do {
try await action()
} catch {
debugPrint("Error occurred: \(error)")
cancelTask()
}
}
}
}

Using os_signpost and the customized instruments package can easily help us verify the result. Here are two videos to compare behaviours after refactoring: Task cancellation as expected and Task cancellation unexpected. It can be seen that tasks can be cancelled when photocells are invisible in the old code base but it doesn’t happen in the new code base.

The red bars mean tasks have been cancelled; the blue ones mean tasks are still working even if related photocells are invisible.

The combination of os_signpost and customized instrument package can display anything we want to profile, such as methods running duration, memory usage, and battery usage. We can define different event concepts to identify events.

Implementation

I encapsulate os_signpost in MEGASignpostLog.swift.

public struct MEGASignpostLog {
private var osLog: OSLog

/// A constant string that produces a human-readable log message.
private let formatString: StaticString = "Key:%{public}@,Value:%{public}@,Concept:%{public}@"

// MARK: - Init

public init(subsystem: String, category: String) {
osLog = OSLog(subsystem: subsystem, category: category)
}

// MARK: - Public

/// Logs a point of interest in your code as an event for debugging performance in Instruments,
/// and includes a detailed message.
public func event(name: StaticString = "Event", key: String, value: String, concept: MEGAEventConcept = .debug) {
os_signpost(.event, log: osLog, name: name, formatString, key, value, concept.rawValue)
}

/// A signpost with pre-defined format that marks the start of a time interval of interest in your code.
public func begin(name: StaticString = "Begin", key: String, value: String, concept: MEGAEventConcept = .debug) -> OSSignpostID {
let id = signpostID()

os_signpost(.begin, log: osLog, name: name, signpostID: id, formatString, key, value, concept.rawValue)
return id
}

/// A signpost with pre-defined format that marks the end of a time interval of interest in your code.
public func end(name: StaticString = "End", key: String, value: String, concept: MEGAEventConcept = .debug, id: OSSignpostID) {
os_signpost(.end, log: osLog, name: name, signpostID: id, formatString, key, value, concept.rawValue)
}

/// Logs a point of interest in your code as a time interval for debugging performance in Instruments,
/// and includes a detailed message.
public func interval<T>(name: StaticString = "Interval",
key: String,
value: String,
concept: MEGAEventConcept = .debug, completion: () throws -> T) rethrows -> T {
let id = begin(name: name, key: key, value: value, concept: concept)

defer { end(name: name, key: key, value: value, concept: concept, id: id)}
return try completion()
}

/// A signpost with customized format that marks the start of a time interval of interest in your code.
public func begin(name: StaticString = "Begin", format: StaticString, arguments: [CVarArg]) -> OSSignpostID {
let id = signpostID()

signpost(type: .begin, name: name, signpostID: id, format: format, args: arguments)
return id
}

/// A signpost with customized format that marks the end of a time interval of interest in your code.
public func end(name: StaticString = "End", id: OSSignpostID, format: StaticString, arguments: [CVarArg]) {
signpost(type: .end, name: name, signpostID: id, format: format, args: arguments)
}

// MARK: Private

private func signpostID() -> OSSignpostID {
return OSSignpostID(log: osLog)
}

/// Logs performance-related events using signposts with the `os_signpost` function.
///
/// - Parameters:
/// - type: The type of the signpost event. Choose from `.begin`, `.end`, or `.event`.
/// - name: A descriptive name for the signpost event. This should be a static string.
/// - signpostID: An identifier for the signpost event.
/// - format: A static string that specifies the format of the log message.
/// - args: An array of `CVarArg` values representing the arguments to be included in the log message.
///
/// - Note:
/// This function allows you to log performance data using signposts with a flexible number of arguments.
/// Depending on the number of arguments provided, it formats and logs the data accordingly.
/// If there are more than three arguments, an assertion failure is triggered,
/// and the data is logged with the first three arguments.
private func signpost(type: OSSignpostType, name: StaticString, signpostID: OSSignpostID, format: StaticString, args: [CVarArg]) {
switch args.count {
case 0:
os_signpost(type, log: osLog, name: name, signpostID: signpostID)
case 1:
os_signpost(type, log: osLog, name: name, signpostID: signpostID, format, args[0])
case 2:
os_signpost(type, log: osLog, name: name, signpostID: signpostID, format, args[0], args[1])
case 3:
os_signpost(type, log: osLog, name: name, signpostID: signpostID, format, args[0], args[1], args[2])
default:
assertionFailure("Too many arguments passed to signpost.")
os_signpost(type, log: osLog, name: name, signpostID: signpostID, format, args[0], args[1], args[2])
}
}
}

/// Used as an adjective to describe another type. Such as "Warning", or "Error".
/// This is also may contain simple shapes or the alphabet, for uses like providing images that
/// help explain the type of thing being drawn.
public enum MEGAEventConcept: String {
case success = "Success"
case failure = "Failure"
case fault = "Fault"
case critical = "Critical"
case error = "Error"
case debug = "Debug"
case pedantic = "Pedantic"
case info = "Info"
case signpost = "Signpost"
case veryLow = "Very Low"
case low = "Low"
case moderate = "Moderate"
case high = "High"
case red = "Red"
case orange = "Orange"
case blue = "Blue"
case purple = "Purple"
case green = "Green"
}

Here are three different instrument packages(XML):

<!-- ThumbnailLoading -->
<?xml version="1.0" encoding="UTF-8" ?>
<package>
<id>com.mega.performance.TimelineThumbnails</id>
<title>TimelineThumbnailsLoading</title>
<owner>
<name>Harry Yan</name>
</owner>

<!-- OSSignPost Interval Schema -->
<os-signpost-interval-schema>
<id>mega-timeline-thumbnail-size-interval</id>
<title>timeline-thumbnial-size-interval</title>

<subsystem>"com.mega.timeline"</subsystem>
<category>"TimelineThumbnailsLoading"</category>
<name>?name</name>

<start-pattern>
<message>"Name:" ?handle ",Begin:" ?begin</message>
</start-pattern>
<end-pattern>
<message>"Name:" ?handle ",End:" ?end ",Concept:" ?concept</message>
</end-pattern>

<column>
<mnemonic>handle</mnemonic>
<title>Image Handle</title>
<type>string</type>
<expression>?handle</expression>
</column>
<column>
<mnemonic>begin-status</mnemonic>
<title>Begin Status</title>
<type>string</type>
<expression>?begin</expression>
</column>
<column>
<mnemonic>end-status</mnemonic>
<title>End Status</title>
<type>string</type>
<expression>?end</expression>
</column>
<column>
<mnemonic>concept</mnemonic>
<title>Concept</title>
<type>event-concept</type>
<expression>?concept</expression>
</column>
</os-signpost-interval-schema>

<instrument>
<id>com.mega.event.timeline</id>
<title>Timeline Thumbnail Loading</title>
<category>Behavior</category>
<purpose>Show thumnail image size</purpose>
<icon>Generic</icon>

<create-table>
<id>timeline-thumbnail-size-interval-table</id>
<schema-ref>mega-timeline-thumbnail-size-interval</schema-ref>
</create-table>

<!-- Define graph to draw for your Instrument (optional) -->
<graph>
<title>Thumbnail Status Graph</title>

<lane>
<title>timeline-thumbnail-size-interval</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>

<plot-template>
<instance-by>handle</instance-by>
<label-format>Thumbnail:%s</label-format>
<value-from>handle</value-from>
<color-from>concept</color-from>
<label-from>end-status</label-from>
<qualified-by>handle</qualified-by>
</plot-template>
</lane>
</graph>

<!-- Define at least one detail view for your Instrument -->
<list>
<title>Timeline Thumbnail Size Interval</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>
<column>handle</column>
<column>begin-status</column>
<column>end-status</column>
<column>concept</column>
<column>start</column>
<column>duration</column>
</list>
</instrument>
</package>
<!-- Album Loading -->
<?xml version="1.0" encoding="UTF-8" ?>
<package>
<id>com.mega.performance.MEGAAlbumPerformance</id>
<title>MEGAAlbumPerformance</title>
<owner>
<name>Harry Yan</name>
</owner>

<!-- OSSignPost Interval Schema -->
<os-signpost-interval-schema>
<id>mega-album-user-albums-interval</id>
<title>album-user-albums-interval</title>

<subsystem>"com.mega.albums"</subsystem>
<category>"Albums"</category>
<name>?name</name>

<start-pattern>
<message>"Name:" ?album-name ",Count:" ?content-count ",Concept:" ?concept</message>
</start-pattern>
<end-pattern>
<message>"Name:" ?album-name ",Status:" ?status ",Concept:" ?concept</message>
</end-pattern>

<column>
<mnemonic>album-name</mnemonic>
<title>Album Name</title>
<type>string</type>
<expression>?album-name</expression>
</column>
<column>
<mnemonic>content-count</mnemonic>
<title>Content Count</title>
<type>int64-value</type>
<expression>?content-count</expression>
</column>
<column>
<mnemonic>concept</mnemonic>
<title>Concept</title>
<type>event-concept</type>
<expression>?concept</expression>
</column>
<column>
<mnemonic>status</mnemonic>
<title>Request Status</title>
<type>string</type>
<expression>?status</expression>
</column>
</os-signpost-interval-schema>

<instrument>
<id>com.mega.albums</id>
<title>Albums Loading</title>
<category>Behavior</category>
<purpose>Profile User Albums Loading</purpose>
<icon>Generic</icon>

<create-table>
<id>album-useralbum-interval-table</id>
<schema-ref>mega-album-user-albums-interval</schema-ref>
</create-table>

<!-- Define graph to draw for your Instrument (optional) -->
<graph>
<title>User Album Loading Graph</title>

<lane>
<title>album-user-interval</title>
<table-ref>album-useralbum-interval-table</table-ref>

<plot-template>
<instance-by>album-name</instance-by>
<label-format>album:%s</label-format>
<value-from>album-name</value-from>
<color-from>concept</color-from>
<label-from>album-name</label-from>
<qualified-by>album-name</qualified-by>
</plot-template>
</lane>
</graph>

<!-- Define at least one detail view for your Instrument -->
<list>
<title>User Album Interval</title>
<table-ref>album-useralbum-interval-table</table-ref>
<column>album-name</column>
<column>content-count</column>
<column>concept</column>
<column>status</column>
<column>start</column>
<column>duration</column>
</list>

<aggregation>
<title>Summary: User Album loaded</title>
<table-ref>album-useralbum-interval-table</table-ref>

<slice>
<column>status</column>
<equals>
<string>Completed</string>
</equals>
</slice>
<hierarchy>
<level>
<column>album-name</column>
</level>
</hierarchy>

<column>
<count/>
</column>
<column>
<sum>content-count</sum>
</column>

</aggregation>
</instrument>
</package>
<!-- Thumbnail Size -->
<?xml version="1.0" encoding="UTF-8" ?>
<package>
<id>com.mega.performance.MEGAPerformance</id>
<version>0.1</version>
<title>MEGAPerformance</title>
<owner>
<name>Harry Yan</name>
</owner>

<!-- OSSignPost Interval Schema -->
<os-signpost-interval-schema>
<id>mega-timeline-thumbnail-size-interval</id>
<title>timeline-thumbnial-size-interval</title>

<subsystem>"com.mega.timeline"</subsystem>
<category>"TimelineThumbnailsLoading"</category>
<name>?name</name>

<start-pattern>
<message>"Name:" ?image-name ",Size:" ?image-size ",Concept:" ?concept</message>
</start-pattern>
<end-pattern>
<message>"Name:" ?image-name ",Status:" ?status ",Concept:" ?concept</message>
</end-pattern>

<column>
<mnemonic>image-name</mnemonic>
<title>Image Name</title>
<type>string</type>
<expression>?image-name</expression>
</column>
<column>
<mnemonic>image-size</mnemonic>
<title>Image Size</title>
<type>size-in-bytes</type>
<expression>?image-size</expression>
</column>
<column>
<mnemonic>concept</mnemonic>
<title>Concept</title>
<type>event-concept</type>
<expression>(if (> ?image-size 10000) then "High" else "Low")</expression>
</column>
<column>
<mnemonic>status</mnemonic>
<title>Request Status</title>
<type>string</type>
<expression>?status</expression>
</column>
</os-signpost-interval-schema>

<!-- OSSignPost Point Schema -->
<os-signpost-point-schema>
<id>mega-timeline-thumbnail-size-event</id>
<title>timeline-thumbnial-size-event</title>

<subsystem>"com.mega.timeline"</subsystem>
<category>"TimelineThumbnailsLoading"</category>
<name>?name</name>

<pattern>
<message>"Name:" ?image-name ",Size:" ?image-size ",Concept:" ?concept</message>
</pattern>

<column>
<mnemonic>image-name</mnemonic>
<title>Image Name</title>
<type>string</type>
<expression>?image-name</expression>
</column>
<column>
<mnemonic>image-size</mnemonic>
<title>Image Size</title>
<type>size-in-bytes</type>
<expression>?image-size</expression>
</column>
<column>
<mnemonic>concept</mnemonic>
<title>Concept</title>
<type>event-concept</type>
<expression>?concept</expression>
</column>
</os-signpost-point-schema>

<instrument>
<id>com.mega.event.timeline</id>
<title>Photos Thumbnail Size</title>
<category>Behavior</category>
<purpose>Show thumnail image size</purpose>
<icon>Generic</icon>

<create-table>
<id>timeline-thumbnail-size-interval-table</id>
<schema-ref>mega-timeline-thumbnail-size-interval</schema-ref>
</create-table>

<create-table>
<id>timeline-thumbnail-size-event-table</id>
<schema-ref>mega-timeline-thumbnail-size-event</schema-ref>
</create-table>

<!-- Define graph to draw for your Instrument (optional) -->
<graph>
<title>Thumbnail Size Graph</title>

<lane>
<title>timeline-thumbnail-size-event</title>
<table-ref>timeline-thumbnail-size-event-table</table-ref>

<plot-template>
<instance-by>image-name</instance-by>
<label-format>img:%s</label-format>
<value-from>image-name</value-from>
<color-from>concept</color-from>
<label-from>image-name</label-from>
</plot-template>
</lane>

<lane>
<title>timeline-thumbnail-size-interval</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>

<plot-template>
<instance-by>image-name</instance-by>
<label-format>img:%s</label-format>
<value-from>image-name</value-from>
<color-from>concept</color-from>
<label-from>image-size</label-from>
<qualified-by>image-name</qualified-by>
</plot-template>
</lane>
</graph>

<!-- Define at least one detail view for your Instrument -->
<list>
<title>Timeline Thumbnail Size Interval</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>
<column>image-name</column>
<column>image-size</column>
<column>concept</column>
<column>status</column>
<column>start</column>
<column>duration</column>
</list>

<list>
<title>Timeline Thumbnail Size Events</title>
<table-ref>timeline-thumbnail-size-event-table</table-ref>
<column>image-name</column>
<column>image-size</column>
<column>concept</column>
</list>

<aggregation>
<title>Summary: Thumbnails Loaded</title>
<table-ref>timeline-thumbnail-size-interval-table</table-ref>

<slice>
<column>status</column>
<equals>
<string>Completed</string>
</equals>
</slice>
<hierarchy>
<level>
<column>image-name</column>
</level>
</hierarchy>

<column>
<count/>
</column>
<column>
<sum>image-size</sum>
</column>

</aggregation>
</instrument>

</package>

Example

Inject the Signpost code into your feature and then you can send the event or interval to the instrument.

public struct MEGASignpost {
public static let chatRoom = MEGASignpostLog(subsystem: "com.mega.meeting", category: "ChatRoom")
public static let chatRoomAvatar = MEGASignpostLog(subsystem: "com.mega.meeting", category: "Avatar")
public static let timelineThumbnails = MEGASignpostLog(subsystem: "com.mega.timeline", category: "TimelineThumbnailsLoading")
public static let albums = MEGASignpostLog(subsystem: "com.mega.albums", category: "Albums")
}

let signpostID = MEGASignpost.timelineThumbnails.begin(name: "Load Single Thumbnail",
format: "Name:%{public}@,Begin:%{public}@",
arguments: [photo.base64Handle, "Begin"])
MEGASignpost.timelineThumbnails.end(name: "Load Single Thumbnail",
id: signpostID,
format: "Name:%{public}@,End:%{public}@,Concept:%{public}@",
arguments: [photo.base64Handle, "Completed", EventConcept.green.rawValue])
MEGASignpost.albums.interval(key: "", value: "") { ... }
MEGASignpost.albums.event(key: "", value: "")

The log formats in your code must be matched with what you defined in <start-pattern> and <end-pattern> tags.

Finally, you can run the instrument package, choose the blank tool, and click + button to pick up your own package.

--

--

MEGA

Our vision is to be the leading global cloud storage and collaboration platform, providing the highest levels of data privacy and security. Visit us at MEGA.NZ