Instrumentsの概要

(音楽)

(拍手) 今回はInstrumentsをご紹介します 私はチベットです 後ほど同僚のベンと アナンドも登場します

すばらしいユーザエクスペリエンスには パフォーマンスが重要です 反応性はユーザとアプリケーションの 信頼関係を築きます 回転するカーソルが現れたり バッテリー寿命が短かったりすると 全体的なエクスペリエンスを損ないます ユーザエクスペリエンスの向上には そういったことが重要なのです 今回はパフォーマンスを測定する ツールをご紹介します Instrumentsです Instrumentsをワークフローに 取り入れてみたい方々に 役立つセッションです

複雑な不具合を起こさないために パフォーマンスの測定は 早い段階で かつ頻繁に行うべきです XcodeとInstrumentsは 互いに良き相棒です ですので私はDockに並べて置き エンジニアリングプロセスにおいて 早い段階で かつ頻繁に使用します

今回のセッションでは まずInstrumentsの機能やUIをご紹介し 次に個々のオペレーションの処理時間を 測定する方法をお見せします どの処理がどれだけ負荷をかけているか Time Profilerを使って調べます 最後にSignpostを追加して アプリケーションの挙動を理解します ではInstrumentsの概要に入ります

Instrumentsはパフォーマンスを分析し テストできるツールで Xcodeのツールセットの一部です iOSなどの各プラットフォームにおいて アプリケーションをプロファイルでき 挙動やパフォーマンスの 理解と最適化を可能にします 開発やテスト デバッグの最中にも使えます すでにXcodeをお持ちの皆さんは Instrumentsを使えます “Product”メニューから “Profile”を選びます このようにXcodeの中にも 組み込まれていますが Instrumentsは 単独のアプリケーションでもあります どちらでパフォーマンスの分析を 始めるかは自由です ところで“Instruments”には ２つの意味があります アプリケーションとしての “Instruments”は エラーを分析する各種ツール “Instrument”を提供します 私がどちらを言及しているか不明な時は アプリケーションだと思ってください Instrumentsはアプリケーションや OSなどのインフラストラクチャから 時系列のトレースデータを収集します 収集されるデータを 単に“トレース”と呼ぶこともあります これらは私が好きなInstrumentです “Time Profiler”はOSが提供する インフラストラクチャを使い 関連スレッドのコールスタックを 一定間隔で収集します “Points of Interest”は アプリケーションの重要なデータを集め SignpostなどのAPIを使って ハイライトできるツールです

Instrumentsを開くと― PagesやNumbersのものに似た テンプレートのリストが表示されます それぞれが各種測定のために 事前設定されています 簡単に誕生日カードを作れる Pagesのテンプレートのようなものです 今回取り上げる Time Profilerテンプレートは 先ほどご紹介したTime Profilerや Points of Interestなどを含んでいます アプリケーションの反応性や 使用率について理解を深められます

Time Profilerテンプレートを開くと 最初に空のドキュメントが開きます 別のInstrumentを追加したい場合は 右上のボタンをクリックします するとライブラリパレットが現れ 使用可能なInstrumentが リストで表示されます 追加したいInstrumentは ドキュメントにドラッグしてください 左上からはプロファイルを制御できます データ収集の記録や 一時停止と停止が可能です その右横はターゲットを示しています 左のターゲットデバイスのリストから プロファイルしたいデバイスを選べます これはプロファイルする デバイスとプロセスを Xcode上で選ぶ際と似ています

通常はアプリケーションの プロセスを選びます ですがShare Extensionを プロファイルしたい場合などは アプリケーションとは別の Extensionのプロセスを選びます

記録を始めるとドキュメントに トレースデータが追加されていきます 記録にはアプリケーションと同じく システムリソースが使われます またInstrumentsは― Windowed Modeという機能で アプリケーションの負担を減らします この機能は記録が終わるまで Instrumentsに分析や結果を表示させず また 記録が終わる直前まで イベントを無視します 問題が起きた時だけ 停止すればいいので便利です 膨大なデータを収集するテンプレートは この機能をデフォルトで使います

Time Profilerテンプレートでの 記録が終わり 多くのトレースデータが追加されました それぞれのデータの内容を 見ていきましょう

ウインドウ上部にはトラックがあります トラックはプロセスやスレッド CPUコアなど １つのイベントのソースの トレースデータを示します １つのInstrumentでも 複数のトラックを持てます 今回の例では３つあります 一番目のトラックには Time Profilerによって CPU使用率のサマリが 表示されています 二番目は後ほどアナンドがご説明する Points of Interestのデータです その他のトラックは より細かい情報を提供します

