ORA-3136発生

システムの「心臓」こと、Oracle Databaseに日々携わるたろーちゃん。
先日、某WEBシステムのデータベースを構築し、お客様に納品しました。
そんなたろーちゃんに、お客様から電話が掛かってきました。何かあったのでしょうか？

お客様「たろーさん、先日はありがとう。」
たろー「お世話になっております。こちらこそ、ありがとうございました。」
お客様「たろーさんに構築してもらった Oracle Database を使って、今、アプリケーション開発チームが性能テストを行っているんだけど、データベース接続時に ORA-3136 が発生して接続に失敗することがあるそうなんだ。」
たろー「 ORA-3136 ですか。性能テスト時のアラートログをメールで送って頂けますでしょうか？」

---

たろーちゃんはお客様にお願いし、アラートログを送ってもらうことにしました。
メールで送られてきたアラートログには、性能テスト時間帯に以下のように出力されていました。
　

***********************************************************************

Fatal NI connect error 12170.

  VERSION INFORMATION:
    TNS for Linux: Version 12.2.0.1.0 - Production
    Oracle Bequeath NT Protocol Adapter for Linux: Version 12.2.0.1.0 - Production
    TCP/IP NT Protocol Adapter for Linux: Version 12.2.0.1.0 - Production
  Time: 07-MAR-2019 01:12:10
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12535
    
TNS-12535: TNS:operation timed out
    ns secondary err code: 12606
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=xxx.xxx.xxx.xxx)(PORT=xxxxx))
Thu Mar 07 01:12:10 2019
WARNING: inbound connection timed out ( ORA-3136 )

たろー「確かに ORA-3136 が発生しているな。これは、『時間内にユーザー認証が完了しなかった場合、接続がサーバーによってタイムアウトされた時に出力されるエラー』だ。SQLNET.INBOUND_CONNECT_TIMEOUTは特に指定していないから、デフォルトの６０秒以内にユーザ認証が何らかの理由で完了しなかったのだろう。」

---

更なる調査のため、たろーちゃんはお客様にお願いして、サーバ実機を確認させてもらうことにしました。

 ORA-3136 の原因は多岐に渡るため、調査するのが難しいエラーです。
今回は長期戦になるかも・・・。

実機確認

今回たろーちゃんが構築した Oracle Database の構成は以下のとおりです。

●シングルインスタンス構成（12cR2 Enterprise Edition）
● Oracle Diagnostics Pack あり

たろーちゃんは、性能テスト実施時間帯の AWR レポートを確認することにしました。
しかし・・・。

◆ AWR レポート出力イメージ（画像は12.1のものです）

たろー「うーむ・・・。 AWR レポートからは特に気になる点は見つからないなぁ。
OSリソース状況はどうだったのだろうか？」

---

たろーちゃんは、同時間帯の vmstat の結果を確認することにしました。

procs -------------memory------------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free      buff  cache   si   so    bi    bo   in   cs    us sy id wa st
 0  0      0 287666336 450308 13793108    0    0     0    68 5263 11802  0  0 99  0  0
 2  0      0 287665344 450308 13793120    0    0     0   192 5480 12791  1  0 99  0  0
 0  0      0 287665984 450308 13793324    0    0     0   224 5296 12270  0  0 99  0  0
 0  0      0 287667104 450308 13793452    0    0     0     0 5179 11989  0  0 100  0  0
 0  0      0 287665920 450308 13793456    0    0     0    88 5463 12142  0  1 99  0  0
 0  0      0 287663520 450308 13793520    0    0     0   112 5474 12671  1  1 99  0  0
 0  0      0 287666400 450308 13793524    0    0     0     0 5214 12107  0  0 99  0  0
 1  0      0 287666816 450308 13793732    0    0     0   184 5350 12184  0  0 99  0  0
＜＜以下、省略＞＞

 
たろー「綺麗なもんだなー・・・。OSリソースは全体的に余裕があったみたいだ。
原因が分からないぞ・・・。」

血液検査

