Oracle Session Snapper – real-time session-level performance stats for DBAs

Tanel Poder

2007-08-19

A post by Jonathan Lewis inspired me to finally complete my version of the Oracle session performance snapper script, which main characteristics are

  1. it reports Oracle session level performance counter and wait information in real time
  2. it does NOT require any database objects to be created

If you are a DBA or consultant working on ad-hoc performance issues, you will like it!

Are you familiar with following situation?

(Monday morning)

Customer: Hey, we need your help! We have serious performance issues in our production environment. It’s a database with x000 online users, several parallel data feeds, continuous batch jobs and reporting going on.

Users have started experiencing occasional bad performance and some batch jobs as well.

You: Ok, lets see it. Do you have any performance monitoring tools installed?

Customer: Yes, we have Xxxxx Xxxxxxxxx installed which shows us a nice green or red light on big screen depending whether there are any problems or not.

You: What color is it showing now?

Customer: Green

You: But you still have the performance problem you described earlier?

Customer: Yes

You: Do you have ANY performance monitoring tools installed?

Customer: Well, we also have a statspack snapshot taken every morning and evening to capture the business workload.

You: Um… Ok… you know forget about it. Can I create a small package to capture some useful performance info on the problematic sessions?

Customer: Yes, but we need to put the DDL scripts through the change review board which gathers every Thursday… but we can’t wait that long!

You: Can we enable tracing?

Customer: Enabling tracing is a change and all changes must go through review board. Also, we don’t really know which exact sessions are affected, it just happens for seemingly random ones… and we can’t just trace every session, can we?

You: Ok, give me a sqlplus window and Excel, we’ll figure something out.

…And now follows a tedious manual SQL execution and copy & paste exercise from various V$ views for getting some meaningful performance information out of Oracle.

Well, not anymore, because The Oracle Session Snapper is in town!

If you know vmstat for Unix, you know it reports you various system level statistic counter deltas over a period you choose.

Well, the Oracle Session Snapper output looks somewhat similar, but it reports you session level deltas of Oracle v$sesstat counters, wait events and starting from 10g also session time model statistics.

All info can be reported in real time, without a need for running and timing multiple SQL scripts and manual calculation of deltas.

And the key unique point of the Session Snapper is – it does not require creation of any database objects, thus no changes in the database at all! Everything is done from within a sqlplus script or anonymous PL/SQL block.

This means that you will be able to get quick session-level performance snapshots even in heavily change-controlled environments, where no object creation whatsoever is allowed without going through a long process.

You can read all the usage details from the script header, but here’s one example of its output:

Tanel@Sol01> @snapper out 1 3 475

-- Session Snapper v1.03 by Tanel Poder (  )

--------------------------------------------------------------------------------------------------------------------------------------------
--        SID, SNAPSHOT START   , SECONDS  , TYPE, STATISTIC                               ,         DELTA,      D/SEC,     HDELTA,   HD/SEC
--------------------------------------------------------------------------------------------------------------------------------------------
DATA,     475, 20070820 01:17:47,         1, STAT, session logical reads                   ,         88232,      88232,     88.23k    88.23k
DATA,     475, 20070820 01:17:47,         1, STAT, consistent gets                         ,         88233,      88233,     88.23k    88.23k
DATA,     475, 20070820 01:17:47,         1, STAT, consistent gets from cache              ,         88232,      88232,     88.23k    88.23k
DATA,     475, 20070820 01:17:47,         1, STAT, calls to get snapshot scn: kcmgss       ,           556,        556,        556       556
DATA,     475, 20070820 01:17:47,         1, STAT, no work - consistent read gets          ,         87677,      87677,     87.68k    87.68k
DATA,     475, 20070820 01:17:47,         1, STAT, table scans (short tables)              ,           139,        139,        139       139
DATA,     475, 20070820 01:17:47,         1, STAT, table scan rows gotten                  ,       7429598,    7429598,      7.43M     7.43M
DATA,     475, 20070820 01:17:47,         1, STAT, table scan blocks gotten                ,         87676,      87676,     87.68k    87.68k
DATA,     475, 20070820 01:17:47,         1, STAT, buffer is pinned count                  ,           138,        138,        138       138
--  End of snap 1
DATA,     475, 20070820 01:17:48,         1, STAT, session logical reads                   ,         87779,      87779,     87.78k    87.78k
DATA,     475, 20070820 01:17:48,         1, STAT, consistent gets                         ,         87772,      87772,     87.77k    87.77k
DATA,     475, 20070820 01:17:48,         1, STAT, consistent gets from cache              ,         87772,      87772,     87.77k    87.77k
DATA,     475, 20070820 01:17:48,         1, STAT, calls to get snapshot scn: kcmgss       ,           552,        552,        552       552
DATA,     475, 20070820 01:17:48,         1, STAT, no work - consistent read gets          ,         87210,      87210,     87.21k    87.21k
DATA,     475, 20070820 01:17:48,         1, STAT, table scans (short tables)              ,           138,        138,        138       138
DATA,     475, 20070820 01:17:48,         1, STAT, table scan rows gotten                  ,       7389897,    7389897,      7.39M     7.39M
DATA,     475, 20070820 01:17:48,         1, STAT, table scan blocks gotten                ,         87211,      87211,     87.21k    87.21k
DATA,     475, 20070820 01:17:48,         1, STAT, buffer is pinned count                  ,           136,        136,        136       136
--  End of snap 2
DATA,     475, 20070820 01:17:49,         1, STAT, session logical reads                   ,         87580,      87580,     87.58k    87.58k
DATA,     475, 20070820 01:17:49,         1, STAT, consistent gets                         ,         87587,      87587,     87.59k    87.59k
DATA,     475, 20070820 01:17:49,         1, STAT, consistent gets from cache              ,         87587,      87587,     87.59k    87.59k
DATA,     475, 20070820 01:17:49,         1, STAT, calls to get snapshot scn: kcmgss       ,           552,        552,        552       552
DATA,     475, 20070820 01:17:49,         1, STAT, no work - consistent read gets          ,         87046,      87046,     87.05k    87.05k
DATA,     475, 20070820 01:17:49,         1, STAT, table scans (short tables)              ,           138,        138,        138       138
DATA,     475, 20070820 01:17:49,         1, STAT, table scan rows gotten                  ,       7375781,    7375781,      7.38M     7.38M
DATA,     475, 20070820 01:17:49,         1, STAT, table scan blocks gotten                ,         87041,      87041,     87.04k    87.04k
DATA,     475, 20070820 01:17:49,         1, STAT, buffer is pinned count                  ,           137,        137,        137       137
--  End of snap 3

