トレーシングを用いた動画メディアプレーヤーの精密パフォーマンス分析 #1

2016-12-01

U-NEXTが利用するマルチメディアテクノロジーにはいくつものコア技術が存在しており、いずれも成熟度合いが増しています。

オープンソースライブラリも充実していることから開発時間やコストを削減する目的で利用する機会も増えているのではないでしょうか。

しかしながら、組み込んだらすぐに役に立つ、というほど簡単にすまないことも多いです。

U-NEXTアプリケーションの開発でも日々こういった技術、特に動画再生に分野については数多くテストしていますが、適切なライブラリを選定したうえで、実際の環境でパフォーマンスを検証し、細かいチューニングを加えて改善することが必要不可欠だと考えています。

例えば、Androidの動画再生プレーヤーとしてGoogleがサポートしているOSSであるExoPlayerの利用検証をしていた際に問題が発生したことがあります。

多くの場合は正常に動画再生が行われますが、特定の機種で再生のカクツキが頻繁に発生してしまいました。

一般に問題の原因調査をする際には、ログ分析やデバッガーを利用することが多いですが、これらのツールはエラーやバグといった問題の原因を探る用途には有用なものの、動画のカクツキのようなパフォーマンス問題が対象になると、必要な情報を十分に得ることができません。

パフォーマンス問題は人間の感覚ではすぐに問題と感じることができますが、システムとしては正常に実行されている状態だからです。

よってボトルネックがどこに存在しているのか、簡単には発見できません。

可能性のある箇所を一通り確認するためにログの測定箇所を増やすと、ログ分析ツールやデバッガーは頻繁に発生する大量なデータの処理を想定していないので、アプリケーションへ負荷を与えてしまい、エラーが増えたり正常な速度で実行できなくなってしまいます。

このような測定負荷による問題を避けるために、トレーシング(精密パフォーマンス測定)という手法があります。

組み込みソフトウェア開発、例えば自動車制御ソフトなどでは一般的に利用されているものですが、Androidアプリケーション開発のようなコンシューマー向けのアプリケーション開発現場ではあまり普及していないように思えます。

今回の記事では、Android SDKがすでにサポートしている “os.Trace” APIと”Systrace”ツールを紹介し、簡単に解説いたします。

次回の記事では、AndroidのメディアプレーヤーであるExoPlayerのカクツキ調査を実施するため開発した”PerformanceLogger”というトレーシングライブラリをご紹介する予定です。

トレーシング

トレーシングとは、特定のプログラムをトレースポイントで指定された場所で実行して、記録する方式です。

トレースポイントは、調査目的に応じて必要となる情報が得られる関数を呼び出す前後に配置することが望ましいです。

トレースポイントでは関数名と時刻情報をメモリ上のトレーシングバッファーに書き込みます。

一連の書き込まれたエントリーをイベントと呼び、記録していきます。測定を終えたらトレース取得ツールを利用して端末からイベント情報を取得します。

トレーシング機能自体はOSが対応していることも多いですが、プログラミング言語のランタイムライブラリを通じて利用することが一般的です。

例えばC++の経験をお持ちの方がいらっしゃれば、TRACE()という表現をどこかでご覧になったことがあるのではないでしょうか。

この機能はCやC++に限らず、Javaなどでも利用することができます。

GoogleのExoPlayer 1) というプロジェクトから例を抜粋しましょう。

// 例1 MediaCodecTrackRendererより抜粋
TraceUtil.beginSection("drainAndFeed");
while (drainOutputBuffer(positionUs, elapsedRealtimeUs)) {}
if (feedInputBuffer(positionUs, true)) {
  while (feedInputBuffer(positionUs, false)) {}
}
TraceUtil.endSection();

beginSection("drainAndFeed")endSection()に囲まれたコードブロックがトレースポイントです。

上記のコードはAndroid OSのトレーシングAPIを直接呼べない(Android OS が18(Android L)以上でないと使えないAPI)ので、ラッパー 2) が呼び出されます。

実際のトレーシングAPIは android.os.Trace に記述されています。

// android.os.Trace
public final class Trace {
 ...
  public static void beginSection(String sectionName);
  public static void endSection();
 ...
}

記録したいコードブロックの先頭でbeginSection()へ特定できる文字列を渡し、コードブロックの末端でendSection()を呼び出します。

beginSection/endSectionを同じスレッドで組むことがポイントです。

このAPIはbeginendの間の実行時間とbeginSectionに渡された特定文字列に加えて、スレッド情報も記録します。

スレッド情報の記録については、トレース図を分析するで説明します。

さらに、beginSection/endSection を例2のように重ねると、実行ブロックの内容も得られます。

// 例2
import android.os.Trace;
  
class Worm {
 
    public void crawl() {
        Trace.beginSection("move_legs");
        moveLegs();
        Trace.endSection();
        Trace.beginSection("update_direction");
        updateDirection();
        Trace.endSection();
    }
  
