Here’s the latest version of my Oracle session level performance Snapper tool:
I’m going to add more stuff to Snapper in coming days, but thought to release something for testing already :)
-
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).
-
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
-
Snapper now displays the SQL child cursor number by default in the “ASH” breakdown section
-
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,492Sampling SID 298,492 with interval 5 seconds, taking 1 snapshots…
– Session Snapper v3.61 by Tanel Poder ( )
SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS, WAITS/SEC, <span style="color: #ff0000;"><strong>AVERAGES</strong></span>
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, 27us298, SOE , WAIT, log file sync , 530709, 106.14ms, 10.6%, [WW ], 20, 4, 26.54ms 298, SOE , WAIT, SQLNet message to client , 65, 13us, .0%, [ ], 34, 6.8, 1.91us 298, SOE , WAIT, SQLNet 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.41ms492, (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!)