PL/SQL procedure successfully completed.

The output contains 3 x 1 second snapshot of session 475 doing heavy nested looping. Note that even though the CPU time used was not updated, the logical IO counts for that session had still increased.

So this tool can be very valuable diagnosing what’s going on when the session seems to be 100% on CPU doing something.

And yes, as I mentioned earlier, this tool can also capture wait and session time model statistics, as seen below:

Tanel@Sol01> @snapper out,gather=wt 30 1 475

-- Session Snapper v1.03 by Tanel Poder (  )

--------------------------------------------------------------------------------------------------------------------------------------------
--        SID, SNAPSHOT START   , SECONDS  , TYPE, STATISTIC                               ,         DELTA,      D/SEC,     HDELTA,   HD/SEC
--------------------------------------------------------------------------------------------------------------------------------------------
DATA,     475, 20070820 01:24:26,        30, TIME, hard parse elapsed time                 ,          1041,         35,     1.04ms    34.7us
DATA,     475, 20070820 01:24:26,        30, TIME, parse time elapsed                      ,         15383,        513,    15.38ms  512.77us
DATA,     475, 20070820 01:24:26,        30, TIME, failed parse elapsed time               ,          1614,         54,     1.61ms    53.8us
DATA,     475, 20070820 01:24:26,        30, TIME, DB CPU                                  ,       3217049,     107235,      3.22s  107.23ms
DATA,     475, 20070820 01:24:26,        30, TIME, sql execute elapsed time                ,      18862882,     628763,     18.86s  628.76ms
DATA,     475, 20070820 01:24:26,        30, TIME, DB time                                 ,      18903962,     630132,      18.9s  630.13ms
DATA,     475, 20070820 01:24:26,        30, WAIT, db file sequential read                 ,        512218,      17074,   512.22ms   17.07ms
DATA,     475, 20070820 01:24:26,        30, WAIT, db file scattered read                  ,      17562414,     585414,     17.56s  585.41ms
DATA,     475, 20070820 01:24:26,        30, WAIT, SQL*Net message to client               ,           762,         25,      762us    25.4us
DATA,     475, 20070820 01:24:26,        30, WAIT, SQL*Net message from client             ,       9549187,     318306,      9.55s  318.31ms
DATA,     475, 20070820 01:24:26,        30, WAIT, SQL*Net break/reset to client           ,          1070,         36,     1.07ms   35.67us
--  End of snap 1

PL/SQL procedure successfully completed.

The output is in CSV and is deliberately formatted the way it could be loaded into a spreadsheet or fed into text manipulation utilities should further processing be required. You should have the sqlplus window at least 140 characters wide when outputting to sqlplus client.

With “trace” option you can also output to your server process tracefile, which allows you to get convenient real-time output using tail -f on the tracefile. However you need execute rights on dbms_system for trace output as the script is using dbms_output.ksdwrt() for writing to tracefile.

The first 5 columns of output should be self-explanatory, the last four columns mean:

The script doesn’t aim to be an example of good programming style (as it started out as just a ad-hoc hack for quickly diagnosing a performance problem).

Also there are quite a few things still in TODO list, but I think this script already fills its purpose – providing quick and simple session level performance snapshots, without any changes to database whatsoever.

So, if you’re still interested, feel free to download The Session Snapper (in form of a single SQL script) from here: https://github.com/tanelpoder/tpt-oracle/blob/master/snapper.sql (Obviously you need to proofread it before using in any of your databases).

I have already used a predecessor of this tool in many places, so I hope you find the Snapper useful too. Feel free to feed me back any shortcomings or desired improvements so I could improve it further.

Update: Over time I have improved Snapper and optimized its output format. Here are the update and new features articles:


  1. I am finally close to launching the completely rebuilt 2024 versions of my Linux & AOT classes in my Learning Platform! (Updates to SQL Tuning class in H2 2024):
    Advanced Oracle SQL Tuning training. Advanced Oracle Troubleshooting training, Linux Performance & Troubleshooting training. Check them out!
  2. Get randomly timed updates by email or follow Social/RSS