性能問題分析や障害解析に役立つのがトレースツールです。Linux向けにはこれまでにSystemTap、LTTngなどさまざまなものが開発されてきました。そのうちの1つであるftraceは、Linuxカーネルが標準でサポートする、低負荷で手軽に使えるトレース機能です。元々はSteven Rostedt氏らがRTカーネルの性能解析向けに開発したものですが、カーネル2.6.27に採用されて以後、2.6.30ではイベントトレース機能やバイナリ出力機能をサポート、その後もさまざまな改善・拡張が続けられてきました。そしてここ最近、大幅な機能拡張が行われていますので、今回はその新機能について紹介します。また、仮想化環境向けのトレース強化も行われていますので、こちらも併せて紹介します。

ftrace最新動向

スナップショット

ftraceの利用方法の1つとして、フライトレコーダとして使うことがあります。トレースを常時メモリ上のリングバッファに記録し続け、もしカーネルがクラッシュしたらクラッシュダンプの中からトレースデータを回収するのです。回収したトレースデータにはクラッシュ直前の動作履歴が残っているわけですから、カーネルクラッシュに至る原因を追究するのに非常に役立ちます。

カーネルが継続動作できない障害が発生した場合はトレースも自動的に止まるので、リングバッファから障害の起きた時点のトレースデータを回収できます。しかしカーネルが継続動作できる障害、たとえば性能低下やアプリケーションのエラーの場合はどうでしょうか？ トレース機能は新しいデータをリングバッファに書くとき、古いデータから順に上書きしていきます。そのためトレースデータの回収が遅れると、問題発生時の情報が上書きされてなくなってしまうのです。

だったら問題発生時にトレースを一時停止すれば良いじゃないか、と思うでしょう。しかしそうすると今度は、一時停止している間に別の重大障害が発生した場合、その直前のトレース情報が取れなくなり、障害原因の追究が難しくなります。

この問題を解決する機能として、ftraceのスナップショット機能がHiraku Toyooka氏により提案されました。スナップショット機能を使うと、トレースを止めることなく、ある瞬間のリングバッファの内容を回収することができます。幸いにもftraceにはレイテンシトレース用の機能として、現在使用中のバッファと予備のバッファをスワップする仕組みが備わっているので、それをユーザ空間からdebugfs経由で使えるようにするだけで実現できました。こちらの機能はすでにLinusツリーにマージされており、カーネル3.9から利用可能になる見込みです。

スナップショットを取得するには、以下の例のように⁠”snapshot⁠”ファイルに⁠”1⁠”を書き込むだけで済みます。取得したスナップショットは通常のトレースデータと同様にcatコマンドで見ることができます。

# echo 1 > snapshot
# cat snapshot

functionトリガー

functionトリガーとはftraceがサポートする機能の1つで、特定の関数が呼ばれたことを契機に、指定したアクションを実行する機能です。以前は、トレース全体をON/OFFするというアクションしかサポートしていませんでした。しかし最近Steven Rostedt氏が新たに、

• ① （⁠上で述べた）スナップショットを取る
• ② スタックトレースを取る
• ③ 特定のイベントの記録をON/OFFする

というアクションを追加しました。さらに、内部で指定した関数にヒットした回数をカウントすることで、アクションを実行する回数に上限を設けることもできます。

これらの機能追加により、高度なトレースが可能になります。たとえばデバッグを行っている時に、本来呼ばれるはずのないカーネル関数が呼ばれていることが判明したとしましょう。②のアクションを使うと、それがどのパスからで呼ばれているのかを容易に解明できます。これらの新しいアクションは3.10でのマージに向けて作業が進められています。

具体的な使い方を紹介しましょう。たとえば、カーネル関数であるvfs_read()が呼ばれた時にスナップショットを最大で1回だけ取得したい、という場合には下記のようにします。

# echo 'vfs_read:snapshot:1' > set_ftrace_filter

目的単位のトレースが可能なマルチバッファ機能

ftraceはカーネル2.6.30からイベントトレース機能をサポートしています。この機能はカーネルの関数内にあらかじめ定義されているトレースポイントにヒットしたとき、所定の情報をイベントとしてリングバッファに記録するというものです。

今までftraceは1つのリングバッファしか扱うことができないために、次のような問題がありました。もし大量に発生するイベントAと滅多に発生しない重要なイベントBの両方をトレースしようとした場合、リングバッファのサイズは有限であるため、重要なイベントBの記録が大量のイベントAによって流されてしまうのです。

