Oracle 10.2.0.1 Instant Client の致命的バグ → 248日目に hang します

いきなり結論。タイトル通り Oracle 10.2.0.1 Instant Client は OS 起動後 248 日でハングします。64 bit 環境なら 198 日でハングします。したがって、Instant Client を使うサービスは全てハングします。これにより、RAC を制御する ons というサービスもハングして Oracle 10g RAC に不具合が発生します。

以下詳細。

- スポンサーリンク -

つい最近のことですが仕事の本番 DB で障害が発生しました。Oracle 10g R2 を使っているのですが、10g R2 がリリースされた直後にいれた Oracle 10g RAC システムでバージョンは 10.2.0.1 となっていました。ある日出社してみるとOracle 10g の監視に使っている Insight Technology 社のPerformance Insight から山のような warining メールが届いていました。エラーの内容を抜粋すると、ons（Oracle Notification Service）つまりアプリケーション・サーバへの障害通知に利用するノードアプリケーションの１つが落ちているようです。

Warning Level : 2
WL=2:/db/crs/oracle/product/10.2.0/app/opmn/bin/ons -a ping (19654)
    :CPU使用時間 59.98sec(/60sec)

取りあえずユーザ向けのサービスが停止している様子はありません。DB サーバへ ssh してみるとロードアベレージが９くらい。CPU の使用率がおかしいです。ons が張り付いて CPU を食いつぶしています。 

oracle   16150 62.9  0.0 22128 4756 ?        R    03:07 281:44 /db/crs/oracle/product/10.2.0/app/opmn/bin/ons -a ping
oracle   30418 62.6  0.0 22128 4752 ?        R    03:16 274:41 /db/crs/oracle/product/10.2.0/app/opmn/bin/ons -a shutdown
oracle   12128 61.3  0.0 22128 4752 ?        R    03:25 263:35 /db/crs/oracle/product/10.2.0/app/opmn/bin/ons -a ping
oracle   26423 61.0  0.0 22128 4752 ?        R    03:34 256:26 /db/crs/oracle/product/10.2.0/app/opmn/bin/ons -a ping
oracle   28610 61.2  0.0 22128 4752 ?        R    03:35 256:30 /db/crs/oracle/product/10.2.0/app/opmn/bin/ons -a shutdown

さらに深追い。cat /crs/oracle/product/10.2.0/app/log/xxxdb02/racg/ora.xxxdb02.ons.log
すると確かに ons で TIMEOUT が発生していますが、あまり情報はありません。 

2007-03-19 03:43:04.812: [    RACG][2540276992] [12123][2540276992][ora.xxxdb02.ons]: timeout: killed the spawned process
2007-03-19 03:43:04.812: [    RACG][2540276992] [12123][2540276992][ora.xxxdb02.ons]: clsrcexecut: env ORACLE_CONFIG_HOME=/db/crs/oracle/product/10.2.0/app
2007-03-19 03:43:04.812: [    RACG][2540276992] [12123][2540276992][ora.xxxdb02.ons]: clsrcexecut: cmd = /db/crs/oracle/product/10.2.0/app/bin/racgeut -e _USR_ORA_DEBUG=0 540 /db/crs/oracle/product/10.2.0/app/bin/onsctl ping
2007-03-19 03:43:04.812: [    RACG][2540276992] [12123][2540276992][ora.xxxdb02.ons]: clsrcexecut: rc = 99, time = 540.040s
2007-03-19 03:43:04.813: [    RACG][2540276992] [12123][2540276992][ora.xxxdb02.ons]: end for xxxource = ora.xxxdb02.ons, action = start, status = 1, time = 1081.080s
2007-03-19 03:44:34.929: [    RACG][2540276992] [28604][2540276992][ora.xxxdb02.ons]: onsctl: shutting down ons daemon ...
timeout: killed the spawned process

さらに深追い。cat /crs/oracle/product/10.2.0/app/log/xxxdb02/crsd/crsd.log
crs のログから見ても ons が OFFLINE になった以上の情報得られず。 

