Oracle Session Snapper, part 2: Getting most out of Snapper

The main design goal of Session Snapper was that it should not require any changes to be made into database.
And to achieve this goal, I was even willing to sacrifice some functionality.

So, for example there is no sorting capability in Snapper output. It would have been easy to create an SQL Type to database, use that as session statistics storage and query results out using an order by on statistics delta column – giving you (probably) most significant resource consumers first. But I didn’t do this as it would have violated the no-database-change-whatsoever design goal. (This problem could however be solved using manual sorting in PL/SQL code as done in Adrian Billington’s variation of runstats utility: http://www.oracle-developer.net/utilities.php )

The second design goal was that snapper should work with as little privileges as possible. So far it requires execute access only on DBMS_LOCK, DBMS_OUTPUT and read access on few V$ views.

However if you run the snapper using “out” option then it will use DBMS_OUTPUT.PUT_LINE for sending data back to the client. Unfortunately the client (SQLPlus in this case) calls DBMS_OUTPUT.GET_LINES to retrieve the output only when the previous database call has finished. Of course this makes sense, because otherwise some asynchronous call capability to Oracle server would be needed, which either has to interrupt the server process somehow for processing the GET_LINES, or another server process should be started for output feed.

Anyway, we don’t have such functionality in Oracle, so this means that if you run snapper in a loop, you will get the output only when the loop finishes and returns control to sqlplus. This is not good enough for having continuous real-time view of your session(s) performance.

Those who have looked into the header or sourcecode of my Session Snapper script have seen that if you use “trace” option and tail -f on that tracefile, you can get continuous real-time Snapper output to your screen (in addition to having that info saved in logfile). This functionality uses DBMS_SYSTEM.KSDWRT() procedure though. This means again that in order to get real-time output, you need to either grant execute priv on DBMS_SYSTEM to your monitoring user or run Snapper as SYS. Both those options violate the design goals of Snapper and may be unacceptable in real life production systems.

So, to combat that, I wrote a script which still gives us real-time Snapper output without need to access DBMS_SYSTEM.

The snapperloop.sql script is actually very simple. It will just run snapper in 1-iteration loop many times in row:

The code looks like this:

set feedback off
prompt
prompt -- Running Snapper 42,000 times in a row, press CTRL+C to cancel...
prompt
@snapper "&1" "&2" "&3" "&4"
@snapper "&1" "&2" "&3" "&4"
@snapper "&1" "&2" "&3" "&4"
@snapper "&1" "&2" "&3" "&4"
@snapper "&1" "&2" "&3" "&4"
@snapper "&1" "&2" "&3" "&4"
(repeat the above line for thousands of times)

...
...
...

So you can just run SnapperLoop exactly how you would run Snapper, just with 1-iteration per run (the third parameter = 1) and let SnapperLoop re-execute Snapper for you. (By the way, note how you can select SIDs dynamically based on a custom query in last parameter):

Sys@Lin11g> @snapperloop out 1 1 "select sid from v$mystat where rownum = 1"

-- Running Snapper 42,000 times in a row, press CTRL+C to cancel...

-- Session Snapper v1.03 by Tanel Poder ( http://www.tanelpoder.com )

--------------------------------------------------------------------------------------------------------------------------------------------
--        SID, SNAPSHOT START   , SECONDS  , TYPE, STATISTIC                               ,         DELTA,      D/SEC,     HDELTA,   HD/SEC
--------------------------------------------------------------------------------------------------------------------------------------------
DATA,     120, 20070826 11:53:17,         4, STAT, opened cursors cumulative               ,             1,          0,          1       .25
DATA,     120, 20070826 11:53:17,         4, STAT, recursive calls                         ,             3,          1,          3       .75
DATA,     120, 20070826 11:53:17,         4, STAT, recursive cpu usage                     ,           285,         71,        285     71.25
DATA,     120, 20070826 11:53:17,         4, STAT, CPU used by this session                ,           285,         71,        285     71.25
DATA,     120, 20070826 11:53:17,         4, STAT, session pga memory                      ,        131072,      32768,    131.07k    32.77k
DATA,     120, 20070826 11:53:17,         4, STAT, calls to get snapshot scn: kcmgss       ,             1,          0,          1       .25
DATA,     120, 20070826 11:53:17,         4, STAT, workarea executions - optimal           ,             4,          1,          4         1
DATA,     120, 20070826 11:53:17,         4, STAT, parse count (total)                     ,             1,          0,          1       .25
DATA,     120, 20070826 11:53:17,         4, STAT, execute count                           ,             1,          0,          1       .25
DATA,     120, 20070826 11:53:17,         4, STAT, sorts (memory)                          ,             2,          1,          2        .5
DATA,     120, 20070826 11:53:17,         4, STAT, sorts (rows)                            ,           610,        153,        610     152.5
DATA,     120, 20070826 11:53:17,         4, TIME, repeated bind elapsed time              ,            14,          4,       14us     3.5us
DATA,     120, 20070826 11:53:17,         4, TIME, parse time elapsed                      ,            37,          9,       37us    9.25us
DATA,     120, 20070826 11:53:17,         4, TIME, PL/SQL execution elapsed time           ,           171,         43,      171us   42.75us
DATA,     120, 20070826 11:53:17,         4, TIME, DB CPU                                  ,       3046537,     761634,      3.05s  761.63ms
DATA,     120, 20070826 11:53:17,         4, TIME, sql execute elapsed time                ,       3047255,     761814,      3.05s  761.81ms
DATA,     120, 20070826 11:53:17,         4, TIME, DB time                                 ,       3047257,     761814,      3.05s  761.81ms
DATA,     120, 20070826 11:53:17,         4, WAIT, PL/SQL lock timer                       ,       1000122,     250031,         1s  250.03ms
--  End of snap 1

-- Session Snapper v1.03 by Tanel Poder ( http://www.tanelpoder.com )

--------------------------------------------------------------------------------------------------------------------------------------------
--        SID, SNAPSHOT START   , SECONDS  , TYPE, STATISTIC                               ,         DELTA,      D/SEC,     HDELTA,   HD/SEC
--------------------------------------------------------------------------------------------------------------------------------------------
DATA,     120, 20070826 11:53:24,         3, STAT, opened cursors cumulative               ,             1,          0,          1       .33
DATA,     120, 20070826 11:53:24,         3, STAT, recursive calls                         ,             3,          1,          3         1
DATA,     120, 20070826 11:53:24,         3, STAT, recursive cpu usage                     ,           282,         94,        282        94
DATA,     120, 20070826 11:53:24,         3, STAT, CPU used by this session                ,           282,         94,        282        94
DATA,     120, 20070826 11:53:24,         3, STAT, calls to get snapshot scn: kcmgss       ,             1,          0,          1       .33
DATA,     120, 20070826 11:53:24,         3, STAT, workarea executions - optimal           ,             4,          1,          4      1.33
DATA,     120, 20070826 11:53:24,         3, STAT, parse count (total)                     ,             1,          0,          1       .33
DATA,     120, 20070826 11:53:24,         3, STAT, execute count                           ,             1,          0,          1       .33
DATA,     120, 20070826 11:53:24,         3, STAT, sorts (memory)                          ,             2,          1,          2       .67
DATA,     120, 20070826 11:53:24,         3, STAT, sorts (rows)                            ,           609,        203,        609       203
DATA,     120, 20070826 11:53:24,         3, TIME, repeated bind elapsed time              ,            12,          4,       12us       4us
DATA,     120, 20070826 11:53:24,         3, TIME, parse time elapsed                      ,            39,         13,       39us      13us
DATA,     120, 20070826 11:53:24,         3, TIME, PL/SQL execution elapsed time           ,           178,         59,      178us   59.33us
DATA,     120, 20070826 11:53:24,         3, TIME, DB CPU                                  ,       3061535,    1020512,      3.06s     1.02s
DATA,     120, 20070826 11:53:24,         3, TIME, sql execute elapsed time                ,       3064089,    1021363,      3.06s     1.02s
DATA,     120, 20070826 11:53:24,         3, TIME, DB time                                 ,       3064090,    1021363,      3.06s     1.02s
DATA,     120, 20070826 11:53:24,         3, WAIT, PL/SQL lock timer                       ,       1000295,     333432,         1s  333.43ms
--  End of snap 1

Or if you don’t want to see the headers (and the annoying tanelpoder.com banner ;) you can run:

Sys@Sol01> @snapperloop out,pagesize=0 1 1 "select sid from v$mystat where rownum = 1"

-- Running Snapper 42,000 times in a row, press CTRL+C to cancel...

DATA,     471, 20070826 12:32:30,         2, STAT, opened cursors cumulative               ,             1,          1,          1        .5
DATA,     471, 20070826 12:32:30,         2, STAT, opened cursors current                  ,             1,          1,          1        .5
DATA,     471, 20070826 12:32:30,         2, STAT, recursive calls                         ,             2,          1,          2         1
DATA,     471, 20070826 12:32:30,         2, STAT, recursive cpu usage                     ,            39,         20,         39      19.5
DATA,     471, 20070826 12:32:30,         2, STAT, CPU used by this session                ,            38,         19,         38        19
DATA,     471, 20070826 12:32:30,         2, STAT, session pga memory                      ,        131072,      65536,    131.07k    65.54k
DATA,     471, 20070826 12:32:30,         2, STAT, session pga memory max                  ,        131072,      65536,    131.07k    65.54k
DATA,     471, 20070826 12:32:30,         2, STAT, calls to get snapshot scn: kcmgss       ,             1,          1,          1        .5
DATA,     471, 20070826 12:32:30,         2, STAT, cursor authentications                  ,             1,          1,          1        .5
DATA,     471, 20070826 12:32:30,         2, STAT, workarea executions - optimal           ,             2,          1,          2         1
DATA,     471, 20070826 12:32:30,         2, STAT, parse count (total)                     ,             1,          1,          1        .5
DATA,     471, 20070826 12:32:30,         2, STAT, execute count                           ,             1,          1,          1        .5
DATA,     471, 20070826 12:32:30,         2, STAT, sorts (memory)                          ,             2,          1,          2         1
DATA,     471, 20070826 12:32:30,         2, STAT, sorts (rows)                            ,           460,        230,        460       230
DATA,     471, 20070826 12:32:30,         2, TIME, repeated bind elapsed time              ,             4,          2,        4us       2us
DATA,     471, 20070826 12:32:30,         2, TIME, parse time elapsed                      ,           678,        339,      678us     339us
DATA,     471, 20070826 12:32:30,         2, TIME, PL/SQL execution elapsed time           ,          1904,        952,      1.9ms     952us
DATA,     471, 20070826 12:32:32,         1, STAT, opened cursors cumulative               ,             1,          1,          1         1
DATA,     471, 20070826 12:32:32,         1, STAT, opened cursors current                  ,             1,          1,          1         1
DATA,     471, 20070826 12:32:32,         1, STAT, recursive calls                         ,             2,          2,          2         2
DATA,     471, 20070826 12:32:32,         1, STAT, recursive cpu usage                     ,            26,         26,         26        26
DATA,     471, 20070826 12:32:32,         1, STAT, CPU used by this session                ,            26,         26,         26        26
DATA,     471, 20070826 12:32:32,         1, STAT, session pga memory                      ,        131072,     131072,    131.07k   131.07k
DATA,     471, 20070826 12:32:32,         1, STAT, calls to get snapshot scn: kcmgss       ,             1,          1,          1         1
DATA,     471, 20070826 12:32:32,         1, STAT, workarea executions - optimal           ,             2,          2,          2         2
DATA,     471, 20070826 12:32:32,         1, STAT, parse count (total)                     ,             1,          1,          1         1
DATA,     471, 20070826 12:32:32,         1, STAT, execute count                           ,             1,          1,          1         1
DATA,     471, 20070826 12:32:32,         1, STAT, sorts (memory)                          ,             2,          2,          2         2
DATA,     471, 20070826 12:32:32,         1, STAT, sorts (rows)                            ,           465,        465,        465       465
DATA,     471, 20070826 12:32:32,         1, TIME, repeated bind elapsed time              ,             4,          4,        4us       4us
DATA,     471, 20070826 12:32:32,         1, TIME, parse time elapsed                      ,            39,         39,       39us      39us
DATA,     471, 20070826 12:32:32,         1, TIME, PL/SQL execution elapsed time           ,           148,        148,      148us     148us
DATA,     471, 20070826 12:32:32,         1, WAIT, PL/SQL lock timer                       ,        980231,     980231,   980.23ms  980.23ms
DATA,     471, 20070826 12:32:34,         1, STAT, opened cursors cumulative               ,             1,          1,          1         1
DATA,     471, 20070826 12:32:34,         1, STAT, opened cursors current                  ,             1,          1,          1         1
DATA,     471, 20070826 12:32:34,         1, STAT, recursive calls                         ,             2,          2,          2         2
DATA,     471, 20070826 12:32:34,         1, STAT, recursive cpu usage                     ,            25,         25,         25        25
DATA,     471, 20070826 12:32:34,         1, STAT, CPU used by this session                ,            25,         25,         25        25
DATA,     471, 20070826 12:32:34,         1, STAT, session pga memory                      ,        131072,     131072,    131.07k   131.07k
DATA,     471, 20070826 12:32:34,         1, STAT, calls to get snapshot scn: kcmgss       ,             1,          1,          1         1
DATA,     471, 20070826 12:32:34,         1, STAT, workarea executions - optimal           ,             2,          2,          2         2
DATA,     471, 20070826 12:32:34,         1, STAT, parse count (total)                     ,             1,          1,          1         1
DATA,     471, 20070826 12:32:34,         1, STAT, execute count                           ,             1,          1,          1         1
DATA,     471, 20070826 12:32:34,         1, STAT, sorts (memory)                          ,             2,          2,          2         2
DATA,     471, 20070826 12:32:34,         1, STAT, sorts (rows)                            ,           465,        465,        465       465
DATA,     471, 20070826 12:32:34,         1, TIME, repeated bind elapsed time              ,             4,          4,        4us       4us
DATA,     471, 20070826 12:32:34,         1, TIME, parse time elapsed                      ,            39,         39,       39us      39us
DATA,     471, 20070826 12:32:34,         1, TIME, PL/SQL execution elapsed time           ,           304,        304,      304us     304us
DATA,     471, 20070826 12:32:34,         1, WAIT, PL/SQL lock timer                       ,        983087,     983087,   983.09ms  983.09ms

You can even spool the output to a file for further analysis if you like. And thanks to formatting it should be fairly easy to post-process it.

You can download snapperloop.sql in zipped file from http://www.tanelpoder.com/files/scripts/snapperloop.zip

This entry was posted in Cool stuff, Oracle and tagged , . Bookmark the permalink.

4 Responses to Oracle Session Snapper, part 2: Getting most out of Snapper

  1. Ranko says:

    Thanks for snapper – great stuff.
    Related to another topic on your blog – how/where did you get descriptions for function calls like opiodr etc except for two Metalink notes you mentioned ( part 1, 2, 3 advanced troubleshooting ).

    Thanks, Ranko.

  2. tanelp says:

    Ranko, i’ve described some techniques in my advanced research techniques presentation: http://integrid.info/hotsos05/Advanced%20Research%20Techniques.pdf

    Basically there’s no ultimate way to find out all the function names (unless you work for oracle), you need to get bits and pieces from here and there (x$ -> v$ mapping, traces, metalink bug descriptions etc), observe and make notes :)

  3. Anil Kumar Bommareddy says:

    http://integrid.info/hotsos05/Advanced%20Research%20Techniques.pdf doesnt work.

    Where can I get the code for snapper?

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>