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,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!)
Thanks Tanel, snapper saved my a… life many times :).
Regards
GregG
Unless its $50,000 per core, how can it be any good ?
:-)
Good point, I’ll get this changed ;)
Tanel, thank you very much for that awesome tool!
Thanks Tanel. Why there is no option for online Advaned Exadata Performance class?
At the moment I only plan to do a couple of on-site seminars at Enkitec offices.
Note that I had incorrect links for registering to (and for more info about) the advanced Exadata classes, I’ve fixed them now on the seminar page.
What an awesome script..and there is no day in my DBA life without using that script…
Even after having valid sessions for the user=xxxx, the snapper is failing with no data found
@snapper all 5 1 user=xxxx
Sampling SID user=maharajt 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
—————————————————————————————————————————————————————————
declare
*
ERROR at line 1:
ORA-01403: no data found
ORA-06512: at line 1571
Thanks Satya for letting me know – bug fixed, so just re-download the script (now it’s version 3.62)
Gr8 turnaround. Newer version works like a charm.
Tanel,
Good work and better representation with one single downgrade (in my humble opinion).
I would still rather to see the HDELTA column with K/M/G representations or dotted representation at least because when you are looking at big numbers they really helped in previous version
Thanks again
Um, scroll right, man :)
Silly me, I did not check the script :)
Actually you are hiding old HDELTA column now. I make it visible again.
For anybody missing it is output_hdelta=1 under CONFIGURABLE STUFF section
Yeah that’s why I made these configurable :)
I liked to use 2 columns only (DELTA and HDELTA/sec) because I didn’t want to make the output too wide … but now with the averages it’s wider anyway … I’ll keep this configurable, but probably will remove one column from the averages section by default too … will decide after using the new version for a while.
I have some more good ideas for snapper :)
I’m impatient to hear about the new additions
As an idea, since you are already sleeping in the script I have integrated ehm.sql from Luca Canali to get the event histograms for I/O during the time
which sometimes help me.
http://externaltable.blogspot.co.uk/2012/05/veventhistogrammetric.html
Unfortunately it is only 11G
If you recall your diag script you wrote here, I have created an html version of it with multiple things and snapper added but could not manage to write about it yet :( I plan to have an offline discussion with you about it before I make it public as it is ultimate TPT scripts in one html diagnostics collection collecting live data in 1-2 mins for a session:)
One bug about snapper
When I set the configurable option I got the below error every run. All I do is disable RAW enable Human readable delta
SP2-0734: unknown command beginning “´╗┐——-…” – rest of line ignored.
Tried to debug it but I think you may know it better than me