trace data followup
Jeff Price, September 06, 2002 - 9:08 am UTC
Thanks. That clears it up except for one thing. If the recursive sql statements aren't listed sequentially following a parent statement, then how can I find all the recursive statements that belong to a specific parent statement?
September 06, 2002 - 1:07 pm UTC
You cannot really, consider this code:
=====================
PARSING IN CURSOR #3 len=222 dep=0 uid=566 oct=47 lid=566 tim=53098119
declare
l_data number;
begin
for x in ( select f(rownum) r, rownum r2 from all_users where rownum < 10 )
loop
execute immediate 'select :x*:x from dual Y$' || x.r2
into l_data
using x.r, x.r;
end loop;
end;
dep=0, top level statement...
=====================
PARSING IN CURSOR #4 len=64 dep=1 uid=566 oct=3 lid=566 tim=53098121
SELECT F(ROWNUM) R,ROWNUM R2 FROM ALL_USERS WHERE ROWNUM < 10
dep=1, first level recursive sql -- you look backwards in the trace to find dep=0 to find the "parent" statement, it works for this one
=====================
PARSING IN CURSOR #5 len=29 dep=2 uid=566 oct=3 lid=566 tim=53098121
select sqrt(:x) from dual X$1
dep=2, second level recursive sql, look backwards to find dep=1 and you found the parent
=====================
PARSING IN CURSOR #5 len=26 dep=1 uid=566 oct=3 lid=566 tim=53098121
select :x*:x from dual Y$1
dep=1, first level recursive -- look backwards for 0 and you find it BUT...
=====================
PARSING IN CURSOR #5 len=29 dep=2 uid=566 oct=3 lid=566 tim=53098121
select sqrt(:x) from dual X$2
dep=2, we KNOW this "parent" is not the immediately prior statement but quite a few back. We cannot TELL that from the trace file, you have to "know" that from the SQL itself. We don't track that information...
=====================
PARSING IN CURSOR #5 len=26 dep=1 uid=566 oct=3 lid=566 tim=53098122
select :x*:x from dual Y$2
=====================
PARSING IN CURSOR #5 len=29 dep=2 uid=566 oct=3 lid=566 tim=53098122
select sqrt(:x) from dual X$3
=====================
PARSING IN CURSOR #5 len=26 dep=1 uid=566 oct=3 lid=566 tim=53098122
select :x*:x from dual Y$3
=====================
PARSING IN CURSOR #5 len=29 dep=2 uid=566 oct=3 lid=566 tim=53098122
select sqrt(:x) from dual X$4
Listing trace events sequentially
Mark Manning, September 06, 2002 - 11:04 am UTC
On every line that begins with "PARSING IN CURSOR", I use a combination of the timestamp (tim) column and the depth (dep) column to accomplish this. The tim value shows at what point something was requested in relation to other requests. This not only applies to parse/execute/fetch operations but also for parse/runtime errors.
I have found this to be VERY handy when researching the behavior of large complex procedures/packages as well as diagnosing problems.
The metalink doc 39817.1 gives a very good understanding of the contents of 10046 trace files.
As this is one way, I am sure Tom has another (probably simipler) way of determining this.
Mark M.
September 06, 2002 - 1:33 pm UTC
whoops -- I just showed it cannot be done! (not reliably anyway)....
Hmm....
frustrating....
Jeff Price, September 06, 2002 - 2:07 pm UTC
Well, that makes sense. I don't like it, but I guess I'll have to log a complaint with the oracle kernel developers. ;)
Basically, what I was trying to accomplish was to create a script to parse the trace file and gather all the associated wait info for each statement, and I wanted to list all the waits from all recursive sql under the initial (dep=0) parent statement. I figured if the dep=0 statement called the sql (directly or indirectly), then those waits should be associated with it.
But it looks like there's no way to make that association.
Damn... back to the drawing board.
frustrating....yes!
Mark Manning, September 06, 2002 - 4:40 pm UTC
Sometime ago, I wrote a program that reads 10046 trace files for the purposes complementing tkprof with regards to showing:
Summary of waits/cpu time/etc by SQL statement
Building of a "statement tree" by first parsing
Mapping subsequent exec/bind/fetch calls in relation to the session.
Here is the first few PARSING IN CURSOR lines of a trace file from an Oracle 8.1.7.4.1 EE instance running on Windoze 2000 Server. This trace file is a level 8 trace of a package that looks at data with given criteria, validates the rules for said criteria, and performs actions based upon those rules (I excluded all the Oracle internal SQL from the listing). The same procedure was executed six times, each with a different criteria.
PARSING IN CURSOR #1 len=52 dep=0 uid=54 oct=47 lid=54 tim=1958614 hv=2149188146 ad='4422cc8'
PARSING IN CURSOR #3 len=55 dep=1 uid=54 oct=98 lid=54 tim=1958797 hv=3020714499 ad='43c62d4'
PARSING IN CURSOR #3 len=72 dep=1 uid=54 oct=3 lid=54 tim=1960455 hv=3349640452 ad='43c113c'
PARSING IN CURSOR #12 len=68 dep=1 uid=54 oct=3 lid=54 tim=1960877 hv=4225966364 ad='4305aa8'
PARSING IN CURSOR #17 len=33 dep=1 uid=60 oct=42 lid=60 tim=1961741 hv=684019188 ad='42ae3dc'
PARSING IN CURSOR #22 len=68 dep=1 uid=60 oct=42 lid=60 tim=1961825 hv=2508626919 ad='420904c'
PARSING IN CURSOR #33 len=82 dep=1 uid=60 oct=7 lid=60 tim=1962180 hv=188990126 ad='42b8c50'
PARSING IN CURSOR #34 len=54 dep=1 uid=60 oct=3 lid=60 tim=1962196 hv=4137328418 ad='42658b8'
PARSING IN CURSOR #22 len=313 dep=1 uid=60 oct=2 lid=60 tim=1962210 hv=2584885057 ad='41ec77c'
PARSING IN CURSOR #35 len=474 dep=1 uid=60 oct=3 lid=60 tim=1962281 hv=302028352 ad='42653d0'
PARSING IN CURSOR #36 len=129 dep=1 uid=60 oct=3 lid=60 tim=1962396 hv=4027223860 ad='4264248'
PARSING IN CURSOR #22 len=100 dep=1 uid=60 oct=3 lid=60 tim=1962445 hv=851802408 ad='41cf0e8'
PARSING IN CURSOR #37 len=258 dep=1 uid=60 oct=3 lid=60 tim=1962461 hv=47320436 ad='42b61bc'
PARSING IN CURSOR #17 len=43 dep=1 uid=54 oct=3 lid=54 tim=1962560 hv=2132789873 ad='42ec1ac'
PARSING IN CURSOR #39 len=176 dep=1 uid=60 oct=3 lid=60 tim=1962655 hv=365793532 ad='42656c4'
PARSING IN CURSOR #22 len=63 dep=1 uid=60 oct=62 lid=60 tim=1962907 hv=3008036782 ad='418facc'
PARSING IN CURSOR #41 len=301 dep=1 uid=60 oct=3 lid=60 tim=1963438 hv=3432234351 ad='42b8574'
PARSING IN CURSOR #42 len=134 dep=1 uid=60 oct=6 lid=60 tim=1963553 hv=1545559916 ad='4260d6c'
When I run the entire trace file through my program, here is what I get (excluding the Oracle internal SQL):
Sequential listing of statements.
2149188146:4422cc8 1958614 (USER) PL/SQL EXECUTE
3020714499:43c62d4 1958797 (USER) ALTER PACKAGE BODY
3349640452:43c113c 1960455 (USER) SELECT
4225966364:4305aa8 1960877 (USER) SELECT
684019188:42ae3dc 1961741 (USER) ALTER SESSION
2508626919:420904c 1961825 (USER) ALTER SESSION
188990126:42b8c50 1962180 (USER) DELETE
4137328418:42658b8 1962196 (USER) SELECT
2584885057:41ec77c 1962210 (USER) INSERT
302028352:42653d0 1962281 (USER) SELECT
4027223860:4264248 1962396 (USER) SELECT
851802408:41cf0e8 1962445 (USER) SELECT
47320436:42b61bc 1962461 (USER) SELECT
2132789873:42ec1ac 1962560 (USER) SELECT
365793532:42656c4 1962655 (USER) SELECT
3008036782:418facc 1962907 (USER) ANALYZE TABLE
3432234351:42b8574 1963438 (USER) SELECT
1545559916:4260d6c 1963553 (USER) UPDATE
624084522:4265bdc 1963570 (USER) UPDATE
2694197967:413273c 1963578 (USER) ALTER SESSION
3879039368:41314dc 1963585 (USER) ALTER SESSION
2725910552:41304ac 1963591 (USER) ALTER SESSION
1096768091:412fb70 1963598 (USER) ALTER SESSION
1697159799:412ecd0 1963613 (USER) PL/SQL EXECUTE
464775564:3f9ffb8 2009021 (USER) PL/SQL EXECUTE
4225966364:4305aa8 2009027 (USER) SELECT
684019188:42ae3dc 2009096 (USER) ALTER SESSION
2508626919:420904c 2009104 (USER) ALTER SESSION
2584885057:41ec77c 2009117 (USER) INSERT
3778901711:42636fc 2009127 (USER) SELECT
4289283319:42b6eb0 2009134 (USER) SELECT
3009714825:42b72d4 2009147 (USER) SELECT
2349399529:3fa5cb4 2009153 (USER) SELECT
813450063:4261730 2009170 (USER) UPDATE
2694197967:413273c 2009183 (USER) ALTER SESSION
3879039368:41314dc 2009189 (USER) ALTER SESSION
2725910552:41304ac 2009194 (USER) ALTER SESSION
1096768091:412fb70 2009200 (USER) ALTER SESSION
4199142592:42659e8 2009205 (USER) UPDATE
2694197967:413273c 2009216 (USER) ALTER SESSION
3879039368:41314dc 2009221 (USER) ALTER SESSION
2725910552:41304ac 2009226 (USER) ALTER SESSION
1096768091:412fb70 2009232 (USER) ALTER SESSION
1697159799:412ecd0 2009243 (USER) PL/SQL EXECUTE
3806514016:3f99378 2011824 (USER) UPDATE
1697159799:412ecd0 2011831 (USER) PL/SQL EXECUTE
544032647:3f9cdec 2014453 (USER) INSERT
1697159799:412ecd0 2014461 (USER) PL/SQL EXECUTE
3629519191:4089c68 2014661 (USER) COMMIT
464775564:3f9ffb8 2015220 (USER) PL/SQL EXECUTE
4225966364:4305aa8 2015227 (USER) SELECT
684019188:42ae3dc 2015296 (USER) ALTER SESSION
2508626919:420904c 2015303 (USER) ALTER SESSION
2584885057:41ec77c 2015315 (USER) INSERT
2349399529:3fa5cb4 2015336 (USER) SELECT
2694197967:413273c 2015354 (USER) ALTER SESSION
3879039368:41314dc 2015360 (USER) ALTER SESSION
2725910552:41304ac 2015365 (USER) ALTER SESSION
1096768091:412fb70 2015371 (USER) ALTER SESSION
2694197967:413273c 2015382 (USER) ALTER SESSION
3879039368:41314dc 2015387 (USER) ALTER SESSION
2725910552:41304ac 2015392 (USER) ALTER SESSION
1096768091:412fb70 2015398 (USER) ALTER SESSION
1697159799:412ecd0 2015410 (USER) PL/SQL EXECUTE
464775564:3f9ffb8 2018177 (USER) PL/SQL EXECUTE
4225966364:4305aa8 2018184 (USER) SELECT
684019188:42ae3dc 2018253 (USER) ALTER SESSION
2508626919:420904c 2018285 (USER) ALTER SESSION
2584885057:41ec77c 2018297 (USER) INSERT
2349399529:3fa5cb4 2018318 (USER) SELECT
62186039:3f97788 2018334 (USER) LOCK TABLE
2694197967:413273c 2018350 (USER) ALTER SESSION
3879039368:41314dc 2018355 (USER) ALTER SESSION
2725910552:41304ac 2018361 (USER) ALTER SESSION
1096768091:412fb70 2018366 (USER) ALTER SESSION
2694197967:413273c 2018377 (USER) ALTER SESSION
3879039368:41314dc 2018383 (USER) ALTER SESSION
2725910552:41304ac 2018388 (USER) ALTER SESSION
1096768091:412fb70 2018393 (USER) ALTER SESSION
1697159799:412ecd0 2018405 (USER) PL/SQL EXECUTE
464775564:3f9ffb8 2021861 (USER) PL/SQL EXECUTE
4225966364:4305aa8 2021868 (USER) SELECT
684019188:42ae3dc 2021937 (USER) ALTER SESSION
2508626919:420904c 2021967 (USER) ALTER SESSION
2584885057:41ec77c 2021979 (USER) INSERT
2349399529:3fa5cb4 2022000 (USER) SELECT
62186039:3f97788 2022018 (USER) LOCK TABLE
2694197967:413273c 2022033 (USER) ALTER SESSION
3879039368:41314dc 2022039 (USER) ALTER SESSION
2725910552:41304ac 2022044 (USER) ALTER SESSION
1096768091:412fb70 2022049 (USER) ALTER SESSION
2694197967:413273c 2022060 (USER) ALTER SESSION
3879039368:41314dc 2022066 (USER) ALTER SESSION
2725910552:41304ac 2022072 (USER) ALTER SESSION
1096768091:412fb70 2022077 (USER) ALTER SESSION
1697159799:412ecd0 2022088 (USER) PL/SQL EXECUTE
464775564:3f9ffb8 2029232 (USER) PL/SQL EXECUTE
4225966364:4305aa8 2029238 (USER) SELECT
684019188:42ae3dc 2029309 (USER) ALTER SESSION
2508626919:420904c 2029342 (USER) ALTER SESSION
2584885057:41ec77c 2029354 (USER) INSERT
2349399529:3fa5cb4 2029376 (USER) SELECT
62186039:3f97788 2029391 (USER) LOCK TABLE
1519337442:3f8b3f8 2029396 (USER) DELETE
2640875297:3f7df58 2029403 (USER) SELECT
2694197967:413273c 2029457 (USER) ALTER SESSION
3879039368:41314dc 2029463 (USER) ALTER SESSION
2725910552:41304ac 2029468 (USER) ALTER SESSION
1096768091:412fb70 2029474 (USER) ALTER SESSION
1697159799:412ecd0 2029483 (USER) PL/SQL EXECUTE
The spacing on the left of the hash value:sql address is meant to show its recursion depth. When I step through each statement, it correctly maps to the order it should run in the package.
Now in your example, I can see where the EXECUTE IMMEDIATE causes issues because it has to reparse (soft if previously executed) the statement as opposed to DBMS_SQL.PARSE once and DBMS_SQL.EXECUTE/BIND many times. However, where you have a subquery in a for loop that calls a function, it appears to reparse it at each call as opposed to putting this in a explicit cursor.
I rewrote your example (without the function) using explicit and implicit cursors in a procedure on a Oracle 9.0.1.1.1 EE instance.
create or replace procedure tracetest as
begin
declare
l_data number;
cursor c_select is
select rownum r, rownum r2
from all_users
where rownum < 10;
begin
for i_select in c_select
loop
select i_select.r*i_select.r
into l_data
from dual;
end loop;
end;
end tracetest;
After running the procedure with event 10046 enabled on 9.0.1, I got this:
PARSING IN CURSOR #1 len=70 dep=0 uid=19 oct=42 lid=19 tim=128114344 hv=567314799 ad='7b08cfe0'
alter session set events = '10046 trace name context forever, level 1'
END OF STMT
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=128114344
=====================
PARSING IN CURSOR #1 len=23 dep=0 uid=19 oct=47 lid=19 tim=130739344 hv=3047870254 ad='7b091618'
BEGIN tracetest; END;
END OF STMT
PARSE #1:c=15625,e=16000,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=130739344
=====================
PARSING IN CURSOR #2 len=61 dep=1 uid=19 oct=3 lid=19 tim=130739344 hv=2765231765 ad='7b1093e0'
SELECT rownum r, rownum r2
from all_users
where rownum < 10
END OF STMT
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=130739344
FETCH #2:c=0,e=0,p=0,cr=5,cu=2,mis=0,r=1,dep=1,og=4,tim=130739344
=====================
PARSING IN CURSOR #4 len=33 dep=1 uid=19 oct=3 lid=19 tim=132786344 hv=2102796684 ad='7b109cd4'
SELECT :b1*:b1
from dual
END OF STMT
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=132786344
FETCH #4:c=0,e=0,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=132786344
FETCH #2:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=132786344
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=134833344
FETCH #4:c=0,e=0,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=134833344
FETCH #2:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=134833344
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=136880344
FETCH #4:c=0,e=0,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=136880344
FETCH #2:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=136895344
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=138942344
FETCH #4:c=0,e=0,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=138942344
FETCH #2:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=138942344
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=140989344
FETCH #4:c=0,e=0,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,tim=140989344
FETCH #2:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=140989344
EXEC #1:c=15625,e=10250000,p=0,cr=40,cu=12,mis=0,r=1,dep=0,og=4,tim=140989344
XCTEND rlbk=0, rd_only=1
While it does show the parse once, execute/fetch many times, it does not show the tim value increasing. This appears to do the same thing on your example as well. Hmmmm. Has something changed with regards to the tim column on 9i? Here is an snippet from the recently updated Metalink Doc 39817.1:
tim Timestamp.
Pre-Oracle9i, the times recorded by Oracle only have a resolution
of 1/100th of a second (10mS). As of Oracle9i some times are
available to microsecond accuracy (1/1,000,000th of a second).
The timestamp can be used to determine times between points
in the trace file.
The value is the value in V$TIMER when the line was written.
If there are TIMESTAMPS in the file you can use the difference
between 'tim' values to determine an absolute time.
Ok, something has changed. However, I find it hard to believe that all statements run within 1 microsecond! So I run it on the 8.1.7 instance (both the 8.1.7 and 9.0.1 are on the same machine). Here is the tracefile for 8.1.7:
PARSING IN CURSOR #1 len=71 dep=0 uid=43 oct=42 lid=43 tim=55117728 hv=2762293374 ad='80ab8ac8'
alter session set events = '10046 trace name context forever, level 1'
END OF STMT
EXEC #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=55117728
=====================
PARSING IN CURSOR #1 len=23 dep=0 uid=43 oct=47 lid=43 tim=55118061 hv=3047870254 ad='80e289d8'
BEGIN tracetest; END;
END OF STMT
PARSE #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=55118061
=====================
PARSING IN CURSOR #2 len=61 dep=1 uid=43 oct=3 lid=43 tim=55118065 hv=1151295142 ad='817ff0ec'
SELECT ROWNUM R,ROWNUM R2 FROM ALL_USERS WHERE ROWNUM < 10
END OF STMT
PARSE #2:c=3,e=4,p=4,cr=26,cu=1,mis=1,r=0,dep=1,og=4,tim=55118065
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118065
FETCH #2:c=0,e=0,p=0,cr=14,cu=4,mis=0,r=1,dep=1,og=4,tim=55118065
=====================
PARSING IN CURSOR #3 len=29 dep=1 uid=43 oct=3 lid=43 tim=55118065 hv=974541619 ad='8234aef0'
SELECT :b1 * :b1 FROM DUAL
END OF STMT
PARSE #3:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=55118065
EXEC #3:c=1,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118065
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118065
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118065
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118065
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118065
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118065
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118066
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118066
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118066
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118066
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118066
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=1,og=4,tim=55118066
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
FETCH #3:c=0,e=0,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=55118066
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=55118066
EXEC #1:c=4,e=5,p=4,cr=201,cu=41,mis=0,r=1,dep=0,og=4,tim=55118066
Looking at this trace file, the same query on the same machine takes longer than 1 microsecond. One important item I would like to point out is the value in the tim column on the 9.0.1 trace file never changes after I issue the alter session set events statement (it always shows tim=128114344). I know several seconds elapsed between the time I typed the alter session and the exec statement in SQLPlus. Possible bug or side effect from the 9i changes?
So what have I learned???
Need to go back to my program and account for EXECUTE IMMEDIATE and "FOR cursor subquery" behavior.
Need to open an iTar about the tim column value in 9i.
As usual, it is a pleasure to read and share ideas in your forum.
Mark M.
September 06, 2002 - 7:31 pm UTC
Hey, I purposely did an example to show it couldn't always be done -- you are right tho -- in a WELL WRITTEN APP -- it won't happen this way (notice that I made the queries UNIQUE -- thats bad, i used dynamic sql where I didn't need to -- thats bad, but I did it to show that in general, you cannot do this dependency stuff)
It must be a windoze specific thingy with the timing however. On solaris I got:
PARSING IN CURSOR #3 len=33 dep=1 uid=187 oct=3 lid=187 tim=1031354825104976 hv=
2102796684 ad='82b03408'
SELECT :b1*:b1
from dual
END OF STMT
PARSE #3:c=0,e=847,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1031354825104959
EXEC #3:c=0,e=389,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1031354825105628
FETCH #3:c=0,e=114,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1031354825105826
FETCH #2:c=0,e=199,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=1031354825106223
EXEC #3:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1031354825106463
...
that was with:
ops$tkyte@ORA9I.WORLD> select * from v$version
2 /
BANNER
----------------------------------------------------------------
Oracle9i Enterprise Edition Release 9.0.1.2.0 - Production
PL/SQL Release 9.0.1.2.0 - Production
CORE 9.0.1.2.0 Production
TNS for Solaris: Version 9.0.1.2.0 - Production
NLSRTL Version 9.0.1.2.0 - Production
and similar result on LINUX (which I have overlaid ontop of ALL of my windows machines finally!!!! Laptop and both desktops... Got my dual monitors at 1600x1200 each going and loving it -- all unix all the time. You know, it is slightly faster too ;) with 9iR2.
Very true
Mark Manning, September 06, 2002 - 9:50 pm UTC
Very true. I was not looking at it from that perspective and was worried that I was way off base or really lucky. It is good to know where the "one offs" are. Thank you for pointing this out. While your example has undesirable side effects that a majority of experienced professionals would not implement in a production environment, it is only a matter of time that I run across one that is like that.
As for the Windoze, not my call. At home, I run SuSE (kernel 2.4.18) on Dual PIII 1.2GHz, 2GB RAM, 6 100GB 7200RPM IDE drives, and Matrox G450 Dual Head each connected to a 17" Sony monitor. Been using Linux for years and loving it. Glad Oracle jumped on the Linux bandwagon. Faster, more stable, and more friendly (Unix IS user friendly, it is just picky as to who it is friends with).
One final food for thought. Two things that came out of Berkley:
1) Unix
2) Acid
Concidence???
Have a good weekend.
ouch!
Jeff Price, September 07, 2002 - 11:23 pm UTC
Ok, now my head is starting to hurt.
Maybe it can't be oversimplified like this, but I'd like to know, given the following:
1) PARSING IN CURSOR #1 len=52 dep=0.....
2) PARSING IN CURSOR #3 len=55 dep=1.....
3) PARSING IN CURSOR #3 len=72 dep=0.....
4) PARSING IN CURSOR #5 len=68 dep=1.....
Is it possible for statement 1 to be the parent of statement of number 4??
(...why do I get the feeling the answer to this will be a solid maybe)
September 08, 2002 - 9:42 am UTC
Is it posible -- sure.
Yes, but it would take a very specific set of actions. It could but I would probably have to write a bit of Pro*C code to do it. It would take a bit of setup (eg: cursor #5 would have been opened and cached previously and we are reusing it) and such but it could happen.
Raw trace information
Neil, May 24, 2004 - 8:07 am UTC
Cary Milsap's book Optimising Oracle Performance was probably published too late for this discussion thread - but has all the information required to interpret the trace file. My problem is turning the trace on from within a pro*C program. I tried this,
EXEC SQL EXECUTE IMMEDIATE 'alter session set events ''10064 trace name context forever, level 12''';
and got nothing! I get tons of output if I use
EXEC SQL alter session set trace=true but I get no wait information. I cannot do this from within a pl/sql block either - I have to issue the alter session command and then call the procedure.
How can I get level 8 or 12 trace information from a pro*c program or a pl/sql program without tracing the whole session?
I'm on 8.1.7
May 24, 2004 - 8:39 am UTC
EXEC SQL ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
has always worked for me.
Follow up to September 6 2002 follow up
malcolm, June 29, 2004 - 10:21 am UTC
<quote>
=====================
PARSING IN CURSOR #5 len=29 dep=2 uid=566 oct=3 lid=566 tim=53098121
select sqrt(:x) from dual X$2
dep=2, we KNOW this "parent" is not the immediately prior statement but quite
a few back. We cannot TELL that from the trace file, you have to "know" that
from the SQL itself. We don't track that information...
=====================
</quote>
You can tell from the trace file because the EXEC and FETCH are immediately succeeded by the FETCH for the parent statement. Or am I wrong?
e.g. from my trace file of your example:
=====================
PARSING IN CURSOR #3 len=29 dep=2 uid=61 oct=3 lid=61 tim=91232595225 hv=1711304324 ad='6d3487b4'
select sqrt(:x) from dual x$2
END OF STMT
PARSE #3:c=10015,e=1457,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=0,tim=91232595195
BINDS #3:
bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=03 oacfl2=1 size=24 offset=0
bfp=0891543c bln=22 avl=02 flg=05
value=2
EXEC #3:c=0,e=892,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=91232596405
FETCH #3:c=0,e=174,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=4,tim=91232596677
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=222 op='TABLE ACCESS FULL DUAL '
FETCH #2:c=10015,e=4058,p=0,cr=10,cu=0,mis=0,r=1,dep=1,og=4,tim=91232597246
=====================
I can tell that this query, #3 (#5 in your trace), parent query was the query last parsed as #2 (#4 in your trace).
Also:
1) Do these # numbers refer to slots in the PL/SQL session_cached_cursors cache?
2) Was the #5 (in your trace) slot reused (not cached) because it was native dynamic SQL?
3) In 10g I've heard Oracle can cache open cursors from native dynamic SQL. Does this mean that if this example were run on 10g, we'd see the # numbers getting higher, as the open cursors are left cached for possible reuse?
Thanks very much.
June 29, 2004 - 4:08 pm UTC
how can you tell -- how about we stick with the original exmaple, how can you tell using just the trace who is the parent of whom?
1) these numbers are cursor #'s, like an array index. start at one and go up -- they are indexes into a array really.
2) correct, NDS in 9i and before always parse/bind/execute/closed them
3) correct.
Turn on/off 10046 inside plsql
Marcio, August 11, 2004 - 9:32 am UTC
Tom, I'm trying figure it out... but, always catch the permission problem -- could you help with this.
I want put some more piece of instrumentation on my code -- like trace 10046 (on/off) So I tried this:
---------------------------
set echo on
drop table t;
create table t ( x int );
create or replace
procedure p ( p_ntimes number, p_trace boolean )
is
l_trace_on varchar2(100) :=
'alter session set events ''10046 trace name context forever, level 12'' ';
l_trace_off varchar2(100) :=
'alter session set events ''10046 trace name context off'' ';
begin
dbms_output.put_line ( l_trace_on );
if ( p_trace ) then
execute immediate l_trace_on;
end if;
for x in 1 .. p_ntimes
loop
insert into t values ( x );
end loop;
commit;
if ( p_trace ) then
execute immediate l_trace_off;
end if;
dbms_output.put_line ( l_trace_off );
end;
/
show error
exec p( 100, true )
set echo off
---------------------------
And have got this:
ops$mportes@FCCUAT9I> create table t ( x int );
Table created.
ops$mportes@FCCUAT9I>
ops$mportes@FCCUAT9I> create or replace
2 procedure p ( p_ntimes number, p_trace boolean )
3 is
4 l_trace_on varchar2(100) :=
5 'alter session set events ''10046 trace name context forever, level 12'' ';
6
7 l_trace_off varchar2(100) :=
8 'alter session set events ''10046 trace name context off'' ';
9 begin
10 dbms_output.put_line ( l_trace_on );
11
12 if ( p_trace ) then
13 execute immediate l_trace_on;
14 end if;
15
16 for x in 1 .. p_ntimes
17 loop
18 insert into t values ( x );
19 end loop;
20 commit;
21
22 if ( p_trace ) then
23 execute immediate l_trace_off;
24 end if;
25
26 dbms_output.put_line ( l_trace_off );
27 end;
28 /
Procedure created.
ops$mportes@FCCUAT9I> show error
No errors.
ops$mportes@FCCUAT9I>
ops$mportes@FCCUAT9I> exec p( 100, true )
alter session set events '10046 trace name context forever, level 12'
BEGIN p( 100, true ); END;
*
ERROR at line 1:
ORA-01031: insufficient privileges
ORA-06512: at "OPS$MPORTES.P", line 12
ORA-06512: at line 1
Thank you.
q on enabling trace dynamically from middle tier
A reader, August 11, 2004 - 12:10 pm UTC
hi tom
we use connection pooling in our middle tier. I am thinking
of having a feature wherein you can enable trace for
a ui page by a flag in the url. However, since i get a
connection from the pool, how do I ensure that at the end
of returning the connection back, I set its trace level
to the same as it was when it was handed over to me (if I
change it to start trace for my ui page)?
thank you!!
August 11, 2004 - 1:44 pm UTC
you can use dbms_system to read_ev and set_ev (to read the event and write the event -- the 10046 event)
thanx!
A reader, August 11, 2004 - 2:30 pm UTC
Ravi, July 21, 2005 - 3:04 am UTC
Tom,
10046, raw output does not seem to record PL/SQL errors including errors during Fetch, No_data_found, User-defined exceptions. But it records if a SQL fails pretty well (e.g an Update statement raising a value error etc).
Is this a feature?
desc tx
Name Null? Type
----------------------------------------- -------- ----------------------------
VAL NUMBER
BEGIN
DECLARE
a VARCHAR2 (1);
BEGIN
SELECT 'sasfdasf'
INTO a
FROM DUAL;
EXCEPTION
WHEN OTHERS
THEN
NULL;
END;
DECLARE
x VARCHAR2 (100);
BEGIN
SELECT 'asfdsaf'
INTO x
FROM DUAL
WHERE dummy = 'Y';
EXCEPTION
WHEN NO_DATA_FOUND
THEN
NULL;
END;
BEGIN
UPDATE tx
SET val = 'AFSDFAS';
EXCEPTION
WHEN OTHERS
THEN
NULL;
END;
DECLARE
resource_busy EXCEPTION;
PRAGMA EXCEPTION_INIT (resource_busy, -54);
BEGIN
RAISE resource_busy;
EXCEPTION
WHEN OTHERS
THEN
NULL;
END;
END;
/
In the above code the only error recorded in the trace file is the Update one. Don't get me wrong, it is not my character to code when-others null. But I am doing a feasibility study to look into all code (Forms, Reports) to use Raw output to check for any 'invisible' when-others null exceptions.
Cheers
Ravi
July 21, 2005 - 8:00 am UTC
no data found is not an error, it is "an event", it is a fake error raised by the plsql runtime engine - it is "syntax", it is not a database error.
same with user defined errors
dbms_trace can be used to capture exceptions.
A reader, July 26, 2005 - 10:41 am UTC
select count(*) from programs
END OF STMT
PARSE #1:c=0,e=175,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=176546314366
BINDS #1:
EXEC #1:c=0,e=172,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=176546314801
WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=203,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=3,tim=176546315182
WAIT #1: nam='SQL*Net message from client' ela= 466 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=176546315807
Why fetch twice?
Guess: It has to do a Second Fetch to check for %NOTFOUND, even if all it wants to do is STOP?
Cheers
Ravi
July 26, 2005 - 10:51 am UTC
this is a sqlplus'ism. sqlplus fetches 1 row and then starts fetching 15 at a time. a NORMAL REAL program won't do that
PARSING IN CURSOR #18 len=62 dep=0 uid=43 oct=47 lid=43 tim=1096083018183372 hv=3524710178 ad='63adb7b8'
declare c number; begin select count(*) into c from dual; end;
END OF STMT
PARSE #18:c=20000,e=41764,p=4,cr=62,cu=0,mis=1,r=0,dep=0,og=4,tim=1096083018183364
BINDS #18:
=====================
PARSING IN CURSOR #19 len=25 dep=1 uid=43 oct=3 lid=43 tim=1096083018184025 hv=1613982543 ad='63ac4358'
SELECT COUNT(*) FROM DUAL
END OF STMT
PARSE #19:c=10000,e=398,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1096083018184016
BINDS #19:
EXEC #19:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1096083018184240
FETCH #19:c=0,e=55,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1096083018184327
EXEC #18:c=10000,e=887,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1096083018184401
WAIT #18: nam='SQL*Net message to client' ela= 2 p1=1650815232 p2=1 p3=0
WAIT #18: nam='SQL*Net message from client' ela= 1018 p1=1650815232 p2=1 p3=0
A reader, July 27, 2005 - 7:13 am UTC
=====================
PARSING IN CURSOR #1 len=94 dep=0 uid=432 oct=47 lid=432 tim=248060680926 hv=350
9760775 ad='8d3f6108'
declare
a number;
begin
Select dummy into a from dual;
exception
when others then null;
end;
END OF STMT
PARSE #1:c=10000,e=9384,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,tim=248060680916
BINDS #1:
=====================
PARSING IN CURSOR #2 len=22 dep=1 uid=432 oct=3 lid=432 tim=248060682497 hv=2450
377988 ad='90af63b8'
SELECT DUMMY FROM DUAL
END OF STMT
PARSE #2:c=0,e=956,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=3,tim=248060682490
BINDS #2:
EXEC #2:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=248060682704
FETCH #2:c=0,e=184,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,tim=248060682926
EXEC #1:c=0,e=2020,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=3,tim=248060683302
WAIT #1: nam='SQL*Net message to client' ela= 6 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 350 p1=1650815232 p2=1 p3=0
=====================
Again, is the above part of the 'fake' errors, ie its the PL/SQL engine that should report the problem?
July 27, 2005 - 10:11 am UTC
the above shows that a select into from plsql does one fetch.
plsql asked for 2 rows, got one and said "cool, thanks". There is no "fake error"
the select into worked perfectly.
A reader, July 27, 2005 - 11:00 am UTC
I take it you noticed the PL/SQL actually failed, that although it took the row, it hit a Value Error.
1) The question is now, is it PL/SQL's responsibility to return the error?
Consider this trace
=====================
PARSING IN CURSOR #1 len=31 dep=0 uid=432 oct=3 lid=432 tim=250357319773 hv=1175
170405 ad='8c6118c8'
select to_number(owner) from tz
END OF STMT
PARSE #1:c=0,e=1467,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,tim=250357319759
BINDS #1:
EXEC #1:c=0,e=138,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=250357320094
WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=204,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=3,tim=250357320475
WAIT #1: nam='SQL*Net break/reset to client' ela= 4 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net break/reset to client' ela= 138 p1=1650815232 p2=0 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 4138099 p1=1650815232 p2=1 p3=0
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=455676 op='TABLE ACCESS FULL TZ '
=====================
Here the column "owner" in the Select is actually of type Character. A To_char would have failed in SQL? In that case an error should have been returned by SQL? A fetch does return 0 rows cnt=0.
But the cnt in STAT says 1 row output and also there is a 'SQL*Net break' to client. Can these 3 events be put together to assume something bad has happened?
July 27, 2005 - 12:37 pm UTC
you are confusing me here -- no context WHATSOEVER.
PLSQL actually failed... WHAT plsql? where?
what is tz, but I see it is EMPTY so no failure.
The select to_number(owner) from tz would not fail due to owner being a character string UNLESS and UNTIL there is a row that isn't a number.
And there were NONE.
Now, PLSQL would have raised the exception NO_DATA_FOUND, since not finding data is NOT an error of course (else there would be NO successful SQL in the world!)
Ignore the count in the stat record, look a the r= in the EXEC record. NO DATA.
I'm not really sure where you are going or what you are trying to analyze here?
A reader, July 28, 2005 - 4:26 am UTC
Sorry for being a bit unclear, my objective was to study outputs of 10046 trace when error happens. First I ran a SQL query which would hit a Invalid Number and then I ran a PL/SQL select from dummy that would hit a Numerical Error which has been 'masked' by a When-others-null. In either case I am hoping the 10046 gives some indication that an error actually happened.
drop table tz;
create table tz as select owner from all_objects where rownum < 10;
alter session set events '10046 trace name context forever, level 12';
select to_number(owner) from tz;
declare
a number;
begin
Select dummy into a from dual;
exception
when others then null;
end;
/
I don't get an error in the 10046 trace file, instead the (partial) output goes for the statement "select to_number(owner) from tz;"
=====================
PARSING IN CURSOR #2 len=32 dep=0 uid=432 oct=3 lid=432 tim=322776437468 hv=3702
632006 ad='915943e8'
select to_number(owner) from tz
END OF STMT
PARSE #2:c=10000,e=18240,p=0,cr=10,cu=0,mis=1,r=0,dep=0,og=3,tim=322776437459
BINDS #2:
EXEC #2:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=322776437757
WAIT #2: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #2: nam='SQL*Net message from client' ela= 795 p1=1413697536 p2=1 p3=0
WAIT #2: nam='db file sequential read' ela= 51 p1=118 p2=126925 p3=1
FETCH #2:c=0,e=767,p=1,cr=3,cu=0,mis=0,r=0,dep=0,og=3,tim=322776439636
WAIT #2: nam='SQL*Net break/reset to client' ela= 3 p1=1413697536 p2=1 p3=0
WAIT #2: nam='SQL*Net break/reset to client' ela= 472 p1=1413697536 p2=0 p3=0
WAIT #2: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
*** 2005-07-28 09:10:27.379
WAIT #2: nam='SQL*Net message from client' ela= 111136878 p1=1413697536 p2=1 p3=
0
=====================
and for the PL/SQL block which I ran next
=====================
PARSING IN CURSOR #4 len=22 dep=1 uid=432 oct=3 lid=432 tim=322887585839 hv=2450
377988 ad='8eb69778'
SELECT DUMMY FROM DUAL
END OF STMT
PARSE #4:c=0,e=913,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=3,tim=322887585829
BINDS #4:
EXEC #4:c=0,e=101,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=322887586055
FETCH #4:c=0,e=168,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,tim=322887586261
EXEC #3:c=0,e=37330,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=3,tim=322887622029
WAIT #3: nam='SQL*Net message to client' ela= 6 p1=1413697536 p2=1 p3=0
*** 2005-07-28 09:10:55.863
WAIT #3: nam='SQL*Net message from client' ela= 27766116 p1=1413697536 p2=1 p3=0
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=455817 op='TABLE ACCESS FULL TZ '
=====================
Neither of the above output an ERROR, why not?
I thought the first being a SQL query which hit a Value Error should have given an error output on the 10046 trace?
July 28, 2005 - 8:55 am UTC
Ok, we'll that isn't in the trace file (the to_number)
and the second one -- well, there quite simply IS NOT ANY ERROR at all to be reported on the server side - select into is a "programming thing".
db_file_multi_block_read
jianhui, March 09, 2006 - 4:05 am UTC
Hello Tom,
It looks puzzling to me when I set db multi block read to 128. Why there are "scattered read" with p3=2? Shouldnt they all be 128?
Thank you.
<quote from trace file>
select /*+ full(t) */ count(*) from stats$latch t
END OF STMT
PARSE #1:c=1,e=1,p=0,cr=52,cu=0,mis=1,r=0,dep=0,og=3,tim=2520214308
BINDS #1:
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=2520214308
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
WAIT #1: nam='file open' ela= 0 p1=0 p2=0 p3=0
WAIT #1: nam='db file scattered read' ela= 11 p1=12 p2=19853 p3=128
WAIT #1: nam='db file sequential read' ela= 1 p1=12 p2=19981 p3=1
WAIT #1: nam='file open' ela= 0 p1=0 p2=0 p3=0
WAIT #1: nam='db file scattered read' ela= 6 p1=67 p2=392 p3=128
WAIT #1: nam='db file scattered read' ela= 1 p1=67 p2=520 p3=2
WAIT #1: nam='db file scattered read' ela= 4 p1=12 p2=121782 p3=128
WAIT #1: nam='db file scattered read' ela= 0 p1=12 p2=121910 p3=2
WAIT #1: nam='db file scattered read' ela= 5 p1=67 p2=1952 p3=128
WAIT #1: nam='db file scattered read' ela= 1 p1=67 p2=2080 p3=2
WAIT #1: nam='db file scattered read' ela= 7 p1=12 p2=123472 p3=128
WAIT #1: nam='db file scattered read' ela= 1 p1=12 p2=123600 p3=2
WAIT #1: nam='db file scattered read' ela= 6 p1=67 p2=4422 p3=128
WAIT #1: nam='db file scattered read' ela= 0 p1=67 p2=4550 p3=2
WAIT #1: nam='db file scattered read' ela= 4 p1=12 p2=125552 p3=128
WAIT #1: nam='db file scattered read' ela= 2 p1=12 p2=125680 p3=2
WAIT #1: nam='db file scattered read' ela= 9 p1=67 p2=18912 p3=128
WAIT #1: nam='db file scattered read' ela= 1 p1=67 p2=19040 p3=2
WAIT #1: nam='db file scattered read' ela= 4 p1=12 p2=127502 p3=128
</quote>
March 09, 2006 - 2:25 pm UTC
Nope, not at all.
say you have blocks 0..127 to read from file 5.
In the buffer cache, blocks 1, 3, 5, 7, 9, .... all of the odd ones ... 127 are loaded.
You will read using physical IO only 0, 2, 4, 6, 8, ..... all of the even ones.
One
block
at
a
time
(unless of course we do a direct read using parallel query, which is preceded by a checkpoint - so we know the stuff on DISK is safe to be read)
Also, there is the chance you have extents that are 130 blocks in size - we'll read 128 and then 2 then 128, then 2 and so on....
number of extents
jianhui, March 09, 2006 - 3:59 pm UTC
Thank you Tom.
Your second guess was right on target.
SQL> select segment_name, extent_id, blocks from dba_extents where segment_name='STATS$LATCH';
SEGMENT_NAME EXTENT_ID BLOCKS
-------------------- ---------- ----------
STATS$LATCH 97 130
STATS$LATCH 0 130
STATS$LATCH 82 130
STATS$LATCH 83 130
STATS$LATCH 84 130
STATS$LATCH 85 130
STATS$LATCH 86 130
STATS$LATCH 87 130
STATS$LATCH 88 130
STATS$LATCH 89 130
STATS$LATCH 90 130
STATS$LATCH 91 130
STATS$LATCH 92 130
STATS$LATCH 93 130
This indicates that number of extents will slow down the multi block read, since each extent gives it a bump for whatever remainder of multi block counts, i.e. mod(130,128), the more extents a segment has, the more bumps it hits when doing multi-block read. Right?
March 09, 2006 - 4:24 pm UTC
this indicates you set the size of your extent "bad", should be not 130 but a nice binary multiple.
You sized it.
You could "fix this" by making each extent in the above smaller (128) and go from 14 to 15 extents and have 14 128 block reads followed by one 28 block read :) that is - ADD another extent!
Redundant BINDS
A reader, March 14, 2006 - 2:27 pm UTC
Below is part of a trace file. For this particular DELETE, there are 200 BINDS #1 sections. Out of the 200, only 22 have distinct values. This was taken from a vendor's application so I don't have access to the code.
How come I see the same values over and over? What can I conclude from this output?
Thanks.
=====================
PARSING IN CURSOR #1 len=320 dep=0 uid=23 oct=7 lid=23 tim=28757540877826 hv=516601529 ad='17a05158'
DELETE FROM RM_FRCST_WS_BKNG_CNCL WHERE PRPRTY_CODE = :1 AND ROOM
_TYPE_CODE = :2 AND RATE_TYPE_CODE = :3 AND DOW = :4 AND BKNG_REGI
ON_CODE = :5 AND SRVC_DATE = :6
END OF STMT
PARSE #1:c=0,e=3984,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=28757540877801
BINDS #1:
bind 0: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0504e8 bln=4000 avl=02 flg=05
value="DL"
bind 1: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05b940 bln=4000 avl=03 flg=05
value="DLW"
bind 2: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05a960 bln=4000 avl=03 flg=05
value="SP3"
bind 3: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d059980 bln=4000 avl=01 flg=05
value="6"
bind 4: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0589a0 bln=4000 avl=03 flg=05
value="IDS"
bind 5: dty=12 mxl=07(49) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=8 offset=0
bfp=ffffffff7d05e9e0 bln=07 avl=07 flg=05
value="3/19/2006 0:0:0"
WAIT #1: nam='db file sequential read' ela= 43543 p1=21 p2=20228 p3=1
BINDS #1:
bind 0: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0504e8 bln=4000 avl=02 flg=05
value="DL"
bind 1: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05b940 bln=4000 avl=03 flg=05
value="DLW"
bind 2: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05a960 bln=4000 avl=03 flg=05
value="SP3"
bind 3: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d059980 bln=4000 avl=01 flg=05
value="6"
bind 4: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0589a0 bln=4000 avl=03 flg=05
value="IDS"
bind 5: dty=12 mxl=07(49) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=8 offset=0
bfp=ffffffff7d05e9e0 bln=07 avl=07 flg=05
value="3/26/2006 0:0:0"
BINDS #1:
bind 0: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0504e8 bln=4000 avl=02 flg=05
value="DL"
bind 1: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05b940 bln=4000 avl=03 flg=05
value="DLW"
bind 2: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05a960 bln=4000 avl=03 flg=05
value="SP3"
bind 3: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d059980 bln=4000 avl=01 flg=05
value="6"
bind 4: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0589a0 bln=4000 avl=03 flg=05
value="IDS"
bind 5: dty=12 mxl=07(49) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=8 offset=0
bfp=ffffffff7d05e9e0 bln=07 avl=07 flg=05
value="3/26/2006 0:0:0"
BINDS #1:
bind 0: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0504e8 bln=4000 avl=02 flg=05
value="DL"
bind 1: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05b940 bln=4000 avl=03 flg=05
value="DLW"
bind 2: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d05a960 bln=4000 avl=03 flg=05
value="SP3"
bind 3: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d059980 bln=4000 avl=01 flg=05
value="6"
bind 4: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=4000 offset=0
bfp=ffffffff7d0589a0 bln=4000 avl=03 flg=05
value="IDS"
bind 5: dty=12 mxl=07(49) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=8 offset=0
bfp=ffffffff7d05e9e0 bln=07 avl=07 flg=05
value="3/26/2006 0:0:0"
.
.
.
Many BINDS #1 here, most of them with the same values
.
.
EXEC #1:c=330000,e=1211332,p=8,cr=655,cu=1174,mis=0,r=200,dep=0,og=4,tim=28757542089417
WAIT #1: nam='SQL*Net message to client' ela= 9 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 1086 p1=1952673792 p2=1 p3=0
XCTEND rlbk=0, rd_only=0
WAIT #0: nam='log file sync' ela= 81883 p1=3121 p2=0 p3=0
WAIT #0: nam='SQL*Net message to client' ela= 8 p1=1952673792 p2=1 p3=0
WAIT #0: nam='SQL*Net message from client' ela= 5041 p1=1952673792 p2=1 p3=0
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE '
STAT #1 id=2 cnt=200 pid=1 pos=1 obj=0 op='PARTITION RANGE SINGLE PARTITION: KEY KEY '
STAT #1 id=3 cnt=200 pid=2 pos=1 obj=35835 op='TABLE ACCESS BY LOCAL INDEX ROWID RM_FRCST_WS_BKNG_CNCL PARTITION: KEY KEY '
STAT #1 id=4 cnt=200 pid=3 pos=1 obj=35900 op='INDEX RANGE SCAN RM_FRCST_WS_BKNG_CNCL_PK PARTITION: KEY KEY '
March 15, 2006 - 9:38 am UTC
we print out only that which they send to us. if the binds are repeated, it is because the vendor code repeatedly executed the delete with the same binds over and over.
elapsed time in 10046 trace file and time spent in sorting,
A reader, November 08, 2006 - 11:15 pm UTC
I need to understand how to analyze how much time spent in doing sorting for a query that has "group by" kind of clause.
The 10046 extended sql trace file perhaps does not show any information about sorting since it takes place in PGA. Also it does not show any kind of information about hash joins which again takes place in PGA.
If I start a query at a time which I capture from dual, run my SQL that does sorting or hash joins with 10046 trace enabled, capture sysdate from dual at the end of the query, compute the time difference between them. Now if I sum all the elapsed time of all the wait events in the extended sql trace file and compare with the value which I took difference, can I assume the difference between them is what Oracle spent time in PGA doing sorting or hash joins?
thanks,
November 09, 2006 - 8:27 am UTC
may I ask why you think this micro bit of data would be useful in real life? I mean - what are you going to "do" about it? Why wouldn't you just look at the sql statement itself?
in any case, up your statistics_level for your session and let sql_trace do it:
select *
from t1 a, t2 b
where a.owner = b.username
order by 1, 2, 3, 4, 5
...
Rows Row Source Operation
------- ---------------------------------------------------
29826 SORT ORDER BY (cr=695 pr=142 pw=0 time=150211 us)
29826 HASH JOIN (cr=695 pr=142 pw=0 time=91424 us)
36 TABLE ACCESS FULL T2 (cr=3 pr=0 pw=0 time=91 us)
49890 TABLE ACCESS FULL T1 (cr=692 pr=142 pw=0 time=50251 us)
total statement time, about 0.15 seconds
spent about 150211-91424 us doing the last step
thanks ,
A reader, November 09, 2006 - 11:02 am UTC
How did you get those lines? Is it from STAT lines on raw trace files?
I am big fan of fixing SQL itself than going to micro details, but I was trying to understand how Oracle internally calculates time for each and every step it incurs.
November 09, 2006 - 2:32 pm UTC
stat lines shown as the row source operation in a tkprof - they come from the trace file.
we do not "internally calculate time", it is an empirical thing - we discover the time it TOOK
Determining "COMMIT" from 10046 trace log
Sanji, November 17, 2006 - 1:20 pm UTC
Tom,
Couple of questions from the following 10046 trace log. (It's an ideal scenario of what "NOT" to do, BUT again, third party application)
DELETE FROM xdbtext WHERE perakt = '0211AC' AND bol = '010983' AND konto = '14050005 '
END OF STMT
PARSE #1:c=0,e=753,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1931080224941
BINDS #1:
EXEC #1:c=0,e=87,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=1931080225123
WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 646 p1=1413697536 p2=1 p3=0
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE '
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=16557 op='INDEX RANGE SCAN PKC_XDBTEXT '
=====================
PARSING IN CURSOR #1 len=88 dep=0 uid=22 oct=7 lid=22 tim=1931080227016 hv=684058175 ad='531afe0'
DELETE FROM xdb02 WHERE perakt = '0211AC' AND bol = '010983' AND konto = '14050006 '
END OF STMT
PARSE #1:c=0,e=1058,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1931080227007
BINDS #1:
EXEC #1:c=0,e=125,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=4,tim=1931080227229
WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 630 p1=1413697536 p2=1 p3=0
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE '
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=19495 op='INDEX RANGE SCAN PKNC_XDB02 '
=====================
PARSING IN CURSOR #1 len=90 dep=0 uid=22 oct=7 lid=22 tim=1931080228804 hv=1270084978 ad='6697e68'
DELETE FROM xdbtext WHERE perakt = '0211AC' AND bol = '010983' AND konto = '14050006 '
END OF STMT
PARSE #1:c=0,e=747,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1931080228795
BINDS #1:
EXEC #1:c=0,e=86,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=1931080228976
WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 640 p1=1413697536 p2=1 p3=0
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE '
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=16557 op='INDEX RANGE SCAN PKC_XDBTEXT '
=====================
PARSING IN CURSOR #1 len=88 dep=0 uid=22 oct=7 lid=22 tim=1931080230914 hv=3805354108 ad='a1c2150'
DELETE FROM xdb02 WHERE perakt = '0211AC' AND bol = '010983' AND konto = '14050007 '
END OF STMT
PARSE #1:c=0,e=1108,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1931080230905
BINDS #1:
EXEC #1:c=0,e=125,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=4,tim=1931080231128
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 632 p1=1413697536 p2=1 p3=0
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE '
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=19495 op='INDEX RANGE SCAN PKNC_XDB02 '
=====================
1> Is there any way we can find out if the commit was issued after every delete statement ? The question stems from the fact that inspite of over 500,000 deletes, the undo tablespace didn't swell. I am presuming that the programmer has issued a commit after every delete statement.
2> How can we find out the associated index "updation" on a delete from the trace log, considering the fact that a delete on a table would modify the corresponding index entries.
Would be really helpful if you could show that with an example.
Thanks
Sanji
November 20, 2006 - 2:13 am UTC
1) XCTEND rlbk=0, rd_only=0
you would be looking for that, that is a transaction end (commit) record in a trace file.
2) query user_indexes for indexes on the table, you KNOW for a fact that they all were modified.
PARSE cpu vs PARSE elapsed?
Loïc, July 12, 2007 - 10:59 am UTC
Hi Tom,
According to the trace sent by malcolm (June 29, 2004 - 10am US/Eastern):
PARSE #3:c=10015,e=1457,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=0,tim=91232595195
, looking at Metalink note 39817.1 and assuming this trace was produced by (at least) 9i version of Oracle, I can tell that this parse operation took 10.015ms cpu for an elapsed duration of 1.457ms. How is this possible?
I myself ran in a similar case which I don't understand:
=====================
PARSING IN CURSOR #2 len=23474 dep=0 uid=113 oct=3 lid=113 tim=1156477564286942 hv=2937241903 ad='ad35d7a4'
SELECT ...
END OF STMT
PARSE #2:c=598910,e=595822,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=4,tim=1156477564286934
BINDS #2:
EXEC #2:c=3999,e=4029,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1156477564292716
WAIT #2: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
...
WAIT #2: nam='db file sequential read' ela= 10812 p1=40 p2=138101 p3=1
FETCH #2:c=629904,e=54355412,p=4138,cr=19479,cu=0,mis=0,r=3,dep=0,og=4,tim=1156477618650903
WAIT #2: nam='SQL*Net message from client' ela= 1903 p1=1413697536 p2=1 p3=0
So, following are my questions?
1/ the timestamp of the "PARSING IN CURSOR" trace is
tim=1156477564286942µs whereas the one for the "PARSE" trace is tim=1156477564286934µs
the difference between these two is: -8µs, how is this possible?
2/ Regarding the "PARSE" trace:
PARSE #2:c=598910,e=595822,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=4,tim=1156477564286934
I can see cpu = 598.910ms and elapsed=595.822ms, how is this possible? I thought the elapsed duration included the cpu duration. Am I wrong? Is it because we are facing hard parsing?
Anyway, thanks in advance for your answers!
Loïc
July 12, 2007 - 12:20 pm UTC
1) it is based on when the process started and when the message was emitted. tim= is start time - not end time. the parse encompassed an operation that itself emitted records.
2) cpu and elapsed are captured using different granularities - so errors may creep in easily (small ones).
Also, if you:
a := get time
loop 100000 times
b = get time
do something
c = get time
ela1 = ela1 + (c-b)
end loop
b = get time
ela2 = b-a
ela1 and ela2 would be slightly different (timing something fast lots of times and adding it up will be different than timing the entire process)
"c" and "e" in 9i,
shiva, October 05, 2007 - 5:11 pm UTC
In the metalink note ID: 39817.1, it has mentioned that in Oracle 9i "c" is measured in centi-seconds and "e" is measured in microseconds. Is that correct? I have pasted the two lines from metalink document below.
c CPU time (100th's of a second in Oracle7 ,8 and 9).
e Elapsed time (100th's of a second Oracle7, 8
Microseconds in Oracle 9 onwards).
puzzle in my 10046 trace file,
A reader, December 22, 2009 - 5:57 pm UTC
I have started tracing a session right before I started executing my DELETE statement using 10046 level 12. The SQL has been running for more than 5.5 hours. It has crossed parsing stage and executing with thousands of DB FILE SEQUENTIAL READ and other wait events.
However, when I add up all the WAIT events with "ela=" and also other statements with "e=", it is just summing to 15 minutes (I am on 10g and I believe elapsed time is in 1/1000000 of a second).
My question is where is the other 5 hours of information in the trace file? How to find what Oracle is doing during that 5 hours?
Thanks,
December 31, 2009 - 11:11 am UTC
cpu time I would suspect.
You need not have a single wait event for a statement to take hours or days, you just need something that is doing a lot of work using a lot of cpu.
Or, needs to use cpu but the system it is running on hasn't any cpu to give it.
STAT lines in 10046 trace file,
A reader, April 16, 2010 - 10:20 am UTC
How to interpret STAT lines in raw trace file?
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=23083167 pr=227427 pw=120955 time=277020031 us)'
STAT #1 id=2 cnt=221 pid=1 pos=1 obj=0 op='VIEW (cr=23083167 pr=227427 pw=120955 time=277020074 us)'
STAT #1 id=3 cnt=221 pid=2 pos=1 obj=0 op='HASH GROUP BY (cr=23083167 pr=227427 pw=120955 time=277019851 us)'
STAT #1 id=4 cnt=2963345 pid=3 pos=1 obj=0 op='VIEW (cr=23083167 pr=227427 pw=120955 time=267672869 us)'
STAT #1 id=5 cnt=4269260 pid=4 pos=1 obj=0 op='WINDOW SORT PUSHED RANK (cr=23083167 pr=227427 pw=120955 time=260691619 us)'
STAT #1 id=6 cnt=4658203 pid=5 pos=1 obj=0 op='NESTED LOOPS (cr=23083167 pr=150895 pw=44423 time=227286984 us)'
STAT #1 id=7 cnt=4658203 pid=6 pos=1 obj=0 op='NESTED LOOPS (cr=9108556 pr=150894 pw=44423 time=194679528 us)'
STAT #1 id=8 cnt=4658203 pid=7 pos=1 obj=0 op='HASH JOIN (cr=4450351 pr=150894 pw=44423 time=162072065 us)'
STAT #1 id=9 cnt=6851374 pid=8 pos=1 obj=42132930 op='TABLE ACCESS FULL BIN_DEFINITION (cr=165584 pr=103744 pw=0 time=36010758 us)'
STAT #1 id=10 cnt=4658203 pid=8 pos=2 obj=42162159 op='TABLE ACCESS BY LOCAL INDEX ROWID CLASS_BIN (cr=4284767 pr=2696 pw=0 time=97831775 us)'
STAT #1 id=11 cnt=4663983 pid=10 pos=1 obj=0 op='NESTED LOOPS (cr=37758 pr=1030 pw=0 time=23347432 us)'
STAT #1 id=12 cnt=5779 pid=11 pos=1 obj=43635796 op='TABLE ACCESS FULL RPT_CLASS_TEST_RUN (cr=270 pr=0 pw=0 time=17497 us)'
STAT #1 id=13 cnt=4658203 pid=11 pos=2 obj=0 op='PARTITION RANGE ITERATOR PARTITION: KEY KEY (cr=37488 pr=1030 pw=0 time=29811794 us)'
STAT #1 id=14 cnt=4658203 pid=13 pos=1 obj=42163435 op='INDEX RANGE SCAN CB_PK PARTITION: KEY KEY (cr=37488 pr=1030 pw=0 time=25080932 us)'
STAT #1 id=15 cnt=4658203 pid=7 pos=2 obj=42132937 op='INDEX UNIQUE SCAN TP_02 (cr=4658205 pr=0 pw=0 time=21255765 us)'
STAT #1 id=16 cnt=4658203 pid=6 pos=2 obj=42161481 op='INDEX UNIQUE SCAN I_PK (cr=13974611 pr=1 pw=0 time=24697828 us)'
In the above, I want to know what step Oracle executed first and so on, and how much time each step Oracle took to execute. The first line in the STAT statement has tim=277020031 us (277 seconds) which is exactly the time my SQL statement took, but I am interested to know how much time each operation spent that way I can focus on that step.
Thanks,
STAT - follow up,
A reader, April 16, 2010 - 12:00 pm UTC
Thanks. HOwever, explain plan in tkprof output doesn't tell which operation spent how much time (out of total elapsed time). I guess using time values in STAT we can figure out that, but I will try to understand by reading "inside out" by starting with highest "pid" to the lowest. If there are more than one value for the same "pid", then go with lowest "pos" to the highest.
This way I can get the difference between two time values which are back to back in repect to "pid" and calculate the time taken by that step.
Is that right logic?
Thanks,
April 16, 2010 - 12:21 pm UTC
the row source operation in tkprof sure does.
the time is shown there if it is in the stat records.
I'm not talking about "explain=u/p" on the tkprof command line, I'm talking about just running tkprof itself.
select *
from
all_users
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.03 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 5 0.00 0.01 0 149 0 49
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.00 0.05 0 149 0 49
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 607
Rows Row Source Operation
------- ---------------------------------------------------
49 HASH JOIN (cr=149 pr=0 pw=0 time=16196 us)
49 HASH JOIN (cr=78 pr=0 pw=0 time=1343 us)
49 TABLE ACCESS FULL USER$ (cr=7 pr=0 pw=0 time=318 us)
67 TABLE ACCESS FULL TS$ (cr=71 pr=0 pw=0 time=177626 us)
67 TABLE ACCESS FULL TS$ (cr=71 pr=0 pw=0 time=370 us)
that row source operation is the output of:
STAT #15 id=1 cnt=49 pid=0 pos=1 obj=0 op='HASH JOIN (cr=149 pr=0 pw=0 time=16196 us)'
STAT #15 id=2 cnt=49 pid=1 pos=1 obj=0 op='HASH JOIN (cr=78 pr=0 pw=0 time=1343 us)'
STAT #15 id=3 cnt=49 pid=2 pos=1 obj=22 op='TABLE ACCESS FULL USER$ (cr=7 pr=0 pw=0 time=318 us)'
STAT #15 id=4 cnt=67 pid=2 pos=2 obj=16 op='TABLE ACCESS FULL TS$ (cr=71 pr=0 pw=0 time=177626 us)'
STAT #15 id=5 cnt=67 pid=1 pos=2 obj=16 op='TABLE ACCESS FULL TS$ (cr=71 pr=0 pw=0 time=370 us)'
the time= steps are all there.
why not ASH and AWR
v.hariharaputhran, April 16, 2010 - 12:49 pm UTC
Mr.Oracle
Appreciate your splendid serves to the oracle community.
I had some long running queries issue in session, when i asked for the 10046 trace + tkprof output, the DBA gave me just ASH and AWR reports and asked why specific 10046. As i resolved the issue with the ASH report, i dint ask for 10046 though later.
With the presence of 10g's AWR and ASH, Can you please explain on what specific scenarios/problems one should go for Raw 10046 trace files.
Regards
V.Hari
April 16, 2010 - 1:08 pm UTC
You can get most of what you need from ASH instead of tkprof/trace (awr would be a better replacement for statspack, not trace)
Sometimes you will need the trace however, ash is a sample - not a recording. It will not have 100% of what you are doing - it will give you a decent idea.
and since many people do not have access to ash/awr, I'll continue to use trace - it is available to all and if you can understand it's output, you already understand ash output.
why not ASH and AWR
V.Hariharaputhran, April 17, 2010 - 8:16 am UTC
Mr.Oracle
Thanks for your time and explanation. Do agree that ASH is just a sample.
Regards
V.Hari
tim value in tkrprof,
A reader, July 21, 2010 - 9:46 am UTC
Hi,
I executed a query which took 1 hr 22 minutes to complete. I traced the session using extended sql trace and did a tkprof on the trace file. According to the tkprof statement, there were operations that took more than 5000 seconds (I think tim value is in microseconds). I am wondering how can tkprof statement comes with such a big number when my total elapsed time is lower than that.
Here is the extract of my tkprof:
4870194 HASH JOIN (cr=3255279 pr=3015201 pw=67641 time=5479628897 us)
3108929 TABLE ACCESS FULL RENJYE_SORT_INC_SORT_BIN (cr=100931 pr=100849 pw=0 time=49771664 us)
438007987 PARTITION RANGE ALL PARTITION: 1 218 (cr=3154348 pr=2856175 pw=0 time=9636192048 us)
438007987 TABLE ACCESS BY LOCAL INDEX ROWID CLASS_BIN PARTITION: 1 218 (cr=3154348 pr=2856175 pw=0 time=7450916526 us)
438007987 BITMAP CONVERSION TO ROWIDS (cr=12625 pr=12424 pw=0 time=1317188941 us)
35375 BITMAP INDEX FULL SCAN CB_04 PARTITION: 1 218 (cr=12625 pr=12424 pw=0 time=41869305 us)(object id 42622879)
July 23, 2010 - 8:58 am UTC
when you measure times at different levels - you get slightly different answers.
start_time := get_time
loop a lot
start_time2 := get_time
do something
elapsed_time2 := elapsed_time2 + (get_time-start_time2)
end loop
elapsed_time := get_time-start_time
the tim= values are the times measured in the loop. Each of those times can be off by the resolution of the clock (plus or minus). Eg - if the clock measures at 1/100th of a second - each timing of do_something might be off by just a tad under 1/100th of a second. add up a lot of those and you get a number that'll deviate from the elapsed time in the outer loop measurement.
the tim value is close, and is especially useful to see where the vast preponderance of the time was spent.