HTraceによるHBaseのトレーシング

(この記事は、Hadoop Advent Calendar 2013の10日目の記事です)

並列分散処理の解析

HadoopやHBaseのような並列分散環境では、処理が多数のノードをまたがって実行されるために、トレーシングや性能のプロファイリングが難しくなります。各ノードで動作するサーバプロセスのロジックでは、他のノードにRPCで処理を依頼して結果を非同期に待つというパターンが多いため、CPUやネットワークのディスクのI/O帯域といったリソースを使い切る状況にはなりにくく、oprofileのようなプロファイラを利用して測定してみても、ボトルネックの手がかりがなかなか見つかりません。
そのような並列分散処理のトレーシングに利用しているツールとしてGoogleが発表したのがDapperで、例によってそれを参考にして作られたオープンソース実装としてHTraceがあります。HBaseのtrunkにはHTraceを利用してトレーシングを行う機能(HBASE-6449)が入っています。
例えば、HBaseシェルで以下のように実行してみます。

> trace 'start'
> create 'test', 'f'
> trace 'stop'

これによって取得されたトレーシング情報により、以下の画像にあるような情報をみることができます。

「クライアントがHMasterのテーブル作成のためのAPIを呼び出し、HMasterがその処理のためにHRegionServerのAPIを呼び出す」というような複数のノードをまたがる処理の流れと、要した時間を分かりやすく見ることができます。テーブルのcreateに続けて、putを実行した場合のトレーシング情報は、以下の画像のようになります。

> trace 'start'
> put 'test', 'row1', 'f:', 'val1'
> trace 'stop'

このグラフ表示自体はHTraceのもっている機能ではなく、HTraceと同様にDapperを参考にしてTwitter社で開発されたZipkinというツールを利用して表示したものです。HTraceには、取得したトレーシングデータをZipkinの形式に変換して送信するためのモジュールが付属しています。
HDFS-5274では、HDFS層にもHTraceによるトレーシング機能を追加するというパッチが既に開発中で、「HLogのhsyncの部分に妙に時間がかかっている」というような、HBaseの先にあるHDFS層も含めた解析ができるようになるものと期待されます。

トレーシングの実装

HTraceを利用したトレーシングは、以下のような使いやすい特徴を持っているというふれこみです。

追加でトレーシング用のモジュールをインストールする必要がない
トレーシングを利用するために設定を変更してサーバを再起動する必要がない
トレーシング時の性能への影響が小さい

