Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Alternative to DTSendSignalFlag to identify key events in Instruments?

Tags:

There used to be a nice tool, DTSendSignalFlag, part of the DTPerformanceSession framework, by which you could programmatically insert flags into Instruments (see Xcode Instruments trace comparison). This feature stopped working in iOS 7.

Has anyone succeeded in getting DTSendSignalFlag to work in iOS 7? Signal flags are (were?) a useful way to programmatically post flags in Instruments via code (really helpful when diagnosing complicated apps in Instruments), but I'm not seeing my programmatically created flags in Instruments when I run on the iOS 7 simulator (but it works when I have Xcode 5 build for the iOS 6 simulator).

like image 873
Rob Avatar asked Sep 26 '13 01:09

Rob


2 Answers

Rather than using flags, we can now use programmatically inserted signposts which are captured in Instrument's "Points of Interest".

In iOS 13 and macOS 10.15, we can use os_signpost. This is illustrated in WWDC 2019 video Getting Started with Instruments.

For example, in Swift:

  • Import the unified logging framework:

    import os.log 
  • Create an OSLog for points of interest:

    private let pointsOfInterest = OSLog(subsystem: Bundle.main.bundleIdentifier!, category: .pointsOfInterest) 
  • When you want to start a points of interest range, you can .begin a point of interest:

    let id = OSSignpostID(log: pointsOfInterest) os_signpost(.begin, log: pointsOfInterest, name: "Download", signpostID: id, "Download %d", index) 
  • When you want to end a points of interest range, you can .end it:

    os_signpost(.end, log: pointsOfInterest, name: "Download", signpostID: id, "Download %d", index) 
  • If you’re not interested in a range of time, but rather a single signpost, you can just post an .event:

    os_signpost(.event, log: pointsOfInterest, name: "Done", "All done") 

Or in Objective-C:

  • Import the unified logging signposts framework:

    @import os.signpost; 
  • Create an OSLog for points of interest:

    os_log_t log = os_log_create("ViewController", OS_LOG_CATEGORY_POINTS_OF_INTEREST); 
  • When you want to start a points of interest range, you can .begin a point of interest:

    os_signpost_id_t identifier = os_signpost_id_generate(log); os_signpost_interval_begin(log, identifier, "Download", "Started %d", index); 
  • When you want to end a points of interest range, you can .end it:

    os_signpost_interval_end(log, identifier, "Download", "Finished %d", index); 
  • If you’re not interested in a range of time, but rather a single signpost, you can just post an .event:

    os_signpost_event_emit(log, OS_SIGNPOST_ID_EXCLUSIVE, "Done"); 

Anyway, the “Points of Interest” instrument can now graphically represent a series of downloads and parse operations (each queue constrained to two concurrent operations per queue) in Instruments:

enter image description here

Note that the name values (one set I used the name Download and the other I used Parse) are nicely separated into different swim-lanes in the Points of Interest tool. And because I used the optional format strings, I can actually see messages where I can clearly correlate each download and parse operation to a specific task in my app.

Above I have used the optional OSSignpostID parameters because I had multiple ranges overlapping and I wanted to avoid any confusion associating a particular .end with the corresponding .begin. If you either aren’t using points of interest ranges or you don’t have overlapping ranges, you technically don’t need to use this optional parameter if no possible ambiguity is possible. (Even if you use these signpost identifiers, make sure that the name of the associated .begin and .end signposts also match, or else Instruments won’t identify them as the start and end of the same point of interest range, even with the same signpost id.)

Anyway, now that you have the “Points of Interest” tool populated with information, you can double-click on a range to select it, or triple-click on it to also set your inspection range.


In iOS 10 and macOS 10.12, we used kdebug_signpost. This is illustrated in WWDC 2016 video System Trace in Depth.

For those processes that take a discrete amount of time, we can use kdebug_signpost_start and kdebug_signpost_end. For example:

kdebug_signpost_start(SignPostCode.download.rawValue, UInt(index), 0, 0, SignPostColor.orange.rawValue) performDownload {     kdebug_signpost_end(SignPostCode.download.rawValue, UInt(index), 0, 0, SignPostColor.orange.rawValue) } 

To mark a single moment in time, we can just use kdebug_signpost:

kdebug_signpost(SignPostCode.done.rawValue, 0, 0, 0, SignPostColor.red.rawValue) 

The first parameter is just some unique numeric code that corresponds to a "signpost code name" that we'll use in Instruments. You can use whatever values you want (between 0 and 16383), but I use something that designates the type of task:

enum SignPostCode: UInt32 {   // some custom constants that I'll reference in Instruments     case download = 0     case parse = 1     case done = 2 } 

The rest of the parameters can be whatever UInt values you want, but in my example, I'll use the second parameter as a unique identifier to match up repeated start and end calls and I'll use the last parameter to color code my regions in Instruments:

enum SignPostColor: UInt {    // standard color scheme for signposts in Instruments     case blue = 0     case green = 1     case purple = 2     case orange = 3     case red = 4 } 

Having done this, you can then profile the app in Instruments, click on the "+" button in the right side of the Instruments toolbar, and add "Points of Interest". By configuring the "Signpost Code Names" to match the numeric values I passed as the first parameter to my signposts, Instruments will actually translate those codes for me. Once I profile the app and I now have my points of interest clearly highlighted for me:

enter image description here

In this snapshot, I profiled seven download operations (in orange) and seven parse operations (in green), constrained to two at a time, respectively. And when they were done, I posted a single "done" signpost (pin red). But the details of this demo app are not critical, but rather this just illustrates how single signposts and start/end signposts are rendered in Instruments' "Points of Interest".

The main issue is that I now have clear correspondence between events in my code and what I see in Instruments. And I can control-click on an entry in the list of signpost ranges and tell Instruments to "Set time filter", if I want, so that when I go back to my other instruments (allocations or time profiler or whatever), the inspection range is filtered down to the relevant points of interest in my app.


Note, the above is Swift. In Objective-C, the kdebug_signpost API is similar, but you have to include:

#import <sys/kdebug_signpost.h> 

Obviously, how you define your enumerations for your codes will change, too.

Note, this kdebug_signpost API was introduced in iOS 10/macOS 10.12. The headers tell us that earlier OS versions could use syscall:

In previous versions of the operating system, applications could use:

syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, <your event code>) | DBG_FUNC_<type>, arg1, arg2, arg3, arg4); 

to record events that would be displayed by Instruments. syscall(2) is now deprecated and this interface replaces the above call.

Note: If you find yourself having to use syscall on an earlier OS version, you'll have to import <sys/kdebug.h>:

#import <sys/kdebug.h> 

Also, I wasn't able to find a declaration of SYS_kdebug_trace in any of the headers, but stumbled across a reference online that said that this value is 180, which I empirically verified:

#ifndef SYS_kdebug_trace #define SYS_kdebug_trace 180 #endif 
like image 116
Rob Avatar answered Sep 29 '22 11:09

Rob


2019

Signpost has been updated with an easier API. Video here (Time: 20:40)

https://developer.apple.com/videos/play/wwdc2019/411/

See Debugging CPU Performance in Apple logging documentation.

https://developer.apple.com/documentation/os/logging

like image 26
skymook Avatar answered Sep 29 '22 10:09

skymook