こうなると、たろーちゃんの伝家の宝刀『血液検査』の出番です。
たろーちゃんは該当時間帯の V$ACTIVE_SESSION_HISTORY の情報を調べることにしました。
※ V$ACTIVE_SESSION_HISTORY に関しては以前の記事『正体不明のパフォーマンス悪化の謎を解き明かせ！』の回をご参照下さい。

たろー「数々の謎を解き明かしてきた『血液検査』なら、何か分かる筈だ。何か・・・。」
たろー「何か・・・原因が・・・。」
たろー「・・・・・・。」
たろー「・・・・・・・・・。」

たろー「何でだ？？『血液検査』も異常がないぞ。」

---

なんと『血液検査』の結果も異常なし。一体、何が起こっているのでしょうか？

『血液検査』が敗けた・・・？
・・・いや、違う。
『血液検査』は敗けてない。
俺が何かを見落としているんだ。

血液検査に異常がないということは？

たろー「『血液検査』はシステムのどこに異常があるのか全て分かると言っても過言じゃない。
その『血液検査』に異常がないということは、発想を逆転させれば・・・！」

---

たろーちゃんは、何かピンッときたようです。
お客様に『ある交渉』をしに行きました。

お客様「え？アプリケーションサーバ側を調査させて欲しいだって？？」
たろー「はい。データベースサーバを調べたのですが、何も手掛かりになるものが発見できなかったんです。そこで、クライアントであるアプリケーションサーバ側を調査させて頂けないでしょうか？」
お客様「いや、今回の接続障害はデータベースサーバ側で発生しているんだよね？」
たろー「・・・。」
お客様「 ORA-3136 がOracle Databaseで発生しているんだよね？」
たろー「はい・・・。」
お客様「じゃあデータベースサーバ側に何らかの問題がある筈じゃないですか？
セキュリティ上の問題もあるし、たろーさんにアプリケーションサーバを触らせる訳にはいかないです。」
たろー「はぁ・・・そうですか・・・。」

ガックリ・・・！

 

 

 

 

---

クライアントであるアプリケーションサーバ側を調査したかった、たろーちゃん。
しかし、お客様からOKを頂くことは出来ませんでした。

たろー「くそ！アプリケーションサーバ側を調べるためには、何か証拠が必要だ。
アプリケーションサーバ側に疑いがあることを示す証拠が・・・。」

---

悩んだ挙句、たろーちゃんは、以下のコマンドを実行しました。
　

SQL> alter system set events '3136 trace name errorstack level 4;name systemstate level 266';

※上記コマンドの詳細については、以前の記事『TRUNCATEを邪魔する犯人は誰だ？』の回を参照して下さい。

たろーちゃんは、この状態でもう一度性能テストをして頂くよう、お客様にお願いしました。

再性能テスト後

再度、性能テストの実施を依頼したたろーちゃんのもとに、お客様から連絡が入りました。前回同様、 ORA-3136 が発生したとのことです。
たろーちゃんは、早速、実機調査を行うことにしました。

たろー「 ORA-3136 発生時、errorstackとsystemstateを出力するよう設定したんだ。
今度は必ず何か手掛かりが・・・。」

■アラートログ

***********************************************************************


Fatal NI connect error 12170.


VERSION INFORMATION:
   TNS for Linux: Version 12.2.0.1.0 - Production
   Oracle Bequeath NT Protocol Adapter for Linux: Version 12.2.0.1.0 - Production
   TCP/IP NT Protocol Adapter for Linux: Version 12.2.0.1.0 - Production
Time: 08-MAR-2019 02:02:58
Tracing not turned on.
Tns error struct:
   ns main err code: 12535
  

TNS-12535: TNS:operation timed out
   ns secondary err code: 12606
   nt main err code: 0
   nt secondary err code: 0
   nt OS err code: 0
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=xxx.xxx.xxx.xxx)(PORT=xxxxx))

Fri Mar 08 02:02:58 2019
System State dumped to trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_362220.trc

たろー「よし、トレースファイルが出力されている！これを見れば・・・・・・。」
たろー（カタカタカタ）
たろー「・・・ついに見つけた！決定的な証拠だ！」

（続く・・・）

次回、このトレースファイルを元にたろーちゃんが戦います！