Advanced Oracle Troubleshooting Guide, Part 3: プロセス?スタックをさらに冒険する
http://blog.tanelpoder.com/2007/09/06/advanced-oracle-troubleshooting-guide-part-3-more-adventures-in-process-stack/の翻訳です。
本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。
注意事項
- 自動翻訳に手を加えたレベルの翻訳と理解してください
- 意味をとりやすくするために追加した箇所については、《…》で囲っています。
- 訳がわからない、または、自信がない箇所は★をつけています。
日本語訳:渡部 亮太 (WR at Csus4 dot net)
履歴
Advanced Oracle Troubleshooting Guide, Part 3: プロセス?スタックをさらに冒険する
2007年9月6日 by Tanel Poder
…というか、むしろスレッドスタック《と呼ぶべきだろうか》、最近はまともなオペレーティングシステムではスレッド(Linuxカーネルではタスクと呼ばれる)を実行する。
とにかく、スタックトレースは究極的な真実を与えます。プログラムが正確に今、何をしているかについて。スタックの破損や不足しているシンボル情報のようなものがあると、トレースはあまり有用なものになりません。しかし、ハングやパフォーマンスの詳細なトラブルシューティングには、スタックトレースは貴重です。
だから、私はもう1つのケーススタディを紹介します。 – データベースにログオンできない場合に、ハングアップしたデータベースを完全に診断する方法です。
私はいくつかの性能診断作業を行っていた。一部のスタックトレース内のいくつかのポイントが共有プールを指している場所★を探していました。X$KSMSPは、どのタイプのチャンクにどのアドレスが与えられているか、そのチャンクの親ヒープはどれか、を特定するための場所です。
しかし、大規模な共有プールで負荷の高いシステムでは、X$KSMSPをSELECTするに非常に注意する必要があると、Hotsosシンポジウムで 1年か2年前、私はジョナサン?ルイスが言及していたことを覚えていた。
その理由は、その中のすべての共有プールチャンクを報告するため、X$KSMSPは共有プール?ラッチを取得してから、共有プール?ヒープのスキャンを開始するということです。
- これは、共有プール?ラッチが非常に長い時間取得されることを意味します。(共有プールが大きくなればなるほど、共有プールにあるチャンクより多くなります)
- これは、結局、ラッチが取得されている間、これらのプールから任意のチャンクを割り当てるか、割り当てを解除することはできないことを意味します
- これは、結局★、(その処理は、セッションパラメータの値に関して、共有プール内の領域を割り当てるので)データベースにログオンすることができなくなること、(その処理はカーソルと実行計画のために、共有プールの領域を割り当てる必要があるので)次の文を解析し、ハードすることができないこと、(いくつかのケースでは共有プール?ラッチを使用するので)ソフト解析を実行することさえもできなくなることを意味します。
共有プールのサイズは、過去のあるメモリリークの問題が原因で、5ギガバイトに設定されていた。
単にX$表の全体にselect * from X$ksmspを実行しないことを決めた。代わりにSELECT * FROM x$ksmsp WHERE ROWNUM <= 10 を実行した。
一度に数行をフェッチするこのアプローチが機能するかどうかを見るために。もちろん、最初はテスト環境で実行した…そしてそれは完全にハングアップしてしまった。Oh man.
よって、何が起こっているか見るために別のSQLPLUSセッションを開始した – そしてそれもハングしまった。これまでのことで、それが、この厳しい《killer》X$KSMSPクエリであることが、私の中でかなり明確になった。そのクエリは、私の "ROWNUM <= 10"トリックを気にしないし、おそらく共有プール全体をsweepし続ける。 – すべての時間、共有プール?ラッチを保持して。
私はOracleにログオンすることができなかったので、次やるべきことは、OSのレベルから私のプロセスが実行していることを確認することです。それに伴う問題は、私のセッションのプロセスIDが何であるか知らなかったことです。セッションでログオンしていた時間を正確に知りませんでした。自分のワークステーションのIP《アドレス》からのTCP接続に対応するSPIDがどれであるかを特定できるlsofを使用するため《に必要な》/dev/kmemのへのアクセス権を持っていませんでした。
テスト環境であるにも関わらず、他の様々な処理やバッチジョブで使用頻度の高いビジーなシステムだったことに注意してください。だから私は、OSレベルでそれをkillする前に、私のプロセスがどのプロセスであるかを本当に確認する必要がありました。
私は、psコマンドとprstatから始めました:
$ prstat 1
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
24331 xxx_user 8312M 8254M cpu515 10 0 1:22.44 4.1% oracle/1
26136 oracle 8347M 8285M cpu528 10 0 0:10.25 4.1% oracle/1
23949 xxx_user 8306M 8248M cpu520 0 0 1:23.21 4.1% oracle/1
21853 oracle 20G 59M sleep 58 0 0:00.00 2.2% oracle/21
21849 oracle 20G 59M cpu16 31 0 0:19.52 2.2% oracle/21
21860 oracle 20G 58M cpu512 32 0 0:23.32 2.0% oracle/19
24681 oracle 20G 35M cpu531 42 0 8:06.28 0.9% oracle/15
26516 oracle 20G 13M sleep 58 0 11:34.29 0.0% oracle/1
27522 oracle 20G 11M sleep 58 0 0:57.33 0.0% oracle/152
13742 oracle 2064K 1800K cpu19 56 0 0:00.00 0.0% prstat/1
27526 oracle 20G 11M sleep 58 0 0:58.45 0.0% oracle/149
27528 oracle 20G 11M sleep 58 0 0:57.07 0.0% oracle/148
27520 oracle 20G 11M sleep 58 0 0:57.28 0.0% oracle/157
27524 oracle 20G 11M sleep 58 0 0:58.18 0.0% oracle/166
CPU使用率とプロセス所有者の名前は、それがトラブルメーカーであるかもしれないいくつかのヒントを与えた、にもかかわらず、私がどんなアクションをとる前にその証拠を得たい。そして、pstackはそのために非常に有用だった(このハングのため、別のセッションでログオンすることができなかったことに注意してほしい!)。
それで、主たる疑わしいプロセス26136においてpstackを実行した。(24CPUのサーバー上で)CPUを100%使用し、リモート《接続》のOracleプロセスであったので、私はこのプロセスを選んだ。他の上位2のプロセスは、ユーザ名が違っており、bequeathを使用して、ローカルユーザーによって生成されていた。
$ pstack 26136
26136: oracleDBNAME01 (LOCAL=NO)
000000010301f6c0 kghsrch (105068700, 0, ffffffff7bc77a68, 118, ffffffff7bc77ad8, 0) + 20
0000000103021f20 kghprmalo (7fffffff, 0, ffffffff7bc77a68, 0, ffffffff77130b90, 140) + 460
0000000103024804 kghalp (ffffffff7fffa898, ffffffff7bc77a68, 58, 7ffffffc, fffffffffffffffc, 104b86ce8) + 884
0000000100bb78a4 ksmspc (0, 38004d988, ffffffff7bc7ad80, 54e50a7d0, 458, 104e22180) + 44
000000010303564c kghscn (104e22180, 38004d988, 1000000000000000, 7ffffff8, 105068700, 54e50a7d0) + 68c
0000000103034750 kghnwscn (0, ffffffff7bc7ad80, 100bb7860, 1858, 2fa0, 105068700) + 270
0000000100bb7a44 ksmshp (100bb7, 1, 380000030, ffffffff7bc77a68, 100bb7860, ffffffff7bc7ad80) + 64
00000001024e67a8 qerfxFetch (10449c000, 0, 10506ae10, ffffffff7bc7ad40, 5651c5518, 1043ae680) + 328
00000001024e7edc qercoFetch (541d07900, 10449dba0, 4e, 1, ffffffff7bc7ad98, 1024e6480) + fc
0000000101aa6f24 opifch2 (2, 5, 60, 1, 104400, 1050685e8) + a64
0000000101a4c694 kpoal8 (0, 1, ffffffff7fffdc70, 0, 10434c0a8, 1) + c34
00000001002d0058 opiodr (14, 10506ae10, 10434ce70, 10506a, 105000, 104000) + 598
0000000102cded94 ttcpip (105071450, 18, ffffffff7fffdc70, ffffffff7fffcf68, 104229c98, ffffffff7fffcf64) + 694
00000001002cd3e8 opitsk (1002cf000, 1, 0, ffffffff7fffddc8, 105071450, 105071458) + 428
0000000101aaf564 opiino (105070000, 105000, 57a321e48, 105000, dc, 105070290) + 404
00000001002d0058 opiodr (4, 10506ae10, 10434c920, 10000, 105071, 105000) + 598
00000001002cc174 opidrv (0, 4, 10506a, 105071450, 0, 3c) + 354
00000001002c9828 sou2o (ffffffff7fffea98, 3c, 4, ffffffff7fffea78, 104aa6000, 104aa6) + 48
00000001002a7b34 main (2, ffffffff7fffeb78, ffffffff7fffeb90, 0, 0, 100000000) + 94
00000001002a7a7c _start (0, 0, 0, 0, 0, 0) + 17c
それで、下から太字のセクションを読みます。(そして、前述したメタリンクノート175982.1を使用します)
- opifch2:これは実行されるFETCH呼び出しです
- qercoFetch:実行計画において行ソースをCOUNTする
- qerfxFetchは:固定表の行ソースです(すなわちX$表へのアクセス)
- ksmshp:X$KSMSPがアクセスされたときに、背後で呼び出される関数に見える
- kghscn:Kernel Generic Heap SCaN カーネルの汎用ヒープスキャンのように考えられる