この問題に対処するため、Steven Rostedt氏はマルチバッファ機能をLKMLに提案しました（2013年2月⁠）⁠。この機能を利用すると、複数のリングバッファのインスタンスを作成することができ、それぞれについてどのイベントのトレース有効にするか、どうオプションを設定するか、など個別にセットアップすることができます。もちろんトレースデータの回収もインスタンスごとに行うことが可能です。このマルチバッファ機能はカーネル3.10で採用される見込みです。

また、ftraceのトレースデータ収集ツールであるtrace-cmdはv3.0からマルチバッファ機能に対応する予定であり、開発者のSteven Rostedt氏が公開しているリポジトリから試験的に利用可能です。

たとえば、lsコマンドを実行しているときのトレースを、スケジューリング関係のイベント（-e sched）とタイマ関係のイベント（-e timer）を別々に取りたい場合は以下のようにします。

# trace-cmd record -e sched -B timer -e timer ls

-B〈インスタンス名〉オプションを指定すると、一時的に〈インスタンス名〉で指定したインスタンスを作成し、以降に指定されたイベントをそのインスタンスのリングバッファに記録するようにします。この例では、timer関連のイベントはtimerリングバッファに記録され、一方スケジューラ関連のイベントはデフォルトのリングバッファに記録されます。

仮想化環境向けトレース

近年、クラウドコンピューティングの後押しもあり、仮想マシンの普及が進んでいます。ハードウェアアシストも充実してきており、高い性能が出るようになりました。しかし、仮想化環境におけるトレース機能はまだ発展途上です。ここではトレース機能の仮想化環境対応動向に触れたいと思います。

ゲストOSとホストOSのトレースデータを統合して解析可能とする統合トレース

たとえば、ゲストOS上で動作するアプリの応答性が悪い、という問題に遭遇したとしましょう。この問題の原因を追究するには、まずそれがゲストOS上の問題なのか、それともホストOS上の問題なのか切り分ける必要があります。しかしゲストOSとホストOSのトレースデータを個別に見ても原因はまず見えてきません。そこで、ゲストOSとホストOS間でトレースデータを統合して解析できるようにするVirtio-traceがYoshihiro Yunomae氏らにより提案されました。

Vritio-traceはゲストOSとホストOSで採取したトレースデータをマージし、時系列順に並べて表示することで、ゲストOS上で発生した問題に対して、ゲスト／ホストの原因の切り分けを容易にします。Virtio-traceでは、この"時系列順に並べる"という処理がポイントになります。

時系列順に並べるためにはftraceの各イベントレコードに付与されたタイムスタンプを利用します。カーネル3.7の時点で利用できるタイムスタンプの種類はlocal、global、counterの3種でした（表1⁠）⁠。このうちcounterはイベントをカウントしていくだけなので、ここではlocalとglobalについて述べます。これらは、Time Stamp Counter（TSC）を、OS起動時に決定された1秒当たりのクロック数（kHz）を使ってsec.usec単位に変換します。このため、どの処理にどの程度時間を消費したかを計測する目的には十分です。しかし、ゲストOSとホストOSで時系列に並べようとした際に、この1秒当たりのクロック数が一致する保証はありません。

2012年、Masami Hiramatsu氏がPlumbers ConferenceにてゲストOSのトレースデータをホストOSから高速に収集する方式の発表を行った際、ゲストOSとホストOSのトレースデータを時系列に並べる方法についても言及したのですが、トレースのタイムスタンプをTSCにすれば良いのではないか、という結論に至りました。最近のx86アーキテクチャのCPUではTSCがコンスタントに増加していくことが保証されているため、ゲスト/ホストの時刻の進み方の一致についてはTSCをそのまま利用することが良いだろう、となったのです。これを受けてDavid Sharp氏がftraceのタイムスタンプ（trace_clock）にx86-tscを選択できるようにし、kernel-3.8で利用可能となりました。

ゲストOSとホストOSのトレースデータを時系列に並べるにはもう一つやるべきことがあります。ゲスト上のTSCはハイパーバイザによって仮想化されており、ゲストTSC = ホストTSC + TSC offset により算出されています。したがって時系列に並べる際は、ゲストTSCからTSC offsetを減算してホストTSCに合わせる必要があります。