収集されたトレースは 数十ものトラックを有するので Track Filterを使ってスレッドや CPUコアごとに分けてもいいでしょう 名前からトラックを 検索することも可能です 詳細ビューでは選択したトラックの トレースデータが確認できます ここではTime Profilerの トラックが選ばれ トレース中に各スレッドで呼び出された 関数が確認できます

右側のインスペクタ内には 拡張詳細ビューがあります 現在の文脈や選択に沿って 使用中のInstrumentによる より詳細な情報を提供するものです この例では最も大きなコールスタックを 示すサマリが提供されています

ある瞬間の状況を確認する もう一つの方法はInspection Headです これはトレースの特定の時間に 置くことができるセレクタで トレースされた すべてのイベントなどを選択できます 選択されたイベントの追加の詳細は ラベルに表示されます 詳細ビューや拡張詳細ビューは 選択されたイベントの情報に合わせ アップデートされます InstrumentsのUIについて ご理解いただけたでしょうか ウインドウ内にあるものはすべて トレースドキュメントの一部です トレースドキュメントは― 事前設定された Instrumentや収集データ 分析に使用中のビューなどを含みます Instrumentsはトレースドキュメントを 保存および再起動できるので 過去の結果の確認や 仲間との共有もできます

それでは同僚のベンを呼び デモを見せてもらいましょう ありがとうございました (拍手) チベット ありがとう それではInstrumentsを使って 実際のプロファイルをお見せします 始めましょう

WWDC 2018に登場した アプリケーションに Solar Systemというものがあります 配布後 よいフィードバックを いただきましたが 一方でパフォーマンスについての ご指摘もありました 特に古いデバイスでの反応性に いくつか問題があったようです ある問題を再現できたので Instrumentsを使って修正しましょう 始めます

アプリケーションは起動しているので Instrumentsを開きます

以前使用したTime Profiler テンプレートがすでに選択されています これは特定の時間窓における問題を 確認するのに便利です “Choose”ボタンを押すと トレースドキュメントが開きます

Xcodeから開かなかったので まずはトレースするプロセスを選びます 左上の“All Processes”をクリックし “Solar System Mac”を選択します 右の数字はプロセスIDで アクティビティモニタに表示されます

アプリケーションを選んだので 左上のボタンから記録を始めます

記録が始まり アプリケーションが表示されました このアプリケーションは 様々なジェスチャに対応しており クリックやドラッグ さらにパンやピンチで拡大もできます これらの操作をしながらCommand+Rで データをリロードしようとすると UIがフリーズし 回転するカーソルが現れます これは目にしたくないものです 問題を再現できたので Instrumentsに戻って策を講じましょう アプリケーションを閉じると 記録も終わります

トレースデータが追加されたので 詳細を見やすいように拡大します カーソルをトラックの領域に置いたまま ピンチで拡大してください 左側にある複数のInstrumentは それぞれがトラックを持ちます Time Profilerは CPU使用率のサマリを示し Points of Interestは 現時点では空です 他にはThermal Stateや スクロールすると下にもあります CPU使用率の上でカーソルを動かすと ラベルに使用率が示されます 特に高い箇所では 使用率が100％を超えています おそらくここでリロード操作が 行われたのでしょう 他のトラックとも比較したいので トラックをピン留めします

トラックの見出しにマウスを合わせると 左にプラスボタンが現れます これをクリックすると トラックが下部にピン留めされます 他のトラックをスクロールすれば 並べて比較が可能です ピン留めは複数できます スクロールしていくと CPUコアごとのトラックが現れ―

Solar System Macの トラックが見つかりました アプリケーションの ライフサイクルイベントも確認できます ここでアプリケーションが フォアグラウンドに表示されました

CPUスパイクの最中に 奇妙な赤い領域がありますね ラベルには“Spinning”とあります これはメインスレッドが ブロックされたことを示します 回転するカーソルの原因です メインスレッドはユーザ入力とUIの アップデートのみに使われるはずですが 別の何かが起きているようです

メインスレッドを見てみましょう Solar System Macのプロセスを開くと アプリケーション内のスレッドが トラックとして現れます 下の方にメインスレッドがありました スパイクを示していますね

これが確認すべきイベントです トラックの領域内で クリックしドラッグすると イベントをフィルタできます 詳細ビューは 選択した時間窓のイベントを示します これを確認しましょう

