このブログにおける最初の記事を読んでくれて感謝します！

さらなるエントリーをなんとか投稿できたならば、コンテンツの種類やスタイルはこのエントリのようになるでしょう。すなわち、Oracleの問題診断情報や、OSとハードウェアに関するトラブルシューティングのテクニックをつかってその問題に触れる・・うーん…internals 😉

それにもかかわらず、体系的なアプローチとメソッドのファンでもあります。さらに高度なトラブルシューティングでの当て推量を減らすための、あまり知られていないOSやOracleの技術を紹介することを考えています。

OK、本題に入りましょう。
トラブルシューティング。
トラブルシューティング=何が起こっているか調べること。

この記事は、私がかつてOracleの外部表に関してであった、原因不明の問題についてのものです。最終的にはOracleのwait interfaceに問題があることが判明したのですが。 私は問題を把握するため、"what's going on" テクニックを使用しました。・・・what's going on 。 Solaris 10 x64/Oracle 10.2.0.2

---

私はUnixのパイプから外部表を介してデータを読み取ることが必要なプロジェクトで働いていた。（圧縮されたフラット?ファイルの内容を、オンザフライでOracleにロードしたい 😉 <ニュアンス不明> )
😉

私はUnixのパイプを作成しました：

$ mknod /tmp/tmp_pipe p
 

Oracleの外部表を作成し、そのパイプから読み取りました：

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.2.0 - Production
With the Partitioning, OLAP and Data Mining options
 
 
USERNAME     INSTANCE_NAME    HOST_NAME                 VER        STARTED      SID SERIAL# SPID
------------ ---------------- ------------------------- ---------- -------- ------- ------- -------
TANEL        SOL01            solaris01                 10.2.0.2.0 20070618     470      14 724
 
Tanel@Sol01> CREATE DIRECTORY dir AS '/tmp';
 
Directory created.
 
Tanel@Sol01> CREATE TABLE ext (
  2     value number
  3  )
  4  ORGANIZATION EXTERNAL (
  5    TYPE oracle_loader
  6    DEFAULT DIRECTORY dir
  7      ACCESS PARAMETERS (
  8      FIELDS TERMINATED BY ';'
  9      MISSING FIELD VALUES ARE NULL
 10      (value)
 11      )
 12      LOCATION ('tmp_pipe')
 13    )
 14  ;
 
Table created.
 
Tanel@Sol01> select * from ext;
 

ここまでは良いです…残念ながら、このselect文が結果を返すことはありませんでした。後で判明したのですが、フラットファイルのデータをUNIXパイプに供給する、リモートのSSHリンク上のgunzipがstuckしていたのです。
それを知らなかったので、この潜在的なセッションのハング状態に対して、 私はV$SESSION_WAITをSELECTするという着手点としては明白な方法を用いてアプローチした。

Tanel@Sol01> select sid, event, state, seq#, seconds_in_wait, p1,p2,p3
  2  from v$session_wait
  3  where sid = 470;
 
    SID EVENT                          STATE                     SEQ# SECONDS_IN_WAIT         P1         P2         P3
------- ------------------------------ ------------------- ---------- --------------- ---------- ---------- ----------
    470 db file sequential read        WAITED KNOWN TIME          164            7338          1       1892          1
 
Tanel@Sol01> /
 
    SID EVENT                          STATE                     SEQ# SECONDS_IN_WAIT         P1         P2         P3
------- ------------------------------ ------------------- ---------- --------------- ---------- ---------- ----------
    470 db file sequential read        WAITED KNOWN TIME          164            7353          1       1892          1
 
Tanel@Sol01> /
 
    SID EVENT                          STATE                     SEQ# SECONDS_IN_WAIT         P1         P2         P3
------- ------------------------------ ------------------- ---------- --------------- ---------- ---------- ----------
    470 db file sequential read        WAITED KNOWN TIME          164            7374          1       1892          1
 
Tanel@Sol01>