このTSC offsetを取得する方法としてはさまざまなものが考えられますが、LKMLで議論した結果「TSC offsetの設定箇所にトレースポイントを追加し、マルチバッファ機能を使ってゲスト起動時からトレースする」という方針で落ち着いています。つまり通常トレース用のバッファとTSC offset記録用のバッファを用意し、ゲストOSの起動前にTSC offsetのトレースポイントを有効化しておきます。そして後ほどトレースデータを時系列に並べる際にそのTSC offsetのイベントを利用するようにします。このようにバッファを分ける理由は、TSC offsetを設定するレアなイベントを他のイベントに上書きされるのを防ぐためです。

ここまで説明したゲストOSとホストOSの時系列の並べ方の詳細については、2013年5月のLinuxCon Japanで、“⁠Integrated Trace for Virtualization Environment⁠”と題したセッションにて発表する予定です。

QEMUトレース

QEMUは x86、ARM、PowerPC などさまざまなアーキテクチャに対応した仮想マシンエミュレータです。QEMUは非常に大規模なソフトウェアであるため、性能解析やデバッグのためにトレース情報を得たいというニーズがあります。ここでは QEMU に実装されているトレース機能について簡単にご紹介します。

QEMUのトレース機能（現状）

QEMUには現在約900ものトレースポイントがあり“⁠simple⁠”⁠、⁠”stderr⁠”⁠、⁠”ust⁠”⁠、⁠”dtrace⁠”の4つのトレースバックエンドを備えています。それぞれのトレースバックエンドで出力先やフォーマットを変更することができます。一覧を表2に記載します。

QEMUではオーバーヘッドが生じるため、デフォルトでトレース機能が無効になっています。トレース機能を有効にするには、configureスクリプト実行時に、上記のトレースバックエンドのいずれかを指定する必要があります。

# ./configure -enable-trace-backend=simple

各トレースバックエンドは、make時にPythonスクリプトでトレース情報を出力する関数が定義されたC言語のソースコードを生成します。ソースコード自動生成の仕組みがあるため、新しいバックエンドを追加するのが非常に簡単になっています。

トレースイベントの有効・無効

QEMUでトレースイベントの有効・無効を指定するには、2つの方法があります。

①起動時に指定する方法

qemuのtrace オプションに、トレースイベントの一覧を記載したファイルを指定して実行します。

# ./qemu -trace events=/path/to/events

# cat /path/to/events
cpu_in
cpu_out
apic_local_deliver

トレースイベント一覧は、QEMU Monitor から取得できます。

(qemu) info trace-events

②QEMU Monitor経由で有効・無効を切り替える方法

こちらはQEMU起動中に有効・無効を切り替えることができます。“⁠trace-event 〈イベント名〉 〈on/off〉⁠”⁠ で各イベントについて有効・無効を切り替えます。

(qemu) trace-event cpu_in on
(qemu) trace-event cpu_out off

QEMUトレースの将来

Dynamic Instrument機能

従来、QEMUのトレースポイント実行時に呼ばれるコールバック関数は、コンパイル時に固定されていました。現在RFC PATCHとして議論されているDynamic Instrument機能を使うと、ユーザが定義したコールバック関数を起動時に動的に指定することができます。Dynamic Instrument機能はユーザがコンパイルしたライブラリを動的読み込みすることで実装されています。

• [Qemu-devel] [RFC][PATCH 00/22] instrument: Let the user wrap/override s

Ftrace Backend

ftraceはユーザ空間からのトレースイベントの記録を可能にする仕組みとしてtrace marker 機能を提供しています。この機能を用いてトレース情報を出力する ftraceバックエンドが最近、Eiichi Tsukata氏により提案されました。ftraceのリングバッファにQEMUのトレース情報を書き込むので、KVMを使う際にKernelのトレース情報とQEMUのトレース情報を簡単に付き合わせることができます。これにより、たとえばKVM VM_EXITに対するQEMU内のハンドラが対応付けられるので便利です。このパッチはQEMUトレースのサブシステムメンテナのツリーに採用済みですので、近いうちに利用できるようになるかも知れません。

• [Qemu-devel] [PATCH 0/2] New trace backend: ftrace

最後に

今回の記事ではftraceを中心としたトレース技術を取り上げましたが、Linuxには他にもさまざまなトレース機能があります。LinuxCon Japan 2013ではftrace以外のトレース機能の動向や、2012年12月に提案されたKtapという新しいトレースツールの発表もありますので、興味のある方はぜひ足を運んでみてください。