このコールグラフは プロファイル中に 呼び出されたすべての関数を示します 今回の場合はフィルタ箇所のみです

この内容を理解しましょう

関数のすべての入口と出口は 追跡していません 代わりにTime Profilerは スナップショットを作成し プロセスで実行中の関数を記録します 左側は“Weight”の列です Solar System Macは100％なので すべてのサンプルで存在しています プロファイル対象だからですね メインスレッドは96.7％となっています スレッドを開いていけば さらに関数を確認できます しかしクリックを繰り返していては 時間がかかるので 便利な技をご紹介しましょう Optionキーを押しながら開くと 制御フローのブランチまで 自動でリストが拡張されます

しかしこの膨大なリストから 問題を見つけ出すのは大変です そんな時は拡張詳細ビューの “Heaviest Stack Trace”が役立ちます これはプロファイル中に 最も多く呼び出された関数を示します 一番上の“Solar System Mac”など 白くハイライトされたフレームは プロセス自体のフレームです

灰色はシステムフレームワークや ライブラリのフレームです メインスレッドのmain関数と 多くのシステムフレームワークの関数が 並んでいます

その下に白くハイライトされた 関数があります 一番上にある“thunk”とは 何でしょうか？ これはコンパイラが生成したコードで アプリケーションのソースコードとは 関係しません ですので今回は無視します 注目すべきは次の“NetworkRequest Scheduler”のクロージャです クリックすると 詳細ビュー内でも選択され ダブルクリックで ソースコードが示されます ここにある “scheduleParsingTask”は メインディスパッチキューで データ解析などを行っています これが問題ですね メインスレッドの役割はユーザ入力と UIのアップデートのみだからです 修正しましょう 詳細ビューの右上のボタンから Xcodeでファイルを開けます

Xcodeが表示されました

メインスレッドをブロックしないよう 処理を移します まずは“parsingQueue”という ディスパッチキューを作成します

次に非同期のクロージャを使い 処理をparsingQueueに移します “workItem”は上へ 解析の完了は UIに通知しておきたいので この呼び出しを メインディスパッチキューに移します

保存し 再びバグを再現しましょう 今回は“Product”メニューから “Profile”を選びます

するとInstrumentsが表示されました 今回テストするのは アプリケーションのコピーではなく Xcodeのドライブの データディレクトリにあるものです “Time Profiler”を選び “Choose”をクリック

テストするターゲットはXcodeにより すでにInstrumentsへ伝わっています 左上のボタンで記録を始めれば アプリケーションが起動します

問題のあるユーザ入力を 再び試してみましょう クリックやドラッグをしながら Command+R 回転するカーソルが 表示されなくなりました 念のためもう一度 クリック ドラッグ Command+R

反応性の問題は解消されたようです

記録を停止し トラックをピンチして拡大します メインスレッドから例の処理が消えたか “Track Filter”を使って確認します

メインスレッドを検索します

“Solar System Mac”だけが 表示されました これを開くと メインスレッドが見られます

CPUスパイクの箇所における メインスレッドの仕事量が減っています そして２度目も同様ですね 処理をメインスレッドから取り除き 反応性を改善できました (拍手) 役立つヒントのご紹介です

アプリケーションによる時間の使い方は Time Profilerで分かります 反応性の改善にも役立ちますし アプリケーションの起動を 素早くしたい時にも役立ちます ぜひ活用してください

反応性に問題があれば メインスレッドを見てみましょう UIのアップデートとユーザ入力にしか 使われないものです ユーザ入力とはMacのマウスクリックや iOSデバイスのタッチなどです

またプロファイルは リリースモードで行ってください コンパイラには 多くの最適化レベルがあります Xcodeでビルド＆ランを繰り返す際に 使われる低レベルな最適化は App StoreやXcodeのアーカイブ機能を 使った配布の際は使用されません

Xcodeがデフォルト設定の場合 プロファイルのアクション設定は リリースです しかし編集したコンパイラフラグの場合 アプリケーションはコンパイラフラグの リリースセットを使います

難しい処理や古いデバイスでの プロファイルが大事です 開発中は今回のバグを 認識していませんでしたが 異なる性能特性のデバイスを持つ 利用者がバグに遭遇しました そのようなデバイスでのテストを ぜひ行ってください

