signpost
概要
2018 年に導入
低コストなトレーシングを実現する
トレース可能なのは、以下の二種類
Pointes: .event を利用する
Intervals: .begin/.end を利用する
OSLog: WWDC 2016 で発表されたロギング機能。効率性とプライバシーを考慮して作られている 特徴
時間
match_continuous_time により高精度な時刻が記録される
singpostID によって、異なるスレッドや DispatchQueue 上の overlap を計測できる
低コスト
フォーマット用の文字列や名前は最適化された上で __TEXT に定数として組み込まれるので、とても軽量
軽量なので #DEBUG は不要
プロダクションビルドでも signpost を利用したデバッグが可能
利用方法
Interval を記録する
os_signpost を計測したい最初と最後の地点で呼び出せば良い。この時、開始/終了地点を対応づけるために、name は一致させる必要がある。
code:swift
let logHandler = OSLog(/* ... */)
os_signpost(.begin, log: logHandler, name: "Fetch Asset")
fetchAsset()
os_signpost(.end, log: logHandler, name: "Fetch Asset")
しかし、非同期でオーバーラップするような処理の場合、名前だけでは対応関係を解決できない。
code:test
処理A : begin --------> end
処理A' : begin -------> end
処理A'': begin ------> end
このような場合には signpostID を利用する。
code:swift
let spid = OSSignpostID(log: logHandler)
// 同一インスタンスを指定して同一の signpost ID を取得することもできる
// トレースしたい区間と生存期間が合致しているインスタンスが存在している場合に便利
let spid = OSSignpostID(log: logHandler, object: obj)
// 引数に渡す
os_signpost(.begin, log: logHandler, name: "Fetch Asset", signpostID: spid)
トレースにメタ情報を渡したい場合は、文字列を追加で引数に不要することができる。
code:swift
// 単に文字列を付与
os_signpost(.begin, log: logHandler, name: "Fetch Asset", "for thumbnail")
// フォーマット指定子も利用できる。OSLog と同様
os_signpost(.begin, log: logHandler, name: "Fetch Asset", "%d %d %d", x1, x2, x3)
// OSLog と同様にプライバシーレベルを付与できる
// Debugger をアタッチしていない状態だと、private レベルのログは出力されない
os_signpost(.begin, log: logHandler, name: "Fetch Asset", "%{public}s", myString)
os_signpost(.begin, log: logHandler, name: "Fetch Asset", "%{private}s", myString)
Best Practice
Signpost の動作モード
signpost にはいくつかの動作モードがある。
Enabled
デフォルトの動作モード
低コストで、メモリ上のリングバッファにのみロギングする
Streaming
Instruments の Immediate モードや log stream --signpost などによって、ロギングした結果を即時表示するような場合の動作モード
高コスト
Dynamic
Instruments による記録が行われている場合のみロギングを有効にする
.dynamicStackTracing の方がスタックトレースを記録する分多少オーバーヘッドは増える
動作モードによるオーバーヘッドは、下記のようになっている。
https://gyazo.com/44de33d6b3638b10a8d607fe963fdb68
オーバーヘッドを最小化するためのポイントは、以下。
Instruments にて、immediate モードではなく deffered モードを利用する
Dynamic Tracing カテゴリを利用する
Dynamic Tracing カテゴリは、signpost がデフォルトでオフになる
レコードしていない間のオーバーヘッドを少なくできる
Interval は停止すること
開始した Interval は停止しないと、Instruments の分析に悪影響が出る。
code:swift
do {
let id = OSSignpostID(myHandle)
os_signpost(.begin, log: myHandle, name: "MyName", signpostID: id)
let result = try MyProcess(data)
// これだと、例外発生時に Interval が停止しない
os_signpost(.end, log: myHandle, name: "MyName", signpostID: id)
} catch {
// ...
}
code:swift
do {
let id = OSSignpostID(myHandle)
os_signpost(.begin, log: myHandle, name: "MyName", signpostID: id)
defer {
// これで、確実に Interval を停止できる
os_signpost(.end, log: myHandle, name: "MyName", signpostID: id)
}
let result = try MyProcess(data)
} catch {
// ...
}
同じデータを複数回ログに載せない
.begin と .end のログに同じデータは載せないようにする
無駄なので
なるだけ .begin の際に表示して、表示したデータはその後は表示しないようにするのが良い
Signpost が動作していない時に不要な動作が発生しないようにする
code:swift
os_signpost(.event,
log: myHandle,
name: "ReceivedPayload",
"Payload: %@",
// これだと、signpost が動作していない場合にも影響を与えてしまう
myObj.expensiveJSONDecodedProperty.description)
code:swift
// signpost が動作している場合のみ必要な処理を実施する
if myHandle.signpostsEnabled {
let decoded = myObj.expensiveJSONDecodedProperty.description
os_signpost(.event, log: myHandle, name: "ReceivedPayload", "Payload: %@", decoded)
}
Custom Instruments
WIP
参考