16.7.4 Oracle Net Servicesのトレース・ファイルの評価

トレース・ファイルは、Oracleサポート・サービスがネットワーク上の問題点を診断してトラブルシューティングする際に役立ちます。この項では、トレース・ファイルの基本的な分析を実行する方法について説明します。

16.7.4.1 ネットワーク・ノード間のデータ・パケットの流れ

Oracle Netは、データ・パケットを送受信することにより、その機能を実行します。supportのトレース・レベルを指定すると、トレース・ファイル内のOracle Netパケットの実際の内容を参照できます。送受信したパケット・タイプの順序により、接続を確立した方法を確認できます。

16.7.4.2 Oracle Netのデータ・パケットのフォーマット

トレース・ファイルの各行は、後ろにメッセージが続くプロシージャで始まります。各プロシージャの後には、実際のデータを示す16進データの行があります。パケットの内部をフローする実際のデータは、16進データの右側に表示される場合があります。

各パケットには、パケット・タイプを示すキーワードがあります。すべてのパケット・タイプは、接頭辞「nsp」から始まります。これは、特定のパケット情報についてトレース・ファイルを検討する場合に役立ちます。トレース・ファイルで使用されるキーワードは次のとおりです。

  • NSPTCN: 接続パケット・タイプで使用します。

  • NSPTAC: 受入れパケット・タイプで使用します。

  • NSPTRF: 拒否パケット・タイプで使用します。

  • NSPTRS: 再送パケット・タイプで使用します。

  • NSPTDA: データ・パケット・タイプで使用します。

  • NSPCNL: 制御パケット・タイプで使用します。

  • NSPTMK: マーカー・パケット・タイプで使用します。

例16-13は、一般的なパケット情報を示しています。この例では、nsconプロシージャはネットワークを通じてNSPTCNパケットを送信します。

例16-13 パケット情報

nscon: entry
nscon: doing connect handshake...
nscon: sending NSPTCN packet
nspsend: entry
nspsend: plen=187, type=1
nspsend: 187 bytes to transport
nspsend:packet dump
nspsend:00 BB 00 00 01 00 00 00  |........|
nspsend:01 33 01 2C 0C 01 08 00  |.3.,....|
nspsend:7F FF 7F 08 00 00 00 01  |........|
nspsend:00 99 00 22 00 00 08 00  |..."....|
nspsend:01 01 28 44 45 53 43 52  |..(DESCR|
nspsend:49 50 54 49 4F 4E 3D 28  |IPTION=(|
nspsend:43 4F 4E 4E 45 43 54 5F  |CONNECT_|
nspsend:44 41 54 41 3D 28 53 49  |DATA=(SI|
nspsend:44 3D 61 70 33 34 37 64  |D=ap347d|
nspsend:62 31 29 28 43 49 44 3D  |b1)(CID=|
nspsend:28 50 52 4F 47 52 41 4D  |(PROGRAM|
nspsend:3D 29 28 48 4F 53 54 3D  |=)(HOST=|
nspsend:61 70 32 30 37 73 75 6E  |sales-12|
nspsend:29 28 55 53 45 52 3D 6D  |)(USER=m|
nspsend:77 61 72 72 65 6E 29 29  |scott))|
nspsend:29 28 41 44 44 52 45 53  |)(ADDRES|
nspsend:53 5F 4C 49 53 54 3D 28  |S_LIST=(|
nspsend:41 44 44 52 45 53 53 3D  |ADDRESS=|
nspsend:28 50 52 4F 54 4F 43 4F  |(PROTOCO|
nspsend:4C 3D 74 63 70 29 28 48  |L=tcp)(H|
nspsend:4F 53 54 3D 61 70 33 34  |OST=sale|
nspsend:37 73 75 6E 29 28 50 4F  |s-12)(PO|
nspsend:52 54 3D 31 35 32 31 29  |RT=1521)|
nspsend:29 29 29 00 00 00 00 00  |))).....|
nspsend: normal exit
nscon: exit (0)

