Troubleshooting high CPU usage with poor-man’s stack profiler – in a one-liner!

Here’s an example of a quick’n’dirty way of profiling stack traces on your command line. This is an example from Solaris (but the script should work on Linux too plus other Unixes with minor modifications).

I created a problem case below, based on a case I once troubleshooted at a client site. Note that they had set optimizer_mode = FIRST_ROWS in their database and the optimized came up with a very inefficient execution plan for the select from DBA_LOCK_INTERNAL view below:

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

It took over 23 minutes to return 927 rows from DBA_LOCK_INTERNAL!

I ran Snapper to see where the time is spent then:

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

The query is apparently 100% on CPU with no significant waits. Normally I would expect some other metrics to pop up in snapper output in such high-CPU cases, like thousands of session logical reads per second, sorts (rows) showing millions of rows sorted per second or parse count (hard) number in hundreds or thousands per second. These are the “usual suspects”.

But this time none of these additional metrics were incremented by the session. So it’s time to systematically drill down by other means.

Now had it been an Oracle 11g+ database (with diagnostics&tuning pack licenses) then I could have just queried ASH PLAN_LINE columns or ran a SQL Monitoring report to see in which execution plan line most of the time was spent (scroll to the bottom):

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)        |
============================================================================================================================================================

From the “Activity” columns in the right end of the above output you can see that most of the time 55.00 + 37.50% of this monitored query runtime was spent in execution plan lines 51 and 52 executing the FIXED TABLE FULL rowsource operations on X$KGLLK and X$KGLPN tables (library cache locks and library cache pins). Well, querying an X$ shouldn’t usually take tens of minutes! So, that’s why you need to also look into the “Execs” column (it’s called “Starts” in extended DBMS_XPLAN output) and we see that Oracle hasn’t accessed these X$ tables once, but already 17407 times – all done within the current execution of the SQL. So this is clearly an execution plan inefficiency in this case – the parent NESTED LOOPS operation (line 40) has just called that execution plan branch (#49-#52) under it that many times – as its first child “branch” (#41, which happens to be a cartesian join) has returned 17406 rows to it. That’s how nested loops work – unfortunately this time we ended up full scanning through the memory structures behind these X$ tables during every nested loop iteration. And that takes a lot of CPU (not to mention latching or mutexes, depending on Oracle version).

So we need to adjust the execution plan (by whatever means, like by gathering stats on the X$ using dbms_stats.gather_fixed_objects_stats or not allowing optimizer_mode = first_rows for this query), so that it would not iterate through these X$s so many times in the plan (and that MERGE JOIN CARTESIAN isn’t so good idea either, although there may be exceptions).

But anyway, we could come to this conclusion because in Oracle 11g, ASH provides us row-source level detail in its samples. But my original problem happened on Oracle 10.1 or 9.2 (don’t remember exactly). I didn’t want to just kill the query and run it with statistics_level = all, I wanted to troubleshoot it right away. So, I used pstack and my os_explain script for that which I have blogged about in past. But this time, as the session wasn’t completely hung, I wanted to take multiple stack samples of the Oracle process and then aggregate the stack samples to create sort of a profile of top functions taking time. And I didn’t want to report just a single top function, I wanted to know who called that function (parent) and who were the grandparents etc.

It’s actually very easy to get a quick semi-hierarchical aggregated stack profile with just an one-liner :) See below – I’m running 100 pstack commands on the Oracle (10.2) process in a row and then aggregating the output based on the indentation of the function name in os_explain output (the italic text is added as comments by me):

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

When reading such stack profiles, you don’t have to decode what every single function name means all the way to the deepest levels. The point of stack profiling is to point out in which “branch” of Oracle function call tree most of the time was spent – and in our case we can already say that 86% of all the CPU time was spent in the kglic() function, which was called by an UNION-ALL row source, which was a few layers down from a NESTED LOOPS rowsource. So we know – by measuring – where Oracle spends all this CPU time. We can focus on figuring out what the kglic function means instead of having to figure out what all of these functions mean.

So while the stack profile doesn’t give us the info how many times a function was called, it does tell us roughly how much time was spent inside (or under) this function in the call tree and that takes us a big step closer to the root cause of this problem.

The real reason I’m writing this blog is that I want to show that basic stack profiling (or tracefile or heap dump profiling) is not too complex. When troubleshooting an urgent issue, you don’t have time for installing and trying out complex development tools and GUI profilers – processing the tracefile with a simple shell, awk or perl/python script can give you the quick’n’dirty answer. I came up with this ad-hoc profiling when troubleshooting a customer problem – it took just a minute to get the answer I wanted. Simplicity wins! Well at least it won in this case.

