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.