16.7.4.3 Oracle Netの関連トレース・エラー出力

問題があると、エラー・コードがトレース・ファイルに記録されます。この例は、データベース・サーバーへのSQL*Plus接続が失敗した場合の典型的なトレース・ファイル出力を示しています。

エラー・メッセージおよびエラー・スタックは太字で示されています。

例16-14 トレース・ファイルの出力例

[22-MAY-2022 13:34:07:687] nsprecv: entry
[22-MAY-2022 13:34:07:687] nsbal: entry
[22-MAY-2022 13:34:07:687] nsbgetfl: entry
[22-MAY-2022 13:34:07:687] nsbgetfl: normal exit
[22-MAY-2022 13:34:07:687] nsmal: entry
[22-MAY-2022 13:34:07:687] nsmal: 44 bytes at 0x132d90
[22-MAY-2022 13:34:07:687] nsmal: normal exit
[22-MAY-2022 13:34:07:687] nsbal: normal exit
[22-MAY-2022 13:34:07:687] nsprecv: reading from transport...
[22-MAY-2022 13:34:07:687] nttrd: entry
[22-MAY-2022 13:35:09:625] nttrd: exit
[22-MAY-2022 13:35:09:625] ntt2err: entry
[22-MAY-2022 13:35:09:625] ntt2err: Read unexpected EOF ERROR on 10
[22-MAY-2022 13:35:09:625] ntt2err: exit
[22-MAY-2022 13:35:09:625] nsprecv: transport read error
[22-MAY-2022 13:35:09:625] nsprecv: error exit
[22-MAY-2022 13:35:09:625] nserror: entry
[22-MAY-2022 13:35:09:625] nserror: nsres: id=0, op=68, ns=12537, ns2=12560;
nt[0]=507, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
[22-MAY-2022 13:35:09:625] nscon: error exit
[22-MAY-2022 13:35:09:625] nsdo: nsctxrnk=0
[22-MAY-2022 13:35:09:625] nsdo: error exit
[22-MAY-2022 13:35:09:625] nscall: unexpected response
[22-MAY-2022 13:35:09:625] nsclose: entry
[22-MAY-2022 13:35:09:625] nstimarmed: entry
[22-MAY-2022 13:35:09:625] nstimarmed: no timer allocated
[22-MAY-2022 13:35:09:625] nstimarmed: normal exit
[22-MAY-2022 13:35:09:625] nsdo: entry
[22-MAY-2022 13:35:09:625] nsdo: cid=0, opcode=98, *bl=0, *what=0,
uflgs=0x440, cflgs=0x2
[22-MAY-2022 13:35:09:625] nsdo: rank=64, nsctxrnk=0
[22-MAY-2022 13:35:09:625] nsdo: nsctx: state=1, flg=0x4201, mvd=0
[22-MAY-2022 13:35:09:625] nsbfr: entry
[22-MAY-2022 13:35:09:625] nsbaddfl: entry
[22-MAY-2022 13:35:09:625] nsbaddfl: normal exit
[22-MAY-2022 13:35:09:625] nsbfr: normal exit
[22-MAY-2022 13:35:09:625] nsbfr: entry
[22-MAY-2022 13:35:09:625] nsbaddfl: entry
[22-MAY-2022 13:35:09:625] nsbaddfl: normal exit
[22-MAY-2022 13:35:09:625] nsbfr: normal exit
[22-MAY-2022 13:35:09:625] nsdo: nsctxrnk=0
[22-MAY-2022 13:35:09:625] nsdo: normal exit
[22-MAY-2022 13:35:09:625] nsclose: closing transport
[22-MAY-2022 13:35:09:625] nttdisc: entry
[22-MAY-2022 13:35:09:625] nttdisc: Closed socket 10
[22-MAY-2022 13:35:09:625] nttdisc: exit
[22-MAY-2022 13:35:09:625] nsclose: global context check-out (from slot 0)
complete
[22-MAY-2022 13:35:09:703] nsnadisc: entry
[22-MAY-2022 13:35:09:703] nadisc: entry
[22-MAY-2022 13:35:09:703] nacomtm: entry
[22-MAY-2022 13:35:09:703] nacompd: entry
[22-MAY-2022 13:35:09:703] nacompd: exit
[22-MAY-2022 13:35:09:703] nacompd: entry
[22-MAY-2022 13:35:09:703] nacompd: exit
[22-MAY-2022 13:35:09:703] nacomtm: exit
[22-MAY-2022 13:35:09:703] nas_dis: entry
[22-MAY-2022 13:35:09:703] nas_dis: exit
[22-MAY-2022 13:35:09:703] nau_dis: entry
[22-MAY-2022 13:35:09:703] nau_dis: exit
[22-MAY-2022 13:35:09:703] naeetrm: entry
[22-MAY-2022 13:35:09:703] naeetrm: exit
[22-MAY-2022 13:35:09:703] naectrm: entry
[22-MAY-2022 13:35:09:703] naectrm: exit
[22-MAY-2022 13:35:09:703] nagbltrm: entry
[22-MAY-2022 13:35:09:703] nau_gtm: entry
[22-MAY-2022 13:35:09:703] nau_gtm: exit
[22-MAY-2022 13:35:09:703] nagbltrm: exit
[22-MAY-2022 13:35:09:703] nadisc: exit
[22-MAY-2022 13:35:09:703] nsnadisc: normal exit
[22-MAY-2022 13:35:09:703] nsbfr: entry
[22-MAY-2022 13:35:09:703] nsbaddfl: entry
[22-MAY-2022 13:35:09:703] nsbaddfl: normal exit
[22-MAY-2022 13:35:09:703] nsbfr: normal exit
[22-MAY-2022 13:35:09:703] nsmfr: entry
[22-MAY-2022 13:35:09:703] nsmfr: 2256 bytes at 0x130508
[22-MAY-2022 13:35:09:703] nsmfr: normal exit
[22-MAY-2022 13:35:09:703] nsmfr: entry
[22-MAY-2022 13:35:09:703] nsmfr: 484 bytes at 0x1398a8
[22-MAY-2022 13:35:09:703] nsmfr: normal exit
[22-MAY-2022 13:35:09:703] nsclose: normal exit
[22-MAY-2022 13:35:09:703] nscall: connecting...
[22-MAY-2022 13:35:09:703] nsclose: entry
[22-MAY-2022 13:35:09:703] nsclose: normal exit
[22-MAY-2022 13:35:09:703] nladget: entry
[22-MAY-2022 13:35:09:734] nladget: exit
[22-MAY-2022 13:35:09:734] nsmfr: entry
[22-MAY-2022 13:35:09:734] nsmfr: 144 bytes at 0x132cf8
[22-MAY-2022 13:35:09:734] nsmfr: normal exit
[22-MAY-2022 13:35:09:734] nsmfr: entry
[22-MAY-2022 13:35:09:734] nsmfr: 156 bytes at 0x138e70
[22-MAY-2022 13:35:09:734] nsmfr: normal exit
[22-MAY-2022 13:35:09:734] nladtrm: entry
[22-MAY-2022 13:35:09:734] nladtrm: exit
[22-MAY-2022 13:35:09:734] nscall: error exit
[22-MAY-2022 13:35:09:734] nioqper:  error from nscall
[22-MAY-2022 13:35:09:734] nioqper:    ns main err code: 12537
[22-MAY-2022 13:35:09:734] nioqper:    ns (2)  err code: 12560
[22-MAY-2022 13:35:09:734] nioqper:    nt main err code: 507
[22-MAY-2022 13:35:09:734] nioqper:    nt (2)  err code: 0
[22-MAY-2022 13:35:09:734] nioqper:    nt OS   err code: 0
[22-MAY-2022 13:35:09:734] niomapnserror: entry
[22-MAY-2022 13:35:09:734] niqme: entry
[22-MAY-2022 13:35:09:734] niqme: reporting NS-12537 error as ORA-12537
[22-MAY-2022 13:35:09:734] niqme: exit
[22-MAY-2022 13:35:09:734] niomapnserror: returning error 12537
[22-MAY-2022 13:35:09:734] niomapnserror: exit
[22-MAY-2022 13:35:09:734] niotns: Couldn't connect, returning 12537
[22-MAY-2022 13:35:10:734] niotns: exit
[22-MAY-2022 13:35:10:734] nsbfrfl: entry
[22-MAY-2022 13:35:10:734] nsbrfr: entry
[22-MAY-2022 13:35:10:734] nsbrfr: nsbfs at 0x132d90, data at 0x132dc8.
[22-MAY-2022 13:35:10:734] nsbrfr: normal exit
[22-MAY-2022 13:35:10:734] nsbrfr: entry
[22-MAY-2022 13:35:10:734] nsbrfr: nsbfs at 0x1248d8, data at 0x132210.
[22-MAY-2022 13:35:10:734] nsbrfr: normal exit
[22-MAY-2022 13:35:10:734] nsbrfr: entry
[22-MAY-2022 13:35:10:734] nsbrfr: nsbfs at 0x12d820, data at 0x1319f0.
[22-MAY-2022 13:35:10:734] nsbrfr: normal exit
[22-MAY-2022 13:35:10:734] nsbfrfl: normal exit
[22-MAY-2022 13:35:10:734] nigtrm: Count in the NI global area is now 1
[22-MAY-2022 13:35:10:734] nigtrm: Count in the NL global area is now 1

