OraSRP 4.1.0

First time I've read about LOBREAD lines in 10046 traces in Vladimir Begun's blog-post dated Jun 2, 2010. I've tried to reproduce such trace in my environment but failed. Since Vladimir is Oracle employee, I've decided that his example was from some yet-unreleased version of database.

...And I successfully forgot to re-check it even when 11.2.0.2 was released.

But recent Tanel's post reminded me about these LOBREAD lines.

So I've added processing of LOBREAD (and LOBAPPEND, LOBARRREAD, LOBARRTMPFRE, LOBARRWRITE etc.) calls in new version of OraSRP. Such calls displayed as 'LOB% calls' event. Remember, this works only for 11.2.0.2 traces - in earlier versions of database server such LOB% calls, I believe, are not instrumented.

As for another new feature of OraSRP 4.1.0, I'd like to inform that new version contains new section - Objects Statistics (per session and per statement). Here's what it looks like (long lines stripped for better readability):

Session Objects Statistics
==================================================
Object/Event                                    % Time       Seconds
--------------------------------------------  --------  ------------
TABLE T1 [43373]                            
    log buffer space                             58.4%       3.9383s
    log file switch completion                   20.8%       1.4027s
    db file scattered read                       18.8%       1.2676s
    db file sequential read                       1.2%       0.0838s
    log file sync                                 0.8%       0.0557s
    undo segment extension                        0.0%       0.0005s

performance of tkprof vs orasrp

Usually tkprof is faster than orasrp. But there are some cases when tkprof processes trace file slower than orasrp. Take for example today's situation.

1.7Gb trace file with about 16 thousands of different statements. Total number of calls is about 10 millions (although, it doesn't matter). OraSRP processed this file for 3 minutes. Tkprof for HP-UX processed it for 5 minutes. Tkprof for Linux consumed 1.5Gb of virtual memory and didn't finish in an hour.

The source of the problem lies in the big number of statements. When the number of statements in trace file is more than, say, 10 thousands, tkprof performs worse than orasrp and may even stuck.

ebook 'Expert Oracle Practices' is out

Expert Oracle Practices is available for download from apress.com. It seems that print version of this book will be available only on Jan 18.

This is the second known for me book (the first one is Troubleshooting Oracle Performance) where OraSRP is mentioned (nothing serious, just mentioned among other profilers).

OraSRP with Google Charts

OraSRP now is able to generate charts using Google Chart API. Actually, OraSRP is just generates a hyperlink and Google generates *.png picture.


This feature is disabled by default and you can enable it by specifying --google-charts flag.

10046 trace file content

Robert Freeman wrote in one of his articles:

  The 10046 trace file contents differ greatly between different versions of Oracle.


Indeed, format of trace files changes sometimes between Oracle versions but definitely not greatly.

Somewhere near 9.2.0.2 STAT lines changed a bit (row source execution statistics was added).
Instead of just:
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=17 op='TABLE ACCESS FULL FILE$'
they started look like this:
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=17 op='TABLE ACCESS FULL FILE$ (cr=4 pr=0 pw=0 time=91 us)'

And in 10.2 format of WAIT lines and BINDS sections changed significantly.

BINDS sections can not be processed by tkprof in any versions of Oracle so I just skip them.

As for WAIT lines, here's the pre-10.2 WAIT line:
WAIT #4: nam='SQL*Net message from client' ela= 2794957 p1=1111838976 p2=1 p3=0 p3=62
Compare it with 10.2:
WAIT #4: nam='SQL*Net message from client' ela= 2794957 driver id=1111838976 #bytes=1 p3=0 obj#=62 tim=42601199281

Wait events parameters (p1,p2,p3) got a meaningful name (as a side note: but sometimes not a meaningful value -- #bytes in 'SQL*Net messages' still always equal to 1) and every WAIT line now have tim-stamp.

The funny thing is that tkprof from Oracle 9.2 correctly process trace files from 10.2! Looks like tkprof parses WAIT line by splitting line on '=' character and just gets the first three values.

In summary, I beleive that when tkprof from old version can correctly process trace files from the new one then it's more natural to say that 'trace files contents does not differ greatly between different versions of Oracle'.

event 'events in waitclass Other' in Oracle 10.2

From release to release Oracle constantly increases the number of events (select count(*) from v$event_name). For example, Oracle 9i has 405 events, Oracle 10.1 has 811 events and Oracle 10.2 has 874 ones.

We can monitor session's wait events via v$session_event and system's ones via v$system_event.

The tricky point here is that in 10.2 a number of events (588, to be exact) are grouped into one event in v$session_event. It's almost all events of wait class (v$event_name.wait_class) 'Other'. In Oracle 10.2 there are 590 events of wait class 'Other' and 284 remaining events:

SQL> select count(*) from v$event_name where wait_class='Other';

COUNT(*)
----------
590

SQL> select count(*) from v$event_name where wait_class!='Other';

COUNT(*)
----------
284

And v$session_event can store information only for 286 events out of 874 ones. Here's some kind of proof:

v$session_event is based on fixed table x$ksles. Below is the definition of gv$session_event taken from v$fixed_view_definition:

select
s.inst_id,               -- INST_ID NUMBER
s.kslessid,              -- SID NUMBER
d.kslednam,              -- EVENT VARCHAR2(64)
s.ksleswts,              -- TOTAL_WAITS NUMBER
s.kslestmo,              -- TOTAL_TIMEOUTS NUMBER
round                    -- TIME_WAITED NUMBER
  (s.kslestim / 10000),
round                    -- AVERAGE_WAIT NUMBER
  (s.kslestim / (10000 * s.ksleswts), 2),
round                    -- MAX_WAIT NUMBER
  (s.kslesmxt / 10000),
s.kslestim,              -- TIME_WAITED_MICRO NUMBER
d.ksledhash,             -- EVENT_ID NUMBER
d.ksledclassid,          -- WAIT_CLASS_ID NUMBER
d.ksledclass#,           -- WAIT_CLASS# NUMBER
d.ksledclass             -- WAIT_CLASS VARCHAR2(64)
from
x$ksles s,
x$ksled d
where
s.ksleswts != 0 and s.kslesenm = d.indx

Note that x$ksles is a fixed table. It means that it resides in fixed area of SGA and it can't be changed (grow/shrink) when instance is running. In other words, it's just a fixed piece of memory which changes its size only after you change 'sessions' parameter.

The field x$ksles.kslesenm is an event# from v$event_name.

Let's see how many events indexes we have in x$ksles:

SQL> select count(distinct kslesenm) from x$ksles;

COUNT(DISTINCTKSLESENM)
-----------------------
                    286

286! If we select events from v$session_event ordered by event# then first 286 events will be exactly these events.

SQL> select event#,name,wait_class from v$event_name order by event#;
     0 null event                           Other
     1 pmon timer                           Idle
     2 rdbms ipc message                    Idle
...
   283 JS kill job wait                     Administrative
   284 JS coord start wait                  Administrative
   285 events in waitclass Other            Other

See that last event with event#=285 ? Named as 'events in waitclass Other'. It's some kind of pseudo-event. When session generates any events with event# more than 285 (all of such events are in class 'Other') then they are reflected in v$session_events as one event 'events in waitclass Other'.

"Optimizing Oracle Performance" in Russian

В декабре 2005 года издательство Символ-Плюс выпустило перевод книги "Optimizing Oracle Performance" под местным названием "Oracle. Оптимизация производительности". ISBN новой книги 5-93286-078-2. Тираж 2000 экземпляров.