dotTraceを使ってみた。

はじめに。

しこしこ延々とノートアプリ(最近絶賛放置中なのでそろそろ手を入れたい)を作っているのですが、作ってる途中で遅いマシンだと仕様に耐えないぐらい遅い時があったので分析するためにdotTraceを使用、それがすこぶる役だったので紹介する記事を書いてみました。

こちら当時の喜びのつぶやきです。

記事の内容としては当時まとめていたんですが、そのまま放置プレイでした。このように喜びを感じてから1年ぐらいたちそうなんですがやっと重い腰を上げて記事にすることにしましたので、その間に新しいバージョンも出ているようであり記事の内容と現状が異なる場合は現状を優先いただきますようお願いします。

改めて経緯

ノートアプリで速いマシンだとまぁ普通に動いてた消しゴム機能がAtom機だとくっそ遅い。 画面の更新レート、秒間0.3フレームとか? 内部的にアクターモデル使って足りして非同期的にワーカースレッドやらUIスレッドやらでいろんな箇所が動いて単純なツリー等では把握しづらい。 のでプロファイラーで分析することを思いつく。

下のリンクのようにVS先生にもプロファイラーはあるのですが(諸事情でまだVS2015です)、 XAML アプリでリソース消費量を分析する - Visual Studio | Microsoft Docs アプリの CPU 使用率を測定する - Visual Studio | Microsoft Docs f:id:omanuke-ekunamo:20190402225415p:plain f:id:omanuke-ekunamo:20190402225516p:plain

  • VSのTimeLineだとXAMLの内部動作は詳しく色々出てるけれどアプリケーションコードとの関連性、なにがきっかけでそれが起きたのかよくわからない。
  • UIスレッド以外はTimelineビューに出てこない?
  • CPU Usageも全部のスレッドがまとめられてるし、どの処理がCPUを食ってるかが分かるだけでいつどのスレッドがどういう風に食ってるのか、それによりどこにどんな影響がありそうだかわからない。

などでいまいち使えない自分の用途には合わなそうな。 そこで課金してるJetBrainさんのdotTraceを試してみることにしました。

dotTraceについて

こんな画面のプロファイラーです。こちらは大体のケースはこれでいいはずらしいTimelineモードでの分析画面です。ぶっちゃけ他のは試してません。 Timeline Viewer Concepts - Help | dotTrace

動かしかた

今回は別のマシンでアプリを動かすリモートデバッグをするので、Agentをアプリを動かすリモート端末上で管理者権限で動かします。 Starting Remote Profiling Session - Help | dotTrace

こちらはデータを収集する側でdotTraceを起動した画面です。 こちらから分析したいアプリを選びプロファイル方法を選択し分析を開始します。 f:id:omanuke-ekunamo:20190402230325p:plain

今回はTimelineを選択します。

分析初めてみる

実際にアプリケーションを動かして必要なところでプロファイルデータを収集開始、データ収集を終えた後、それを各種ビューで見て分析するというのが基本的な流れになります。

Runより接続の画面が出て接続が成功するとアプリケーションがリモートで開始され、本体側にプロファイリングセッションをコントロールする画面が出てきます。 f:id:omanuke-ekunamo:20190402231341p:plain

アプリが起動、プロファイルが始まりデータが取得されていますが、今回は起動時のプロファイルデータはいらないのでDropします。これでデータ収集が一時的に停止します。 f:id:omanuke-ekunamo:20190402231419p:plain

調べたいところまで処理を進めていざ準備が整ったらStartを押してデータ収集を開始します。 そこでおもむろに調べたい処理を行い、気が済んだらGet Snapshot and Waitを押しデータ収集を止めます。 f:id:omanuke-ekunamo:20190402231519p:plain

収集したデータをもにょもにょ10秒ぐらい処理したのち次のようなTimelineビューワーが表示されます。 f:id:omanuke-ekunamo:20190402231927p:plain

レイアウトはデフォルトのものとは変わってるかもなのですみません。 画面は以下のようになっています。

1.メインのタイムラインビュー 分析中における各スレッドでどのような処理が行われたか見渡せます。

2.CallTree どの処理がどれぐらいCPUを食っているか、そこから先何を呼んでるかのツリービュー

3.CallStack どの処理がどれぐらいCPUを食っているか、それがどこから呼ばれているか。2のビューで処理を選択するとその中での処理のが出る…のかの。

4.Source View 2,3で処理を選択した時にそのソース

5.Filters イベントの種類などでいろんな見方が出来そう。今回は使ってないですが、どこでメモリアロケートしてるのかどこでGCやJIT起きてるかなど役立ちそうです。

リアルワールド分析

今回2回数秒ずつ消しゴム操作をやってみました。 ざっとみると8608のCLR WorkerがメインのUIスレッドっぽく処理食ってます。 そのほかに10848のCLR Workerと5728のCLR Workerが食ってそうで他にもちらほら赤い処理が見られます。 メインの所を詳しく見てみましょう。

詳しく見るには該当するスレッドの見たい範囲をマウスでドラッグして範囲選択します。 見るスレッドも8608チェックを入れてフィルタしましょう。 OnPointerMovedが処理を食っており、そこをたどっていくと時間かかってる処理が見つかってきます。 f:id:omanuke-ekunamo:20190402232158p:plain

自分の場合だとこのupdateContsが時間を食っています。これは毎回する必要のないレイアウト処理なのでここを何とかするだけでだいぶ処理を削れそうです。

