Oracle Instant Client 10.2.0.1を利用した場合、突然DBへ接続ができなくなる現象

Tech

【追記】(2008/02/13)
以下の対応を行ったのですが、また同様の現象が発生してしまいました。Oracle Instant Client 10.2.0.3にバージョンアップすることで問題が解消されていればよいのですが...

※このエントリへのアクセスがあるようなので、タイトルをもう少し分かりやすく変更しました。

以下のOSおよびソフトウェア組み合わせで動かしているウェブサーバがあります。

突然何の前触れもなくOracleへ接続ができなくなりました。Apacheのエラーログを見ると、以下のようなエラーが頻発していました。

[Sun Oct 01 02:00:12 2006] [error] [client xxx.xx.xxx.xxx] PHP Fatal error:  Maximum execution time of 30 seconds exceeded in /xxx/xxx/xxx/xxx.php on line 31
[Sun Oct 01 02:00:12 2006] [error] [client xxx.xx.xxx.xxx] PHP Warning:  Unknown(): OCI8 Recursive call!\n in Unknown on line 0

様子を見ていたのですが、接続先のDBサーバの負荷が高いわけでもなく、一向に収束する気配もないので、いったんApacheを再起動することにしました。本来であれば、以下のような形で起動するのですが、子プロセスが起動しない。

[root@xxx xxx]# ps auxf 
(snip)
root      5091  0.0  0.8 98556 8884 ?        S    15:50   0:00 /usr/local/httpd2.0.59/bin/httpd -k start
nobody    5092  0.2  1.3 102756 13484 ?      S    15:50   0:03  \_ /usr/local/httpd2.0.59/bin/httpd -k start
nobody    5095  0.2  1.3 102748 13432 ?      S    15:50   0:02  \_ /usr/local/httpd2.0.59/bin/httpd -k start
nobody    5096  0.2  1.4 102756 14952 ?      S    15:50   0:03  \_ /usr/local/httpd2.0.59/bin/httpd -k start
nobody    5097  0.2  1.4 102748 14924 ?      S    15:50   0:02  \_ /usr/local/httpd2.0.59/bin/httpd -k start
nobody    5098  0.2  1.3 102756 13480 ?      S    15:50   0:03  \_ /usr/local/httpd2.0.59/bin/httpd -k start
nobody    5101  0.1  1.3 102748 13480 ?      S    15:50   0:02  \_ /usr/local/httpd2.0.59/bin/httpd -k start
(snip)

具体的には、以下のような感じで親プロセスしか起動せず、しかもCPUが100%近くのままになってしまいました。

[root@xxx xxx]# ps auxf 
(snip)
root      5091  99.9  0.8 98556 8884 ?        S    15:50   0:00 /usr/local/httpd2.0.59/bin/httpd -k start

しかもたちの悪いことに apachectl stop とコマンドを叩いても、not runningなんて怒られる始末。(起動してもhttpd.pidファイルも生成しないし、ログファイルも出力しないので正しく起動していないのでしょう)

問題がなんとも掴めないので、問題の切り分けをすることにしました。

  1. httpd.confの設定をデフォルトに戻して起動するか？
  2. php.iniの設定をデフォルトに戻して起動するか？

まずはhttpd.confの設定を元の状態に戻して、Apacheが問題なく起動するか確認をしました。これは問題なく起動しました。次にデフォルトからphpの設定(LoadModuleとかAddTypeの辺り)を削除して起動しました。これも問題なく起動しました。最後にphpの設定を追記した状態で起動しました。すると先ほどのダメな状態に逆戻りしてしまいました。

上記からphp周りの設定に問題がある可能性があるので、php.iniの設定をデフォルトに戻すことにしました。まずはphp.iniをデフォルトに戻した上で、httpd.confにphpの設定を追記した状態でApacheを起動しました。すると今度はきちんと起動しました。php.iniは特別な設定をしているのは以下の個所だけなので、oci8.soのロードが怪しいのかなとあたりを付けました。

; Oracle
extension=oci8.so

最近は設定を触っていないので、怪しいと言えば怪しい部分です。そこまではたどり着いたのですが、それ以上は何も分からずじまい。何せエラーログが吐き出されないのだからどうしようもないです。

別の切り口からということで、Apacheの親プロセスについてシステムコールとシグナルをトレースしてみると、何かヒントが得られるかもしれないと思い、調べてみました。すると以下の結果が得られました。

[root@xxx xxx]# strace -p 5091
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277

上記の「time(NULL)」をキーワードにして、Googleで検索をしてみるも、それらしきキーワードが見つからず、どうしようもない状態に。どうしようもないので、1人はそのまま原因調査をもう1人(というか俺ですが)が別の方法での対応を検討することにしました。

色々調べてもらった結果、別のキーワードを見つけて、原因と対応策が見つかりました。やったー！

[root@xxx xxx]# strace -f /usr/local/httpd2.0.59/bin/apachectl start
access("/xxx/oracle/admin/network/conf/sqlnet.ora", F_OK) = -1 ENOENT (No such file or directory)
access("/usr/lib/oracle/10.2.0.1/client/network/admin/sqlnet.ora", F_OK) = -1 ENOENT (No such file or directory)
access("/xxx/oracle/admin/network/conf/sqlnet.ora", F_OK) = -1 ENOENT (No such file or directory)
access("/usr/lib/oracle/10.2.0.1/client/network/admin/sqlnet.ora", F_OK) = -1 ENOENT (No such file or directory)
fcntl64(161185400, F_SETFD, FD_CLOEXEC) = -1 EBADF (Bad file descriptor)
fcntl64(161185416, F_SETFD, FD_CLOEXEC) = -1 EBADF (Bad file descriptor)
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
times(NULL)                             = -2141161277
(snip)

ってことでやっと本質の部分に触れるわけですが、どうやらOracle Instant Client 10.2.0.1をインストールし、利用しているサーバを連続248日以上稼動させると発生するバグのようです。


Back in the days of Oracle 8, there was a fairly imfamous bug in the Oracle client where new connections would fail if the client had been up for 248 days or more. This got fixed, and wasn't a problem with Oracle 9i at all. Now Oracle have managed to introduce a similar bug in 10.2.0.1, although in my experience the number of days appears to be shorter (180+).

うーん、結局Oracleのバグが減員だったとは....この手のバグは結構有名だったりするのでしょうか？

ちなみに以下のサイトで詳しい情報が載っていますので、参考にして下さい。

ってことで、結論として対応は以下の通りになりました。

  • サーバのOS再起動
  • Oracle Instant Client 10.2.0.1をOracle Instant Client 10.2.0.2にアップデート

これで無事に問題は解消されました。はぁー、疲れた。

【追記】

Oracle Instant Clientは、oracle.comからダウンロードして下さい。oracle.comのアカウント登録が必要です*1。

oracle.co.jpでは最新版のOracle Instant Clientが用意されていませんので注意が必要です。いつになったら最新版を用意してくれるんでしょうかね。古いバージョンだと問題が起こるのだから、置き換えてもらわないと困るのですが。

【2007/03/24追記】
Oracle Instant Clientの最新版(Linux x86の場合、10.2.0.3)がOTN Japanにて公開されています。

追記を書きました。

*1:OTNのアカウントとは異なるので注意して下さい