Posts in category TVD$XTAT

Synthetic Commits and Rollbacks

Aug19
2009 3 Comments Written by Christian Antognini

Yesterday, I received the following question from a TVD$XTAT user:

XCTEND lines are reported as “COMMIT/ROLLBACK (synthetic)”. Using Goolge and Metalink I can’t find any other resources describing “COMMIT/ROLLBACK (synthetic)”. This term seems not be widely used, although Hotsos uses the same term. Could you please elaborate what exactly that is and why it possibly happens?

To understand what “synthetic” means, let’s have a look to two small trace files.The first one is generated by tracing the execution of the following SQL statements in SQL*Plus:

UPDATE scott.emp SET sal = sal*1.15;
COMMIT;

The relevant part of the trace file is the following. Notice that:

There are two cursors: the first one is the update, the second one is the commit.
In the second one, because it is a commit, between the PARSE and the EXEC lines there is a XCTEND line. Note that the database engine emmits a XCTEND line for every commit or rollback. To differentiate the two, the attribute “rlbk” is used: 0=commit, 1=rollback.
The “log file sync” wait is associated to the second cursor, the commit.

=====================
PARSING IN CURSOR #3 len=35 dep=0 uid=84 oct=6 lid=84 tim=1250674381587415 hv=950048100 ad='38e58340' sqlid='crk1wdnwa15b4'
UPDATE scott.emp SET sal = sal*1.15
END OF STMT
PARSE #3:c=0,e=338,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1494045816,tim=1250674381587404
EXEC #3:c=2999,e=2831,p=0,cr=7,cu=4,mis=0,r=14,dep=0,og=1,plh=1494045816,tim=1250674381590917
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  EMP (cr=7 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=14 pid=1 pos=1 obj=73268 op='TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=14 us cost=3 size=70 card=14)'
WAIT #3: nam='SQL*Net message to client' ela= 11 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381592362
WAIT #3: nam='SQL*Net message from client' ela= 1812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381594288
CLOSE #3:c=0,e=28,dep=0,type=0,tim=1250674381594476
=====================
PARSING IN CURSOR #2 len=6 dep=0 uid=84 oct=44 lid=84 tim=1250674381594857 hv=255718823 ad='0' sqlid='8ggw94h7mvxd7'
COMMIT
END OF STMT
PARSE #2:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1250674381594814
XCTEND rlbk=0, rd_only=0, tim=1250674381595557
EXEC #2:c=1000,e=740,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=1250674381596086
WAIT #2: nam='log file sync' ela= 1974 buffer#=1980 p2=0 p3=0 obj#=-1 tim=1250674381598390
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381598664
WAIT #2: nam='SQL*Net message from client' ela= 2770 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381601434
CLOSE #2:c=0,e=17,dep=0,type=3,tim=1250674381601595
=====================

The second trace file is generated by tracing the execution of the same operations from a Java program. The following is the method that contains the update and the commit:

private static void test(Connection connection) throws Exception
{
  Statement statement = connection.createStatement();
  statement.execute("UPDATE scott.emp SET sal = sal * 1.15");
  statement.close();
  connection.commit();
}

The relevant part of the trace file is the following. Notice that:

There is only one cursor: the update. No cursor related to the commit is available.
Just after the CLOSE line there is a XCTEND line with the attribute “rlbk” set to 0. Obviously a commit was performed.
The “log file sync” wait is associated to cursor number 0. Note that the database engine associate to cursor number 0 all lines that cannot be associated to other cursors. In this case a cursor with the commit statement is missing, hence it is not possible to associate the wait to it.

=====================
PARSING IN CURSOR #2 len=37 dep=0 uid=84 oct=6 lid=84 tim=1250673660406187 hv=517367075 ad='38d919e4' sqlid='cc8438wgdct93'
UPDATE scott.emp SET sal = sal * 1.15
END OF STMT
PARSE #2:c=39994,e=40693,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1494045816,tim=1250673660406167
EXEC #2:c=17997,e=18116,p=0,cr=7,cu=4,mis=0,r=14,dep=0,og=1,plh=1494045816,tim=1250673660427450
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  EMP (cr=7 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=14 pid=1 pos=1 obj=73268 op='TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=5 us cost=3 size=70 card=14)'
WAIT #2: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250673660432401
WAIT #2: nam='SQL*Net message from client' ela= 12925 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250673660446291
CLOSE #2:c=0,e=45,dep=0,type=0,tim=1250673660447335
XCTEND rlbk=0, rd_only=0, tim=1250673660449381
WAIT #0: nam='log file sync' ela= 1325 buffer#=1217 p2=0 p3=0 obj#=-1 tim=1250673660454674
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250673660454885
=====================

The interesting thing to note about the second case is that a commit was performed without executing a COMMIT statement. This is possible because at the OCI level a commit can be performed by calling the function OCITransCommit. In other words, without having to execute a statement.

Now, back to the question. When TVD$XTAT processes a trace file like the second one, it automatically generates a cursor related to the commit operation. The text of the cursor will be “COMMIT (synthetic)”. So, the term “synthetic” is only added to point out that it is a generated cursor. In addition, TVD$XTAT also associate the waits associated to the cursor 0 to the generated cursor. This is very important because in some situations, for example when commits are executed very often or when long rollbacks are executed, the time needed for the commit/rollback is not negligible. As a result, if they were not accounted, the unaccounted-for time could be relevant.

BTW, it is not a coincidence that the Method R Profiler (a.k.a. Hotsos Profiler) and TVD$XTAT uses the same term. I fact, while comparing the two profilers, I noticed that in Method R Profiler the generated statements were called “synthetic”. I found the idea good and since I was looking for a method to mark such statements as well, I borrowed their term.

Posted in SQL Trace

TVD$XTAT 4.0 Beta 9

Apr09
2009 10 Comments Written by Christian Antognini

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. Not only I introduced some new features, but I also fixed a couple of major bugs related to memory consumption and poor performance…

The detailed change log since Beta 8 is the following:

Added formatting for bind variable values of type DATE
Added support for several execution plans for a single cursor
Added number of executions and hash value to execution plans
Added detection of incomplete execution plans
Added support for RPC bind variables
Added command-line option to control logging level
Added warning for 11.1.0.7 trace files (because of bug# 7522002 timing information might be wrong)
Improved data type detection to distinguish VARCHAR2 from NVARCHAR2 and CHAR from NCHAR
Improved handling of incorrectly formatted input lines
Changed logging formatter (time is displayed with the following pattern HH:mm:ss)
Reduced memory utilization for the processing of large trace files
Fix to prevent poor performance for the processing of large trace files
Fix to replace special characters not supported by XML (the unicode character FFFD is used istead of the special ones)
Fix in template to correctly handle space character in SQL text and bind variable values
Fix to ignore timestamp lines not generated by SQL trace

As always, your feedback is welcome!

Posted in SQL Trace, TOP

Execution Plan Hash Value in SQL Trace Files

Jan12
2009 3 Comments Written by Christian Antognini

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.

Posted in 11gR1, SQL Trace