Re: strange tkprof output for SQLs - II

Hello all,

Thanks to Bjorn Engsig of MiracleAS.dk

Also,

Here is the answer from Oracle support. I wanted to share with you:

######### Begin
tkprof substracts the child statistics from parent ones. .
the trace file is missing the line for PARSE call of the blsql block - as it's missing
it's impossible to to determine the start and therefore the times are reported
to be zero - could be the result of how the tracing was enabled. .
As it seems enabling trace from different session can produce incomplete

trace file I suggest you enable it in current session to get most accurate
results.
######### End

I had seen this wrong behavior for current statements before. But as seen in the thread, while closing the parent PL/SQL block, we are missing the PARSE line of parent statement in the trace since it's parsed before enabling trace. So, tkprof is unable to determine the starting time and sets cpu,elapsed times to ZERO.

as a result:

Be careful if you enable sql trace from other session. You can see wrong tkprof outputs not only for the current running statement, but also for statements which are parsed before enabling trace.

regards...

Danisment Gazi Unal wrote:

> Hello Mogens,
>
> I saw this problem whether or not shared pool was flushed for PL/SQLs.
>
> Here are my observations for SQLs!!! and PL/SQLs:
>
> - Enabling sql trace from current session:
> When a cursor is closed after their child recursive statements, their
> recursive statistics parsed after the statement are included in
> parent's statistics. Recursive statements parsed before the statement
> are not included.
>
> - Enabling sql trace from other session after a while(after the
> parenet statement is parsed):
> Recursive statistics are not included in parent statement. But tkprof
> doesn't use exac values in raw trace file. If they are not included,
> why doesn't tkprof return exac values in raw trace files ? I'll debug
> tkprof if it calls Oracle's kernel function to see if tkprof is just a
> simple formatter or calculates something that I'm missing.
>
> I did not understand this is expected behavior or not. I would like to
> know statistics in raw trace files are inclusive or exclusive.
>
> I'm facing diffierent behaviors for this problem. I've opened an iTAR.
>
> thanks in advance...
>
>
> Mogens Nørgaard wrote:
>
>> Danisment - isn't it always "alter system flush shard_pool"? I
>> thought so...
>>
>> Danisment Gazi Unal (Unal Bilisim) wrote:
>>
>> >Hello,
>> >
>> >I did 2 tests for PL/SQL and SQL statements. This is the test for
>> >SQL.
>> >
>> >Here are the steps:
>> >
>> >SQL > alter session flush shared_pool;
>> >SQL > alter session set sql_trace=true;
>> >SQL > insert into test select * from test;
>> >SQL > alter session set sql_trace=false;
>> >
>> >
>> >FROM DICTIONARY:
>> >
>> >SVRMGR> select
>> >SQL_TEXT,DISK_READS,BUFFER_GETS,ROWS_PROCESSED,COMMAND_TYPE from
>> v$sql
>> >where sql_text like 'insert into test select * from test%';
>> >
>> >SQL_TEXT DISK_READS BUFFER_GET
>> ROWS_PROCE
>> >COMMAND_TY
>> >------------------------------------- ---------- ----------
>> ----------
>> >----------
>> >insert into test select * from test 345 1014
>> >8192 2
>> >1 row selected.
>> >
>> >
>> >FROM RAW TRACE FILE:
>> >
>> >PARSING IN CURSOR #1 len=36 dep=0 uid=5 oct=2 lid=5 tim=2795932206
>> >hv=895761708 ad='5083d50c'
>> >insert into test select * from test
>> >END OF STMT
>> >PARSE
>> #1:c=7,e=28,p=17,cr=42,cu=2,mis=1,r=0,dep=0,og=4,tim=2795932206
>> >.
>> >other recursive statements.
>> >.
>> >. near end of file
>> >EXEC
>> >#1:c
>> 28,e=258,p=328,cr=597,cu=373,mis=0,r=8192,dep=0,og=4,tim=2795932464
>> >
>> >
>> >
>> >BUFFER GETS IN RAW TRACE FILE:
>> >cr: 597 + 42 = 639
>> >cu: 373 + 2 = 375
>> >
>> >Buffer gets = 639 + 375 = 1014, which is same as v$sql.BUFFER_GETS
>> >
>> >
>> >DISK_READS IN RAW TRACE FILE:
>> >
>> >p: 17 + 328 = 345, which is same as v$sql.DISK_READS.
>> >
>> >According to these test, results in dictionary and raw trace files
>> are
>> >same. But tkprof formats as below:
>> >
>> >
>> >insert into test select * from test
>> >
>> >
>> >call count cpu elapsed disk query
>> >current rows
>> >------- ------ -------- ---------- ---------- ----------
>> ----------
>> >----------
>> >Parse 1 0.00 0.02 17 42
>> >1 0
>> >Execute 1 0.12 1.86 91 126
>> >356 8192
>> >Fetch 0 0.00 0.00 0 0
>> >0 0
>> >------- ------ -------- ---------- ---------- ----------
>> ----------
>> >----------
>> >total 2 0.12 1.88 108 168
>> >357 8192
>> >
>> >
>> >DISK_READS = 108
>> >BUFFER GETS = 168 + 357 = 525
>> >
>> >Question:
>> >
>> >Which one is correct ? Dictionary/raw trace file or tkprof results
>> ?
>> >
>> >My comment:
>> >
>> >I guess, tkprof substructs child recursive statements from parent
>> user
>> >statement ? Why ? This is not a PL/SQL statement ? So, statistics
>> are
>> >already not included in parent statement ? I guess statistics in
>> raw
>> >trace files are inclusive statistics which include statistics of
>> their
>> >child statements according to call orders of kernel calls. But is
>> this
>> >expected behavior.
>> >
>> >Thanks in advance...
>> >
>> >--
>> >Danisment Gazi Unal
>> >http://www.unal-bilisim.com
>> >
>> >
>>
>> --
>> Please see the official ORACLE-L FAQ: http://www.orafaq.com
>> --
>> Author: Mogens =?ISO-8859-1?Q?N=F8rgaard?=
>> INET: mln_at_miracleas.dk
>>
>> Fat City Network Services -- (858) 538-5051 FAX: (858) 538-5051
>> San Diego, California -- Public Internet access / Mailing
>> Lists
>> --------------------------------------------------------------------
>>
>> To REMOVE yourself from this mailing list, send an E-Mail message
>> to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
>> the message BODY, include a line containing: UNSUB ORACLE-L
>> (or the name of mailing list you want to be removed from). You may
>> also send the HELP command for other information (like subscribing).
>
> --
> Danisment Gazi Unal
> http://www.unal-bilisim.com
>

--
Danisment Gazi Unal
http://www.unal-bilisim.com



-- 
Please see the official ORACLE-L FAQ: http://www.orafaq.com
-- 
Author: Danisment Gazi Unal
  INET: dunal_at_unal-bilisim.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).