夜間バッチを実行するとORA-3136が発生する

世間がお盆休みだったある日、夜間バッチを実行するとORA-3136が発生するとの調査依頼がありました。

バッチ実行時、毎回1分後にエラーがalert.logに記録されるものの、バッチ処理自体は正常終了しているとの事です。

リリース間近の本番環境で、構成は以下の通りです。

Oracle RAC（2ノード） EE 12.1.0.2
RHEL Version 7.3

ORA-3136は接続時の認証処理タイムアウトのエラーで、sqlnet.oraのINBOUND_CONNECT_TIMEOUTでタイムアウトとなるまでの時間を指定しますが、何も指定していなければデフォルトの60秒でエラーが発生します。

JavaプログラマBronze　SE　7 オラクル認定資格試験学習書 （オラクル認定資格教科書） [ 山本道子（プログラミング） ]

今回の環境ではsqlnet.oraに何も指定していない為、デフォルトの60秒でタイムアウト・エラーとなった訳ですが、では何故バッチが正常終了しているのか謎です。

 このシステムではパッケージ・ソフトを使用しており、接続方式はJDBC Thinドライバとの事。ソースファイルは公開されていない為、このバッチが具体的にどういう作りになっているのかは不明だそうです。

接続エラーが発生しているのに処理そのものは正常終了しているので、エラー発生時に接続をリトライするような作りなのかも知れません。

接続エラーが発生するのに処理が正常終了する理由は不明ですが、接続エラーを回避するのが目的ですので、切り分けの為、DBに接続してインスタンス情報を取得するだけの簡単なテスト・プログラムをjavaで作成しました。

スクリプトは以下の通りで、接続文字列および接続ユーザは実際のバッチ処理で使用されているものに合わせました。

DBAccess01.java

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.Statement;

public class DBAccess01{
   public static void main(String args) {
      try {
         new DBAccess01().execute();
      }catch(Exception e) {
         e.printStackTrace();
      }
   }

public void execute() throws Exception {
   Connection conn = null;
   Statement stmt = null;
   ResultSet rs = null;

   Class.forName("oracle.jdbc.driver.OracleDriver");
   DriverManager.registerDriver(new oracle.jdbc.driver.OracleDriver());

   conn = DriverManager.getConnection("jdbc:oracle:thin:@(DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = TCP)(HOST = node1)(PORT = 1521))) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = orcl) (INSTANCE_NAME = orcl1)))", "TEST", "password");

   stmt = conn.createStatement();
   rs = stmt.executeQuery("select instance_name from v$instance");

   while(rs.next()) {
      System.out.println("Result:" + rs.getString("instance_name"));
   }

   rs.close();
   stmt.close();
   conn.close();
   }
}

Oracle JDBC DriverとJDK バージョンは以下の通りです。

$ java -jar ojdbc7.jar
Oracle 12.1.0.2.0 JDBC 4.1 compiled with JDK7 on Mon_Jun_30_11:30:34_PDT_2014

$java -version
openjdk version "1.8.0_141"
OpenJDK Runtime Environment (build 1.8.0_141-b16)
OpenJDK 64-Bit Server VM (build 25.141-b16, mixed mode)

実行手順は以下の通りとなります。

/tmp にDBAccess01.javaを配置。
以下の環境変数を設定。
$ export CLASSPATH=<ORACLE_HOME>/jdbc/lib/ojdbc7.jar:/tmp
$ export PATH=<ORACLE_HOME>/jdk/bin:$PATH
/tmp に移動して、コンパイル。
$ javac DBAccess01.java
DBAccess01.class が作成されるので、以下の通り実行。
$ java DBAccess01
Result:orcl1

APサーバ上で上記テストjavaを実行して時間計測したところ、10から30秒程度、かかりました。

これは遅い。明らかに遅い。

60秒はかかっていないものの、60秒かかればORA-3136が発生するのは確かです。

念の為、APサーバ上からsqlplusでも同一の接続文字列・同一ユーザで接続してみましたが、1秒程度で接続できます。

リスナー・トレース設定を有効にして確認すると、以下の部分で遅延が見られます。

[000001 13-AUG-2019 11:24:08:736] nsevwait: waiting for transport event (1 thru 11)...
[000001 13-AUG-2019 11:24:23:115] nsevwait: 0 newly-posted event(s)

調べてみましたが、これだけだと何かを待っている事がわかるだけで、何を待っているかまでは判明しないようです。

更に調査したところ、以下のドキュメントに辿り着きました。

Linux x86/x86-64環境においてJDBC接続がタイムアウトもしくは遅延する問題について(KROWN:131975) ( Doc ID 1744770.1 )

概略は以下の通りです。

Oracle 11g JDBC Driver では、ログイン時に乱数生成のためにjava.security.SecureRandom.nextBytes(byte)メソッドを使用しています。
Linux 上で Oracle 11g JDBC Driver を使用しているユーザーは、次の 2つの問題に遭遇する可能性があります。

#1 JVM は、SecureRandom.nextBytes(byte)が実行されたとき、/tmp (もしくは、-Djava.io.tmpdir で設定したtmpディレクトリ) の全てのファイルをリストしようと試みます。このディレクトリにファイル数が多い場合、この処理に時間がかかり、サーバーのタイムアウトの原因になります。

#2 SecureRandom.nextBytes(byte)は、Linux 上の /dev/random を使用しています。
/dev/random は乱数生成機能が不足しているハードウェアでは、その操作が全体のログイン処理を停止させる程度まで処理が遅くなることがあります。 

 #1 の対処策は/tmpの下をクリーンアップする事ですが、こちらは効果がありませんでした。

#2の対処策で、以下のオプションをつけて実行します。

$ java -Djava.security.egd=file:/dev/../dev/urandom DBAccess01

この結果、接続時間が1秒程度に短縮したので、#2のケースに該当している事が判明しました。バッチプログラムの実行時にオプション指定は出来ないので、以下のファイルを書き換えます。

$JDK_HOME/jre/lib/security/java.security のsecurerandom.source パラメータを以下のように変更。
securerandom.source=file:/dev/./urandom

これでバッチ処理を実行したところ、エラーは発生しなくなりました。

この件とは関係ありませんが、お盆中って電車が空いていて良いです。