Thanks Tom
Richard, May 05, 2003 - 2:00 pm UTC
Well, thanks once again for a great answer.
Your suggestion did help out with some improvement.
Clarification
A reader, June 23, 2004 - 4:27 pm UTC
Tom,
Your test harness script is very useful. However, I have the following questions :
You mention that the test harness cannot be used in a multi-user environment and can be useful for a controlled environment.
1. Does that mean only for single-user session? If that is the case, how can we have latch contentions (since only our session will be accessesing the memory structures and there is no other competing session/process).
2. Also, the total latches for Run1 and Run2 per summary is 45778 and 58643 respectively. However, the individual LATCH.* counts for Run1 and Run2 is only close to 20000 and 32000 respectively. How did you arrive at 45778 and 58643. Are there some part of the LATCH.* outputs that you are not showing in the output?
3. Also, the Session Cursor cache hits for Run1 is 997 and for Run2 is 1. Does that mean that Run1 had more session cursor cache hits (a.k.a softer soft parse) because of the ALTER SESSION SET SESSION_CACHED_CURSORS=100 for Run1 and ALTER SESSION SET SESSION_CACHED_CURSORS=0 for Run2.
Thanks much for your great help and suggestions to Oracle community
June 23, 2004 - 9:23 pm UTC
1) you look at latch USAGE. the more latches you get, the more contention probable.
in a single user mode, we can measure how many latches (which are serialization devices, AKA locks) you took. the more you take, the less likely the implementation will scale.
2)
ops$tkyte@ORA920> exec runstats_pkg.rs_stop(500) /* only show those things
that differ by at least 500 */
so i only showed these:
LATCH.library cache pin 4,080 6,080 2,000
LATCH.shared pool 4,144 6,153 2,009
LATCH.library cache pin alloca 2,046 6,036 3,990
LATCH.library cache 8,167 13,160 4,993
but there were others not shown. the diffs for this big ones were 2+2+4+5 = 13k
3) yes, that was exactly the goal of this simulation -- to show the effect of session_cached_cursors on latching.
Not a huge impact on runtime in single user mode.
Potential HUGE impact on scalability.
softer soft parse vs. no parse
Anil Pant, July 05, 2004 - 7:03 am UTC
I was going through your book 'Effective Oracle By Design'. In chapter 5 on page 288-289 you have discussed about No Parse I didnt understand how static cursor can be no parse. If so then cannot we always go for static cursor ?
When you say No Parse approach it means using static cursor ?
Also on page 300 regarding triggers.
<<text>>
what we can ascertain from this example is that the sql statements are cached .... we will package our sql and call the packaged sql code from the trigger
<</text>>
Does this mean if the triggers has 5 different sql statements then each statement will be processed as opposed to a single unit ?
Pls explain
July 05, 2004 - 10:26 am UTC
if you have a procedure:
procedure p
is
begin
for x in ( select * from t )
loop
....
and you enable sql_trace and you call p 50 times -- see how many times select * from t was parsed -- under normal day to day circumstances, it'll be parsed once.
that is the beauty of static sql in plsql (and pro*c). In java, odbc, whatever - -you have to do it yourself, you have to parse once and execute many.
with the triggers -- my point was this statement caching does not happen with triggers. so, move all sql out of trigger into a plsql package and make the trigger be a one line call to the packaged code.
if you have a trigger that is:
for each row
begin
for x in ( select * from dual ) loop null; end loop;
end;
/
and you insert into table values ( 1 ); 50 times -- with sql trace - see how many times select * from dual was parsed, it'll be 50. Now, make the trigger be:
begin
p( ..... );
end;
/
where p has the select * from dual -- do the 50 single row inserts and you'll see the select from dual parsed once.
runstats question
Ryan Gaffuri, August 25, 2004 - 11:17 am UTC
Not sure how to explain this, so I am providing as much info as possible. If I am missing something let me know. My main question is, how can a query that consumes more resources return in less time when I am the only user connected to the instance? I ran this several times.
I wanted to test hash partitionings effect on performance. So I have 2 tables with 16 hash partions. I did a join of the two. I then created duplicate tables with the same indexes that are not partioned.
Run 1 is the the non-hash partioned tables
run 2 is the hash partitioned table.
This is more of a general question. Any idea how to identify why this would happen? Its more a curiousity than anything else.
tab1 has about 800,000 rows
tab2 has about 6.5m rows
t.col7 = '<val>' reduces the set to 6,000 rows.
I.col7 IN (<vals>) reduces the set to about 25,000 rows
The result of the join is about 200 rows. So I expect a nested loop, with tab1 as the lead table in the join. I get that in both queries.
The interesting thing is that both queries use different indexes...
hash partioned tables use indexes of the form
tab1 just an index on col8. No join columns.
tab2 index on all the join columns leading with the hash partiioned key(its a local index).
non hash partitioned tables use the following indexes
-- tab1 uses an index that leads col8, then uses an indexes on the join columns. I have them ordered from most selective
-- tab2 uses an index that leads with col8 followed by the join columns.
hash_col is the column that is hashed.
select COUNT(col1)
FROM tab1 t, tab2 I
WHERE I.hash_col= T.hash_col
AND I.col2 = T.col2
AND I.col3 = T.col3
AND I.col4 = T.col4
AND I.col5 = T.col5
AND I.col6 = '<val>'
AND I.col7 IN (<vals>)
AND T.col8 = <value>;
exec runstats_pkg.rs_stop(500);
Run1 ran in 1203 hsecs
Run2 ran in 1713 hsecs
run 1 ran in 70.23% of the time
Name Run1 Run2 Diff
STAT...session uga memory 2,048 0 -2,048
STAT...index scans kdiixs1 13,681 6,841 -6,840
STAT...shared hash latch upgra 13,681 6,841 -6,840
LATCH.cache buffers chains 99,782 91,333 -8,449
STAT...buffer is not pinned co 20,864 31,279 10,415
STAT...no work - consistent re 21,218 34,103 12,885
STAT...session logical reads 62,792 48,321 -14,471
STAT...consistent gets 62,265 47,792 -14,473
STAT...consistent gets - exami 27,366 6,848 -20,518
STAT...table fetch by rowid 7,271 30,081 22,810
STAT...buffer is pinned count 7,357 35,722 28,365
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
100,697 92,363 -8,334 109.02%
PL/SQL procedure successfully completed.
If I need to provide more information please let me know. This isn't the first time I have seen runstats results where one query consumes more resources but has a shorter response time.
August 25, 2004 - 11:38 am UTC
latches are locks, locks are serialization devices, serialization devices inhibit scalability in a multi-user environment
Here, the difference in latching is not very huge
and given you were the only user -- well, you had to wait for no one.
soft parse
APL, December 22, 2004 - 7:09 am UTC
Our application is using jdbc 2.1. Its showing lot of soft parses. They are using bind variables. By using the parameter session_cached_cursors we can increase the performance.My question is how to avoid this soft parse in web based applications?
Our applications were running fine for the past 6 months. But suddenly its performance degraded and when i go through the trace file the major problem i identified is this parsing. What can i do for it?
December 22, 2004 - 9:54 am UTC
RE : Elapsed time
A reader, January 26, 2005 - 12:01 pm UTC
Hi Tom,
I installed the runstats components on my database and tried running the following piece of code :
declare
cursor c1 is select object_name from user_objects where object_type = 'FUNCTION' and object_name like 'F%';
type t_c1rec is table of user_objects.object_name%TYPE INDEX BY BINARY_INTEGER;
c1rec t_c1rec;
i number;
begin
runStats_pkg.rs_start;
for crec in c1
loop
i := i + 1;
end loop;
runstats_Pkg.rs_middle;
i := 0;
open c1;
loop
fetch c1 bulk collect into c1rec limit 100;
i := i + 1;
exit when c1%notfound;
end loop;
close c1;
runstats_pkg.rs_stop;
end;
I have the following runstats output
Run1 ran in 5 hsecs
Run2 ran in 4 hsecs
run 1 ran in 125% of the time
Name Run1 Run2 Diff
LATCH.active checkpoint queue 0 1 1
LATCH.messages 8 9 1
STAT...cursor authentications 1 0 -1
STAT...parse count (total) 1 0 -1
STAT...recursive cpu usage 11 10 -1
STAT...opened cursors current 1 0 -1
STAT...opened cursors cumulati 1 0 -1
LATCH.Consistent RBA 2 0 -2
LATCH.mostly latch-free SCN 0 2 2
LATCH.row cache objects 50 52 2
LATCH.row cache enqueue latch 50 52 2
LATCH.lgwr LWN SCN 0 2 2
LATCH.redo writing 5 2 -3
LATCH.enqueues 4 0 -4
STAT...Elapsed Time 14 18 4
LATCH.session allocation 8 0 -8
STAT...buffer is not pinned co 106 93 -13
STAT...table scan blocks gotte 106 93 -13
STAT...session logical reads 627 614 -13
STAT...no work - consistent re 106 93 -13
STAT...consistent gets 110 97 -13
STAT...recursive calls 17 3 -14
LATCH.shared pool 26 3 -23
LATCH.library cache pin alloca 26 0 -26
LATCH.session idle bit 26 0 -26
LATCH.library cache pin 38 8 -30
LATCH.library cache 75 8 -67
LATCH.checkpoint queue latch 0 109 109
LATCH.cache buffers chains 2,981 2,769 -212
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
3,814 3,532 -282 107.98%
I was expecting that the elapsed time for the second run to be lesser than the first (since I was using bulk operations). However, I always see extra time for run2. I tried this for two or three runs and got the same results. Let me know if I am doing something wrong
January 26, 2005 - 1:25 pm UTC
you don't want to do it like that, you want 5 calls to the database
and unless you have thousands or at least HUNDREDS of rows -- you cannot really expect to see much benefit from a bulk collect (you are not doing enough work)
and lastly, the difference between:
Run1 ran in 5 hsecs
Run2 ran in 4 hsecs
is nonexistent. I would expect if you ran that over and over you would find the numbers to vary between 0 and 10 -- for each (insufficient work happening here to use a wall clock time)
ops$tkyte@ORA9IR2> exec runStats_pkg.rs_start;
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> declare
2 cursor c1 is select object_name from all_objects;
3 type t_c1rec is table of user_objects.object_name%TYPE INDEX BY BINARY_INTEGER;
4 c1rec t_c1rec;
5 i number;
6 begin
7 for crec in c1
8 loop
9 i := i + 1;
10 end loop;
11 end;
12 /
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> exec runstats_Pkg.rs_middle;
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> declare
2 cursor c1 is select object_name from all_objects;
3 type t_c1rec is table of user_objects.object_name%TYPE INDEX BY BINARY_INTEGER;
4 c1rec t_c1rec;
5 i number;
6 begin
7 i := 0;
8 open c1;
9 loop
10 fetch c1 bulk collect into c1rec limit 100;
11 i := i + 1;
12 exit when c1%notfound;
13 end loop;
14
15 close c1;
16 end;
17 /
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> exec runstats_pkg.rs_stop(1000);
Run1 ran in 114 hsecs
Run2 ran in 71 hsecs
run 1 ran in 160.56% of the time
Name Run1 Run2 Diff
LATCH.simulator hash latch 4,992 2,816 -2,176
STAT...recursive calls 27,953 284 -27,669
STAT...session logical reads 151,886 115,460 -36,426
STAT...consistent gets 151,876 115,445 -36,431
STAT...no work - consistent re 86,583 50,149 -36,434
STAT...buffer is pinned count 49,119 85,760 36,641
STAT...buffer is not pinned co 129,219 65,117 -64,102
LATCH.cache buffers chains 301,724 228,847 -72,877
STAT...session pga memory 0 131,072 131,072
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
308,200 233,149 -75,051 132.19%
PL/SQL procedure successfully completed.
and if you run this in 10g:
ops$tkyte@ORA10G> exec runStats_pkg.rs_start;
PL/SQL procedure successfully completed.
ops$tkyte@ORA10G>
ops$tkyte@ORA10G> declare
2 cursor c1 is select object_name from all_objects;
3 type t_c1rec is table of user_objects.object_name%TYPE INDEX BY BINARY_INTEGER;
4 c1rec t_c1rec;
5 i number;
6 begin
7 for crec in c1
8 loop
9 i := i + 1;
10 end loop;
11 end;
12 /
PL/SQL procedure successfully completed.
ops$tkyte@ORA10G>
ops$tkyte@ORA10G> exec runstats_Pkg.rs_middle;
PL/SQL procedure successfully completed.
ops$tkyte@ORA10G>
ops$tkyte@ORA10G> declare
2 cursor c1 is select object_name from all_objects;
3 type t_c1rec is table of user_objects.object_name%TYPE INDEX BY BINARY_INTEGER;
4 c1rec t_c1rec;
5 i number;
6 begin
7 i := 0;
8 open c1;
9 loop
10 fetch c1 bulk collect into c1rec limit 100;
11 i := i + 1;
12 exit when c1%notfound;
13 end loop;
14
15 close c1;
16 end;
17 /
PL/SQL procedure successfully completed.
ops$tkyte@ORA10G> exec runstats_pkg.rs_stop(1000);
Run1 ran in 66 hsecs
Run2 ran in 60 hsecs
run 1 ran in 110% of the time
Name Run1 Run2 Diff
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
128,649 127,623 -1,026 100.80%
PL/SQL procedure successfully completed.
<b>a dead heat (because PLSQL is silently array fetching 100 rows at a time for us automagically in 10g....</b>
Not clear
A reader, January 26, 2005 - 1:34 pm UTC
Tom,
I am not clear as to what you say hear and what you mean by "you don't want to do it like that, you want 5 calls to the database". Are you saying that the example I am using is not good enough for me to prove the point. Please explain
January 26, 2005 - 1:53 pm UTC
did you see the 5 calls
runstats_pkg.start (call 1)
your code (call 2)
runstats_pkg.middle (call 3)
your code version 2 (call 4)
runstats_pkg.stop (call 5)
some statistics are not put into the v$ tables until the end of a call. consider:
ops$tkyte@ORA9IR2> declare
2 x number;
3 begin
4 runStats_pkg.rs_start;
5 for i in 1 .. 100000
6 loop
7 x := ln(i);
8 end loop;
9
10 runStats_pkg.rs_middle;
11 for i in 1 .. 500
12 loop
13 x := ln(i);
14 end loop;
15 runStats_pkg.rs_stop(100);
16 end;
17 /
Run1 ran in 569 hsecs
Run2 ran in 2 hsecs
run 1 ran in 28450% of the time
Name Run1 Run2 Diff
STAT...redo size 1,804 1,932 128
LATCH.SQL memory manager worka 134 0 -134
STAT...Elapsed Time 570 3 -567
<b>so, apparently, the first run ran lots slower -- but the difference in CPU time was neglible -- i mean, we see no recorded difference in CPU time???
However...</b>
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
357 113 -244 315.93%
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> exec runStats_pkg.rs_start;
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> declare
2 x number;
3 begin
4 for i in 1 .. 100000
5 loop
6 x := ln(i);
7 end loop;
8 end;
9 /
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> exec runStats_pkg.rs_middle;
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> declare
2 x number;
3 begin
4 for i in 1 .. 500
5 loop
6 x := ln(i);
7 end loop;
8 end;
9 /
PL/SQL procedure successfully completed.
ops$tkyte@ORA9IR2> exec runStats_pkg.rs_stop(100);
Run1 ran in 567 hsecs
Run2 ran in 10 hsecs
run 1 ran in 5670% of the time
Name Run1 Run2 Diff
STAT...redo size 1,804 1,936 132
LATCH.SQL memory manager worka 134 0 -134
STAT...Elapsed Time 568 11 -557
STAT...CPU used by this sessio 562 4 -558
STAT...CPU used when call star 562 4 -558
STAT...OS User time used 571 0 -571
STAT...session pga memory 0 65,536 65,536
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
738 478 -260 154.39%
PL/SQL procedure successfully completed.
<b>There we big time CPU difference and other things</b>
You need to use 5 independent database calls.
Pls. clarify
A reader, January 26, 2005 - 2:03 pm UTC
Tom,
Now I understood what you meant by "5 calls to the database". However, in the last discussion thread, you use 100000 as the loop limit for the first for loop and 500 for the second for loop. Any reason for that?
January 26, 2005 - 2:30 pm UTC
so there would be measurable differences between the two.
I was trying to show that "some things are not recorded until the end of the call"
CPU is one of them.
So, I wanted something that used alot of cpu, and something that did not.
Pls. clarify
A reader, January 27, 2005 - 9:42 am UTC
Tom,
After your feedback, I ran the following code snippets in my development box to find out the effect of data type conversions on CPU time.
begin
runstats_pkg.rs_start;
end;
/
declare
x varchar2(10) := '01-JAN-05';
y date;
i integer;
begin
for i in 1..100000
loop
y := x;
end loop;
end;
/
begin
runstats_pkg.rs_middle;
end;
/
declare
x date := '01-JAN-05';
y x%type;
i integer;
begin
for i in 1..100000
loop
y := x;
end loop;
end;
/
begin
runstats_pkg.rs_stop;
end;
/
Run1 ran in 312 hsecs
Run2 ran in 11 hsecs
run 1 ran in 2836.36% of the time
Name Run1 Run2 Diff
LATCH.active checkpoint queue 2 1 -1
LATCH.event group latch 1 0 -1
LATCH.lgwr LWN SCN 1 2 1
LATCH.mostly latch-free SCN 1 2 1
LATCH.process allocation 1 0 -1
STAT...messages sent 1 0 -1
STAT...redo entries 514 513 -1
STAT...redo buffer allocation 1 0 -1
LATCH.session timer 1 0 -1
LATCH.Consistent RBA 2 0 -2
LATCH.channel handle pool latc 2 0 -2
LATCH.process group creation 2 0 -2
LATCH.post/wait queue 2 0 -2
LATCH.transaction allocation 2 0 -2
LATCH.loader state object free 4 2 -2
LATCH.list of block allocation 2 0 -2
LATCH.dummy allocation 2 0 -2
LATCH.dml lock allocation 2 0 -2
LATCH.sequence cache 3 0 -3
LATCH.undo global data 3 0 -3
LATCH.redo allocation 519 515 -4
LATCH.user lock 4 0 -4
LATCH.redo writing 7 3 -4
LATCH.channel operations paren 5 0 -5
LATCH.child cursor hash table 7 0 -7
STAT...bytes received via SQL* 275 266 -9
LATCH.enqueue hash chains 10 0 -10
STAT...change write time 11 0 -11
LATCH.messages 28 9 -19
LATCH.enqueues 31 0 -31
LATCH.session allocation 52 0 -52
LATCH.SQL memory manager worka 81 0 -81
LATCH.library cache pin alloca 122 8 -114
STAT...redo size 65,912 65,784 -128
LATCH.process queue reference 210 52 -158
LATCH.library cache pin 191 26 -165
LATCH.shared pool 207 27 -180
LATCH.checkpoint queue latch 288 96 -192
LATCH.session idle bit 276 8 -268
STAT...Elapsed Time 320 19 -301
STAT...CPU used by this sessio 317 11 -306
STAT...CPU used when call star 317 11 -306
LATCH.library cache 365 36 -329
LATCH.row cache enqueue latch 348 0 -348
LATCH.row cache objects 362 0 -362
LATCH.cache buffers chains 3,302 2,575 -727
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
6,448 3,362 -3,086 191.79%
I am able to understand the difference in elapsed time and CPU times between the two approaches and was hoping that there should be no differences as far as latching is concerned (since per my understanding, there is no logic in the PL/SQL block that would involve any latches). Why is the output showing so much differences in the latch.
Please advise
January 27, 2005 - 10:03 am UTC
are you on a single user system and did you run this repeatedly.
The issue is latches are "system wide", the statistics -- they are your session, but the latches are system wide.
You do NO IO -- so those cache buffers chains latches, they are probably someone elses. when run on a "quiet" system:
Name Run1 Run2 Diff
LATCH.Consistent RBA 1 0 -1
LATCH.lgwr LWN SCN 1 0 -1
LATCH.mostly latch-free SCN 1 0 -1
LATCH.library cache 52 54 2
LATCH.redo allocation 9 7 -2
LATCH.library cache pin 44 46 2
LATCH.redo writing 3 0 -3
LATCH.messages 4 0 -4
STAT...bytes received via SQL* 996 987 -9
STAT...CPU used by this sessio 48 3 -45
STAT...CPU used when call star 48 3 -45
STAT...Elapsed Time 52 5 -47
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
263 255 -8 103.14%
PL/SQL procedure successfully completed.
which is what I would expect. I think in your case, they are just "noise"
(and if you run this in 10g, beware of:
Run1 ran in 2 hsecs
Run2 ran in 0 hsecs
begin
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
ORA-06512: at "OPS$TKYTE.RUNSTATS_PKG", line 39
ORA-06512: at line 2
:)
RE : Cache buffers latch
A reader, January 27, 2005 - 11:59 am UTC
Tom,
Cache buffers latch will show up if you do lot of logical I/Os. Correct?
Please advise
January 27, 2005 - 12:49 pm UTC
correct.
runStats
SR, February 08, 2005 - 4:44 pm UTC
Tom,
Is there any reason why you don't use v$sesstat, v$session_event for the sid = :s (where you do testing), which is saved from yet another session so as to not impact sid :s itself. This should give session specific latches etc? I got some wild number variations on runStats runs one system and then it became apparant that the system load may be causing it (?)
Thanks
February 09, 2005 - 1:48 am UTC
there is no such thing as "session specific latches"
runstats is explicity designed to be run "single user" as a measurment tool.
Trap to be careful when running runstats
Albert Nelson A, February 11, 2005 - 11:28 am UTC
Dear Tom,
Your runstats_pkg is nice.
I like to share the following:
As the start time for the second run is captured at runstats_pkg.rs_middle, any delay in typing the second query adds to the run time of the second query. I think getting from a script solves this.
Example:
SQL> set serveroutput on size 40000
SQL> exec runstats_pkg.rs_start;
PL/SQL procedure successfully completed.
SQL> ed
Wrote file afiedt.buf
1 declare
2 n number;
3 begin
4 for i in 1..10000 loop
5 select 1 into n from dual;
6 end loop;
7* end;
SQL> /
PL/SQL procedure successfully completed.
SQL> exec runstats_pkg.rs_middle;
PL/SQL procedure successfully completed.
--- Here waited for some time ---
SQL> ed
Wrote file afiedt.buf
1 declare
2 n number;
3 begin
4 for i in 1..1000 loop
5 select 1 into n from dual;
6 end loop;
7* end;
SQL> /
PL/SQL procedure successfully completed.
SQL> exec runstats_pkg.rs_stop(500);
Run1 ran in 3443 hsecs
Run2 ran in 3508 hsecs
run 1 ran in 98.15% of the time
Name Run1 Run2 Diff
LATCH.messages 16,841 17,426 585
LATCH.library cache pin alloca 35,794 38,412 2,618
LATCH.undo global data 19,541 16,899 -2,642
LATCH.multiblock read objects 18,400 14,710 -3,690
LATCH.session idle bit 75,622 79,699 4,077
LATCH.shared pool 33,092 27,549 -5,543
STAT...buffer is not pinned co 10,000 1,000 -9,000
STAT...execute count 10,005 1,005 -9,000
STAT...recursive calls 10,003 1,003 -9,000
STAT...table scans (short tabl 10,000 1,000 -9,000
STAT...table scan rows gotten 10,000 1,000 -9,000
STAT...table scan blocks gotte 10,000 1,000 -9,000
STAT...no work - consistent re 10,000 1,000 -9,000
LATCH.transaction allocation 10,576 0 -10,576
LATCH.library cache pin 92,914 79,450 -13,464
LATCH.library cache 129,711 113,710 -16,001
STAT...session logical reads 30,018 3,020 -26,998
STAT...consistent gets 30,006 3,007 -26,999
STAT...calls to get snapshot s 30,001 3,001 -27,000
LATCH.cache buffers chains 1,016,867 851,500 -165,367
STAT...session pga memory -196,608 0 196,608
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
1,601,553 1,394,274 -207,279 114.87%
PL/SQL procedure successfully completed.
Same thing from script:
SQL> set serveroutput on size 4000
SQL> get c:\rs.sql
1 begin
2 runstats_pkg.rs_start;
3 end;
4 /
5 declare
6 n number;
7 begin
8 for i in 1..10000 loop
9 select 1 into n from dual;
10 end loop;
11 end;
12 /
13 begin
14 runstats_pkg.rs_middle;
15 end;
16 /
17 declare
18 n number;
19 begin
20 for i in 1..1000 loop
21 select 1 into n from dual;
22 end loop;
23 end;
24 /
25 begin
26 runstats_pkg.rs_stop(500);
27* end;
28
29
SQL> @c:\rs.sql
PL/SQL procedure successfully completed.
PL/SQL procedure successfully completed.
PL/SQL procedure successfully completed.
PL/SQL procedure successfully completed.
Run1 ran in 41 hsecs
Run2 ran in 7 hsecs
run 1 ran in 585.71% of the time
Name Run1 Run2 Diff
LATCH.enqueue hash chains 557 56 -501
LATCH.library cache pin alloca 826 88 -738
LATCH.session idle bit 1,827 219 -1,608
LATCH.shared pool 7,737 993 -6,744
STAT...buffer is not pinned co 10,000 1,000 -9,000
STAT...execute count 10,005 1,005 -9,000
STAT...no work - consistent re 10,000 1,000 -9,000
STAT...recursive calls 10,003 1,003 -9,000
STAT...table scan rows gotten 10,000 1,000 -9,000
STAT...table scans (short tabl 10,000 1,000 -9,000
STAT...table scan blocks gotte 10,000 1,000 -9,000
LATCH.library cache pin 21,709 2,194 -19,515
LATCH.library cache 22,445 2,275 -20,170
STAT...session logical reads 30,015 3,023 -26,992
STAT...consistent gets 30,005 3,008 -26,997
STAT...calls to get snapshot s 30,001 3,001 -27,000
LATCH.cache buffers chains 73,074 8,328 -64,746
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
131,431 14,473 -116,958 908.11%
PL/SQL procedure successfully completed.
SQL>
Regards,
Albert Nelson A
February 12, 2005 - 7:53 am UTC
the fix is to script it as I always do
test.sql:
exec runstats_pkg.rs_start
exec procedure1;
exec runstats_pkg.rs_middle
exec procedure2;
exec runstats_pkg.rs_stop
and run SQL> @test
I always do it in a script.
A reader, February 23, 2005 - 12:12 pm UTC
Hi Tom,
From your previous post
"if you have a procedure:
procedure p
is
begin
for x in ( select * from t )
loop
....
and you enable sql_trace and you call p 50 times -- see how many times select *
from t was parsed -- under normal day to day circumstances, it'll be parsed
once.
that is the beauty of static sql in plsql (and pro*c). In java, odbc, whatever
- -you have to do it yourself, you have to parse once and execute many.
with the triggers -- my point was this statement caching does not happen with
triggers. so, move all sql out of trigger into a plsql package and make the
trigger be a one line call to the packaged code.
if you have a trigger that is:
for each row
begin
for x in ( select * from dual ) loop null; end loop;
end;
/
and you insert into table values ( 1 ); 50 times -- with sql trace - see how
many times select * from dual was parsed, it'll be 50. Now, make the trigger
be:
begin
p( ..... );
end;
/
where p has the select * from dual -- do the 50 single row inserts and you'll
see the select from dual parsed once.
"
If we call a procedure or package from inside a trigger, will we be still able to get the new and old values (after the before the change, if it is an update) by calling only the procedure/package ? Will that reduce the soft parsing count ?
Right now we are using something like this for before/after insert/update trigger
trade_ins_rec.trade_id := :new.trade_id ;
trade_ins_rec.award_type_id := :new.award_type_id ;
trade_ins_rec.currency_id:= :new.currency_id ;
trade_ins_rec.amount := :new.amount ;
trade_ins_rec.last_update := :new.last_update;
trigger_pkg.trade_ins_insert(trade_ins_rec);
where trade_ins_insert is a procedure in package trigger_pkg
but this is parsing once for each insert or update
thanks
Regi
February 24, 2005 - 4:45 am UTC
the trigger can pass the :new values using IN OUT or OUT parameters - and the plsql procedure you invoke can "write to them" and modify them. So yes, you can access :new and :old, you pass them as parameters.
What is parsing once? give us a tiny example demonstrating your point. Here is mine:
ops$tkyte@ORA9IR2> create table t1 ( x int );
Table created.
ops$tkyte@ORA9IR2> create table t2 ( x int );
Table created.
ops$tkyte@ORA9IR2> create or replace procedure p( p_x in number )
2 as
3 begin
4 insert into t2 in_proc values ( p_x );
5 end;
6 /
Procedure created.
ops$tkyte@ORA9IR2> create trigger t1_trigger
2 after insert on t1 for each row
3 begin
4 insert into t2 in_trigg values ( :new.x );
5 p(:new.x);
6 end;
7 /
Trigger created.
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> @trace
ops$tkyte@ORA9IR2> alter session set events '10046 trace name context forever, level 12';
Session altered.
ops$tkyte@ORA9IR2> insert into t1 values ( 1 );
1 row created.
ops$tkyte@ORA9IR2> insert into t1 values ( 1 );
1 row created.
ops$tkyte@ORA9IR2> insert into t1 select rownum from all_users;
24 rows created.
INSERT INTO T2 IN_TRIGG VALUES ( :B1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 26 0.00 0.00 0 3 33 26
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 29 0.00 0.00 0 3 33 26
********************************************************************************
INSERT INTO T2 IN_PROC VALUES ( :B1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 26 0.00 0.00 0 1 26 26
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 27 0.00 0.00 0 1 26 26
IN_TRIGG, parsed 3 times -- because we did three inserts.
IN_PROC, parsed 1 time -- because plsql cached it since the insert was in a stored, named object (a procedure)
A reader, February 23, 2005 - 4:13 pm UTC
Hi Tom,
You can ignore the above post. It is incorrect.
The call of the package/procedure from inside the trigger does eliminate unnecessary parsing.
The soft parse count was increasing for the actual insert/update itself not for the one inside the trigger
thanks
Regi
Don't I need v$timer granted directly as well.
Mark Brady, July 12, 2006 - 12:08 pm UTC
I'm posting this as a review here because:
1. No review section for the runtats page
2. This is the example linked directly from there
I finagled the 3 privs to the v_$ views you listed as prerequisites but when I try to compile the view i get an error indicating I need privs on v$timer as well.
If this is the case perhaps you could update the runstats to add that prereq. If not what am I doing wrong?
July 12, 2006 - 3:47 pm UTC
you would of course need access to all of the v_$ views - sorry about that.
function in the Query
Pingu, December 28, 2006 - 7:26 am UTC
Hi
My developers runs queries with functions, the function is quite simple, it simply translates some character into normal a, b, c, d
RETURN LTRIM( RTRIM(
TRANSLATE(
UPPER( P_TEXTO ),
'ÁÉÍÓÚÀÈÌÒÙÄËÏÖÜÂÊÎÔÛ`´¨^',
'AEIOUAEIOUAEIOUAEIOU''''''''' )
) );
There is heavy latch contention in the database, library cache latch, I ran query against v$sysstat and v$db_object_cache I noticed that parse count is very high, 3500/second and number of executions of package is high as well, please see the results
STATISTIC# NAME CLASS VALUE
---------- ------------------------------ ---------- --------------------------------
177 parse time cpu 64 0
178 parse time elapsed 64 0
179 parse count (total) 64 40890933702
180 parse count (hard) 64 72106
!sleep 5
STATISTIC# NAME CLASS VALUE
---------- ------------------------------ ---------- --------------------------------
177 parse time cpu 64 0
178 parse time elapsed 64 0
179 parse count (total) 64 40890950930
180 parse count (hard) 64 72106
OWNER NAME DB_L NAMESPACE TYPE SHARABLE_MEM LOADS EXECUTIONS LOCKS PINS KEP
----------- ----------- ---- ------------------ -------------- ------------ ---------- --------------- ---------- ---------- ---
OPS$PROD PKG_INTGG TABLE/PROCEDURE PACKAGE 228179 31 -1767520083 17 5 YES
OPS$PROD PKG_INTGG BODY PACKAGE BODY 32551 29 -310023399 17 5 YES
!sleep 5
OWNER NAME DB_L NAMESPACE TYPE SHARABLE_MEM LOADS EXECUTIONS LOCKS PINS KEP
----------- ------------ ---- ------------------ -------------- ------------ ---------- --------------- ---------- ---------- ---
OPS$PROD PKG_INTGG TABLE/PROCEDURE PACKAGE 228179 31 -1767499820 17 3 YES
OPS$PROD PKG_INTGG BODY PACKAGE BODY 32551 29 -310014413 17 0 YES
I was wondering why this suffers latch contention if the package is loaded in the memory?
Anyway to improve a bit this?
TIA
December 28, 2006 - 9:49 am UTC
why do you think this is all about the function
function in the Query
pingu, December 28, 2006 - 10:44 am UTC
Hi
I suspected the function because there is nothing else I can suspect about, well except the number of soft parses but hell I dont think 3000 soft parses per second in a dedicated server with 8 CPUs would cause this sort of library cache contention?
TIA
December 29, 2006 - 9:04 am UTC
why do you fell compelled to curse?
Anyway, you typically do not parse a function call like that. You parse:
a) SQL
b) a call to a top level anonymous block to run plsql
but the function, it would not be parsed, I doubt you have code like:
parse( "begin :y := my_function(:x); end;" );
bind x
bind y
execute
more likely you have plsql that calls this function - and that would NOT incur a parse.
function in the query
Pingu, December 29, 2006 - 12:46 pm UTC
Hi
The function is called in a query such as
select pkg1.trans_text(column1), column2, column3
from table1
where ........
I checked the application code and it open cursor, fecth and closes the curosr ALL the time, I guess library cache latch contention may be caused by soft parses instead of function calls?
TIA
December 30, 2006 - 8:58 am UTC
yes, precisely my point.
If you have latch contention that is :)
You have not demonstrated that to us as yet either.
and if your developers cared about performance, they would not have used plsql right there - that should just be 100% plain SQL. if they want to hide that function with the nested builtins - they should have used a view.
function in the query
PINGU, December 30, 2006 - 12:06 pm UTC
Hi
Its Pingu again
Do you think select pkg1.trans_text(column1), is worse than select LTRIM( RTRIM(
TRANSLATE(
UPPER( P_TEXTO ),
'ÁÉÍÓÚÀÈÌÒÙÄËÏÖÜÂÊÎÔÛ`´¨^',
'AEIOUAEIOUAEIOUAEIOU''''''''' )
) )
?
Also what cana view help in this case... cant really see.
We have heavy latch contention yes, very very heavy library latch contention.
TIA
December 30, 2006 - 12:23 pm UTC
absolutely, it is exactly what I said - don't use plsql when plain old sql will more than do.
A view can be used to hide the transalte(upper(column),'string1','string2') - just like the plsql function is.
create a view with that function result as a column, so instead of:
select pkg.function(c1), .... from table;
you
select c1_translated, ..... from view_of_table;
function in a query
A reader, December 30, 2006 - 12:28 pm UTC
Hi
Performance wise do they make any difference? I dont think so, dont they?
select pkg.function(c1), .... from table;
select c1_translated, ..... from view_of_table;
December 30, 2006 - 1:33 pm UTC
we never have to have an "i don't think so" situation - I try to teach people how to measure things....
So, let us measure things.
ops$tkyte%ORA10GR2> /*
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> drop table t;
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create table t as select * from all_objects;
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create or replace function f( p_str in varchar2 ) return varchar2
ops$tkyte%ORA10GR2> as
ops$tkyte%ORA10GR2> begin
ops$tkyte%ORA10GR2> return ltrim( rtrim( translate( upper( p_str ), '!@#$%^&*()_+', '------------' ) ) );
ops$tkyte%ORA10GR2> end;
ops$tkyte%ORA10GR2> /
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create or replace view vw
ops$tkyte%ORA10GR2> as
ops$tkyte%ORA10GR2> select object_name,
ops$tkyte%ORA10GR2> ltrim( rtrim( translate( upper( object_name ), '!@#$%^&*()_+', '------------' ) ) ) object_name_translated
ops$tkyte%ORA10GR2> from t
ops$tkyte%ORA10GR2> /
ops$tkyte%ORA10GR2> */
ops$tkyte%ORA10GR2> exec runStats_pkg.rs_start;
PL/SQL procedure successfully completed.
ops$tkyte%ORA10GR2> set autotrace traceonly statistics
ops$tkyte%ORA10GR2> select f(object_name) from t;
50079 rows selected.
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3985 consistent gets
0 physical reads
0 redo size
1692818 bytes sent via SQL*Net to client
37103 bytes received via SQL*Net from client
3340 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
50079 rows processed
ops$tkyte%ORA10GR2> exec runStats_pkg.rs_middle;
PL/SQL procedure successfully completed.
ops$tkyte%ORA10GR2> select object_name_translated from vw;
50079 rows selected.
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3985 consistent gets
0 physical reads
0 redo size
1692826 bytes sent via SQL*Net to client
37103 bytes received via SQL*Net from client
3340 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
50079 rows processed
ops$tkyte%ORA10GR2> set autotrace off
ops$tkyte%ORA10GR2> exec runStats_pkg.rs_stop(10000);
Run1 ran in 1059 hsecs
Run2 ran in 941 hsecs
run 1 ran in 112.54% of the time
Name Run1 Run2 Diff
LATCH.library cache pin 20,086 28 -20,058
LATCH.library cache 30,161 65 -30,096
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
67,027 16,210 -50,817 413.49%
PL/SQL procedure successfully completed.
used less latching, ran a little faster (older releases will show a larger disparity between the run times)
function in a query
Pingu, January 01, 2007 - 2:21 pm UTC
Hi
I run the tests and I see that changing custom function call to standard function reduces latch contention.
Sorry about this, but why using a custom function needs so many library cache latches? It was only calling some standard functions.
January 01, 2007 - 7:49 pm UTC
did you actually have latch contention...
anyway, it does, it is visible, it is something you can see - when sql calls the plsql, the plsql cannot be "changed" - we need to access that stuff from the shared pool - hence we protect it.
Quick example for divisible equal to zero
Suresh, January 04, 2007 - 2:33 am UTC
Hi,
Tom
Being a great fan of you and learning all from your site...... Thanks once again for contributing your time. Can you give a quick example of "Divisible equal to zero error" as i am getting it in a single user system in 10g with no sessions connected while running stats.
January 05, 2007 - 9:02 am UTC
scott%ORA9IR2> select 1/0 from dual;
select 1/0 from dual
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
not sure what you are looking for really??
and if you are running statistics gathering, you have sessions connected.
Is the time to compute the plan available?
Charlie B., January 23, 2007 - 3:26 pm UTC
Tom -
Great information, as always!
The application I manage frequently does joins of 10+ tables. Views of views are also common. Is there anything in Perfstat that indicates how much time is consumed calculating the plans for these statements? Or is it just a part of (say) parse_time_cpu?
Statement cache on 10g triggers
Phil (UK), July 03, 2007 - 10:24 am UTC
Hi Tom
Does 10g still not cache SQL in triggers? If so, is your advice from 2005 still valid in that we call packaged code from triggers rather than in the trigger itself?
Cheers!
Phil
July 03, 2007 - 10:44 am UTC
well, when you ran it... :)
10gr2 has not changed the behaviour (but, 11g is right around the corner)
insert inside trigger vs procedure call
Thomas, October 02, 2007 - 6:32 am UTC
Tom,
we're using update-triggers extensively to keep a history of changes on certain tables.
So I wanted to reproduce what you wrote above:
"with the triggers -- my point was this statement caching does not happen with
triggers. so, move all sql out of trigger into a plsql package and make the
trigger be a one line call to the packaged code."
I tried to measure the effect on latch statistics the way you did -and failed.
Here's what I did (running single-user on 9.2.0.7):
DELETE FROM run_stats;
CREATE TABLE watch AS SELECT rownum id, 1 value FROM all_objects;
CREATE TABLE watch_hist AS SELECT rownum id , 1 value, sysdate dt_changed FROM watch WHERE 1=2;
-- approach #1: direct insert into watch_hist
CREATE OR REPLACE TRIGGER WATCH_UPD
BEFORE UPDATE ON Watch FOR EACH ROW
BEGIN
INSERT INTO Watch_Hist ( id, value, dt_changed) VALUES
(
:OLD.id, :OLD.value, SYSDATE
);
END;
/
INSERT INTO Run_Stats SELECT 'before', stats.* FROM stats;
UPDATE watch SET value = 2;
COMMIT;
INSERT INTO Run_Stats SELECT 'after 1', stats.* FROM stats;
-- approach #2: call a proecedure to do the insert
CREATE OR REPLACE PROCEDURE ins_watch_hist( a_id IN NUMBER, a_value IN VARCHAR2 )
AS
BEGIN
INSERT INTO Watch_Hist ( id, value, dt_changed) VALUES
(
a_id, a_value, SYSDATE
);
END;
/
CREATE OR REPLACE TRIGGER WATCH_UPD
BEFORE UPDATE ON Watch FOR EACH ROW
BEGIN
ins_watch_hist
(
:OLD.id, :OLD.value
);
END;
/
UPDATE watch SET value = 3;
COMMIT;
INSERT INTO Run_Stats SELECT 'after 2', stats.* FROM stats;
SELECT A.name,
B.value - A.value "b-a",
C.value - B.value "c-b",
C.value - B.value - ( B.value - A.value ) diff
FROM Run_Stats A,
Run_Stats B,
Run_Stats C
WHERE A.name = B.name
AND C.name = B.name
AND A.runid = 'before'
AND B.runid = 'after 1'
AND C.runid = 'after 2'
AND C.value != A.value
ORDER BY ABS( diff ) DESC;
NAME b-a c-b DIFF
------------------------------------------------ ---------- ---------- ----------
STAT...session pga memory max 4919092 1049112 -3869980
STAT...session pga memory 4263732 1114648 -3149084
STAT...redo size 22686468 22739844 53376
STAT...table scan rows gotten 33957 35459 1502
LATCH.library cache 68938 70374 1436
STAT...session logical reads 107064 105948 -1116
LATCH.simulator hash latch 7226 6170 -1056
STAT...bytes received via SQL*Net from client 1055 2005 950
LATCH.library cache pin 68607 69429 822
LATCH.shared pool 34469 35280 811
STAT...consistent gets 1560 857 -703
STAT...consistent gets - examination 1196 542 -654
STAT...dirty buffers inspected 815 1438 623
I expected to see a measurable REDUCTION in library cache latches. What's wrong with my approach?
thanks in advance,
Thomas
October 03, 2007 - 5:22 pm UTC
you ran one update statement in each??
run a couple hundred, then measure.
and you are hard parsing first time around - you just created the table.
we want to see that the sql in the trigger gets parsed everytime a client executes a statement, whereas the statement is cached if plsql does it:
ops$tkyte%ORA10GR2> create table t1 ( x int );
Table created.
ops$tkyte%ORA10GR2> create table t2 ( x int );
Table created.
ops$tkyte%ORA10GR2> create table t3 ( x int );
Table created.
ops$tkyte%ORA10GR2> insert into t1 values ( 1 );
1 row created.
ops$tkyte%ORA10GR2> insert into t2 values ( 1 );
1 row created.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create or replace procedure t2_proc( p_x in number )
2 as
3 begin
4 insert into t3 (x) values ( p_x );
5 end;
6 /
Procedure created.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create or replace trigger t1
2 after update on t1 for each row
3 begin
4 insert into t3 values (:new.x);
5 end;
6 /
Trigger created.
ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> create or replace trigger t2
2 after update on t2 for each row
3 begin
4 t2_proc(:new.x);
5 end;
6 /
Trigger created.
ops$tkyte%ORA10GR2> exec dbms_monitor.session_trace_enable;
PL/SQL procedure successfully completed.
ops$tkyte%ORA10GR2> begin
2 for i in 1 .. 1000
3 loop
4 execute immediate 'update t1 x'||mod(i,2) || ' set x = x+1';
5 end loop;
6 end;
7 /
PL/SQL procedure successfully completed.
ops$tkyte%ORA10GR2> begin
2 for i in 1 .. 1000
3 loop
4 execute immediate 'update t2 x'||mod(i,2) || ' set x = x+1';
5 end loop;
6 end;
7 /
PL/SQL procedure successfully completed.
the execute immediate helps in 10g - cause 10g plsql cached dynamic sql, we want to mimick a client applications typical work - parse, execute, close.
tkprof says:
INSERT INTO T3 VALUES (:B1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1000 0.03 0.04 0 0 0 0
Execute 1000 0.09 0.10 0 1001 3042 1000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2000 0.13 0.14 0 1001 3042 1000
********************************************************************************
INSERT INTO T3 (X) VALUES ( :B1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1000 0.09 0.07 0 3 1030 1000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1001 0.09 0.07 0 3 1030 1000
you do this to reduce the parsing.
test of the same code
Fabian, August 25, 2011 - 7:16 am UTC
I've run some part of your first example as follow :
exec runstats_pkg.rs_start;
declare
l_cursor demo_pkg.rc;
l_num number;
begin
for i in 1 .. 1000
loop
demo_pkg.parse1( l_cursor );
fetch l_cursor into l_num;
close l_cursor;
end loop;
end;
/
exec runstats_pkg.rs_middle;
declare
l_cursor demo_pkg.rc;
l_num number;
begin
for i in 1 .. 1000
loop
demo_pkg.parse1( l_cursor );
fetch l_cursor into l_num;
close l_cursor;
end loop;
end;
/
exec runstats_pkg.rs_stop(0);
so the second time I've run the same code as in first run
I've expected to get no difference but...
Run1 ran in 931 hsecs
Run2 ran in 630 hsecs
run 1 ran in 147.78% of the time
Name Run1 Run2 Diff
STAT...free buffer requested 0 1 1
LATCH.transaction branch alloc 3 2 -1
STAT...heap block compress 9 8 -1
STAT...SQL*Net roundtrips to/f 3 2 -1
STAT...execute count 1,004 1,003 -1
STAT...parse count (total) 1,003 1,002 -1
STAT...parse time cpu 0 1 1
STAT...session cursor cache co 1 0 -1
STAT...session cursor cache hi 1,003 1,002 -1
LATCH.Shared B-Tree 2 1 -1
LATCH.active checkpoint queue 3 2 -1
LATCH.lgwr LWN SCN 3 2 -1
LATCH.mostly latch-free SCN 3 2 -1
LATCH.KMG MMAN ready and start 3 2 -1
STAT...non-idle wait count 3 2 -1
LATCH.Change Notification Hash 3 2 -1
STAT...redo ordering marks 0 1 1
LATCH.session timer 3 2 -1
LATCH.job_queue_processes para 2 1 -1
LATCH.SQL memory manager latch 1 0 -1
LATCH.ksuosstats global area 1 0 -1
LATCH.kwqbsn:qsga 1 0 -1
LATCH.FOB s.o list latch 0 1 1
STAT...opened cursors cumulati 1,004 1,003 -1
STAT...redo subscn max counts 0 1 1
LATCH.PL/SQL warning settings 3 2 -1
STAT...calls to kcmgas 0 1 1
STAT...sql area evicted 3 1 -2
LATCH.ksz_so allocation latch 0 2 2
LATCH.OS process: request allo 0 2 2
LATCH.OS process allocation 18 16 -2
LATCH.channel handle pool latc 1 3 2
LATCH.resmgr:free threads list 0 2 2
LATCH.parameter table manageme 0 2 2
LATCH.session idle bit 13 15 2
LATCH.process group creation 0 2 2
LATCH.process allocation 0 2 2
LATCH.In memory undo latch 5 3 -2
LATCH.undo global data 11 9 -2
LATCH.dummy allocation 1 3 2
LATCH.resmgr:active threads 0 2 2
LATCH.ASM db client latch 6 4 -2
LATCH.JS slv state obj latch 1 3 2
STAT...user calls 6 4 -2
LATCH.space background task la 7 4 -3
LATCH.redo writing 12 9 -3
LATCH.simulator hash latch 1 4 3
STAT...consistent gets from ca 15 18 3
STAT...cleanout - number of kt 7 10 3
STAT...consistent gets - exami 7 10 3
STAT...consistent gets 15 18 3
STAT...active txn count during 7 10 3
STAT...CPU used by this sessio 8 11 3
LATCH.qmn task queue latch 4 0 -4
LATCH.object queue header heap 13 9 -4
LATCH.redo allocation 12 8 -4
LATCH.call allocation 0 4 4
LATCH.session allocation 1 5 4
STAT...parse time elapsed 10 6 -4
STAT...undo change vector size 3,336 3,332 -4
STAT...recursive cpu usage 5 9 4
STAT...consistent changes 29 33 4
STAT...db block changes 44 49 5
STAT...calls to kcmgcs 22 28 6
LATCH.OS process 1 7 6
LATCH.row cache objects 54 48 -6
LATCH.object queue header oper 15 9 -6
LATCH.shared pool simulator 52 45 -7
LATCH.active service list 20 12 -8
STAT...db block gets from cach 29 37 8
STAT...db block gets 29 37 8
STAT...workarea memory allocat 8 0 -8
LATCH.session switching 1 11 10
STAT...session logical reads 44 55 11
LATCH.cache buffers chains 182 168 -14
LATCH.channel operations paren 55 39 -16
LATCH.messages 88 64 -24
LATCH.shared pool 37 70 33
LATCH.JS queue state obj latch 72 36 -36
STAT...DB time 80 18 -62
LATCH.SQL memory manager worka 204 137 -67
LATCH.enqueues 158 80 -78
LATCH.enqueue hash chains 161 82 -79
LATCH.checkpoint queue latch 241 161 -80
STAT...redo size 4,416 4,516 100
STAT...bytes sent via SQL*Net 441 262 -179
STAT...Elapsed Time 931 631 -300
STAT...bytes received via SQL* 978 653 -325
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
1,610 1,233 -377 130.58% Even if diffs are small for this example they seems to not safe for some more complicated scenarios. How to resolve it (out of the running in more one, which I used to use:
3x
exec runstats_pkg.rs_start;
<b>code1;</b>
exec runstats_pkg.rs_middle;
<b>code2;</b>
exec runstats_pkg.rs_stop(500);
3x
exec runstats_pkg.rs_start;
<b>code2;</b>
exec runstats_pkg.rs_middle;
<b>code1;</b>
exec runstats_pkg.rs_stop(500);
but that's not "perfect".
It comes from my "private" database (no other users), 11.2.0.2.
And here you have results from 10.2.0.5 for the other issue (comparing two method of lobs loading to table) with treshold set to 500:
Name Run1 Run2 Diff
LATCH.shared pool 16 571 555
STAT...undo change vector size 2,928 2,320 -608
LATCH.done queue latch 134 756 622
LATCH.redo writing 171 894 723
LATCH.object queue header heap 220 952 732
STAT...Elapsed Time 481 1,280 799
LATCH.direct msg latch 135 936 801
LATCH.session queue latch 135 936 801
LATCH.mostly latch-free SCN 172 986 814
LATCH.messages 236 1,088 852
LATCH.redo allocation 188 1,046 858
LATCH.session allocation 262 1,344 1,082
LATCH.enqueues 256 1,542 1,286
LATCH.ksfv messages 269 1,692 1,423
LATCH.In memory undo latch 370 1,973 1,603
LATCH.session idle bit 390 2,364 1,974
LATCH.dml lock allocation 574 2,899 2,325
LATCH.simulator hash latch 440 2,934 2,494
LATCH.checkpoint queue latch 846 3,415 2,569
LATCH.undo global data 564 3,213 2,649
LATCH.library cache pin 715 3,715 3,000
LATCH.cache buffers lru chain 439 3,627 3,188
LATCH.row cache objects 573 4,188 3,615
LATCH.enqueue hash chains 975 5,418 4,443
LATCH.library cache lock 1,003 5,629 4,626
LATCH.library cache 1,211 6,720 5,509
LATCH.object queue header oper 1,053 8,229 7,176
LATCH.cache buffers chains 15,202 108,707 93,505
Looks like only STATS are more or less reliable.
Any comment, please?
August 30, 2011 - 4:19 pm UTC
elapsed times are really unpredictable. run it again and again and you'll seem run1 faster than run2, run2 faster than run1 and so on.
Perhaps better to use dbms_utility.get_CPU_time these days, that is what I use in my runstats now (wasn't available way back when)
and remember - latching is SYSTEM WIDE. If you are testing in a multi-user database - that can be wildly unpredictable. runstats is only really good for a single user instance.
Fabian, September 01, 2011 - 4:31 am UTC
maybe even it would be better to use hierarhical profiler instead runstats while using pl/sql these days.
anyway thank you for that comment.
regards,
September 01, 2011 - 8:19 am UTC
that shows time by line.
I'm trying to figure out "which approach is more scalable" - that comes down to resources (statistics) used and latching performed.
I might desire to use something that runs slower in single user mode than something else does - if it used a small fraction of some resource that must be shared.
If you are trying to tweak a plsql routine to run a bit faster by finding an inefficient algorithm - profiling (old or new) would be appropriate.
If you are trying to figure out what approach scales better - statistics, latches and locks - you want to reduce the amount of shared resources you need.
Especially in this example - the runtimes (in single user mode) would not be significantly different. However, the latch usage would be - that is what we were looking for, what our desired goal was. Profiling wouldn't have shown us that at all.