systemtapで動的追跡をしよう(1)

NTT オープンソースソフトウェアセンタ笠原辰仁

はじめに

PostgreSQLのバージョン8.2から、Soralis, FreeBSD, Mac OSXなどで使用可能なDtraceという情報取得ツールに対応しました。Dtraceを使うと、PostgreSQLのトレーシング (ある処理がどのような関数等を通過してきたかの解析) やプロファイリング (ある期間にどんな処理がどれだけ実施されたかの解析) が可能になります。PostgreSQLのマニュアルでも動的追跡という項で紹介されています。これを利用することで、ボトルネックの発見などが可能になります。

Linuxでは、Dtraceの類似の機構としてSystemtapというツールが備わっています。本来は、カーネル内部のトレーシングやプロファイリングを主な目的としたツールですが、ユーザアプリケーションの情報取得も可能です。本記事では、Systemtapを使ったPostgreSQLの動的追跡の方法を紹介します。なお、用いるスクリプトやプロダクトを除き、本記事で紹介している方法や動的追跡における観点はDraceを使った場合でも同じです。

Systemtapを使う前に

PostgreSQLは、独自に稼動統計情報を収集していたり、一部性能情報などをログに出力する機能を持っています。これらの情報は、常時取得しておき、問題が起こった際に、まずその原因箇所の狙いをつける際に有用です。一方、Systemtapが活躍するのは、標準の稼動統計情報やログに出力される性能情報だけでは問題を解析するのに不十分な場合です。 Systemtapは任意の情報をアドホックに収集できるため解析ツールとしては強力ですが、呼び出しの頻度が高い箇所をトレースしようとするとオーバーヘッドが大きくなり、また解析も難しくなりますので注意しましょう。調査したいものは何か？それに対して最適な方法なのか？ということを、 Systemtapを用いる前に検討してみてください。

Systemtapについて

Systemtapはとても機能が豊富です。本記事では、簡単な使い方を紹介するのに留めます。

Systemtap自体の情報については、下記に有用な情報があります。Systemtapとはどういうものか？スクリプトの書き方などは？といった細かな事項については、こちらを参考にしてみてください。

Systemtapを使うための準備

Systemtapを使うため、まずは必要なものを揃えます。本記事ではOSにFedora 12を用いて紹介しています。

Systemtapのインストール

Systemtapのインストールは、RPMパッケージを用いると簡単です。まずは、必要となる以下のパッケージが揃っているかを確認しましょう。なお、本来のカーネル内部の情報を追う場合には "kernel-debuginfo" などが必要になりますが、PostgreSQLだけを対象にする場合には必須ではありません。

$ rpm -qa | grep systemtap
systemtap-sdt-devel-1.0-2.fc12.x86_64
systemtap-runtime-1.0-2.fc12.x86_64
systemtap-1.0-2.fc12.x86_64

なお、Systemtapのバージョンによって、下記で行うPostgreSQLのビルドに必要な "/usr/bin/dtrace" や "/usr/include/sys/sdt.h" が無い場合があります。すでに上記の3つのパッケージがインストールされていたとしても、dtraceコマンドなどが無い古いバージョンかもしれません。そのため、最新版にアップデートしておくことをお勧めします。

パッケージが無いor不足している場合は、yumを使って取得してきます。以下のコマンドでRPMパッケージの取得・インストールをします。root権限で実施しましょう。

# yum install systemtap systemtap-runtime systemtap-sdt-devel

PostgreSQLのインストール

Systemtapのインストールが終わったら、次はPostgreSQLのインストールを行います。PostgreSQLコミュニティから配布されているRPMパッケージのPostgreSQLを使う場合には、postgresql-debuginfoを入れておきましょう。ソースを入手して自前でビルドする場合には、以下の手順を踏みます。今回はソースを用いてみます。なお、ソースを使った場合とRPMを使った場合で、動的追跡の方法は変わりませんので、好みの方法を選べます。ただし、パッケージによっては無理なものあるので、注意しましょう。(例えば、Fedoraのリポジトリにはdebuginfoパッケージがありません……)

ソースはこちらから取得します。本記事の執筆ではPostgreSQL8.4.2を用いました。入手をしたら、解凍して以下のconfigureを行い、インストールをします。

$ tar zxvf postgresql-8.4.2.tar.gz
$ cd postgresql-8.4.2
$ ./configure --enable-dtrace --enable-debug
$ make && make install

