Here’s the latest version of my Oracle session level performance Snapper tool:

• http://blog.tanelpoder.com/files/scripts/snapper.sql

I’m going to add more stuff to Snapper in coming days, but thought to release something for testing already :)

1. There are some cosmetic changes, like printing empty lines and header lines for better readability (still controllable by the pagesize parameter, look into the scripts).
2. I’ve made some changes in the visual “graph” column just for easier readability when glancing at a snapper report:

   the @-character is used for CPU time (@ looks like a letter C a bit, doesn’t it :)
   the #-character is for all other Time model time
   thw W-character is for wait time 

3. Snapper now displays the SQL child cursor number by default in the “ASH” breakdown section 
4. The main new feature is the addition of event count columns from V$SESSION_EVENT, which allows me to calculate session-level wait event duration averages too. For example, next time you see the log file sync wait event taking lots of time, you can immediately check how much these individual waits take on average instead of having to derive it from other metrics like user commits and transaction rollbacks. In the example below I’ve identified one user session performing commits (SID 298) and also LGWRs session (492) and am snapping them at the same time.

Scroll right in the below section to see the wait time average columns (if you want narrower output, look into the script’s “configurable stuff” section to hide individual columns):

SQL> @snapper all 5 1 298,492

Sampling SID 298,492 with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v3.61 by Tanel Poder ( http://blog.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    298, SOE       , STAT, Requests to/from client                                   ,            36,        7.2,         ,             ,          ,           ,
    298, SOE       , STAT, opened cursors cumulative                                 ,           379,       75.8,         ,             ,          ,           ,
    298, SOE       , STAT, user commits                                              ,            54,       10.8,         ,             ,          ,           ,
    298, SOE       , STAT, user calls                                                ,            72,       14.4,         ,             ,          ,           ,
    298, SOE       , STAT, recursive calls                                           ,           433,       86.6,         ,             ,          ,           ,

... lots of output removed ...

    298, SOE       , STAT, execute count                                             ,           323,       64.6,         ,             ,          ,           ,
    298, SOE       , STAT, bytes sent via SQL*Net to client                          ,          2859,      571.8,         ,             ,          ,           ,
    298, SOE       , STAT, bytes received via SQL*Net from client                    ,          6972,      1.39k,         ,             ,          ,           ,
    298, SOE       , STAT, SQL*Net roundtrips to/from client                         ,            34,        6.8,         ,             ,          ,           ,
    298, SOE       , STAT, cell flash cache read hits                                ,            44,        8.8,         ,             ,          ,           ,
    298, SOE       , TIME, parse time elapsed                                        ,          1242,    248.4us,      .0%, [          ],          ,           ,
    298, SOE       , TIME, PL/SQL execution elapsed time                             ,         39365,     7.87ms,      .8%, [#         ],          ,           ,
    298, SOE       , TIME, DB CPU                                                    ,        137978,     27.6ms,     2.8%, [@         ],          ,           ,
    298, SOE       , TIME, sql execute elapsed time                                  ,        152021,     30.4ms,     3.0%, [#         ],          ,           ,
    298, SOE       , TIME, DB time                                                   ,        690485,    138.1ms,    13.8%, [##        ],          ,           ,
    298, SOE       , WAIT, latch: cache buffers chains                               ,            27,      5.4us,      .0%, [          ],         1,         .2,       27us
    298, SOE       , WAIT, log file sync                                             ,        530709,   106.14ms,    10.6%, [WW        ],        20,          4,    26.54ms
    298, SOE       , WAIT, SQL*Net message to client                                 ,            65,       13us,      .0%, [          ],        34,        6.8,     1.91us
    298, SOE       , WAIT, SQL*Net message from client                               ,        511002,    102.2ms,    10.2%, [W         ],        34,        6.8,    15.03ms
    298, SOE       , WAIT, PL/SQL lock timer                                         ,       3589765,   717.95ms,    71.8%, [WWWWWWWW  ],       227,       45.4,    15.81ms
    298, SOE       , WAIT, cell single block physical read                           ,         30350,     6.07ms,      .6%, [W         ],        47,        9.4,   645.74us
    298, SOE       , WAIT, events in waitclass Other                                 ,            50,       10us,      .0%, [          ],         1,         .2,       50us

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    492, (LGWR)    , STAT, non-idle wait time                                        ,           328,       65.6,         ,             ,          ,           ,
    492, (LGWR)    , STAT, non-idle wait count                                       ,           350,         70,         ,             ,          ,           ,
    492, (LGWR)    , STAT, in call idle wait time                                    ,           148,       29.6,         ,             ,          ,           ,
    492, (LGWR)    , STAT, messages received                                         ,           343,       68.6,         ,             ,          ,           ,
    492, (LGWR)    , STAT, background timeouts                                       ,             1,         .2,         ,             ,          ,           ,
    492, (LGWR)    , STAT, physical write total IO requests                          ,           384,       76.8,         ,             ,          ,           ,
    492, (LGWR)    , STAT, physical write total bytes                                ,       1330688,    266.14k,         ,             ,          ,           ,
    492, (LGWR)    , STAT, cell physical IO interconnect bytes                       ,       2661376,    532.28k,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo wastage                                              ,        105336,     21.07k,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo writes                                               ,           344,       68.8,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo blocks written                                       ,          2604,      520.8,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo write time                                           ,           332,       66.4,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo blocks checksummed by FG (exclusive)                 ,           200,         40,         ,             ,          ,           ,
    492, (LGWR)    , TIME, background cpu time                                       ,        117983,     23.6ms,     2.4%, [#         ],          ,           ,
    492, (LGWR)    , TIME, background elapsed time                                   ,       4282180,   856.44ms,    85.6%, [######### ],          ,           ,
    492, (LGWR)    , WAIT, rdbms ipc message                                         ,       1673152,   334.63ms,    33.5%, [WWWW      ],       261,       52.2,     6.41ms
    492, (LGWR)    , WAIT, log file parallel write                                   ,       3068565,   613.71ms,    61.4%, [WWWWWWW   ],       367,       73.4,     8.36ms
    492, (LGWR)    , WAIT, events in waitclass Other                                 ,            55,       11us,      .0%, [          ],         4,         .8,    13.75us

--  End of Stats snap 1, end=2012-12-18 20:23:18, seconds=5

---------------------------------------------------------------------------------------------
Active% | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS
---------------------------------------------------------------------------------------------
    71% |                 | 0         | log file parallel write             | System I/O
     7% |                 |           | log file sync                       | Commit
     5% | c13sma6rkr27c   | 0         | ON CPU                              | ON CPU
     2% | 0y1prvxqc2ra9   | 0         | ON CPU                              | ON CPU

--  End of ASH snap 1, end=2012-12-18 20:23:18, seconds=5, samples_taken=42

PL/SQL procedure successfully completed.

Having a quick way to check session level wait event average durations can speed up your troubleshooting – as it’s an important difference whether your session is responding slowly due to 1000 x 1 ms waits or 1 x 1000 ms wait.

Of course averages may hide some detail, but with Snapper these averages are not from system wide, but from session level sources and usually calculated over a snapshot of a few seconds, not minutes or hours.

As a next step, I plan to add more helpful averages (the usual things I currently manually calculate when needed) after the TIME model and some STAT metrics in Snapper output too. This should help to save a few seconds when troubleshooting that super-critical issue next time ;-)

So please test it out and tell me what you think!

(P.S. I have just updated my Oracle performance online seminars page with 2013 info!)

As I promised last year, I have 2 christmas gifts for you. I have already forgotten what the other one was supposed to be :), but the first one is Snapper v3.52 which has (the much requested) Oracle 9.2 support!

The syntax is the same, with Snapper you can now sample ASH-like data on Oracle 9.2 too. Instead of SQL_IDs it will display you SQL hash values:

SQL> @snapper ash,ash1=user+sql_id,ash2=sid+event 5 1 all
Sampling SID all with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v3.52 by Tanel Poder @ E2SN ( http://tech.e2sn.com )

--------------------------------------------------
Active% | SQL_HASH_VAL | EVENT
--------------------------------------------------
    19% | 867131449    | db file scattered read
    19% | 1458866975   | db file scattered read
    13% | 1267657304   | db file scattered read
     6% | 884811952    | ON CPU
     6% | 581825634    | db file scattered read
     3% | 867131449    | ON CPU
     3% | 1267657304   | ON CPU
     3% | 1866659945   | ON CPU
     3% | 1671194465   | db file scattered read
     3% | 3021169464   | ON CPU

------------------------------------------------
Active% | USERNAME             | SQL_ID
------------------------------------------------
    23% | SYSTEM               | 867131449
    19% | SYSTEM               | 1458866975
    16% | SYSTEM               | 1267657304
     6% | SYSTEM               | 581825634
     6% | SYSTEM               | 884811952
     3% | SYSTEM               | 1558333473
     3% | SYSTEM               | 1671194465
     3% | SYSTEM               | 1866659945
     3% | SYSTEM               | 1927486197
     3% | SYSTEM               | 2700565926

--------------------------------------------
Active% |    SID | EVENT
--------------------------------------------
    77% |     18 | db file scattered read
    19% |     18 | ON CPU
     3% |     18 | db file sequential read

--  End of ASH snap 1, end=2011-01-10 03:02:58, seconds=5, samples_taken=31

PL/SQL procedure successfully completed.


Other than the 9i change, the rest of the snapper is pretty much the same as earlier, with some minor bugfixes and additions.

You can download it from here.

If you want to get the most out of snapper, read this article here (and make sure you look inside the script!)

Here’s a treat for Oracle geeks, hackers and maniacs out there…

Update: As the beginning says, this article was meant as something interesting about Oracle’s internals and CTRL+C / OCICancel() handling. There’s a more practical way for canceling session calls if you are running Oracle Enterprise Edition and are currently using resource manager:

You can set the consumer group for a session to CANCEL_SQL to cancel its current call:

DBMS_RESOURCE_MANAGER.SWITCH_CONSUMER_GROUP_FOR_SESS (
session_id IN NUMBER,
session_serial IN NUMBER,
consumer_group IN VARCHAR2);

Thanks to commenter “null” for this info. Note that I haven’t tested how/whether this feature works correctly so there’s homework for you ;-)

I recently received a question about how to cancel queries running in another Oracle session, so that the session would not be killed, but would remain alive.

Well, there’s no supported way I can tell you, but thanks to how Oracle handles out-of-band breaks on Unix platforms, you can cancel database calls using an OS tool – kill.

Before we go on, here’s how query cancellation (pressing CTRL+C in sqlplus for example) works in Oracle:

1. The user presses CTRL+C or clicks some button in App which runs OCICancel()
2. The client process sends an urgent TCP packet (which is a regular TCP packet with URG bit set) to the socket in the database server it is connected to
3. The server OS TCP stack receives the urgent TCP packet and sends URGENT signal to the process which owns the socket (the Oracle server process)
4. Unix interrupts whatever the current process was doing and calls the URGENT signal handler function (which Oracle has registered during process startup)
5. The urgent signal handler blindly assumes that the urgent signal has been received because user wants to cancel the query, stops the execution and returns back with an error: ORA-01013: user requested cancel of current operation

So, if we can’t make our application send the break packet, OCICancel() then we can just send the SIGURG signal to the Oracle process just like the OS TCP stack would do when it receives the packet with urgent bit set.

Here’s an example:

In one session I’m running a DBMS_STATS call:

SQL> exec dbms_stats.gather_database_stats;

I identify the SPID of that session’s process and send an URG signal to that process:

kill -URG 4476

And the call gets cancelled in the other session:

SQL> exec dbms_stats.gather_database_stats;
<pre>BEGIN dbms_stats.gather_database_stats; END;

*
ERROR at line 1:
ORA-00604: error occurred at recursive SQL level 1
ORA-01013: user requested cancel of current operation
ORA-06512: at "SYS.DBMS_STATS", line 13336
ORA-06512: at "SYS.DBMS_STATS", line 13682
ORA-06512: at "SYS.DBMS_STATS", line 13826
ORA-06512: at "SYS.DBMS_STATS", line 13790
ORA-06512: at line 1

My session was not killed – I still can run queries in it:

SQL> select * from dual;

D
-
X

SQL>

This works only on Unix platforms. Also this does not work when your client application is Windows sqlplus! This is because Windows sqlplus does not set up the out-of-band break checking properly when connecting. Maybe this is because old Windows versions TCP stacks didn’t know anything about urgent TCP packets! :)

A word of warning – this stuff is not for your everyday production usage! While it works and we know how and why it works, it’s not a good idea to send “random” signals to Oracle processes at your will. So the better way is to make your application able to cancel its database calls when you want it, but well in real world its not always (or should I even say rarely) possible.

Another thing to consider is when you run Oracle with Direct NFS, there will be network connections to the NFS server used by your server process, in addition to the client-server communication. I haven’t tested what happens when you send URG packet to a process in the DNFS case.

So try this out at your own risk ;-)

If you want to know more about query cancelling and what the in-band and out-of-band break checking is then you can read one of my old blog posts about it:

• http://blog.tanelpoder.com/2008/02/05/oracle-hidden-costs-revealed-part-1/

I just published a new script and article about calculating the real Oracle process memory usage on Solaris.

The problem with V$PROCESS* views (and the V$SESSTAT) is that they will tell you what Oracle thinks it’s using, not the real amount of memory used. There will be discrepancies due how memory is actually allocated in OS, libraries out of Oracle’s control, the static memory areas inside Oracle binary and of course bugs.

I was working on one of such problems and decided to make my life easier by writing the script. It’s not so much about calculating the exact figures (they will never be 100% correct), but more about presenting the memory usage data in a better and more convenient fashion.

The script is called procmm and stands for Process Memory Matrix as it shows the memory usage in a matrix grid.

Here’s an example output to show what I’m talking about:

oracle@solaris02:~/research/memory$ ./procmm.sh -t `pgrep -f ora_.*SOL102`

-- procmm.sh: Process Memory Matrix v1.01 by Tanel Poder ( http://tech.e2sn.com )
-- All numbers are shown in kilobytes

Total PIDs 17, working: .................

PID            SEGMENT_TYPE      VIRTUAL          RSS         ANON       LOCKED    SWAP_RSVD
------ -------------------- ------------ ------------ ------------ ------------ ------------
0                       lib       389844       388796        13180            0        17816
0                    oracle      1629064      1628908         3336            0        42012
0            ism_shmid=0x1d      6963336      6963336            0      6963336            0
0             hc_SOL102.dat           48           48            0            0            0
0                      anon        32936        15936        15452            0        32868
0                     stack         1660         1628         1592            0         1660
0                      heap        37004        18016        16844            0        37004
------ -------------------- ------------ ------------ ------------ ------------ ------------
0                 TOTAL(kB)      9053892      9016668        50404      6963336       131360

And here’s the full article and in there a link to the script:

• http://tech.e2sn.com/oracle/performance/unix-performance-tools/process-memory-matrix

Comments are welcome here, as I haven’t set up commenting on my other site yet…

Alex Gorbachev invited me to speak at Oracle Meetup @ Sydney event in April.

I in addition to useful (and less cool) stuff I showed some useful (and very cool) stuff there too. I demoed my PerfSheet tool and also something completely new what I’ve been working on for last few months. Alex has uploaded couple of videos in to youtube, if you’re interested what I’ve been up to in last few months, check them out here:

http://www.pythian.com/news/2590/sydney-oracle-meetup-2-visualizing-oracle-performance

Hi all,

I have been extremely busy over last couple of months, that’s why there haven’t been any blog entries (no, I haven’t ran out of good ideas ;-)
I just managed to find some time on a day-time 9-hour flight from Shanghai to Finland, thus here’s a blog entry about something what I had wanted to write about for long time… I’m talking about the PerfSheet tool I wrote a year ago and have been showing at few conferences already. It has been a great time saver for me over this year when working through performance data for troubleshooting or capacity planning tasks.

If you don’t want to read further through my comments, just download PerfSheet from http://www.tanelpoder.com/files/PerfSheet.zip and see how it works yourself!

For others, let me give some history first:

[Read more...]