Measuring Performance Using Logging

(音楽)

(拍手)

こんにちは Darwin Runtimeチームの シェーンです 今日のテーマは ロギングを使った パフォーマンス計測です

ご存じのとおり パフォーマンスは ユーザエクスペリエンスの カギを握るものです 素早くダイナミックな動作や 応答の速さが求められます

でも…

ソフトウェアは複雑です アプリケーションの動作には 多くのプログラムが関係し 時に予想外の パフォーマンスを生みます しかし そうした成果を 発見するためには プログラムへの 深い理解が欠かせません “このコードは いつ実行されるのか” “要する時間は どれくらいか” ここで優れたツールが 求められるわけです 我々は より優れたツールを提供して 生産性の向上に 貢献したいと思います そこで今日 紹介するのは signpostという ツールです 新たにOSLogに 加わったもので macOSで使用できます 他にもiOSやSwift Ｃ言語に対応 更にInstrumentsでも 使えます つまりsignpostの データを取り込んで プログラムの動きを 確認できるのです まずは歴史をお話しします OSLogは２年前に 登場しました 最新のロギング機能で システムから デバッグ情報を得ます 効率性とプライバシーを 考慮して作られたものです これがOSLogのコードです “Hello world”を 表示させてみます パフォーマンスの ユースケースのために signpostは OSLogのAPIを拡張 パフォーマンスに 関する情報が デベロッパツールに 統合されます そこでコードを加え Instrumentsを実行させます

プログラムの動きと signpostのアクティビティが 時系列で可視化されました 下部はsignpostのデータを 統計分析した表で プログラムの動作を 多角的に見ることができます 今回はsignpostの 使い方とメリットを お話しします その後 Instrumentsと signpostによる情報表示を 実際にご覧に入れましょう

まずは―

簡単な例を用います これが あなたの アプリケーションだとします インターフェイスの リフレッシュに 要する時間を 調べてみましょう そのために画像を読み込ませ 表示してみます アセットの取得中は このようにシンプルです 取得が終われば リフレッシュが完了します signpostにより タスクの 始まりと終わりを記録し ２つのログイベントを 結びつけます os signpostの 関数呼び出しを使います BEGINとENDの ２つの関数が表示されました BEGINのほうには 矢印の下に“b”と ENDのほうには “e”と示しました この２つのポイントから 経過時間を計算するのです いいですか？ コード上 アルゴリズム実装は シンプルです インターフェイスの 各エレメントに― アセットを取得し これを計測するのです signpostを コードベースに組み込むため os.signpostを インポートします signpostは OSLogの機能の一部なので ログハンドルを作成します ここではサブシステムと カテゴリが引数になります プロジェクトを通して サブシステムは同一でしょう バンドルIDのように コンポーネントや フレームワークを示します

カテゴリはsignpostと 関連付けるために必要です 後ほど また登場します

ログハンドルを作ったら BEGINとENDの２つの CALL文を設定 ここにログハンドルを 渡します ３つ目の引数は signpost名で 経過時間を示す 文字列が入ります 今回 計測する 処理時間のことです この文字列は BEGINやENDの目印として 一致させるために使われます 時系列では こうなります 各タスクの始めに os signpostを置き 各タスクの最後にも os signpostを置く BEGINとENDの文字列が 呼応するため ２つは結びつきます では 各タスクではなく リフレッシュ全体に要した 時間を計るには？ BEGINとENDのペアを もう１つコードに加えるだけ 簡単ですね 今回は文字列と signpost名を変え ループとは異なる時間を 計測するように設定しました

時系列では―

２つのsignpostを追加

リフレッシュすると 文字列がマッチし ２つの点が結びつきます

たとえが 少し難しいのですが… プログラムは １つ完了してから 次に進むとは限りません 非同期的に 多くのタスクが 進行することもあります そのような場合は 最終的にすべて完了するよう タスクを進めます これらのタスクも 同時進行になり得ます ですから 他のsignpostと 区別するため 情報を追加する 必要があります ここまでは 最初と最後にマッチする― 文字列だけで 区別してきました これではオーバーラップする 処理時間を区別できません そこでsignpost IDを 追加してみましょう

このIDにより 同種のオペレーションでも 個々を区別できます 同時進行でも signpost IDが異なれば 別々の時間を計算します 最初と最後のIDさえ そろえておけば ２つは自動で結びつきます IDはコンストラクタでも 生成できますが オブジェクトでも 生成できます オブジェクトを 使っている場合に便利です 同じインスタンス内では 同一IDが生成されるため signpost IDを格納したりする 必要もありません

つまり…