Instrumentsは 全プラットフォーム対応です デモはMacでしたがiOSやwatchOS tvOSでも同じように使用できます シミュレータにも対応していますが この場合 注意事項があります シミュレータはMacで動くので Macとリソース競合します CPUやメモリの性能特性 ファイルシステムやディスクの挙動 組み込みデバイスでは異なるはずの 熱的制約もMacと共有します この場合 Instrumentsは 現状の理解には役立ちますが アプリケーションの動作を秒単位で シミュレーションすることはしません 配布前に実際のハードウェアで テストしてください

反応性は改善しましたが やることはまだあります CPUスパイクを軽減することが できるはずです スパイクはバッテリーの消費や デバイスの発熱にもつながり ファンの動作音が利用者を苛立たせます そこでアナンドに登場してもらい アプリケーションが行う処理を Signpostで理解しましょう (拍手) ベン ありがとう コードの中でどのように Signpostを使うのかをご紹介します Instrumentsで集めたトレースデータと システムリソースの使われ方を さらに理解しましょう

まずはSignpostについてです Time Profilerと比較しながら ご説明しましょう Time Profilerはアプリケーションの 全スレッドを一定間隔で観測し コードの統計的プロファイルを 提供します そしてコールスタックと時間に 相関性を持たせますが この相関性からはコードがどう実行され またなぜ実行されるのかは分かりません 短い時間で何度も 実行されるのかもしれませんし もっと長い時間で 回数は少ないかもしれません 特定の引数を取る関数がCPUを 継続的に高負荷にするのかもしれません どんなパターンなのかを識別するには コードの詳細な測定のログが 必要となります そうなると― パフォーマンス測定のログは どう取るべきなのでしょう？ 幸いなことにprint文の読み方を Instrumentsに教える必要はありません Signpostを使うのです

今回の目的に役立つ機能が Signpostには多くあります

構造化されたパフォーマンスデータの 収集に特化しているため 出力するよりも簡単で効率的です

時間測定を ビルトインサポートしているので クロックソースやタイムベースを 気にする必要はありません また すでにInstrumentsは Signpostのトレース方法を知っています 私がInstrumentsでSignpostを使って 収集したトレースデータを見てください

Points of Interestのトラックが示す 関心領域は コードにSignpostを加えて指定した 処理時間です ではベンが行っていた作業の続きを デモでお見せしましょう

先ほどInstrumentsで集めたトレースが このように表示されています

CPU使用率が高い領域があります

なぜCPU時間を 消費するのか知るために この領域のコードに Signpostを加えます スタックのトレースを確認します

ベンは先ほど 一番上から順に見ていきました

そうするとコードが どのように実行を開始したか分かります しかし今回はリーフレベルの 関数から見ていきます 重い関数や頻繁に呼び出される関数を 見つけるためです この“setupScene”が― リロードの際に 多くの配列を操作しているようです これにかかっている時間を 正確に知りたいと思います Xcodeに移り このコードを確認してみましょう

こちらが“setupScene”です 私がここでパフォーマンス測定を 試みた痕跡が残っています “mach absolute time”を含む print文がありますね そして下の方にスクロールしていくと “mach absolute time”を含む print文の終わりがあります しかしInstrumentsは print文の読み方を知りません ですので最初にログハンドルを作成し Instrumentsと会話できるようにします

やってみましょう

カテゴリ名は “pointsOfInterest”です Instrumentsの “Points of Interest”と一致します

最初のprint文は― 開始時間を指定する “os signpost”に置き換えます そうなると終了時間の指定も必要です 下方にスクロールしていく代わりに Swiftのdefer文を使って 終了時間の指定を行います ブロックの中身は 現在のスコープが終わると実行されます

これらの変更を反映し Instrumentsでプロファイルしましょう

Time Profilerテンプレートを選びます ターゲットの選択領域には すでにSolar Systemが見えるので 記録を始めます

もう一度 問題の起きた操作をしながら リロードを行います

データが取れたので記録を停止します

CPU使用率の高い領域を ピンチして拡大します

下にある Points of Interestのトラックは コードに加えた関心領域を示しています Signpostで指定した時間である “setupScene”の行です 記録されたいくつかの関心領域が トラックに並んでいます 想定よりも数が多いです マウスオーバーして関心領域の数を 数えてもいいのですが 詳細ビューからも分かります この領域をクリックしながらドラッグし トラックをクリックすると 詳細ビュー内でPoints of Interestの トラックのサマリが更新されます

確認してみると“setupScene”は この領域内で８回実行されており 平均時間はおよそ200msとなっています

情報は他にもあります ジャンプバーから“List: Regions of Interest”を選ぶと 記録されたすべての関心領域を 時系列で確認できます

