poor-manスタック プロファイラでCPU使用率が高い事象をトラブルシューティング – ワンライナーで!


http://blog.tanelpoder.com/2013/02/14/troubleshooting-high-cpu-usage-with-poor-mans-stack-profiler-in-a-one-liner/
の翻訳です。

本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。

注意事項


  • 自動翻訳に手を加えたレベルの翻訳と理解してください
  • 意味をとりやすくするために追加した箇所については、《…》で囲っています。
  • 訳がわからない、または、自信がない箇所は★をつけています。


日本語訳:渡部 亮太 (WR at Csus4 dot net)

履歴


  • 2013-04-09: 初稿up


poor-manスタック プロファイラでCPU使用率が高い事象をトラブルシューティング – ワンライナーで!

2013年2月14日 by

コマンドラインでスタックトレースをプロファイリングする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.14

DBA_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プロセスの複数のスタックのサンプルを取って、スタックのサンプルを集約し、時間がかかっている上位ファンクションのプロファイルのようなものを作成したいと思った。そして、私はちょうど1つの最上位の関数をレポートするのではなく、誰がその関数を読んでいるのか(親)、祖父母が誰なのか《どの関数なのか》を知りたいと思った

ワンライナーだけで :) 迅速い半階層集約されたスタック?プロファイルを取得することは、実際には非常に簡単です。下記を参照してください – 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

だから、基本的なスタックプロファイリングは、つなげられた2,3のシェルコマンドだけで行うことができます。Windowsのprocmon やMac OSXのアクティビティモニタのサンプル?プロセスのような完全な階層スタックプロファイルではありません。しかし、たった1行のコードなのです :-)