signpost IDは 呼び出しの際 付加的な情報を加えることで あるオペレーションの 最初と最後を関連付けます これにより オペレーションの同時進行や 所要時間の差に対応できます

実際のコードを 見てみましょう 同期の読み込みを 非同期の呼び出しにします アセットの取得後に 開始する― 完了ハンドラを追加します 全アセットの取得後も同様に 完了ハンドラを追加します ENDのos signpostを 完了の前に入れ 最後にマッチするように 設定しました

複数のアセット取得が 同時に進行するため それぞれに signpost IDが必要です 上の例は コンストラクタで生成し 下の例は オブジェクトで作っています そして 生成したsignpost IDを CALL文に渡せば完了です

signpostは分類や 階級付けに似ています すべてのオペレーションは ログハンドルで関連付けられ 各オペレーションに signpost名を付与

タスクが同時に進行するため signpost IDを与え 個々の処理時間を 識別できるようにしました

このインターフェイスは 非常に柔軟です BEGINやENDの引数や signpost名 ハンドルやIDも 自由にコントロールできます 今回はBEGINとENDの引数が 同じだったため ２つはマッチしました しかし分けることも可能です 別のオブジェクトや ソースファイルを使えます このCALL文を幅広く応用し コードにsignpostを 組み込んでみてください

以上がsignpostによる 時間の計測です 今度は signpostに 付加的な情報を加えるため CALL文にメタデータを 加えてみます

基本のCALL文に 文字列のパラメータを足すと BEGINとENDに 情報を追加できます 更に文字列は OSLog形式なので 複数のBEGINとENDにも対応 signpostに 付加情報を渡せます 例えば４つの整数を渡すため “%d”を使います これはOSLogの形式なので 多くの引数に対応します 浮動小数点の数字も 書式指定子を用いた指示も システムに伝えられます

動的に文字列を 呼び出すことも可能 呼び出した関数や 入力された情報も渡せます 一定のメモリから 文字列を参照するため 人間が読める文字なら 設定は自由です

Instrumentsで 表示されるものと同じなので 気軽に情報を 追加してみてください すべての文字列を 表示したり 付加データに アクセスしたりできます

次は― 時間軸に個別のポイントを 追加する場合です BEGINとENDの signpostに加えてみます 例えば 特定の時間に 縛られない― 一定の時間です イベント型の os signpostを使います コードはBEGINやENDと 同様に見えますが イベント型です １つの時点がマークされます 前後関係がある場合も ユーザ行動のように 突発的な場合もあるでしょう アセット取得時の一時点です アセットの提供元に 接続した時や その一部の取得を開始した時 特定の処理時間内であれば 何度でも処理状況を アップデートできます

もしくはイベントの発生を トラッキングするとします 例えばユーザが リフレッシュした時 パフォーマンスに問題があり スワイプを繰り返すと 点がいくつも発生します

通常signpostは デフォルト設定されています その設定の切り替え方を 説明します

我々はsignpostを 軽量化するため コンパイラの最適化に 注力しました 実行時間の前にタスクが 完了するようにしたのです またInstrumentsの裏で 行う仕事を分けました つまりsignpostは 少ないリソースで済むのです コードへの影響も 小さくなります また短いタイムスパンでも signpostを活用し 細やかな計測を 行うことが可能です もちろんオフにもできます 例えばコードの オーバーヘッドを軽減する時 またはsignpostカテゴリが ２つある中で 一方のデバッグに 集中したい時などです その場合 OSLogの機能を活用します 無効なログハンドルです これは シンプルなハンドルです すべてのos signpostの 呼び出しに対し 何もしない状態になります Ｃ言語に このハンドルがある場合は 引数も求められません

ランタイムに ハンドルを変更するだけです

最初に使ったコードを 例にします １番上に初期設定があります ここに条件式を追加します 割り当て先は 通常のコンストラクタか 無効のハンドルです

前者ならos signpostが 呼び出されますが 後者だと 何も実行されません ご説明したとおり CALL文の内容は変更不要です 変えるのは初期設定だけ ここでは環境変数の 条件を付けました デバッグする時の Xcodeは この設定です

CALL文は変更不要ですが 計測に使う 固有の機能は使えます 高いけど デバッグに役立つものです ログハンドルのプロパティで signpostが オンに なっているか確認します 付加的なオペレーションを 制御するためです

これまでの例は Swiftで見せましたが signpostはＣ言語にも 対応しています

お話しした全機能が使えます ログハンドルや ３つのsignpostの設定 IDの付け方も同様です Ｃ言語のデベロッパ視点で 書かれた― HeaderDocも ぜひ参照してください

以上が コードにsignpostを― 組み込む方法でした 次はInstrumentsでの 活用法を見てみましょう ここからは 同僚のチャドが ご説明します では (拍手)