2007-03-19 03:25:03.661: [  CRSXXX][1566763360]0Stop of `ora.xxxdb02.ons` on member `xxxdb02` succeeded.
2007-03-19 03:25:03.661: [  CRSXXX][1566763360]0ora.xxxdb02.ons RESTART_COUNT=0 RESTART_ATTEMPTS=3
2007-03-19 03:25:03.661: [  CRSXXX][1566763360]0Restarting ora.xxxdb02.ons on xxxdb02
2007-03-19 03:25:03.666: [  CRSXXX][1566763360]0startRunnable: setting CLI values
2007-03-19 03:25:03.666: [  CRSXXX][1566763360]0Attempting to start `ora.xxxdb02.ons` on member `xxxdb02`

srvctl start nodeapps -n xxxdb02 して RAC の状態を確認。あら、確かに落ちているサービスがあります。 

名前           型             ター...ト 状態      ホスト      
------------------------------------------------------------
ora.xxx.db     application    ONLINE    ONLINE    xxxdb01     
ora....01.inst application    ONLINE    ONLINE    xxxdb01     
ora....02.inst application    ONLINE    ONLINE    xxxdb02     
ora....xxdb.cs application    ONLINE    ONLINE    xxxdb01     
ora....x01.srv application    ONLINE    ONLINE    xxxdb01     
ora....b_bk.cs application    ONLINE    ONLINE    xxxdb02     
ora....x02.srv application    ONLINE    ONLINE    xxxdb02     
ora....01.lsnr application    ONLINE    ONLINE    xxxdb01     
ora....b01.gsd application    ONLINE    ONLINE    xxxdb01     
ora....b01.ons application    ONLINE    OFFLINE               
ora....b01.vip application    ONLINE    ONLINE    xxxdb01     
ora....02.lsnr application    ONLINE    ONLINE    xxxdb02     
ora....b02.gsd application    ONLINE    ONLINE    xxxdb02     
ora....b02.ons application    ONLINE    OFFLINE               
ora....b02.vip application    ONLINE    ONLINE    xxxdb02


ここで保守ベンダーから有用な連絡あり。詳細は Oracle の保守契約違反になるのでネットで得られる情報レベル＋実際に発生した事実にフィルタリングして情報共有すると、いきなり結論で書いたとおり Oracle 10.2.0.1 Instant Client は OS 起動後 248 日でハングします。64 bit 環境なら 198 日でハングします。patch を適用して 10.2.0.2 へ upgrade すれば問題は回避できます。patch をダウンロードするには年間何百万円もする Oracle のサポートを契約している必要があります。

ちなみに、oracle.co.jp ではトライアル版も現時点で 10.2.0.1 なので 10.2.0.2 を手に入れるにはサポートしかありません。oracle.com ではトライアル版も 10.2.0.2 がでています。

なお、client 環境であれば、無償提供されている instant client を 10.2.0.2 以上にすれば OK です。ダウンロードには OTN へのユーザ登録が必要です。


と言うわけで、Oracle 10g の 10.2.0.1 をお使いの方でインストール後 OS 再起動をかけていないって方はそろそろ同じ現象が発生する時期に来ているかと思いますので、198 日毎に OS 再起動をするか patch をあてて 10.2.0.2 へ upgrade するかの対処をとられるのがよろしいかと。

client 環境つまりアプリケーションサーバ側は複数台でロードバランスしている場合が多いかと思いますので instant client を最新の 10.2.0.3 へ upgrade するのは比較的簡単かと思います。おそらく、DBD::Oracle とかもライブラリのリンクのし直しが必要なので再コンパイルしないとダメかと思います。※ここ、まだ未検証だけど近々実施。

10g RAC の upgrade は patch あてる際には全てのノードを停止して patch あてるのが推奨されているのでデータベース停止を伴うこととなりなかなか実施しづらいところですね。

ネットでは同様の情報がここらへんで手に入ります。

ところで、この 248 日問題。過去のバージョンでも度々発生しています。たとえば、SUMMARY: oracle hang なんかでもスレッドがたっていますが、8.1.7 とかでは database 本体に同様のバグがあったようです。

普段安定して動作している分だけ、いきなりこの手の不具合で障害が発生するとかなりビビリますよ。ホント頼みますわ Oracle さん。

- スポンサーリンク -

関連する記事＆スポンサーリンク