Ashtop!

June 08, 2016 ❖ Tags: oracle, performance, ashtop, tanel

I live inside SQLPLUS. I do this because it’s everywhere that Oracle exists. That means that I don’t have to worry about installing some other tool. And if for some reason SQLPLUS isn’t available, I can easily install it through the instant client. Another reason why I prefer SQLPLUS over anything else is that I can copy and paste my output to share my results with anyone over email, reports, pretty much anywhere that accepts text. Show what you know.

So, once inside SQLPLUS, one of my favorite tools (besides Snapper) is Tanel Poder’s ashtop. I like it for its simplicity, but mostly for its versatility. If you have DIAGNOSTIC pack then Active Session History (ASH) data is a treasure trove of information. The best thing about it is that it takes a snapshot of all your active sessions every second. The worst thing about it is ASH consists of a snaphot of all of your sessions every second. Too much data to sieve through. That’s where ashtop comes in. It takes four inputs. Group by columns, a filter clause, and your start and end snap times.

For example if you want to see what has been happening in your database (by event) for the last five minutes (and ashtop is RAC friendly):

SQL> @ashtop inst_id,event "1=1" sysdate-5/60/24 sysdate

    Total
  Seconds     AAS %This      INST_ID EVENT                                    FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ---------- ---------------------------------------- ------------------- ------------------- -----------------
    10080    33.6   12% |          3                             2             2016-06-08 11:35:00 2016-06-08 11:39:59              5230
     9651    32.2   11% |          2                                          2016-06-08 11:35:00 2016-06-08 11:39:59              4854
     9542    31.8   11% |          1                                          2016-06-08 11:35:00 2016-06-08 11:39:59              4927
     7853    26.2    9% |          4                                          2016-06-08 11:35:00 2016-06-08 11:39:59              4842
     7191    24.0    9% |          5                                          2016-06-08 11:35:00 2016-06-08 11:39:59              4495
     2648     8.8    3% |          6                                          2016-06-08 11:35:00 2016-06-08 11:39:59              1413
     2319     7.7    3% |          5 db file sequential read                  2016-06-08 11:35:00 2016-06-08 11:39:59              1727
     2107     7.0    2% |          3 db file sequential read                  2016-06-08 11:35:00 2016-06-08 11:39:59              1948
     2066     6.9    2% |          4 db file sequential read                  2016-06-08 11:35:00 2016-06-08 11:39:59              1547
     1954     6.5    2% |          1 db file sequential read                  2016-06-08 11:35:00 2016-06-08 11:39:59              1885
     1485     5.0    2% |          2 db file sequential read                  2016-06-08 11:35:00 2016-06-08 11:39:59              1480
     1011     3.4    1% |          6 db file sequential read                  2016-06-08 11:35:00 2016-06-08 11:39:59              1009
      856     2.9    1% |          4 gc cr block busy                         2016-06-08 11:35:01 2016-06-08 11:39:59               829
      797     2.7    1% |          5 gc cr block busy                         2016-06-08 11:35:00 2016-06-08 11:39:58               778
      735     2.5    1% |          1 gcs log flush sync                       2016-06-08 11:35:01 2016-06-08 11:39:59                 1
      678     2.3    1% |          2 gc cr block busy                         2016-06-08 11:35:00 2016-06-08 11:39:59               562
      625     2.1    1% |          3 gc cr block busy                         2016-06-08 11:35:00 2016-06-08 11:39:59               532
      552     1.8    1% |          3 SQL*Net message from dblink              2016-06-08 11:35:00 2016-06-08 11:39:59               534
      542     1.8    1% |          3 gc current block 3-way                   2016-06-08 11:35:00 2016-06-08 11:39:59               529
      525     1.8    1% |          4 gc current block 3-way                   2016-06-08 11:35:00 2016-06-08 11:39:59               474

20 rows selected.

Or how about the TOP SQL?

