Striving for Optimal Performance

In a previous post I already pointed out that as of 11.1.0.7 new information is provided in the SQL trace files. One of them is the value “plh” in the PARSE, EXEC and FETCH lines. This new value provides the execution plan hash value. While adding this information to the output generated by TVD$XTAT I had to decide how to handle this new value. Hence, I executed the following test case in SQL*Plus…

• I prepared the test environment by executing the following SQL statements:

ALTER SYSTEM FLUSH SHARED_POOL;

CREATE TABLE t 
AS 
SELECT rownum AS id, rpad('*',100,'*') AS pad 
FROM dual
CONNECT BY level <= 1000;

ALTER TABLE t ADD CONSTRAINT t_pk PRIMARY KEY (id);

EXECUTE dbms_stats.gather_table_stats(ownname=>user,tabname=>'t')

VARIABLE id NUMBER

• I enabled SQL trace:

EXECUTE dbms_monitor.session_trace_enable(waits=>false,binds=>false)

• I execute three time the same query that, by the way, takes advantage of extended cursor sharing (a.k.a. adaptive cursor sharing and intelligent cursor sharing):

EXECUTE :id := 10;

SELECT count(pad) FROM t WHERE id < :id;

EXECUTE :id := 990;

SELECT count(pad) FROM t WHERE id < :id;

SELECT count(pad) FROM t WHERE id < :id;

• I disabled SQL trace and displayed the name of the trace file:

EXECUTE dbms_monitor.session_trace_disable

SELECT value 
FROM v$diag_info 
WHERE name = 'Default Trace File';

Now, let’s check the content of the trace file…

• For the first query, the following information is provided. Notice that in the line PARSE the value of “plh” is “0″; in the line EXEC the value of “plh” is “4270555908″; in the lines PARSE and EXEC the value of “mis” is “1″ (the cursor was hard parsed); according to the execution plan (the line beginning with STAT; notice that I manually removed the runtime statistics and query optimizer estimations to keep the output more readable) the table was read through an index range scan.

PARSING IN CURSOR #2 len=39 dep=0 uid=83 oct=3 lid=83 tim=1231427339018492 hv=1107655156 ad='2e70b9cc' sqlid='asth1mx10aygn'
SELECT count(pad) FROM t WHERE id < :id
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1231427339018492
EXEC #2:c=2000,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
FETCH #2:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=4270555908,tim=1231427339018492
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE'
STAT #2 id=2 cnt=9 pid=1 pos=1 obj=72373 op='TABLE ACCESS BY INDEX ROWID T'
STAT #2 id=3 cnt=9 pid=2 pos=1 obj=72374 op='INDEX RANGE SCAN T_PK'
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4270555908,tim=1231427339018492
CLOSE #2:c=0,e=0,dep=0,type=0,tim=1231427339018492

• For the second query, the following information is provided. Notice that in the lines PARSE and EXEC the value of “plh” is “4270555908″ (the same as the previous query) and the value of “mis” is “0″ (the cursor was not hard parsed), i.e. a cursor already present in the library cache was reused.

PARSING IN CURSOR #4 len=39 dep=0 uid=83 oct=3 lid=83 tim=1231427339018492 hv=1107655156 ad='2e70b9cc' sqlid='asth1mx10aygn'
SELECT count(pad) FROM t WHERE id < :id
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
FETCH #4:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=0,og=1,plh=4270555908,tim=1231427339018492
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE'
STAT #4 id=2 cnt=989 pid=1 pos=1 obj=72373 op='TABLE ACCESS BY INDEX ROWID T'
STAT #4 id=3 cnt=989 pid=2 pos=1 obj=72374 op='INDEX RANGE SCAN T_PK'
FETCH #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4270555908,tim=1231427339018492
CLOSE #4:c=0,e=0,dep=0,type=0,tim=1231427339018492

• For the third query, the one taking advantage of extended cursor sharing, the following information is provided. Notice that in the line PARSE the value of “plh” is “4270555908″ (the same as the previous query) and the value of “mis” is “0″ (cursor was not hard parsed); in the line EXEC the value of “plh” is “2966233522″ and the value of “mis” is “1″ (cursor was hard parsed); according to the execution plan the table was read through a full table scan, i.e. not the same execution plan as the previous queries.