どのようにしてこれを実現しているのか、HBaseに追加されたトレーシング用のコードを簡単に確認してみます。
クライアント側のコードには、RPCを実行する際にサーバに渡すデータに、トレーシング用のデータを埋め込むためのコードが入っています。このコードは、クライアントアプリケーションがトレーシングを実行するためのAPIを呼び出した結果として、「トレーシング区間」にいる場合のみ実行されるような条件分岐の中にあります。
o.a.h.hbase.ipc.RpcClient#writeRequest::

    protected void writeRequest(Call call) {
      if (shouldCloseConnection.get()) return;
      try {
        RequestHeader.Builder builder = RequestHeader.newBuilder();
        builder.setCallId(call.id);
        if (Trace.isTracing()) {
          Span s = Trace.currentSpan();
          builder.setTraceInfo(RPCTInfo.newBuilder().
            setParentId(s.getSpanId()).setTraceId(s.getTraceId()));
        }

RPCで渡されるトレーシング情報は、呼び出しの親子関係を判断するためのIDだけという、小さなものです。
Tracing.proto::

message RPCTInfo {
  optional int64 trace_id = 1;
  optional int64 parent_id = 2;
}

これがリクエストヘッダのoptionalなフィールドとして定義されています。
RPC.proto::

message RequestHeader {
  // Monotonically increasing call_id to keep track of RPC requests and their response
  optional uint32 call_id = 1;
  optional RPCTInfo trace_info = 2;
  optional string method_name = 3;
  // If true, then a pb Message param follows.
  optional bool request_param = 4;
  ...

RPCで呼ばれた処理をサーバ側で実行するための共通部品にも、リクエスト中にトレーシング情報が存在すれば、トレーシング用のロジックを初期化するコードがあります。これによってサーバサイドでの処理の実行時刻についての情報が取得されます。また、サーバ側のロジックがさらにRPCで別ノードの処理を呼び出す場合にも、上記のトレーシング用呼び出し元情報(RPCTinfo)がリクエストに付加されて下流に伝わっていくことになります。
o.a.h.hbase.ipc.CallRunner#run::

      try {
        ...
        if (call.tinfo != null) {
          traceScope = Trace.startSpan(call.toTraceString(), call.tinfo);
        }
        ...
      } finally {
        if (traceScope != null) {
          traceScope.close();
        }

HBaseの各サーバプロセス(HMasterやHRegionServer)内では、トレーシング情報を保存するためのReceiverと呼ばれるモジュールが動作しています。このReceiverが、各ノードのトレーシング情報をファイルに書き出すなり、Zipkinに送信するなりします。トレーシング情報は、プロセス内のキュー経由でReceiverに渡されて非同期に処理されるので、性能に影響を与えにくくなっています。
o.a.h.hbase.regionserver.HRegionServer::

    private SpanReceiverHost spanReceiverHost;
    ...
    spanReceiverHost = SpanReceiverHost.getInstance(getConfiguration());

さらに、トレーシングを実行する頻度や契機を制御するための、Samplerというモジュールをトレーシングの際に利用することができます。

    public static TraceScope startSpan(String description, Sampler<TraceInfo> s, TraceInfo tinfo) {
       Span span = null;
       if (isTracing() || s.next(tinfo)) {
         span = new MilliSpan(description, tinfo.traceId, tinfo.spanId,
             random.nextLong(), Tracer.getProcessId());
       }
       return continueSpan(span);
     }

まとめると、小さなトレーシング情報をRPCで受け渡されるデータのオプショナルなフィールドとして定義し、トレーシング情報が付いているリクエストが来た時だけトレーシングのための条件分岐に入るという作りが、使いやすさとオーバーヘッドの小ささを実現するポイントとなっているようです。

HTraceを使ってみる

ここでは参考として、実際にHTraceとZipkinを動かしてトレーシング情報を見てみるための手順を紹介します。以下の手順は、Amazon EC2でRHELのインスタンス(RHEL-6.4_GA-x86_64-10-Hourly2 (ami-5769f956))を利用して試した際のものです。
HTraceが追加されているのは0.96系以降のバージョンなので、trunk版のソースコードをビルドして実行します。まず、ビルドに必要なツール類をインストールします。(ここでは手っ取り早くRHELに付属のOpenJDK 7を利用していますが、実際の運用にはまだOracle JDKのほうが無難だと思います。)

$ sudo yum install git gcc gcc-c++ java-1.7.0-openjdk-devel

$ tar zxf apache-maven-3.0.5-bin.tar.gz
$ export PATH=/opt/apache-maven-3.0.5/bin:$PATH

$ wget http://protobuf.googlecode.com/files/protobuf-2.5.0.tar.bz2
$ tar jxf protobuf-2.5.0.tar.bz2 
$ cd protobuf-2.5.0
$ ./configure && make
$ sudo make install

次に、HBaseのソースコードをチェックアウトして、以下のdiffのように一部のファイルを修正します。

$ git clone https://github.com/apache/hbase
$ cd hbase
$ vi conf/hbase-site.xml 
$ vi pom.xml 
$ vi hbase-server/pom.xml 
$ git diff
diff --git a/conf/hbase-env.sh b/conf/hbase-env.sh
index 91aca76..2597970 100644
--- a/conf/hbase-env.sh
+++ b/conf/hbase-env.sh
@@ -26,7 +26,7 @@
 # into the startup scripts (bin/hbase, etc.)
 
 # The java implementation to use.  Java 1.6 required.
-# export JAVA_HOME=/usr/java/jdk1.6.0/
+export JAVA_HOME=/usr/lib/jvm/java-1.7.0-openjdk.x86_64
 
 # Extra Java CLASSPATH elements.  Optional.
 # export HBASE_CLASSPATH=
diff --git a/conf/hbase-site.xml b/conf/hbase-site.xml
index c516ac7..51b98aa 100644
--- a/conf/hbase-site.xml
+++ b/conf/hbase-site.xml
@@ -21,4 +21,8 @@
  */
 -->
 <configuration>
+  <property>
+    <name>hbase.trace.spanreceiver.classes</name>
+    <value>org.cloudera.htrace.impl.ZipkinSpanReceiver</value>
+  </property> 
 </configuration>
diff --git a/hbase-server/pom.xml b/hbase-server/pom.xml
index f5723b2..555488b 100644
--- a/hbase-server/pom.xml
+++ b/hbase-server/pom.xml
@@ -447,6 +447,10 @@
       <groupId>org.cloudera.htrace</groupId>
       <artifactId>htrace-core</artifactId>
    </dependency>
+    <dependency>
+      <groupId>org.cloudera.htrace</groupId>
+      <artifactId>htrace-zipkin</artifactId>
+    </dependency>
   </dependencies>
   <profiles>
     <!-- Skip the tests in this module -->
diff --git a/pom.xml b/pom.xml
index 77c97b7..f785c4c 100644
--- a/pom.xml
+++ b/pom.xml
@@ -1353,6 +1353,11 @@
         <artifactId>htrace-core</artifactId>
         <version>${htrace.version}</version>
       </dependency>
+      <dependency>
+        <groupId>org.cloudera.htrace</groupId>
+        <artifactId>htrace-zipkin</artifactId>
+        <version>${htrace.version}</version>
+      </dependency>
     </dependencies>
   </dependencyManagement>
   <!-- Dependencies needed by subprojects -->

書き換えたら、HBaseをビルドします。

$ mvn package -DskipTests

ビルドが終わったら、そのままソースツリーの中からサーバを実行することができます。デフォルトの設定の場合、ZooKeeperサーバもHMasterもHRegionServerも全部、1つのプロセス中で実行するローカルモードで起動します。

$ bin/hbase master start

つぎに、トレーシング情報を表示するために利用するZipkinをダウンロードします。

$ git clone https://github.com/twitter/zipkin
$ cd zipkin

Zipkinはソースツリーを取得してコマンドを実行すると、その場でまずビルドが行われ、サーバプロセスが起動してきます。とりあえずターミナルを3つ開いて、以下のコマンドを実行します。

(ターミナル1)$ bin/collector
(ターミナル2)$ bin/query
(ターミナル3)$ bin/web

準備が整ったら、HBase Shellを起動し、トレーシングを実行してみます。

$ bin/hbase master start
> trace 'start'
> create 'test', 'f'
> trace 'stop'

ZipkinのWeb UIはデフォルト設定では8080番ポートで待ち受けているため、Webブラウザでそこにアクセスして、トレーシング情報を確認します。

ローカルモードで確認できたら、HBaseを疑似分散モードで起動するように設定変更して試してみるとよいでしょう。上の方で貼付けた画像は、疑似分散モードで試した際のものです。