本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。
注意事項
- 自動翻訳に手を加えたレベルの翻訳と理解してください
- 意味をとりやすくするために追加した箇所については、《…》で囲っています。
- 訳がわからない、または、自信がない箇所は★をつけています。
日本語訳：渡部 亮太 (WR at Csus4 dot net)
履歴
- 2013-04-09: 初稿up
poor-manスタック プロファイラでCPU使用率が高い事象をトラブルシューティング – ワンライナーで！
コマンドラインでスタックトレースをプロファイリングするquick'n'dirtyな方法の一例を示します。これは、Solarisからの例です。（しかし、スクリプトに少し変更を加えれば、Linuxなどの他のUnix系のプラットフォームで動作するはずです）
クライアントのサイトで私がかつでトラブルシュートした事例をもとに、以下の問題事例を作成しました。データベースにOPTIMIZER_MODE = FIRST_ROWSを設定していて、最適化された下記のDBA_LOCK_INTERNALビューからのSELECT文に対して、非常に非効率的な実行計画作られたことに注意してください：
SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS;
Session altered.
SQL> SET TIMING ON
SQL> SELECT * FROM dba_lock_internal;
...
... the output data stripped ...
...
927 rows selected.
Elapsed: 00:23:27.14DBA_LOCK_INTERNALから927行を戻すために23分以上かかりました！
私は時間を費やしている箇所を確認するために、Snapperを実行しました：
SQL> @snapper4 all 5 1 222
Sampling SID 222 with interval 5 seconds, taking 1 snapshots...
\-- Session Snapper v4.00 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)
\---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES
\---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
222, SYS , STAT, non-idle wait count , 1, .19, , , , , ~ per execution
222, SYS , TIME, DB CPU , 6028084, 1.17s, 117.2%, [@@@@@@@@@@], , ,
222, SYS , TIME, sql execute elapsed time , 6032677, 1.17s, 117.3%, [##########], , ,
222, SYS , TIME, DB time , 6032677, 1.17s, 117.3%, [##########], , , ~ unaccounted time
222, SYS , WAIT, library cache: mutex X , 6, 1.17us, .0%, [ ], 1, .19, 6us average wait
\-- End of Stats snap 1, end=2013-02-14 21:30:45, seconds=5.1
\---------------------------------------------------------------------------------------------
Active% | SQL_ID | SQL_CHILD | EVENT | WAIT_CLASS
\---------------------------------------------------------------------------------------------
100% | c884zcqpv9y5h | 0 | ON CPU | ON CPU
\-- End of ASH snap 1, end=2013-02-14 21:30:45, seconds=5, samples_taken=50
クエリは有意な待機を伴うことなく、明らかにCPUを100％使用している。このようなCPU使用率が高い状況では、私は通常、Snapperの出力にいくつかのメトリックが現れることを予期する。非常に多くのsession logical readsや、毎秒非常に多くの行をソートするsorts (rows)や、毎秒非常に多くのparse count (hard)のように。これらは、“usual suspects”です。
しかし、今回は、これらの追加のメトリックのいずれも増分されませんでした。《増分している状況を確認できませんでした》だから、他の手段で体系的に、ドリルダウンする時がきた。
(Diagnostic & Tuning Packがある）Oracle Database 11g以降であれば、多くの時間が費やされた実行計画の行がわかるように、単純にASHの PLAN_LINE列を照会するか、SQL監視レポートを実行していたかもしれない：（下へスクロール）
SQL> @xp 222 eXplain with Profile: Running DBMS_SQLTUNE.REPORT_SQL_MONITOR for SID 222... SQL Monitoring Report SQL Text \------------------------------ SELECT * FROM dba_lock_internal Global Information \------------------------------ Status : EXECUTING Instance ID : 1 Session : SYS (222:569) SQL ID : c884zcqpv9y5h SQL Execution ID : 16777216 Execution Started : 02/14/2013 21:30:16 First Refresh Time : 02/14/2013 21:30:22 Last Refresh Time : 02/14/2013 21:30:54 Duration : 38s Module/Action : sqlplus@mac02.local (TNS V1-V3)/- Service : lin112 Program : sqlplus@mac02.local (TNS V1-V3) Global Stats \============================================== | Elapsed | Cpu | Concurrency | Other | | Time(s) | Time(s) | Waits(s) | Waits(s) | \============================================== | 42 | 42 | 0.00 | 0.06 | \============================================== SQL Plan Monitoring Details (Plan Hash Value=1240353084) \============================================================================================================================================================ | Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Mem | Activity | Activity Detail | | | | | (Estim) | | Active(s) | Active | | (Actual) | | (%) | (# samples) | \============================================================================================================================================================ | 0 | SELECT STATEMENT | | | | 33 | +6 | 1 | 421 | | | | | 1 | VIEW | DBA_LOCK_INTERNAL | 4 | | 33 | +6 | 1 | 421 | | | | | 2 | UNION-ALL | | | | 33 | +6 | 1 | 421 | | | | | 3 | NESTED LOOPS | | 1 | | 1 | +6 | 1 | 25 | | | | | 4 | NESTED LOOPS | | 1 | | 1 | +6 | 1 | 25 | | | | | 5 | FIXED TABLE FULL | X$KSUSE | 1 | | 1 | +6 | 1 | 248 | | | | | 6 | VIEW | GV$_LOCK | 1 | | 1 | +6 | 248 | 25 | | | | | 7 | UNION-ALL | | | | 1 | +6 | 248 | 6461 | | | | | 8 | FILTER | | | | 1 | +6 | 248 | 6461 | | | | | 9 | VIEW | GV$_LOCK1 | 2 | | 1 | +6 | 248 | 6461 | | | | | 10 | UNION-ALL | | | | 1 | +6 | 248 | 6461 | | | | | 11 | FIXED TABLE FULL | X$KDNSSF | 1 | | | | 248 | | | | | | 12 | FIXED TABLE FULL | X$KSQEQ | 1 | | 1 | +6 | 248 | 6461 | | | | | 13 | FIXED TABLE FULL | X$KTADM | 1 | | 1 | +0 | 248 | 0 | | 2.50 | Cpu (1) | | 14 | FIXED TABLE FULL | X$KTATRFIL | 1 | | | | 248 | | | | | | 15 | FIXED TABLE FULL | X$KTATRFSL | 1 | | | | 248 | | | | | | 16 | FIXED TABLE FULL | X$KTATL | 1 | | | | 248 | | | | | | 17 | FIXED TABLE FULL | X$KTSTUSC | 1 | | | | 248 | | | | | | 18 | FIXED TABLE FULL | X$KTSTUSS | 1 | | | | 248 | | | | | | 19 | FIXED TABLE FULL | X$KTSTUSG | 1 | | | | 248 | | | | | | 20 | FIXED TABLE FULL | X$KTCXB | 1 | | | | 248 | | | | | | 21 | FIXED TABLE FULL | X$KSQRS | 1 | | 1 | +6 | 25 | 25 | | | | | 22 | NESTED LOOPS | | 1 | | | | 1 | | | | | | 23 | NESTED LOOPS | | 1 | | | | 1 | | | | | | 24 | MERGE JOIN CARTESIAN | | 5 | | | | 1 | | | | | | 25 | NESTED LOOPS | | 1 | | | | 1 | | | | | | 26 | FIXED TABLE FULL | X$KSUPRLAT | 1 | | | | 1 | | | | | | 27 | FIXED TABLE FIXED INDEX | X$KSUPR (ind:1) | 1 | | | | | | | | | | 28 | BUFFER SORT | | 100 | | | | | | | | | | 29 | FIXED TABLE FULL | X$KSLWT | 100 | | | | | | | | | | 30 | FIXED TABLE FIXED INDEX | X$KSUSE (ind:1) | 1 | | | | | | | | | | 31 | FIXED TABLE FIXED INDEX | X$KSLED (ind:2) | 1 | | | | | | | | | | 32 | NESTED LOOPS | | 1 | | | | 1 | | | | | | 33 | NESTED LOOPS | | 1 | | | | 1 | | | | | | 34 | MERGE JOIN CARTESIAN | | 1 | | | | 1 | | | | | | 35 | FIXED TABLE FULL | X$KSUPR | 1 | | | | 1 | | | | | | 36 | BUFFER SORT | | 100 | | | | | | | | | | 37 | FIXED TABLE FULL | X$KSLWT | 100 | | | | | | | | | | 38 | FIXED TABLE FIXED INDEX | X$KSLED (ind:2) | 1 | | | | | | | | | | 39 | FIXED TABLE FIXED INDEX | X$KSUSE (ind:1) | 1 | | | | | | | | | | -> 40 | NESTED LOOPS | | 1 | | 37 | +6 | 1 | 396 | | | | | -> 41 | MERGE JOIN CARTESIAN | | 1 | | 37 | +6 | 1 | 17406 | | | | | 42 | NESTED LOOPS | | 1 | | 35 | +6 | 1 | 15 | | | | | 43 | NESTED LOOPS | | 1 | | 35 | +6 | 1 | 15 | | | | | -> 44 | FIXED TABLE FULL | X$KSUSE | 1 | | 37 | +6 | 1 | 15 | | | | | -> 45 | FIXED TABLE FIXED INDEX | X$KSLWT (ind:1) | 1 | | 37 | +6 | 15 | 15 | | | | | -> 46 | FIXED TABLE FIXED INDEX | X$KSLED (ind:2) | 1 | | 37 | +6 | 15 | 15 | | | | | -> 47 | BUFFER SORT | | 100 | | 37 | +6 | 15 | 17406 | 243K | | | | 48 | FIXED TABLE FULL | X$KGLOB | 100 | | 1 | +6 | 1 | 1208 | | | | | -> 49 | VIEW | DBA_KGLLOCK | 2 | | 41 | +2 | 17407 | 396 | | 2.50 | Cpu (1) | | -> 50 | UNION-ALL | | | | 37 | +6 | 17407 | 15M | | 2.50 | Cpu (1) | | -> 51 | FIXED TABLE FULL | X$KGLLK | 100 | | 42 | +1 | 17407 | 15M | | 37.50 | Cpu (15) | | -> 52 | FIXED TABLE FULL | X$KGLPN | 100 | | 40 | +3 | 17407 | 116K | | 55.00 | Cpu (22) | ============================================================================================================================================================
上記の出力の右端にある"Activity"列から、この監視対象のクエリの実行時間のほとんどを占める 55.00+37.50パーセントが、X$KGLLKとX$KGLPNテーブル（ライブラリ?キャッシュ?ロックやライブラリ?キャッシュ?ピン）へのFIXED TABLE FULL 行ソース オペレーションを実行する実行計画の行、51,52に費やされていることがわかります。まあ、X$を照会するのに、通常数十分を要してはいけません！これがあなたが "Execs"列（それは拡張DBMS_XPLAN出力の "Starts"と呼ばれています）を検討する必要がある理由です。Oracleは一度だけこれらのX$表にアクセスしたのではなく、すでに17407回アクセスしていることがわかります。- すべてはSQLの現在の実行において行われています。だから、これは明らかに、この場合の実行計画の効率の悪さです – 親ネステッド?ループ操作（行40）はちょうど（＃49 – ＃52）、その実行計画ブランチと呼ばれたその下にその何倍 – その最初の子 "ブランチ"として（#41、直積結合が発生している）、それ《親ネステッドルーム結合》に17406行を返しました。★これがネステッドループの動作である。 – 残念なことに、このとき、ネストテッドループの繰り返しのたびに、これらのX$表の後ろのメモリ構造をフルスキャンするはめになった。そして、それは多くのCPUを使用します。（いうまでもなく、Oracleのバージョンに依存して、ラッチもしくはMutexです）。
だから、（dbms_stats.gather_fixed_objects_statsをつかってX$に関する統計情報を収集することや、このクエリの場合optimizer_mode = first_rowsを許可しないなど、どんな手段でもよいが）、これらのX$表を何度もイテレートしないように、実行計画を調整する必要がある。（例外があるかもしれないが、MERGE JOIN CARTESIANは、良いアイデアではありません）
Oracle 11gのASHは、そのサンプルデータにおいて、行ソース?レベルの詳細を提供していますので、やはり、私たちはこの結論に達する可能性があります。しかし、オリジナルである私の問題は、Oracle 10.1または9.2（正確に覚えていない）で起こりました。私は単にクエリをkillして、statistics_level = allを指定して再実行するようなことはしたくなかった。私はすぐにそれを解決したいと考えました。だから、私は、pstackと、私《＝Tanel Poderさん》が昔ブログで書いたos_explainスクリプトを使った。しかし、このとき、セッションが完全にハングアップしていなかったので、私は、Oracleプロセスの複数のスタックのサンプルを取って、スタックのサンプルを集約し、時間がかかっている上位ファンクションのプロファイルのようなものを作成したいと思った。そして、私はちょうど１つの最上位の関数をレポートするのではなく、誰がその関数を読んでいるのか（親）、祖父母が誰なのか《どの関数なのか》を知りたいと思った
ワンライナーだけで 
迅速い半階層集約されたスタック?プロファイルを取得することは、実際には非常に簡単です。下記を参照してください – Oracle（10.2）プロセスにたいして100回pstackのコマンドを実行し、os_explainで出力される関数名のインデントに基づき、出力を集約しています。（イタリック体のテキストは私が追加したコメントです）：
solaris01$ for i in {1..100} ; do pstack 6430 | os_explain -a ; done | sort -r | uniq -c
100 ????????
100 main <<-- 100 samples out of 100 taken (100%) had main() as a grandparent function
100 opimai_real
100 sou2o
100 opidrv
100 opiodr
100 opiino
100 opitsk
100 ttcpip
100 opiodr
100 opifch
100 SELECT FETCH:
100 VIEW: Fetch
100 * NESTED LOOP JOIN: Fetch
100 UNION-ALL: Fetch
100 VIEW: Fetch
100 * FIXED TABLE: Fetch
100 UNION-ALL: Fetch <<-- 100% of execution during sampling was under this UNION-ALL in the plan
86 kqlftp <<-- under the parent UNION-ALL, 86% was spent in kqlftp function (kqlf functions are used for reading X$ tables)
9 kqlftl
3 UNION-ALL: RowProcedure
1 FIXED TABLE: GCol
86 kglic <<-- one level deeper 86% of total time was spent in kglic function, which is used for library cache scanning
8 kglLockIterator
1 kglFreeFreeList
1 VIEW: RowProcedure
1 memcpy
1 ksfflt
1 kqlfnn
3 kqlfgl
85 kglic0
1 kghfrf
1 kghalf
1 expeal
7 ksfglt
23 ksfflt
3 kqlfnn
5 kgligp
1 evaiand
18 yield
3 sskgslgf
4 kslgetl
4 kslfre
このようなスタック?プロファイルを読み込むときは、関数名の意味を深い階層までずっとデコードする必要はありません。スタックプロファイリングのポイントは、多くの時間が費やされたOracleの関数コールツリーの"ブランチ"を特定することです。 – 私たちのケースでは、我々はすでに、kglic()関数において、すべてのCPU時間の86％が費やされたと言えます。これは、UNION-ALLから呼び出され、NESTED LOOPS行ソースから数段階降りたものです。だから我々は、OracleがこのすべてのCPU時間を費やしている場所を知っている。 – 測定することによって – これらすべての関数が何を意味するかを理解するかわりに、我々はkglic関数が何を意味するかに集中できます。
スタック プロファイルは関数が呼び出された回数についての情報を与えるものではありませんが、コールツリーにおけるこの関数の中（ま?たは配下）で費やされた大体の時間を教えてくれます。そして、私たちをこの問題の根本的な原因にぐっと近づけてくれます。
私はこのブログを書いている本当の理由は、私はその基本的なスタックプロファイル（や、トレースファイルまたはヒープダンププロファイリング ）はあまりにも複雑ではないことを示したかったためです。緊急の問題をトラブルシューティングするときは、複雑な開発ツールとGUIプロファイラをインストールして試してみるための時間はありません – 簡単なシェルやawkやPerl / Pythonのスクリプトでトレース?ファイルを処理することがquick'n'dirtyな答えを与えてくれます。顧客の問題をトラブルシューティングするときに私は、このアドホックプロファイリングを思い付きました – 私が望んでいた答えを得るためにわずか数分かかりました。シンプルさが勝ちます！まあ、少なくとも、このケースで勝ちました。
Linuxでは、sortコマンドを同様に動作させるために追加の環境変数を設定する必要があることに注意してください。（それがOracleの11.2から取られているとして、出力は上記と若干異なります）Linuxでは、pstackコマンドはgdb の単なるシェルスクリプトのラッパーであることに注意してください、したがって、かなり遅いです。Linuxの本番サーバ上で楽しむためだけにプロセスを検査したくはないでしょうが、一度いくつかのプロセスの動作がおかしくなり、 （そして、プロセスをkillする準備ができていて、）引き金を引く前に証拠を収集するための適切なアプローチです。
[root@oel6 tmp]# export LC_ALL=C ; for i in {1..100} ; do pstack 17163 | ./os_explain -a ; done | sort -r | uniq -c
100 main
100 ssthrdmain
100 opimai_real
100 sou2o
100 opidrv
100 opiodr
100 opiino
100 opitsk
100 ttcpip
100 opiodr
100 opifch
100 SELECT FETCH:
100 VIEW: Fetch
100 * NESTED LOOP JOIN: Fetch
100 UNION-ALL: Fetch
100 NESTED LOOP JOIN: Fetch
100 SORT: Fetch
100 NESTED LOOP JOIN: RowProc
100 VIEW: Fetch
100 * FIXED TABLE: Fetch
100 UNION-ALL: Fetch
45 kqlftp
53 kqlftl
1 UNION-ALL: RowProcedure
98 kglic0
1 VIEW: RowProcedure
17 kglic_cbk
10 kglReleaseHandleReference
10 kglReleaseBucketMutex
1 kglGetSessionUOL
29 kglGetHandleReference
4 kglGetBucketMutex
1 expeal
1 kqlpgCallback
5 kgligp
7 kgligl
13 kglReleaseMutex
3 kglGetSessionUOL
16 kglGetMutex
1 evaiand
2 kqlfgl
8 kgxRelease
8 kgxExclusive
3 kglMutexNotHeld
1 kglMutexHeld
1 kglIsMutexHeld
1 expepr
1 ??
1 P2D3
だから、基本的なスタックプロファイリングは、つなげられた２，３のシェルコマンドだけで行うことができます。Windowsのprocmon やMac OSXのアクティビティモニタのサンプル?プロセスのような完全な階層スタックプロファイルではありません。しかし、たった1行のコードなのです