instrumentsxcode-instruments

How do you match strings in custom Instruments start-pattern?

I am having trouble matching a string literal in start-pattern in a custom instrument (see WWDC 2018 video Creating Custom Instruments) in Xcode’s Instruments.

For example, this start-pattern works ...

<start-pattern>
    <message>?name ?value</message>
</start-pattern>

<column>
    <mnemonic>name</mnemonic>
    <title>Name</title>
    <type>string</type>
    <expression>?name</expression>
</column>
<column>
    <mnemonic>value</mnemonic>
    <title>Value</title>
    <type>uint64</type>
    <expression>?value</expression>
</column>

... with this OSSignpost:

let id = OSSignpostID(log: log)

os_signpost(.begin, log: log, name: "Interval", signpostID: id, "Foo %d", 42)
...
os_signpost(.end, log: log, name: "Interval", signpostID: id)

The ?name ?value pattern works, capturing "Foo" as the name and 42 as the value. Fine.

But when I try using string literals in my message, it does not work, e.g. this start-pattern...

<start-pattern>
    <message>"Name:" ?name ",Value:" ?value</message>
</start-pattern>

... with this os_signpost ...

let id = OSSignpostID(log: log)

os_signpost(.begin, log: log, name: "Interval", signpostID: id, "Name:Foo,Value:%d", 42)
...
os_signpost(.end, log: log, name: "Interval", signpostID: id)

This "Name:" ?name ",Value:" ?value pattern does not work, though the documentation suggests it should.

What am I doing wrong?

Solution

  • If you use string literals in the start-pattern, you must use printf-style format string.

    Thus, this will not work:

    os_signpost(.begin, 
            log: log, 
            name: "Interval", 
            signpostID: id, 
            "Name:Foo,Value:%d", 
            42)

    But if we move the "Foo" value out of the format string, and make it a parameter, it will work:

    os_signpost(.begin, 
            log: log, 
            name: "Interval", 
            signpostID: id, 
            "Name:%{public}@,Value:%d", 
            "Foo", 
            42)

    The issue rests in this idiosyncratic detail of the format string within the os_signpost call. One may have assumed that start-pattern/message parses the result of the os_signpost final output, but it appears (when using string literals in the message key, at least) that it is actually parsing the format string, itself.

    FWIW, this is my final, admittedly basic, interval instrument:

    <?xml version="1.0" encoding="UTF-8" ?>
<!-- Instruments Developer Help: https://help.apple.com/instruments/developer/mac/current/ -->
<package>
    <id>com.robertmryan.CustomInterval</id>
    <version>0.1</version>
    <title>Custom OS Signpost Interval</title>
    <owner>
        <name>Robert Ryan</name>
    </owner>

    <import-schema>os-signpost</import-schema>

    <!-- See https://help.apple.com/instruments/developer/mac/current/#/dev536412616 -->
    <os-signpost-interval-schema>
        <id>custom-interval-schema</id>
        <title>Interval</title>
        <owner>
            <name>Robert Ryan</name>
        </owner>
        <purpose>Provide mechanism for multicolored intervals posted by `os_signpost`; The string generated by `os_signpost` must be in form of "Label:%d,Concept:%{public}@", where "Label" is string that will control what text appears in the interval, and "Concept" is one of the strings listed in https://help.apple.com/instruments/developer/mac/current/#/dev66257045 that dictates the color of the interval. No spaces after the commas within this string.</purpose>
        <note>That message must use that printf-style format, not embedding the values in the format string literal.</note>

        <!-- you can constrain this to a particular subsystem if you'd like:
        <subsystem>"com.domain.MyApp"</subsystem>
        -->
        <category>"Interval"</category>
        <name>?name</name>

        <start-pattern>
            <message>"Label:" ?label ",Concept:" ?concept</message>
        </start-pattern>

        <column>
            <mnemonic>name</mnemonic>
            <title>Name</title>
            <type>string</type>
            <expression>?name</expression>
        </column>
        <column>
            <mnemonic>label</mnemonic>
            <title>Label</title>
            <type>string</type>
            <expression>?label</expression>
        </column>
        <column>
            <mnemonic>concept</mnemonic>
            <title>Concept</title>
            <type>event-concept</type>
            <expression>?concept</expression>
        </column>
    </os-signpost-interval-schema>

    <instrument>
        <id>com.robertmryan.CustomInterval.instrument</id>
        <title>Custom OS Signpost Interval</title>
        <category>Behavior</category>
        <purpose>Provide multi-colored intervals as dictated by the "event-concept" parsed from the `start-pattern` string.</purpose>
        <icon>Generic</icon>

        <create-table>
            <id>custom-interval-table</id>
            <schema-ref>custom-interval-schema</schema-ref>
        </create-table>

        <graph>
            <title>Custom Interval Graph</title>
            <lane>
                <title>Interval</title>
                <table-ref>custom-interval-table</table-ref>
                <plot-template>
                    <instance-by>name</instance-by>
                    <label-format>%s</label-format>
                    <value-from>name</value-from>
                    <color-from>concept</color-from>
                    <label-from>label</label-from>
                    <qualified-by>layout-qualifier</qualified-by>
                </plot-template>
            </lane>
        </graph>

        <list>
            <title>Custom Interval List</title>
            <table-ref>custom-interval-table</table-ref>
            <column>name</column>
            <column>label</column>
            <column>concept</column>
            <column>start</column>
            <column>duration</column>
        </list>
    </instrument>
</package>

    And my type for posting a custom interval for that instrument:

    //
//  InstrumentsInterval.swift
//
//  Created by Robert Ryan on 6/5/21.
//

import Foundation
import os.log

/// EventConcept enumeration
///
/// This is used to dictate the color of the intervals in our custom instrument.
/// See [Event Concept Engineering Type](https://help.apple.com/instruments/developer/mac/current/#/dev66257045).

enum EventConcept: 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"
}

/// Interval to be shown in custom instrument when profiling app

struct InstrumentsInterval {
    static let category = "Interval"

    let name: StaticString
    let label: String
    let concept: EventConcept
    let log: OSLog
    let id: OSSignpostID

    init(name: StaticString, label: String, concept: EventConcept = .debug, log: OSLog) {
        self.name = name
        self.concept = concept
        self.label = label
        self.log = log
        self.id = OSSignpostID(log: log)
    }

    /// Block based interval
    func perform<T>(block: () throws -> T) rethrows -> T {
        begin()
        defer { end() }
        return try block()
    }

    /// Manually begin an interval
    func begin() {
        os_signpost(.begin, log: log, name: name, signpostID: id, "Label:%{public}@,Concept:%{public}@", label, concept.rawValue)
    }

    /// Manually end an interval
    func end() {
        os_signpost(.end, log: log, name: name, signpostID: id)
    }
}

    Which you can then use like so:

    let log = OSLog(subsystem: Bundle.main.bundleIdentifier!, category: InstrumentsInterval.category)

let interval = InstrumentsInterval(name: "Foo", label: "1", concept: .red, log: log)

interval.perform {
    ...
}

    Which can yield the following in Instruments (in this example, I was constraining app to four concurrent tasks at a time):

    sample instruments log