PARSING IN CURSOR #13 len=39 dep=0 uid=83 oct=3 lid=83 tim=1231427339018492 hv=1107655156 ad='2e70b9cc' sqlid='asth1mx10aygn'
SELECT count(pad) FROM t WHERE id < :id
END OF STMT
PARSE #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4270555908,tim=1231427339018492
EXEC #13:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2966233522,tim=1231427339018492
FETCH #13:c=0,e=0,p=0,cr=19,cu=0,mis=0,r=1,dep=0,og=1,plh=2966233522,tim=1231427339018492
STAT #13 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE'
STAT #13 id=2 cnt=989 pid=1 pos=1 obj=72373 op='TABLE ACCESS FULL T'
FETCH #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2966233522,tim=1231427339018492
CLOSE #13:c=0,e=0,dep=0,type=0,tim=1231427339018492

In summary, according to this test:

• The value of “plh” in the line EXEC provides the hash value of the execution plan used to execute a SQL statement.
• The value of “plh” in the line PARSE cannot be trusted.

This is just a short note to point out that I just uploaded under the section Downloadable Files of TOP a new version of TVD$XTAT.

The change log since Beta 7 is the following:

• Improved generation of synthetic cursors (particularly for RPC and XCTEND)
• Added support for 11.1.0.7 formatting of XCTEND
• Added check for questionable values for cpu and elapsed time
• Extended the list of recognized data types
• Fix to avoid Java 1.6.0 bug 6506304
• Fix to correctly handle attribution of bind variables
• Fix to correctly handle bind variables containing invalid numbers
• Fix to correctly handle bind variables containing the value NULL
• Fix to avoid parse errors for bind variables containing kkscoacd lines
• Fix to avoid warnings about freed cursors
• Fix to avoid warnings for lines beginning with “*** TRACE CONTINUED FROM FILE”

Please, do not hesitate to contact me if you have any kind of problem while using it.

Trivadis Extended Tracefile Analysis Tool (TVD$XTAT) is a command-line tool. Like TKPROF, its main purpose is to take a raw SQL trace file as input and generate a formatted file as output.

Why Is TKPROF Not Enough?

In late 1999, I had my first encounter with extended SQL trace, through MetaLink note Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output (39817.1). From the beginning, it was clear that the information it provided was essential for understanding what an application is doing when it is connected to an Oracle database engine. At the same time, I was very disappointed that no tool was available for analyzing extended SQL trace files for the purpose of leveraging their content. I should note that TKPROF at that time did not provide information about wait events. After spending too much time manually extracting information from the raw trace files, I decided to write my own analysis tool: TVD$XTAT.

Currently, TKPROF provides information about wait events, but it still has three major problems that are addressed in TVD$XTAT:

• As soon as the argument sort is specified, the relationship between SQL statements is lost.
• Data is provided only in aggregated form. Consequently, useful information is lost.
• No information about bind variables is provided.

TVD$XTAT is freeware. You can download it (presently, version 4.0 beta 7) from this page. TOP fully describes how to use it to identify performance problems. The installation is documented in the README file.

It goes without saying that all feedbacks about TVD$XTAT are highly welcome.

During some tests with patchset 11.1.0.7 (which is presently available for Linux 32-bit and 64-bit only) I noticed something new in the SQL trace files.

Let’s see what is the difference if I run the following statements with and without the patchset:

execute dbms_monitor.session_trace_enable(waits=>FALSE)
SELECT 'Hello world!' FROM dual;
execute dbms_monitor.session_trace_disable

The relevant part of the trace file is the following:

• 11.1.0.6.0

PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1222018499653282 hv=1643260990 ad='6e1e6ac8' sqlid='7a45d99hz4b1y'
SELECT 'Hello world!' FROM dual
END OF STMT
PARSE #1:c=1000,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1222018499653279
EXEC #1:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1222018499653403
FETCH #1:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1222018499653472
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1222018499653788

• 11.1.0.7.0

PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1222018585374765 hv=1643260990 ad='6f5af5e0' sqlid='7a45d99hz4b1y'
SELECT 'Hello world!' FROM dual
END OF STMT
PARSE #1:c=999,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1222018585374765
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1222018585374765
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1222018585374765
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
FETCH #1:c=1000,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1222018585396826
CLOSE #1:c=0,e=0,dep=0,type=0,tim=1222018585396826

You spotted the difference?

Yes! There are two fetches. But, what I wanted to point out with this post, is the new line beginning with CLOSE.