SQL> @ashtop sql_id "SESSION_TYPE='FOREGROUND'" "to_date('2016-06-08 11:13:55','YYYY-MM-DD hh24:mi:ss')" "to_date('2016-06-08 11:18:55','YYYY-MM-DD hh24:mi:ss')"
    Total
  Seconds     AAS %This   SQL_ID        FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ------------- ------------------- ------------------- -----------------
     3879    12.9    9% | 3m2bd8b47vqdb 2016-06-08 11:13:55 2016-06-08 11:18:54              3844
     3496    11.7    9% | 15h9ky6b1asrq 2016-06-08 11:13:55 2016-06-08 11:18:54                69
     3019    10.1    7% | b6604q8a2tzwb 2016-06-08 11:13:55 2016-06-08 11:18:54               150
     2733     9.1    7% |               2016-06-08 11:13:55 2016-06-08 11:18:54                 7
     1810     6.0    4% | 6p3rp0rhu9qg7 2016-06-08 11:13:55 2016-06-08 11:18:54              1810
     1733     5.8    4% | 9y2ukuujrbsrq 2016-06-08 11:13:55 2016-06-08 11:18:54               866
     1631     5.4    4% | 1cmkstr4vuuu9 2016-06-08 11:13:55 2016-06-08 11:18:54              1630
     1216     4.1    3% | dfffkcnqfystw 2016-06-08 11:13:55 2016-06-08 11:18:45                14
     1140     3.8    3% | 9zatpamc9jwbg 2016-06-08 11:13:55 2016-06-08 11:18:54               358
      896     3.0    2% | gjh6bhnnnhbf8 2016-06-08 11:13:55 2016-06-08 11:18:54               444
      815     2.7    2% | fcb61k50dt3j4 2016-06-08 11:13:55 2016-06-08 11:18:54                 4
      739     2.5    2% | 8hm9kfpzc8nwv 2016-06-08 11:15:01 2016-06-08 11:18:18                30
      732     2.4    2% | 33tvdaj21zbty 2016-06-08 11:13:55 2016-06-08 11:18:54               700
      647     2.2    2% | d6c22h0yj78sr 2016-06-08 11:13:55 2016-06-08 11:18:54               647
      593     2.0    1% | 0xqmdw2tpbxr3 2016-06-08 11:13:55 2016-06-08 11:18:54               583
      545     1.8    1% | 8dfpzb2zcd0b1 2016-06-08 11:13:55 2016-06-08 11:18:53               544
      500     1.7    1% | backa1t0f7f1m 2016-06-08 11:14:39 2016-06-08 11:18:54               283
      451     1.5    1% | fknjzjxnn8frk 2016-06-08 11:13:55 2016-06-08 11:18:53               426
      446     1.5    1% | bvpd504brfxc8 2016-06-08 11:13:55 2016-06-08 11:18:54               409
      396     1.3    1% | bamdzcvpskcmp 2016-06-08 11:14:31 2016-06-08 11:18:53               396

20 rows selected.

You can group by anything available in V$ACTIVE_SESSION_HISTORY. Want to find out who’s blocking who? Use BLOCKING_SESSION and BLOCKING_INST_ID. Want to know where in your execution plan your time is being spent? Use SQL_PLAN_LINE_ID and SQL_PLAN_OPERATION. Want to know what called your SQL? Use TOP_LEVEL_SQL_ID.

If a question can be answered with ASH, then you can answer it faster with ashtop and it will be easier to see and share with your colleagues. One problem with ASH is that you only get a handful of hours worth of these second samples. If you need to go back further in time, then you need to use DBA_HIST_ACTIVE_SESS_HISTORY which trims the data down to 10 second samples. Still very effective for a lot of troubleshooting. In this case you need to use dashtop (also Tanel’s) but I’ve been using a modified version that I had to tune to use for a couple of the databases I’ve been on recently.

I’ll probably be showing more ashtop examples as I continue to add posts since I use it so often. Happy troubleshooting!