“Duration”の列は 関心領域の長さを示します これを見る限り―

それぞれの処理時間の長さは ほとんど同じです およそ210～220msですね 一体なぜ 似たような量の処理を 何度も繰り返しているのでしょう？

そこでsetupSceneの呼び出し元を 確認してみます それにはTime Profilerが記録した コールグラフが役立ちます

ウインドウの右下にあるスタックを 再び確認します この中の“prepareScene”という 関数を見てみましょう ダブルクリックでソースが表示されます prepareSceneは１度しか setupSceneを呼び出していません 反復の原因ではないですね ジャンプバーの“Root”をクリックし コールグラフの全体を表示します そしてコールスタックを 探っていきましょう

隣の呼び出し元を選ぶと ４つのループがあります おそらくこれが反復の原因です Xcodeでこのコードを より詳しく見てみましょう このボタンから Xcodeでファイルを開きます

Xcode上で４つのループが確認できます 知っている関数です “updateWithPlanets”は― サーバからのデータを リロード時に受け取ります そして惑星の 新たなデータがある場合には その惑星の内部モデルに アップデートを適用します しかし複数の惑星のアップデート情報を 含んだデータを受け取ると “prepareScene”を呼び出して 都度 全体を再描画しているようです

トレースを見ると ビュー全体の再描画にかかる負荷は 惑星の内部モデルのアップデートよりも はるかに大きなものです そこで内部モデルのアップデートを すべてバッチ処理し ビューを１度だけ 再描画するようにします 単純だったようにも思えますね しかし新機能の追加や 無関係のバグの修正をするうちに パフォーマンスに関するこの種の問題は 知らぬ間に起こり得ます こういったバグを 起こさないために重要なのは 機能を何度も動かすテストを 書くことです リロード操作を行うXCTestを すでに書いておきました

テストの左側にあるボタンを クリックすると実行されますが 今回は副ボタンのクリックで プロファイルのアクションを出します Instrumentsで テストをビルドし実行させます

Time Profilerテンプレートを開き トレースを記録しましょう

Measure APIの呼び出し元に リロード操作を入れました このAPIは処理を何度か実行して 複数の反復測定を収集します これにより測定が一貫性を持って 反復されているかどうかや ランツーラン変動性が あるかが分かります

反復が終わったようなので トレースを終了します

“Points of Interest”の トラックを拡大します 新たに行が追加されていますね

一番下は私がコードに加えた “setupScene”ですが その上にはMeasure APIによる行が 表示されているのが分かります それぞれの反復の実行にかかった 処理時間を示すものです

ざっと見たところ この処理は かなり一貫性を持って行われています では１つの反復の中で 何が起きているかを見てみましょう クリックとドラッグでも選択できますが １つのイベントや処理時間を ピッタリと選択する技があります トリプルクリックです

選択領域の情報は 詳細ビューに表示されます

この領域では“setupScene”は 一度しか呼び出されていないようです このように私たちは Signpostから得た情報を利用し CPU時間を大幅に 削減することに成功しました (拍手)

では これまでのおさらいです

Time Profilerが収集する 統計的プロファイルからは どのコードが 最も実行されているかが分かります しかしコードがなぜ どのように実行されるのかは Signpost APIを使った測定でないと 分からないのです また テストの有用性についても 見てきました 早い段階で正確に何度も処理を再現し プロファイルすることが大事です

今回は CPU使用率に 問題がある箇所で見られた― パフォーマンスに関する問題を 解決してきました しかしInstrumentsは他にも― リソース使用状況の理解に役立つ テンプレートを持っています ファイルやディスクの 使用状況が分かるテンプレート ネットワークの 使用状況が分かるテンプレート また別のテンプレートにおいては アプリケーションとOSなどの間の やり取りについても理解できます 他にもあります カスタムInstrumentsというものです 例えばフレームワーク作者が 利用者に― パフォーマンスに関する質問への 回答をお願いするとします その場合はカスタムInstruments パッケージを提供しましょう

異なるInstrumentを集めた カスタムテンプレートの作成も可能です 特定のパフォーマンスに関する質問にも 答えやすくなります

ぜひ皆さんも開発の早い段階で プロファイルを頻繁に行ってください そしてInstruments 11を すぐ試してください トラックのピン留めや階層ビューなど 新たな機能もあります 大変面白い機能です

便利な機能やワークフローなどを まとめたドキュメンテーションや 2018年のセッションもご覧ください それでは (拍手)