AbemaTV iOSチームのエンジニアが教える、Signpostを用いたプロファイリング

Siginpostを用いたプロファイリング

鈴木俊裕氏：「Profiling using signpost」というタイトルで発表します。

AbemaTVでiOSチームと、Streaming Clientっていう動画ドメインに特化したチームに所属しています。チームでは「トッシー」とか呼ばれてるんで、適当に呼んでもらえればと思っています。

今日はSignpostの話なんですけど、この後発表します弊社の横山が、前回まったく同じタイトルでLTしてまして（笑）。

（会場笑）

ぜんぜん知らなかったんですけど。このときはLTだったということで、若干かぶりつつも、今回はさらに深掘りしていきますんで、楽しんでいただければと思っています。Signpostと、あとはCustom Instrumentsに言及します。

スライドは全部英語なんですが、「周りにあんまりSignpost使ってる人いないな」という印象で、英語で公開しとくといろいろ全世界からフィードバックが得られた経験があるので、ちょっと英語で申しわけないんですが、口頭で補足させていただければと思っております。

Signpostは「標識」っていう意味があります。

これは今年発表されたものです。

このへんは飛ばしていきます。

経緯としては、2014年から続く流れで2016年にOSLogが出てきて、1年空いて2018年にSignpostが出てきたと。基本的なバックグラウンドは共有していて、APIも似ている両者になります。

これと併せて、Instrumentsにも今年かなり大幅な改善が入って。これまでは例えばTime ProfilerとかLeaksとかは別々に実装されていたらしいんですけれども、今年かなり内側のリファクタリングが入って、Standard UIとAnalysis Coreというものにわかれて実装されたという経緯もあるようです。

Signpostの機能

Signpostなんですが、いつも見るこの画面のなかにはデフォルトではないので、Blankを選んでいただいて、右上のドロップダウンメニューからこのSignpostとPoints of Interestを、どっちかだけでもいいんですけど選ぶと使えます。

1つ目の「Signpost」って書いてあったほうが、この「Interval」と呼ばれるものです。

これは、ご存知だと思いますけれども、どの処理にどれぐらいかかったのかとか、あとは下の詳細リストのほうに、任意のメタデータを任意のフォーマットで出力することができます。

Points of Interestは、シンプルにいつ何が起こったのかを、メタデータとともに出力することができるというものになります。

Points of Interestはご想像のとおり、とってもシンプルで、1行書けば出てくるというものです。

Intervalは当然ちょっと複雑な実装が必要で、beginとendイベントが1対1になるように書いてやると。非同期の処理の場合の一意性の担保は、このSignpostIDのオブジェクトで保証するというものになります。

特徴として、OSLogもそうなんですけど、Lightweightだっていうことが言われていて。具体的に何がLightweightなのかというと、このようにメタデータをフォーマットストリングに渡すんですけど、ここの文字列の生成を実際に観測するときまで遅延するというのが1つ。

遅延してもすぐ観測したら結局パフォーマンスには影響が出てしまうので、Immediateモードがopt-outされるDeferredかLastのどっちかのオプションを選ぶと、アプリの本体のパフォーマンスには影響が少ない状態でプロファイルができるということでした。

これはゲームエンジンとかのプロファイルにも使われているテクニックだというふうに言っていました。

さらに、Instrumentsにつながってるときだけに限定した処理がやりたいということであれば、こういうふうに書けるし。

もういっそ全部disable、例えば本番コードで動かしたくないっていうことなら、これですね。

disableのログハンドラーがあるので、これに入れ替えてあげれば、実際のログを吐くコードにはほとんど手を入れることなく制御できます、ということが紹介されていました。

ケーススタディ

ここでケーススタディを紹介します。

こちら、僕の作っているBitriseのクライアントアプリのAPI処理を入れてみたもの、最初入れてみたときのもので、自分でもびっくりしたんですけど、スクロールしたら50個の並列リクエストが出てきて（笑）。

（会場笑）

これ、ひどいですよね、本当（笑）。

処理の限界を超えていて、最後とか何秒もかかっていて。「どうもスクロールが遅いな」と思ったら、こういうことになっていて。

コードを改善したらスッキリしたと。こういう改善が細かい数字も含めて視覚的にわかるので、とっても良いものだなと思いました。詳しくはこのプルリクエストにあります。

ちょっと使いづらい部分もあって。例えば、このグラフを描画するタイムとかも、nameのパラメータのタイムになってしまうのと。あとは、標準で勝手に真ん中のNavigation TransitionにReloadいうのが出てきてしまって。これはけっこう重たいっていうのと、単純に太くて高さが自分で変えられないので、ちょっと使いづらいなっていうのがあります。

導入した当初は使えてなかったんですけど、Custom Instrumentsとしてチャレンジしてみたらかなり使いやすくなりまして、さっきのname単位だったところも、自分で好きな単位で描画することもできますし、下のリストも自分で好きなものを出力することができます。

Custom Instrumentsの話をしていきますけれども、一番の利点として、チーム内で共通したデバッグフローを構築できるというのが大きいのかなと思います。なので、レポジトリにコミットしてしまうのがいいのかなというような感じです。このように、先ほどの一覧に自分の作ったものを表示することもできます。

Custom Instrumentsは.instrpkgっていう拡張子のファイルなんですけど、これはxmlとCLIPSっていう言語、よく知らないですけど、LISPっぽい言語で記述することができます。特定のマッチングを分けたりとかもできると。詳しくはヘルプページを見てもらいたいんですけど。こんな感じですね。

セッションでは、例えばこの同じエンドポイントに対して、重複したリクエストをしていたら、警告をInstruments上で出すとかいうデモがされていて、「あ、便利そうだな」と思ったんですけど。