V$SESSION_WAITのSTATE列とSECONDS_IN_WAIT列は、直近2時間のCPUを浪費していたとしている。本当か？（WAITED???は、現在どのイベントでも待機していないことを意味する。このような場合でのEVENT列は、CPUのおける処理に移る前に待機していた最後のイベントを示す。）

うーん..それを確認してみましょう：

$ prstat -p 724
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
   724 oracle    621M  533M sleep   59    0   0:00:00 0.0% oracle/1
 

prstatコマンドは、このプロセスが現在スリープ状態にあること、CPUを使用していないし、その2時間の "RUN"時間中に実質的にCPUを使用していないことをレポートしている！

（非常に強力なツールである）psコマンドで確認してみましょう：

$ ps -o user,pid,s,pcpu,time,etime,wchan,comm -p 724
    USER   PID S %CPU        TIME     ELAPSED            WCHAN COMMAND
  oracle   724 S  0.0       00:01    02:18:08 ffffffff8135cadc oracleSOL01
 

psコマンドからも、プロセス724は、2時間以上18分に存在していましたが（ELAPSED列）、CPU時間はたったの約1秒を使用したこと（TIME）が確認できます。また、STATE列の「S」はsleep状態にあることを示します。

だから、OracleのV$SESSION_WAITまたは標準Unixツールのどちらかは私たちに嘘をついていることになります。上のエビデンスから、嘘をついているのはOracleであることはかなり明確である（また、そのようなケースでは、常に、下位のレベルの計測は、上位のレベルで何が起こっているかを知る良いチャンスである）。

それでは、我々のコードが、あるシステムコールを実行しているか、システムコール内でsleepしているかを確認するため、truss（Linuxではstrace、HP-UXではtusc）を使用してみましょう…

$ truss -p 724
read(14, 0xFFFFFD7FFD6FDE0F, 524273) (sleeping...)
 

うーん、この行に続いてなにも出力されないので、ファイルディスクリプタ14の読み出し動作の完了をプロセスが待っているように見えます。
ファイルディスクリプタ 14はどのファイルについてのものでしょう？

$ pfiles 724
724:    oracleSOL01 (LOCAL=NO)
 
...snip...
 
  14: S_IFIFO mode:0644 dev:274,2 ino:4036320452 uid:100 gid:300 size:0
      O_RDONLY|O_LARGEFILE
      /tmp/tmp_pipe
...snip...
 

問題の箇所は、すでに明らかです。tmp_pipeから来るデータがありません。このことは、パイプの他端にいるgunzipが何をやっていたかをチェックするよう、私を導いた。そして、それはstuckしていた。さらに、パイプにデータを供給するため、SSHを待っていた。そしてsshは、何らかのネットワーク?トランスポートの問題でstuckしていた。

ベースラインは、（Oracleのwait interfaceのような）上位レベルのツールが奇妙なまたは矛盾する情報を提供する場合、何が起こっているのか特定するために、低レベル（OS）のツールを頼れるということです。今回は、Oracleのwait interfaceが外部表の読み取りを記録していなかった。私は、Oracle peopleにこの情報を報告し、それが今ではバグとして提出されていると思います。

---

かなり侵入的なツールを用いたが（私は十分に考えることなく、ビジーな本番インスタンスプロセスにtrussをアタッチしない）、今回は比較的明らかなセッションハングを特定するだけの簡単なデモだった。

しかし、他の選択肢があります。このガイドの次のパートで、セッションは大きな待機を報告しておらず、かつ、CPUを多く使用しているときに何をすべきかのような、より複雑な問題を扱います。（私はそれをなんとか書こうとしているところだ）
OracleとUNIXのツールを使えば、それがスピンしているサーバプロセスの実行プロファイルを把握するのは非常に簡単です。しかも、まったくOracleに接続せずに（pstack、mdb、スタックトレースという声を聞いた 😉 ）

私がブログを始めたばかりなので、ブログのレイアウト、フォントサイズ、読みやすさ、わかりやすさなどのようなものも含めて、あらゆるフィードバックをいただければうれしいです。また、このトラブルシューティングガイドの第2部をなんとか投稿するまで、数日かかると思います。

忍耐をもってお読みいただき、ありがとうございました:-)