configure オプションに "--enable-dtrace" と "--enable-debug" を忘れず付与します。Soralis等でDTraceを使う場合には "--enable-dtrace" だけで良いのですが、Systemtapを使う場合には "--enable-debug" が必要になります。その他のconfigureオプションは好みで付与して下さい。その後はmake installを行い、これでPostgreSQLのインストールは終わりです。

動的追跡を試してみよう

これで動的追跡の準備が大方整いました。では、追跡に使うスクリプトを作成しましょう。スクリプトは、おおまかに言うと、プローブポイントに来た場合のアクションとプローブ開始/終了時のアクションを記述することになります。スクリプトの書式は比較的シンプルです。また、便利な組み込み関数も用意されています。今回紹介するのはSystemtap用のスクリプトですが、Dtraceを使う場合にはDスクリプトというものを使うことになります。書式や構文はSystemtapのものとは異なりますが、基本的には同じ様な処理を記述することになります。では、今回はシンプルなスクリプトを作成してみます。

Systemtapスクリプトの作成

まずは簡単に、トランザクションの開始(BEGIN)と終了(COMMIT/ABORT)時に標準出力へメッセージを送り、動的追跡の終了時に、追跡を行った期間に発生したBEGINとCOMMIT、ABORTの回数を出力するスクリプトを作成してみます。

PostgreSQL 実行ファイルのパス "/usr/bin/postgres" は環境に合わせてください。 RPM を使うとこのパスですが、ソースコードからの場合は "/usr/local/pgsql/bin/postgres" にインストールされている場合もあります。

#!/usr/bin/stap

# シェル内で使用する変数宣言
global start_count, commit_count, abort_count

# プローブ開始時の処理
probe begin
{
  printf("probe start!\n")
}

# transaction__start 通過時のアクション
# process のところには、使用するpostgresのパスを記述します。
probe process("/usr/bin/postgres").mark("transaction__start")
{
  # "start"という文字列を表示
  printf("%s\n", "transaction__start")
  # start_count をインクリメント
  start_count++
}

# transaction__commit 通過時のアクション
probe process("/usr/bin/postgres").mark("transaction__commit")
{
  printf("%s\n", "commit")
  commit_count++
}

# transaction__abort 通過時のアクション
probe process("/usr/bin/postgres").mark("transaction__abort")
{
  printf("%s\n", "abort")
  abort_count++
}

# プローブ終了時の処理
probe end
{
  printf("\nprobe end! count...\n")

  # 各処理の累積数の表示
  printf("start  count : %d\n", start_count)
  printf("commit count : %d\n", commit_count)
  printf("abort  count : %d\n", abort_count)
}

上記のスクリプトが作成できたら適当に名前をつけて保存します。本項の例ではtest.stpとしました。では、root権限を持つユーザでstapコマンドを実施してみます(下記の例ではsudoを使っています)。引数に作成したスクリプトを指定しましょう。-vは詳細なログを出力するオプションです。無くてもOKです。

stapコマンドを実行すると、下記の様な出力がされます。(掲載の都合上、一部メッセージを改行しています。)

$ sudo stap -v test.stp
Pass 1: parsed user script and 60 library script(s) 
in 190usr/30sys/220real ms.

Pass 2: analyzed script: 2 probe(s), 1 function(s), 
0 embed(s), 1 global(s) in 30usr/0sys/32real ms.

Pass 3: translated to C into "/tmp/stapS6Qyix/
stap_d723fa846ddf168184814bb09e6dbc5d_1277.c" 
in 160usr/10sys/168real ms.

Pass 4, preamble: (re)building SystemTap's version of uprobes.
Pass 4: compiled C into "stap_d723fa846ddf168184814bb09e6dbc5d_1277.ko"
in 3170usr/960sys/4023real ms.

Pass 5: starting run.

"Pass 5: starting run"が表示されたら、systemtapによるトレースが開始です。別の端末などから適当にトランザクションを発行してみます。発行し終えたら、stapコマンドを実行した端末でCtl-Cを実行してみましょう。すると、stap実行端末に下記の様なメッセージが続けて出力されます。PostgreSQLのログなどに出力されるわけではないので注意して下さい。

start
commit
start
commit
start
abort
^C
probe end! count...
start   count : 3
commit  count : 2
abort   count : 1
Pass 5: run completed in 10usr/80sys/22378real ms

このように、トランザクションの開始・終了時に"start"などのメッセージが出力され、systemtapの終了時に、累積回数の集計と表示ができました。今回は、まず簡単なsystemtapの使い方を紹介しました。次回は、もう少し応用を効かせた動的追跡を行ってみます。

(2010年3月31日公開)

systemtapを使った動的追跡