    private void updateDirection() {
        Trace.beginSection("sense_obstacle");
        senseObstacle();
        Trace.endSection();
        Trace.beginSection("sense_food");
        senseFood();
        Trace.endSection();
        Trace.beginSection("find_direction");
        findDirection();
        Trace.endSection();
    }
  
    private void moveLegs() { /* actual leg movement by one increment   */ }
  
    private void senseObstacle() { /* identify objects in front of eyes */ }
  
    private void senseFood() { /* identify food */  }
     
    private void findDirection() {  /* calculate next direction */ }
}

取得できた情報を時間軸線に示すと、以下のようなトレース図を描くことができます。

トレース図の例
トレース図の例

トレースを取得する

例のように、トレースしたいコードブロックをbeginSection/endSectionで囲んでアプリケーションを再ビルドした後に、どのようにトレースを取得して可視化していけばよいでしょうか。

Androidであれば、表示のためにChromeブラウザーを利用できます。ADB接続を使って、実行中のアプリからトレーシングデータをまず取得します。

出力ファイル名と測定ターゲット(アプリケーション名)に加えて、beginSection/endSection におけるトレーシングパラメータである time(=取得期間=秒単位)と buf-size (=トレーシングバッファーのサイズ=KByte単位)を指定します。

buf-sizeはトレーシングデータを記録するために割り当てられるメモリーの容量です。

トレーシングデータは通常のログ出力と比べて合計容量は少なくすみますが、トレースポイントが増えれば増えるほどメモリーを使用します。

ログとは異なりファイル出力やターミナルバッファーへのコミットをしないので、一気にメモリにデータを書き込みます。従って、--buf-size設定で、メモリーを小さめにした方がよいでしょう。

// Systrace実行
$ cd ~/android-sdk/platform-tools/systrace
$ python systrace.py --app "com.google.android.exoplayer.demo" --time=10 --buf-size 1024 -o ~/Documents/trace_1.html

トレースを分析する

Systrace.pyが出力したデータファイルはJavaScriptウェブビューアーとトレースデータが結合された形式となっています。Chromeでブラウザ開くと、以下のようなトレース図が見えます。

横軸が時系列を、縦軸はスレッドを表示しています。各スレッドごとにbeginSection/endSectionで測定されたトレースポイントがタイムスライスとして表示されています。タイムスライスを選択すると、詳細情報を確認することが出来ます。

  • Title (タイムスライスのラベルと同一): beginSection に渡された特定文字列
  • Start: beginSection の時刻
  • Wall Duration: beginSection からendSectionまでに経過したシステム時計の時間
  • CPU Duration: スレッドがbeginSectionendSectionの間に使ったCPUの消費時間

複数重なった部分は、ネストされたコールであることを示します。例としてトレース図 1a をご覧いただくと、”doSomeWork”と示されたブロックに”drainAndFeed”ブロックがネストされていることがわかります。

トレース図1a
トレース図1a

一方で、スライス間にスキマがある場合は、トレース情報が含まれていない実行ブロックでスレッドが実行されたのか、あるいは単に処理待ち状態だったのか、判別ができません。スレッド実行情報を確認することで判断します。

トレース図1b
トレース図1b

ExoPlayerImplInというスレッド位置の上に、薄いスライスがあります。それを選択することでスレッドの実行情報が示されているのがトレース図1bです。

  • Running process: スレッドが実行されているプロセス
  • Running thread: スレッド名
  • State: スレッドの実行状態
  • Duration: スレッド実行時間
  • On CPU: マルチコアの場合、実行しているCPU番号

例えば”State”が”Runnable”であればスレッドは実行されているがトレースしていなかった状態ということになりますし、”Sleeping”であれば処理待ちであったと判別することができます。

“Systrace”ツールの基本的な解説は以上です。その他にも役立つ機能がありますので、関心を持たれましたら参考文献を確認ください。

まとめ

  • トレーシングを利用することで、アプリケーションへ負荷をかけず実行状況をを測定することができます。
  • プログラム上の気になるコードブロック周りにトレースポイントを定義すると、実行中のプロセスがそのブロックを通った時点でトレースメモリに記録を残します。今回はAndroid SDKを例にSystraceというトレースデータ取得ツールを紹介しました。
  • Chromeブラウザでトレース図を表示することでプログラム実行中に通ったコードブロックがタイムスライスとして表示され、視覚的に理解できるようになります。
  • タイムスライス情報とスレッド実行情報から、パフォーマンス問題のボトルネックを分析するために必要な情報(どんな処理がどの程度時間を要したのか、あるいは待ち状態だったのか)を得られるようになります。
  • トレーシングを例②のようにネストすることで、処理時間の内訳を把握できます。

今回はトレーシングの基本的な内容に留まっていますが、次回はExoPlayerをチューニングするために開発した精密トレーシングツールをご紹介します。ぜひ、またお立ち寄りください。

参考文献

脚注

  1. ExoPlayerリポジトリー (Github): https://github.com/google/ExoPlayer
  2. ExoPlayerのTraceUtil : https://github.com/google/ExoPlayer/blob/release-v2/library/src/main/java/com/google/android/exoplayer2/util/TraceUtil.java