接続障害(2/2)

2019年8月28日『心臓外科医の術式』

1 前回のおさらい
2 再度、交渉
3 アプリケーションサーバ側の調査結果は？

前回のおさらい

前回は、たろーちゃんがORAエラーの原因がアプリケーション側にあるという
決定的な証拠を見つけたところで終わりました。
さて、ここからが面白いお話です

再度、交渉

お客様「え？アプリケーションサーバ側が長時間無応答になっているだって？？」
たろー「はい。このトレースファイルを見て頂けますか。」

■トレースファイル

client details:
       O/S info: user: xxxxx, term: , ospid: 31821
       machine: xxxxx program: xxxxx (TNS V1-V3)
       application name: xxxxx (TNS V1-V3), hash value=1851990384
     Current Wait Stack:
      0: waiting for 'SQL*Net message from client'
         driver id=0x54435000, #bytes=0x1, =0x0
         wait_id=30 seq_num=33 snap_id=1
         wait times: snap=1 min 37 sec, exc=1 min 7 sec, total=1 min 7 sec
         wait times: max=infinite, heur=1 min 7 sec
       wait counts: calls=0 os=0
         in_wait=1 iflags=0x1a0
   nt secondary err code: 0
   nt OS err code: 0

たろー「これは Oracle Database から見たクライアント側（アプリケーションサーバ）の状態です。
待機イベント『SQL*Net message from client』で１分７秒も待ちが発生しています。
この時のアプリケーションサーバ側の状態を調査したいんです。」
お客様「むむむ。」
たろー「 ORA-3136 は、『時間内にユーザー認証が完了しなかった場合、接続がサーバーによってタイムアウトされた時に出力されるエラー』です。アプリケーションサーバ側が、何らかの理由で応答を返せていない可能性が高いんです。」
お客様「・・・分かった。アプリケーションサーバ側を調査してみよう。
しかし、たろーさんにアプリケーションサーバを触らせる訳にはいかない。
別の担当者に調査させるから、待っていてくれないかな？」
たろー「はい、分かりました。」

頑張った甲斐があり、なんとかアプリケーションサーバ側にメスを入れることが出来ました。
たろーちゃんが直接調査することは出来ませんが、それだけでも十分でした。
心臓外科医が心臓以外にメスを入れるのは、本当に大変なことなのです。

アプリケーションサーバ側の調査結果は？

お客様「たろーさん、お待たせ。アプリケーションサーバ側の調査が終わったよ。」
たろー「ありがとうございます、どうでしたか？」
お客様「たろーさんの言う通りだった。まずはこれを見てくれ。」
　

procs -----------memory---------- ---swap-- -----io---- --system- - -----cpu-----
  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs   us sy id wa st
 16  0      0 3129424  45532 2347280    0    0     0     0 2887 1844 85 15  0  0  0
 15  0      0 3129424  45540 2347276    0    0     0    20 3346 1867 84 15  1  0  0
 15  0      0 3129424  45540 2347284    0    0     0     0 3179 1888 83 17  1  0  0
 15  0      0 3129424  45540 2347284    0    0     0     0 2653 1843 86 14  1  0  0
 15  0      0 3129424  45540 2347284    0    0     0     0 2865 1855 85 15  0  0  0
 15  0      0 3129424  45540 2347284    0    0     0     0 3400 1908 84 16  1  0  0
 15  0      0 3129424  45540 2347284    0    0     0     0 3013 1832 85 15  0  0  0
 15  0      0 3129424  45548 2347284    0    0     0    20 2648 1924 85 15  1  0  0
 15  0      0 3129424  45548 2347284    0    0     0     0 2908 1869 85 15  1  0  0
 15  0      0 3129424  45548 2347284    0    0     0     0 3273 1838 85 15  0  0  0
 15  0      0 3129424  45548 2347284    0    0     0     0 3052 1804 85 15  0  0  0
 14  0      0 3129424  45548 2347284    0    0     0     0 2665 1861 87 13  1  0  0
 15  0      0 3129424  45548 2347284    0    0     0     0 2962 1872 85 15  1  0  0
 14  0      0 3129424  45556 2347284    0    0     0    20 3401 1817 85 16  0  0  0
 14  0      0 3129424  45556 2347284    0    0     0     0 3063 1827 85 15  1  0  0
 14  0      0 3129424  45556 2347284    0    0     0     0 2680 1841 86 14  0  0  0
 12  0      0 3129424  45556 2347284    0    0     0     0 2920 1819 86 14  1  0  0
 14  0      0 3129424  45556 2347284    0    0     0     0 3455 1888 86 14  0  0  0
 14  0      0 3129424  45564 2347284    0    0     0    20 3010 1862 84 15  1  0  0
 13  0      0 3129424  45564 2347284    0    0     0     0 2680 1838 84 16  1  0  0
 14  0      0 3129424  45564 2347284    0    0     0    36 2990 1854 83 16  1  0  0
 14  0      0 3129424  45564 2347284    0    0     0     0 3477 1845 85 14  1  0  0
 15  0      0 3129424  45564 2347284    0    0     0     0 2956 1893 83 16  1  0  0
＜＜以下、省略＞＞

たろー「 CPU のアイドルが殆ど無く、runキューも多いですね。」
お客様「調べてみた所、この時、アプリケーションサーバ上で動作しているJavaアプリケーションでFullGC（フル・ガベージコレクション）が頻発していたんだ。JavaVMに指定するヒープサイズが小さ過ぎたのが原因だ。」
たろー「よく OutOfMemoryError 発生しませんでしたね。」
お客様「まったくだ。いっそのこと OutOfMemoryError が発生してくれれば、アプリケーション側の監視で気づけたんだが・・・。」
たろー「FullGC実行中はJavaVMは完全に動作を止めますからね。それで Oracle Database に対して応答が返せなかったんですね。」
お客様「今回のことを踏まえ、アプリケーションサーバのCPU増強にメモリ増強。JavaVMのヒープサイズの見直しを行うことにしたよ。性能テストでこれらのことが分かったのは、すごく収穫だった。ありがとう、たろーさん。」

こうしてたろーちゃんは、自分の守備範囲外にまで飛び出して、原因を突き止めることに成功しました。

今回の「心臓外科医の術式」いかがだったでしょうか？
ORA-3136は、データベースサーバだけに原因があるとは限らないエラーです。
『血液検査』で異常がないということは、発想を逆転すると『心臓以外に異常がある』ということになります。
しかし今回のように、セキュリティ上の理由や役割・担当の境界で、データベース以外を調査することが困難なことがあります。そういう時は、データベース以外に異常があることを示す証拠が必要になります。
証拠の発見～原因究明までの、見事な「術式」だったのではないでしょうか。

次回も頑張りますので、応援よろしくお願い致します。

投稿者プロフィール

DBひとりでできるもん運営チーム

「DBひとりでできるもん」運営チームです。
「親しみやすさと技術力」をテーマに、技術情報・サービス・インフラ系資格取得に役立つ情報、社員等の情報をお届けします。
70名弱の事業部員で鋭意、執筆中です。
少しでも当社を知って頂けるよう、愛情込めて頑張ります！
※facebook、X(旧twitter)、インスタグラムでは「DBひとりでできるもん」の更新情報を発信しています。