ノート:

オペレーティング・システムのエラー・コードはエラー・スタックに表示されます。各オペレーティング・システムには独自のエラー・コードがあります(オペレーティング・システムのエラー・コードの詳細は、システムのドキュメントを参照してください)。

エラー・コードを評価する最も効率的な方法は、ロギングされている最新のnserrorエントリを検索することです。これは、セッション・レイヤーが接続を制御しているためです。最も重要なエラー・メッセージはファイルの最後部にあるメッセージです。これらは最新のエラーであり、接続の問題の原因を示しています。

特定のリターン・コードの情報に関しては、Oracleエラー・ツールのoerrを使用します。このためには、任意のコマンドラインで次のように入力します。
oerr tns error_number

例として、例16-14で示されているトレース・ファイル内にログ記録された、次のnserrorエントリについて考えます。

[22-MAY-2022 13:35:09:625] nserror: nsres: id=0, op=68, ns=12537, ns2=12560;
nt[0]=507, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0

前述の例では、メインTNSエラーは12537で、セカンダリ・エラーは12560です。プロトコル・アダプタ・エラーは507です。oerrを使用することによって、リターン・コード12537、12560、および507の詳細を検索できます。次の例ではユーザー入力は太字で示されています。

oerr tns 12537
12537, 00000, "TNS:connection closed"
// *Cause: "End of file" condition has been reached; partner has disconnected.
// *Action: None needed; this is an information message.

oerr tns 12560
12560, 00000, "TNS:Database communication protocol error."
// *Cause:  A lower level communication protocol adapter error occurred.
// *Action: 
//    - Check for lower level network transport errors in the error stack
//      for additional information.
//    - Ensure the protocol specification used in the address for the
//      connection is correct.
//    - For further details, turn on network tracing and rerun the
//      operation. Turn off tracing when the operation is complete.
//    - Contact Oracle Support.

oerr tns 507
00507, 00000, "Connection closed"
// *Cause: Normal "end of file" condition has been reached; partner has
//  disconnected.
// *Action: None needed; this is an information message.