ありがとう シェーン 次は signpostが活用できる― Instruments 10の ３つの新機能をご紹介します １つ目はos signpost 記録や可視化― アプリケーション内の アクティビティ分析ができます ２つ目が Points of Interest 概要と どんな時に 便利かを説明します 最後に 新しいカスタム機能と os signpostとの 使い方をお見せします signpostを活用する ヒントになります それではデモをお見せします

デモ用のアプリケーションを 用意しました Trailblazerです ハイキングスポットを 紹介するもので スクロールすると 画像が表示されます 最初は白い背景が表示され 遅れて画像が現れます 最新のアプリケーションでは 一般的な挙動と言えます パフォーマンスには 優れますが プロファイルには不向きです 多くの非同期処理が 起きるためで スクロールと 画像の 読み込みが重なります 速くスクロールされると 読み込みが完了せず 画像が表示されません こういう場合は キャンセルしないと 平行して 読み込みを続けようとします そこでsignpostを使って アプリケーションを 分析します

これがコードです startImageDownloadを 使っています 画像を読み込む際 呼び出され 該当の画像の名前が 渡されます ダウンローダの記載はここ ダウンロードが終わると コールバックを受け取れます 今回はダウンローダが 同時に起動していますので signpost IDの生成に ピッタリです ダウンローダの オブジェクトでIDを作ります

ここがos signpostの BEGINです networkingの ログハンドルに送ります ちょっと見てみましょう アプリケーションの バンドルIDがあり カテゴリがあります

次に 背景画像の 読み込み完了が分かるように 画像のsignpost名を渡します 次にsignpost IDです BEGINにメタデータを加え 読み込む画像の名前を 伝えます ダウンロードを開始 プロパティが ダウンローダの作動を トラッキングします 完了すると コールバックが送られます 読み込んだ画像を表示し ENDを呼び出します ログハンドルも名前もIDも 同じものを使いますが 次はサイズを規定する メタデータを追加します ご覧のとおり 今回は詳細に “xcode:size-in-bytes” と記しました XcodeとInstrumentsに 引数をバイト単位で表示し 分析させるためです これについて 詳しくはヘルプ内の デベロッパガイドをご覧ください

ダウンロードが完了すると nilに戻ります 終わり方は２つあります 今のが成功例で 次はキャンセルする場合です 再読み込みに備え 作動中のダウンローダを 先にキャンセルします そのためにENDを置きます 同じログハンドルと 名前とIDを使いましょう メタデータに “Cancelled”と加え 成功した場合と区別します 準備は終わりました 次はプロファイルを 作成します Instrumentsが 立ち上がります

まだインストール中ですね 立ち上がりました 新規作成を選び― Libraryへ 新しいos signpostを 使ってみます ここに ありますね

ドラッグ＆ドロップで トレースを表示 スペースを広げて― Recordを押します 先ほどのiPhoneを持ってきて 普通のスクロールと 速いスクロールをします 画面が止まるのを待ち―

Instrumentsに戻り 記録を確認します

記録を停止します トラックビューを 見てください これは背景画像の処理で signpost名です Optionを押しながら拡大 処理時間が見られます 最初と最後の メタデータも見えますね

縮小して もう一度 トレースを見てみます 同時に読み込まれている 画像の数は ５つくらいですね キャンセルは成功です 確認したければ 詳細を見てみましょう 処理時間のメタデータに “Cancelled”と 書かれています

次に詳しい数字を確認します 例えば処理に要した 時間を見るなら―

処理時間のサマリーへ カテゴリごとに ブレイクダウンされます その下は名前ごと そしてメッセージごとです 少し狭めましょう 93個の画像を読み込む リクエストがありました うち12個はlocation１ そのうち７つはキャンセル ５つは3.31MBで 読み込みました

所要時間が 右側に表示されます キャンセルに要した― 最短時間と平均時間が 出ています 処理完了の場合より ずっと短いです 想定どおりの傾向です キャンセルした全イベントの 詳細を確認するには 横の矢印をクリック リストビューが開いて キャンセルのメッセージを 受け取った場所が分かります 更に このように 該当箇所の処理時間が トレースビューで示されます エラーの原因を探す時に 便利です

いつ処理時間が発生したか 知る方法は分かりました ではメタデータを 分析する方法は？ 例えばネットで 何バイトの画像を 読み込んだのか知るには？ サイズに関するメッセージを メタデータに加えましたが これが使えそうですね やってみます サマリーの Metadata Statisticsへ