Note that on Linux you need to set an extra environment variable to get the sort command to behave (the output is slightly different than above as it’s taken from Oracle 11.2). Note that on Linux the pstack command is just a shell script wrapper around gdb, thus is pretty slow. You probably don’t want to examine processes just for fun on Linux production servers, but once some process starts behaving badly (and people are ready to kill it anyway) it is a decent approach for gathering evidence before pulling the trigger.

[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

So, basic stack profiling can be done just with a few shell commands chained together. It’s not fully hierarchical stack profiling like ProcMon on Windows or the Sample Process in Activity Monitor of Mac OSX, but again its just one line of code :-)

This entry was posted in Oracle. Bookmark the permalink.

12 Responses to Troubleshooting high CPU usage with poor-man’s stack profiler – in a one-liner!

  1. GregG says:

    Great post as usual, have You seen http://poormansprofiler.org ?
    Is that method slow in Your opinion ?
    Regards
    GregG

    • Tanel Poder says:

      Ha, very cool! Looks like there are also others who appreciate that sometimes you can get the basics of what you need with almost no effort :-)

      Yep it’s slow to call & exit gdb in a loop like this… takes a couple of seconds to start gdb every time (it loads libraries etc). But if the job is stuck running for minutes, hours or forever anyway, then it’s ok to wait for 2 minutes to get 100 samples. Or you can take just 10 samples, it’s enough to detect big problems anyway.

      And good points about the oprofile and dtrace’s stack/ustack actions – they work differently than pstack. The DTrace stack action just checks the current instruction pointer and stack pointer (IP,SP) of a CPU and walk the stack backwards from there. So whoever happens to be on CPU when sampling, will be reported. But not any of the other processes who are not on CPU. gdb allows you to attach to any process and sample its stack, on CPU or not.

      • Tanel Poder says:

        Note that pstack and ostackprof also sample a process regardless of whether they’re on CPU or not.

        • Tanel Poder says:

          I was just thinking of a way to keep gdb attached after taking a stack backtrace (bt). You can just keep gdb attached and the target program running with the “continue” command. But then how to break into debugger again a few milliseconds later to issue the next “bt”? Normally you would do it with CTRL+C from keyboard – so it will be possible to just send SIGINT signal to the gdb process from shell and then pipe another “bt; c” command to it.

          I continued reading the site you listed and noticed that someone had come up with a slightly different way already, with also utilizing signals. They tell gdb to stop the process every time the target process receives a SIGUSR2 signal (“handle SIGUSR2 stop nopass” command) and that breaks into the debugger command prompt, so that the debugger can issue the “bt” call. I wouldn’t use SIGUSR2 on Oracle though as it’s used for notifying the target process about an incoming Oradebug request.

  2. Yousuf says:

    Excellent info !!

    Thanks for your sharing..

    Could you please share your Apple laptop configuration details…

    Like CPU, Memory and version of Apple laptop.

    Thanks

    Yousuf

    • Tanel Poder says:

      Yousuf, this is what I have:

      - Macbook Pro 15″ – Early 2011
      - Processor 2.3 GHz Intel Core i7
      - Memory 16 GB 1333 MHz DDR3
      - HDD Crucial M4 SSD 512GB (I bought and installed it separately)
      - Graphics AMD Radeon HD 6750M 1024 MB
      - Software OS X 10.8.2

      I upgraded RAM from 8GB to 16GB just a couple of weeks ago. Mainly to be able to run 4-5 VMs simultaneously :)

  3. Wojciech says:

    Tanel, with what tool such a problem may be handled in AIX environment?

  4. Anonymus says:

    Sir,
    can you please tell me why have you used ./ in linux (even though the variable is exported) but simply os_explain in sun solaris.

  5. anonymus says:

    Sir,
    Can you please tell me why have you used ./ (even though the variable is exported)in linux but not in solaris.

  6. Jack says:

    Hi Tanel,

    I am getting the following error while running the snapper4 script. See below:

    SQL> snapper4 all 5 1 lgwr
    SP2-0734: unknown command beginning “snapper4 a…” – rest of line ignored.
    SQL> @snapper4 all 5 1 lgwr
    Sampling SID lgwr with interval 5 seconds, taking 1 snapshots…
    SP2-0552: Bind variable “NSTR” not declared.

    Thanks
    Jack

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>