消しゴムの処理を行うにあたってめんどくさい計算処理をしてたのでそこかしらと思ってたけれどそんな部分はわずか0.32%でした。こういう時自分の場合は毎回なんですが、何かCPUバウンドな処理だと思ってるものは案外消費してないことが多いですね。それ以外のUIな処理や余計な処理・ループなどで食ってる場合がほとんどです。

まぁこれは自分のプログラムが雑なせいですが改善の余地が大幅にあるのでカリッカリチューンに比べればとても楽です。 f:id:omanuke-ekunamo:20190402232230p:plain

ほかに処理を食ってるものを見てみましょう。 f:id:omanuke-ekunamo:20190402232301p:plain

こちらを見てみると編集後にサムネイルを更新する処理が走ってます。

編集後にこの処理が走りそこに時間がかかるのはしょうがないのですが、編集中に走ってるのは意味がなく、また別のAppilcationViewを作ってそちらで処理してるのでUIスレッドには影響をお及ぼさないかと思ってたのですが、体感的に影響するっぽいので編集中に走るのは好ましくありません。

ほかの編集処理では編集中に走らないように編集したというイベントをもとに処理を抑制していたので同様にしないといけないことが分かりました。

もう一つ時間かかってる処理はバックグラウンドでのデータの保存処理のようです。 f:id:omanuke-ekunamo:20190402232325p:plain

こちらも編集中のイベントをもとにRxでSampleされて動いているものなので長い編集操作中に走ってました。

バックグラウンドスレッドだからSampleでも大丈夫か思ってますが、処理に影響する様ならPriority下げるなりThrottleで処理を抑制するなり、処理自体それなりにかかってるので減量が必要かもしれませんが、今回は仕方がないものとしてスルーします。

そのほかのちらほらある赤いものを見てみます。

f:id:omanuke-ekunamo:20190402232413p:plain

複数のスレッドをまとめてみるにはあるスレッドで範囲選択した後、他に見たいスレッドの番号のあるカラムをクリックします。 時間のかかってる処理内容見ると…んーETW関連と若干のアプリコードですかね。 のであまり関係なさそうなのでスルー。

このように範囲選択やスレッドを選択した場合、見たくなくなったスレッドなど、スレッドについているチェックボックスを外すことでクリアできますが、それらはフィルターとしてタイムラインの上部にfilter appliedとして表示されています。のでクリアする場合はそちらからクリアすることもできます。

分析結果をもとに消しゴム操作中にサムネイル作成処理が走らないようにして毎回やる必要のないレイアウト処理として走っていたupdateContsを抑制してみました。 f:id:omanuke-ekunamo:20190402232447p:plain

ざっと見、サムネイルの作成処理は編集中には走ってないようです。

メインの処理を掘ってみますと先ほど時間のかかってたupdateContsはなくなっています。がaddRemoveFiguresはまだ時間をとっているようです。 ので消しゴム操作中は影響のあった点を覚えて置き時間のかかるaddRemove処理は後でまとめてやることにしました。 その修正を施したのがこちら。

f:id:omanuke-ekunamo:20190402232514p:plain

async _canvasCtrl_Drawの描画処理が48.6%を占めてOnPointerMovedからの処理は19.4%まで減りました。

当初のを見直してみます。 f:id:omanuke-ekunamo:20190402232631p:plain

こちらではOnPointerMovedに66.6%かかり描画は11.9%です。これは描画が軽いのではなく描画処理に回す余裕がほとんどなくそれがフレームレートの低下につながっていました。

修正後は大幅に描画処理に時間を費やすことができているのが分かります。 dotTraceのTimelineの特徴としてアプリケーション全体で何が起こってるのか時間の経過とスレッドの関係をもとに空間的に把握でき、調べたいところを深く掘り下げて行くことができます。

まとめ

今回使ってみたきっかけは作ってるノートアプリが非力なOneMixYoga先生で動かしたときにくっそ遅かったけれどどこが遅いのかよくわかんねという理由からでした。

Timelineで見たところ思いもよらなかったところの処理が走ってることが多く、それらをうまく抑制したり処理方法を変えたりすることで全体的におおむね許容できる速度にすることができました。 今回使ってみて改善個所を見つけるのに極めて有効だったのでこれは啓蒙せねばと記事にまとめてみました。

その他気に入ったところ

好きなタイミングでデータ収集を始めることができる。

起動からのイベントを収集しているのですが、途中で止めてそれまでのデータをドロップして、いざ調べたい処理を行う直前にデータ収集を開始して必要な部分だけのデータで分析できるのでノイズに惑わされることなく素早く解析ができる。

軽い

ETWを使ってるおかげかOneMixYogaなるAtomZ8350を積んだおっそいマシンでのリモートデバッガーでもそんな遅くなることなく操作して分析できる。

色々フィルタが強力っぽい(試してません)

使ってないですが、上で言ったようなメモリアロケーションやGC、JIT、LINQなどいろいろなイベントや処理種類でのフィルタ出来るので的確な分析が出来そう

総評

今回使ってみたようにUIアプリケーションでなんか遅いっぽいけど何が遅いのかよくわかんねって時にはうってつけだと思うのでよかったら是非お試しあれ。 UIアプリだけでなくIISだとかASPだとかServiceなどに対してもできるようなので其方でもまた便利かもしれません。