よって、このスタックトレースは、X$表から取得し(qerfxFetch)、これが結果として最終的には、ヒープ?スキャナのように考えられる操作(kghscn)となったコードを、プロセスが実行していたことを証明する。これは、まさにX$KSMSPが行っていることです。それは全体の共有プール?ヒープをスキャンして、そこにあるすべてのメモリチャンクにたいする1行のデータを返します。
私のクエリにCOUNT(*)がないにもかかわらず、なぜ、qercoFetch関数が含まれていたのか?説明は以下の通りです:
SQL> select * from x$ksmsp where rownum <=1;
ADDR INDX INST_ID KSMCHIDX KSMCHDUR KSMCHCOM
\-------- ---------- ---------- ---------- ---------- ---------------
04AA0A00 0 1 1 1 free memory
SQL> @x
PLAN_TABLE_OUTPUT
\--------------------------------------------------------------------
\--------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
\--------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | |
|* 1 | COUNT STOPKEY | | | | |
| 2 | FIXED TABLE FULL | X$KSMSP | | | |
\--------------------------------------------------------------------
Predicate Information (identified by operation id):
\---------------------------------------------------
1 - filter(ROWNUM<=1)
qercoFetchの行ソース関数は、私のクエリの一部「ROWNUM <= 10」を施行する必要があるものだった。10行を受け取った後、qerfxFetch関数の呼び出しを停止していたはずですが、何らかの理由で処理が継続された。もしくは、その結果セットの一部だけを伴って、呼び出している関数に制御を返せるほどqerfxFetch関数は十分に洗練されていなかったことが理由かもしれない。
qercoFetchがハーフウェイを通じてフェッチを停止するかどうかを判断するために★。(多くの行ソースは、スタックにおいてカスケード接続するやり方で、データを返すような柔軟性があります。例えば、ネステッド?ループ(qerjoFetch、qerjotFetch)はカスケード接続しています。ハッシュ結合は、結合ビルドパーティションはメモリ中で組み立てる(qerhjFetch)瞬間からカスケード接続しています。マージソート結合は、ハイレベルな視点からカスケード接続されていません。結合される両方の行ソースは、返される前にソートされる必要があるためです。
しかし、両方の行ソースが(メモリまたはTEMP表領域のいずれかにおいて)ソートされているとき、再びカスケード接続するやり方で一致した行戻すことができます。これは、呼び出し元の関数は、唯一のX行をフェッチして処理を行ってから、次のx行を取得できることを意味する。このXは ARRAYSIZE – 一度にオラクルからフェッチする行の量 – に通常依存している。とにかく、私は次のポストのため、この興味深いトピックを残します 😉
ハング診断を続けます。
prstatおよびpstackを使用して、トラブルメーカーのX$KSMSPスキャナプロセスを特定した後、サーバプロセスの開始時間に対するSQLPLUS.EXEのタイムスタンプもチェックしたことを思い出した(もちろん、タイムゾーンの違いおよびクロックのドリフトを考慮して)。CPU上にあろうとしているか《CPUを使用しようとしているか》、sleep しているすべてのプロセスがあるときに便利です。 – すべてのプロセスに対してpstack《を実行すること》が好きでない限り
SQLPLUS.EXEの開始時間に近いログオン時間を持つようなプロセスを特定し、それに対してpstackを取得した:
$ pstack 4848
4848: oracleDBNAME01 (LOCAL=NO)
ffffffff7c9a5288 semsys (2, 6d0a000a, ffffffff7fffa79c, 1, 10)
0000000102f782c8 sskgpwwait (ffffffff7fffab48, 10501dba8, 0, 200, ffffffffffffffff, 2b) + 168
0000000100af4b74 kslges (31c, 0, 57f338090, 0, 876, 578802b68) + 4f4
0000000102d70ea0 kglhdgn (3000, ffffffff7fffb3d0, 12, 0, 0, 380003910) + 180
0000000102d58974 kglget (105068700, ffffffff7fffb360, fc, 1000, 0, 1) + b94
000000010128f454 kkttrex (8, 1050683c0, 10506ae08, 105000, 10506a000, 9) + 4b4
000000010128e6c8 kktexeevt0 (31a8, 57a3ae0a0, 105068f74, 2, 4, 10506ae08) + 3a8
0000000101a77b60 kpolon (51, 51, 40002d91, 105071450, 80000, ffffffff7fffdc70) + c0
00000001002d0058 opiodr (1a, 10506ae10, 10434cc68, 10506a, 105000, 105000) + 598
0000000102cded94 ttcpip (105071450, 20, ffffffff7fffdc70, ffffffff7fffcf68, 104228a98, ffffffff7fffcf64) + 694
00000001002cd3e8 opitsk (1002cf000, 1, 0, ffffffff7fffddc8, 105071450, 105071458) + 428
0000000101aaf564 opiino (105070000, 105000, 57f337fd8, 105000, e3, 105070290) + 404
00000001002d0058 opiodr (4, 10506ae10, 10434c920, 10000, 105071, 105000) + 598
00000001002cc174 opidrv (0, 4, 10506a, 105071450, 0, 3c) + 354
00000001002c9828 sou2o (ffffffff7fffea98, 3c, 4, ffffffff7fffea78, 104aa6000, 104aa6) + 48
00000001002a7b34 main (2, ffffffff7fffeb78, ffffffff7fffeb90, 0, 0, 100000000) + 94
00000001002a7a7c _start (0, 0, 0, 0, 0, 0) + 17c
最初のセッションがハングアップしてしまった後に起動しようとした、他のセッションだったように見えます。
上から今回のスタックのハイライト表示のセクションを読んでみましょう。
- semsys は、0を超えて増加するようにセマフォカウント(値)を待機することができる、Solarisのシステムコールである。つまり、このシステムコールは、誰かがセマフォを介してそれをポストするまで、あるスレッドをスリープ状態にできます。
- sskgpwwaitは、Oracleプロセスがイベントを待機することを可能にするOracleオペレーティング?システム依存(OSD)レイヤの関数である。
- kslgesは(スリープタイムアウト機能付き)ラッチ獲得関数である。
- kglhdgnは新しいライブラリ?キャッシュ?オブジェクト(ハンドル)を作成するためのコールである。
- kglgetは、ライブラリ?キャッシュ?オブジェクトを配置するためのルックアップコールである。(それが《オブジェクトを》見つけられない場合は、ライブラリ?キャッシュ?ミスがインクリメントされ、字上記のkglhdgn()が呼び出される)
- kktのコールは内部トリガーをfireすることに関連している(ログオントリガと監査、他に?)
- kpolonは、私の知る限り、セッションのセットアップとログオンに関連している
よて、このスタックは、ログオン中の内部トリガのために(このデータベースは、セッションの監査を使用していた《by the way》)共有プール内のライブラリ?キャッシュ?オブジェクトを作成しようとしているときに、このプロセスがstuckしていたことをを示している。(私は完全に正しくない可能性があります)
とにかく、元のセッション(X$KSMSPを通じてスキャンしていたセッション)をkillしたとき、データベースが再び正常に動いた。
(私の愚かな過ちにより 😉 Oracleのインストルメンテーション《診断機能》が使用できなかった場合において、スタックトレースの利点が今一度示された。このことは、あなたが正常に動作すべきだと思う場合でも、テスト環境ですべてを徹底的にテストする必要があることをもう一度示している。