けっこう複雑なコードを書く必要があって。ちょっとここまでは今回やってないんですけども。

簡単に自分も、「パターンマッチでメッセージをフィルタできないかな？」と思ってやってみましたが、ちょっとコンパイルが通らなくて、CLIPSのコンソールでは動いたんですけど、Xcodeがコンパイルしてくれなくて。詳しい人いたら教えてほしいです。

ということで、ここまでのまとめは、Signpostを使うとアプリのパフォーマンスが視覚化できて、Custom Instrumentsを使うとさらに便利っていう話ですね。

Tipsを紹介

デモにいく前に細かいTipsを紹介していきます。

2016年のセッションですけれども、Logging Etiquetteっていうスライドがあって、ここでWrapperは書くなっていうのが言及されていまして。

これ、なんでかっていうと、フォーマットストリングそれぞれの引数を……要は生成を遅延してくれてるので、それの最適化が失われてしまうっていうこと。

あとは、コメントにも書いたんですけど、うまくCVarArgを、CVarArgの配列として扱うことが、扱えるんですけど、ランタイムでクラッシュする原因になってしまい。結局、このように配列で渡す、配列を1回生成して渡すWrapperしかいまのところ書けなくて。ちょっとそこだけコストになるので、書く場合はそこを許容するしかないのかなと思います。

こちらは、Rxに埋め込んでみた例です。これ、SubscribeからNext、NextからNext、最後NextからCompletedの間の時間を計測できます。これは飛ばしますが、興味がある方はあとで聞いていただければお見せできます。

あとは細々としたもので、Development署名をしないと、Instrumentsから起動のエラーがあるんでご注意くださいっていうことと、Immediateモードはデバッグするときにはとても便利なんで、プロファイルしないときはいいんじゃないかなと思います。

サンプルコードっていうのはまったくなくて、Appleのスライドから目grepするしかなかったんですけど、みなさんは幸運なことに、私のスライドとサンプル、Bitriseのアプリもあるので、見ていただくと手っ取り早く実装できるかもしれないです。

あと、「本番で有効にするか？」という問題があると思うんですけど、セッションでは本番で無効にすることによって、デバッグ環境で有効にしたら不具合を再現しなくなってしまったみたいなことがみなさんも経験あると思うんですけど、「そういうのを避けるためには常に有効にしてたほうがいいんじゃない？」みたいな雰囲気ではありました。

実際に測ってみたんですけど、ほとんど、1万回して1ミリセックもかからなかったみたいな。もしかしたら処理が間違ってただけかもしれないんですけど（笑）、ほとんど影響はありませんでした。今年のリファクタリングでも改善されたのかもしれないですけども、そんな印象でした。

これは、最近チームで導入するにあたってドキュメントをQiitaに上げたものです。Custom Instrumentsのインストール方法っていうすごい初歩的な情報がどこにもなかったので（笑）、調べて書きました。

細かい話は2014年、16年、18年の関連するセッションで詳しく説明されてるんで、興味ある方は見ていただければと思います。意外と時間が……、あと2分ぐらいですね。わかりました。

Signpostのデモ

（以下、デモ）

ここでデモをします。一応Custom Instrumentsの作り方ぐらいをやらさせていただければと思うんですけど、このターゲットの追加からCustom Instrumentsはできまして、ここのMacOSのInstruments packageってやればあるんで、これですね。これを選択してもらって作ると、このInstruments Packageができるんで、これをシコシコと、ドキュメントに沿って記述するんですけれども。

これ、びっくりしたというかおもしろいのが、コード補完が効くんですよ（笑）。xmlでコード補完は初めて見たんですけど（笑）。カッコいいなと思って。これがあるおかげで、わりと楽に、幸せな気持ちで、xmlに接することができて、感謝の気持ちでいっぱいなんですけど。このへんがテーブル定義ですね。このへんがxmlに必要なメタデータがあって。

これがInstrumentsのUIの実装の部分で。上に出てくるグラフの単位。あとは下のリスト。リストは複数定義できるかたちです。

あと最後、テンプレート。ここにこういうふうに書いておくと、起動時にさっきの一覧にも出てくるようになる……気がする。ちょっとこのへんの関係がまだよく理解できてないんですけど、とりあえず起動してみます。

これでデバッグモードで、最初は自分のOSテンプレートはないのでBlankを選んで。

これをクリックすると、一番上にデバッグのタイムポストが出てくるんで、これをクリックして、選択して。あとは比較のために表示を伸ばして。

こんな感じで、いま動画コンテンツのライセンスリクエストの通信部分に仕込んでるんですけど、止まっちゃいましたね（笑）。

（会場笑）

けっこう固まるんですよ（笑）。デバッグビルドしてるせいかもしれないんですけど。

こんな感じで止めます。これでズームしたりとか。それで……2つ重複したので、デモとしてはわりと失敗ですけど、ご了承ください（笑）。

こんな感じで、わかりやすく出きたら良かったんですけど、これがレスポンスのデータサイズと、ハッシュと、あとはどれぐらいかかったとか、出してくれるということですね。

ここのPointsOfInterestは、このプルダウンの6個目を選ぶのがポイントなんですけど、これを入れるとわかりやすいのが出てきて、いつ何が起こったかがわかるという感じですね。上のグラフも連動してる、というかたちです。ちょっとオーバーしてるんで、このへんで終わりたいと思います。

Signpost、日常で使ってる人はどのくらいいますか？

（会場挙手なし）

あ、ゼロ、良かった。

（会場笑）

そしたら、みなさん帰ったらSignpostを自分のアプリに入れていただくと、きれいに視覚化できるんで、ぜひお試しいただければと思います。オーバーしてすみません。ありがとうございました。

（会場拍手）