Cary Millsap (Oracle Ace Director, co-founder of the OakTable) explains how the principles of the Agile Manifesto have defined his most commercially and technically successful projects (specifically, the implementation of the Agile Manifesto called Extreme Programming (XP), as explained by Kent Beck). Watch a full video recording of the session, including the Q+A.
Visit the Red Gate website for more Oracle database development webinars.
Cary Millsap is an entrepreneur, software technology advisor, software developer, and Oracle software performance specialist. His technical papers are quoted in many Oracle books, in Wikipedia, in blogs all over the world, and in dozens of conference presentations each month. His blog is read by thousands of people each month. He has presented at hundreds of public and private events around the world. He wrote the book “Optimizing Oracle Performance” (O’Reilly 2003), for which he and co-author Jeff Holt were named Oracle Magazine’s 2004 Authors of the Year.
2 Comments
Mich Talebzadeh
26/01/2012
Hi Cary,
I have partially read your excellent book on Oracle performance. I have a question that you may kindly advise me.
This is the code I ran. It is pretty basic.
set timing on
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'test_with_tdash_tester';
DECLARE
type array is table of tdash%ROWTYPE index by binary_integer;
l_data array;
l_rec tdash%rowtype;
BEGIN
SELECT
a.*
,RPAD('*',4000,'*') AS PADDING1
,RPAD('*',4000,'*') AS PADDING2
BULK COLLECT INTO
l_data
FROM ALL_OBJECTS a;
FOR rs IN 1 .. l_data.count
LOOP
BEGIN
SELECT * INTO l_rec FROM tdash WHERE object_id = l_data(rs).object_id;
EXCEPTION
WHEN NO_DATA_FOUND THEN NULL;
END;
END LOOP;
END;
The output of tkprof is as follows. Need few clarifications and appreciate feedback. My questions are highlighted as below:
****
==> Question
****
SQL ID: 78kxqdhk1ubvq
Plan Hash: 3995659421
SELECT *
FROM
T WHERE OBJECT_ID = :B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 1 63 0 0
Execute 72184 0.88 1.03 4 54 0 0
Fetch 72184 1.46 9.87 81365 368659 0 71727
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 144369 2.36 10.92 81370 368776 0 71727
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 96 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)
1 INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 3 0.00 0.00
db file sequential read 12464 0.00 2.63
db file scattered read 14590 0.02 4.61
********************************************************************************
****
==> These are stats for the loop that results in 71727 rows read into buffe?
SELECT *
FROM
T WHERE OBJECT_ID = :B1
****
DECLARE
type array is table of t%ROWTYPE index by binary_integer;
l_data array;
l_rec t%rowtype;
BEGIN
SELECT
a.*
,RPAD('*',4000,'*') AS PADDING1
,RPAD('*',4000,'*') AS PADDING2
BULK COLLECT INTO
l_data
FROM ALL_OBJECTS a;
DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );
FOR rs IN 1 .. l_data.count
LOOP
BEGIN
SELECT * INTO l_rec FROM t WHERE object_id = l_data(rs).object_id;
EXCEPTION
WHEN NO_DATA_FOUND THEN NULL;
END;
END LOOP;
END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 9.88 11.58 322 48685 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 9.88 11.58 322 48685 0 1
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 96
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
****
==> This is what the client sent for the whole of PL/SQL block. It shows one execution of PL/SQL block and the summary of CPU and elapsed time with 322 physiical block reads.
****
SQL ID: 9babjv8yq8ru3
Plan Hash: 0
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 96
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
****
==> This one I can ignore
****
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 9.88 11.58 322 48685 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 9.88 11.58 322 48685 0 2
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 0.00 0.00
log file sync 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 12 0.00 0.01 1 63 0 0
Execute 72218 0.89 1.04 4 55 2 1
Fetch 72231 1.46 9.87 81370 368776 0 71773
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 144461 2.36 10.93 81375 368894 2 71774
Misses in library cache during parse: 11
Misses in library cache during execute: 10
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 12469 0.00 2.63
Disk file operations I/O 3 0.00 0.00
db file scattered read 14590 0.02 4.61
72186 user SQL statements in session.
34 internal SQL statements in session.
72220 SQL statements in session.
********************************************************************************
Trace file: test.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
72186 user SQL statements in trace file.
34 internal SQL statements in trace file.
72220 SQL statements in trace file.
14 unique SQL statements in trace file.
532743 lines in trace file.
17 elapsed seconds in trace file.
****
==> Are the overall totals the statistics that needs to be quoted. Non-recursive is the SQL that client sent and recursive is the SQL executed from the SQL client sent
The total CPU for the whole query is it 9.88+2.36 seconds and total wait time is 11.58+10.93?
****
Many thanks
Mich
Cary Millsap
26/01/2012
Mich,
tkprof is notoriously bad at reporting response times. It's not that the numbers are wrong: it's that there is no effort performed within tkprof to deal with the double-counting that is inherent in how Oracle acquires the durations of db-calls (like PARSE, EXEC, and FETCH) and OS-calls (which, unfortunately, Oracle calls "waits").
Notice that the numbers you're showing here (9.88+2.36, 11.58+10.93) don't add up to the reported elapsed duration of the trace file of 17 seconds. One example of double-counting occurs when one db-call calls another db-call (so-called recursive SQL), which you have here. But with tkprof, double-counting is a problem even when there's no recursive SQL. That's because some of the OS-calls occur within the context of db-calls, and some don't. The ones that do occur within the context of db-calls have their time double-counted as both db-call time and OS-call ("wait") time.
Over the years, my staff and I grew weary of trying to unravel tkprof time data. We found that in many cases it was just easier to go to the raw trace data and compute it ourselves. Over time, we developed our own software to give a better presentation of Oracle trace data. That's what our our Method R Profiler and the mrskew tool from the Method R Tools software package do (method-r.com/software/workbench).
I can give you a much better answer if you can email me your raw trace file (the .trc file that you feed into tkprof). I'll be glad to run our tools on it and send you the answer. Just attach your file in an email to the userid "info" at our method-r.com domain. I'll keep an eye out for it.
—Cary Millsap, Method R Corporation
No trackbacks yet.