サブシステム カテゴリ フォーマットごとに ブレイクダウンされます フォーマットの下は引数です 今回の場合は arg0だけでした Instrumentsが合計値を算出 バイトで表示されます ここでは読み込んだ画像が 80MBだと分かりました

横には 最短･最長･平均時間もあり 分析するのに最適です パフォーマンスを 統計的に分析できます

signpostは 軽量という話でしたね 事実ですが 今見せた操作は例外です

デフォルトの immediateモードでは 記録もデータの閲覧も ほぼリアルタイムです その場合 signpostは Instrumentsに直接 データを送ります バッファリングする 最適化のデータより 優先して送られます signpostの場合 デモで行った規模なら オーバーヘッドは 気にならない程度です しかし １秒に何千もの signpostが必要な場合 負荷が大きくなります それを回避する方法です 記録の前に Instrumentsの記録モードを 変更します Recordボタンから Recording Optionsを 選択します

下部に現れる Global Optionsを押すと Immediateモードに なっています これを“５秒間”に 変更します ウィンドウ制限です すべての イベントではなく ５秒分だけを 記録するという設定です これによりInstrumentsが OSを邪魔しなくなります システムやゲームの パフォーマンス調査に 非常によく使われる手段です スタッターやエラーを 発見できます

以上が os signpostでした 次は Points of Interestです

再度 Trailblazerを 使います

画像を選択すると 詳細が表示されます 別の画像を選べば また詳細が現れます いつどこで 詳細が表示されるか トラッキングできれば 便利です ユーザの関心や行動を 予測できますからね signpostで可能ですが Instrumentsを使って すべて記録する 必要があります 必然的に多くのイベントに 埋もれてしまいます Points of Interestで 優先度を上げましょう コードを見てみましょう メソッド viewDidAppearの中に os signpostのイベントを 作りました 詳細の名前がここに入ります Points of Interestに これが送られます 識別子のついた ハンドルが作られ 専用のカテゴリが 設けられます Instrumentsは これを目印に 該当する箇所を探し カテゴリ分けします タイムプロファイルを 見てみましょう Points of Interestが 自動で読み込まれています 記録を開始します

先ほどと同じように ２ヵ所の詳細を閲覧します もう１ヵ所 やっておきましょう

Instrumentsに戻ります Points of Interestが しっかりと記録されています ユーザが見ていた場所や 詳細なデータが分かります あなたの アプリケーションの中で ユーザの関心が高い場所を 把握できます デベロッパチームやコミュニティで このデータを 共有することもできます

以上が signpostを使った― Points of Interestの デモでした

Instruments 10の もう１つの特長は カスタマイズできることです 今回 カスタム版の デモのために Trailblazer専用の パッケージを作ってきました 今から実行してみます

見てください

パッケージが インストールされた― Instrumentsの コピーが現れました これを立ち上げましょう Trailblazer Networking テンプレートがあります これを選ぶと 専用のトレースドキュメントが Instrumentsに現れます それでは早速 記録をしてみましょう os signpostとカスタム版の 違いを確認します もう一度 画像を読み込みます

トレースを見てみましょう 見た目から違いますね 拡大してみます 左側を見てください signpost名ではなく 画像名で並んでいます 画像２の読み込みが 行われたのは ここと ここです 各読み込みに 画像のサイズを表記しました 3.5MBを超えると 赤くなる設定もしています このようにグラフを カスタマイズしました 下の詳細も違います とてもシンプルなリストです トレースでも確認できます そして更に… 画面を戻しますね 全ダウンロードの サマリーも見られます これが合計です Timesliceという 便利な機能も “同時進行のタスクは いくつあるか”という― 問いに答えてくれます タスクの数を知るには 画面上の縦線を 時間軸に動かします 縦線と交差する数が 同時に進行する タスクの数です これも役立つ データの１つです もしチームで プロジェクトを進行するなら カスタム版は最適です コードの詳細を知られずに signpostのデータを活用し プログラムを共有できます 重要な特長です 他にもあります このカスタム版は わずか115行のXMLで すべて定義されています 幅広く応用が利き 強力であると同時に 簡単なのです

デモは以上です

(拍手)

今日はsignpostの APIを使い Points of Interestと 処理時間のデモを行いました メタデータを集め Instrumentsで 可視化し分析しましたね 更にsignpostのデータを 使いやすくするため Instrumentsの カスタム版を作りました 今回の情報は非常に有益です ぜひアプリケーションの パフォーマンス向上に 役立ててください os signpostとInstrumentsを うまく活用すれば ユーザエクスペリエンスを 改善できます 今回は以上ですが ラボにもお越しください テクノロジーラボは 本日３時からです セッション410でも お話しします Instrumentsの カスタム版について Trailblazerを例に 解説します ありがとうございました (拍手)