はじめまして!

本日、ラクーン技術戦略部によるブログを開設いたします。
tips、ノウハウ、新技術の紹介など、技術者ならではの情報発信をしていければと思います。



では僭越ながら記念すべきファーストエントリを書かせていただきます。

今回はphp用プロファイラ「xhprof」の導入、問題発生、及びstraceによる原因究明の顛末を書いてみようかと思います。

0, 前提

[開発用サーバ]
CentOS 5.x
PHP 5.2.x
Oracle Instant Client

1, xhprof導入

httpdの公開ディレクトリを/var/www/htmlとします。

まず、xhprofをビルドし、php.iniにxhprof.so読込設定を追加しました。
ビルド方法に関してはウェブ上にたくさん情報があるので割愛します。

次にxhprofのソース一式の中にある下記ディレクトリをhttpdの公開ディレクトリ配下にコピーしました。
/var/www/html/xhprof_lib
/var/www/html/xhprof_html
さらに下記ソースのファイルをxhprof.phpという名前で公開ディレクトリ直下に保存し、
<?php

define('XHPROF_ROOT',   '/var/www/html');
define('XHPROF_SOURCE', 'test-application'); // name of your application

require_once XHPROF_ROOT . '/xhprof_lib/utils/xhprof_lib.php';
require_once XHPROF_ROOT . '/xhprof_lib/utils/xhprof_runs.php';

function xhprof_finish() {
    $xhprof_data = xhprof_disable();

    $xhprof_runs = new XHProfRuns_Default();
    $run_id = $xhprof_runs->save_run($xhprof_data, XHPROF_SOURCE);

    printf(
        "<a href=\"http://%s/xhprof_html/index.php?run=%s&source=%s\">xhprof</a>\n",
        $_SERVER['HTTP_HOST'],
        $run_id,
        XHPROF_SOURCE
    );
}

xhprof_enable();
register_shutdown_function('xhprof_finish');
php.iniに対してプログラム実行前に上記ファイルを読み込む設定+αを追記しました。
auto_prepend_file = "/var/www/html/xhprof.php"
xhprof.output_dir = "/tmp"
この設定により、httpd上のphpが自動でプロファイリング可能となります。
以上で準備は完了し、いざプロファイリングというところで…。

2, 問題発生!そして原因究明へ。

Oracleへ接続できなくなる事態が発生!
具体的にはoci_connect()がfalseを返しており、oci_error()でも有用な情報が得られません。
アプリケーション、httpd共に不審なログは出ていません。

こんなときこそstraceで原因究明!

httpdを一度終了させてから、strace経由で起動します。
# apachectl stop
# strace -o /tmp/strace.log -f apachectl start &
起動しました。
-oオプション指定で結果をファイルに出力、-fオプション指定で子プロセスまで追っかけます。
-oを指定すると画面に何も出力しなくなるので、バックグラウンドで起動します。
アプリケーションをブラウザから叩き、再度エラーを確認したのち、
# apachectl stop
上記コマンドでhttpdもろともstraceを終了させます。

さて、httpdが実行したシステムコールは全て/tmp/strace.logに記録されているので、確認してみると、
12463 execve("/usr/sbin/apachectl", ["apachectl", "start"], [/* 28 vars */]) = 0
12463 brk(0)                            = 0x10b92000
12463 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ba4b5dd5000
12463 uname({sys="Linux", node="foo.bar.hoge", ...}) = 0
12463 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
といった感じで、最初の数千行はhttpdの起動処理です。
ブラウザから叩いた瞬間より確認したいので、「GET /」で検索します。
12469 read(28, "GET /app HTTP/1.1\r\nHost:"..., 8000) = 493
と書かれた行が見つかりました。
28はhttpdがlistenしていたsocketのファイルハンドルですね。
この行以降に原因が潜んでいそうです。

Oracleの接続時に問題が発生していそうなので、「oracle」で検索してみます。
そうすると、
12469 open("/path/to/oracle/client/lib/libxxxx.so/libyyyy.so", O_RDONLY) = -1 ENOTDIR (Not a directory)
12469 open("/path/to/oracle/client/lib/libxxxx.so/libzzzz.so", O_RDONLY) = -1 ENOTDIR (Not a directory)
12469 lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
12469 lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
12469 lstat("/var/www/html", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
12469 lstat("/var/www/html/lib", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
12469 lstat("/var/www/html/lib/DbException.php", {st_mode=S_IFREG|0764, st_size=1005, ...}) = 0
12469 open("/var/www/html/lib/DbException.php", O_RDONLY) = 33
上記のようなおかしな行を発見しました。
最初の2行で「ENOTDIR (Not a directory)」って言われてるし、libxxxx.soってファイル名じゃないの?という疑問が浮かびます。
さらに3行目以降は例外クラスのファイルを探しているので、
if (oci_connect(...) === false) {
    throw new DbException(...);
}
といった内容のプログラムが想像できます。

ここで推理。
この辺のsoファイルを呼び出したいのはphpエクステンション=oci8なハズ。
そこでoci8.soがどのファイルとリンクしているかlddで確認。
# ldd /path/to/php/lib/oci8.so
libxxxx.so => /path/to/oracle/client/lib/libxxxx.so
おっと、前述のディレクトリ扱いされていたsoファイルにリンクしています。
ではこのsoファイルは前述のlibyyyy.so、libzzzz.soとリンクしているのか確認。
# ldd /path/to/oracle/client/lib/libxxxx.so
しかしリンクしておらず。

今度はxhprofを無効にした状態(=Oracleへ正常に接続できる状態)でstraceしてみます。
※php.iniのauto_prepend_fileをコメントアウトしてhttpdをリスタート

するとstraceの結果から下記の行が見つかりました。
13951 open("/path/to/oracle/client/lib/libyyyy.so", O_RDONLY) = 33
正常に読込できています。

以上の結果を鑑みて、xhprofが原因でOracleのクライアントライブラリに不具合を及ぼしたと判断できます。
xhprofは内部であちこちフックしていそうなので、なんとなくイメージはつきますね。

3, 原因究明後

その後いろいろ調べた結果、Instant ClientではなくFull Clientを導入すると解決しそうなことが分かりました。

以上の通り、straceはトラブルシューティングツールとして素晴らしいものです。
しかし、アプローチがどうしてもローレベルなため、少し敷居が高いところが玉にキズですね。
ただ、使いこなせれば非常に強力なツールですので、使ったことがない方は是非お試しください!



最後になりましたが、TECH BLOG by raccoonを今後ともよろしくお願いいたします。
研究のための3つの理由
言語を検出 » Japanese

言語を検出 » Japanese

言語を検出 » Japanese