Striving for Optimal Performance

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.

In the next months I’ll be speaking at several conferences and user group meetings. I’m looking forward to meet some of you at one of these events.

The abstracts of the presentations are the following (in Switzerland and Germany I’ll give the presentation in German; hence the last abstract is in German. The short summary is that I’ll present the Oracle Database 11g Release 2 feature called “Edition-Based Redefinition”):

• Interpreting Execution Plans: An execution plan describes the operations carried out by the SQL engine to execute an SQL statement. Every time you have to analyze a performance problem related to an SQL statement or simply question the decisions taken by the query optimizer, you must know the execution plan. Whenever you deal with an execution plan, you carry out three basic actions: you obtain it, you interpret it, and you judge its efficiency. The aim of this session is to describe in detail how you should perform the second of these three actions—in other words, how to read execution plans.
• Parallel Processing: When you submit a SQL statement to a database engine, by default it is executed serially by a single server process. Therefore, even if the server running the database engine has several CPUs, your SQL statement runs on a single CPU. This means that the amount of resources used for the execution of a SQL statement is restricted by the amount of processing a single CPU can do. The purpose of parallel processing is to distribute the execution of a single SQL statement over several CPUs.
  This session describes not only how parallel processing works, but also when to use it. In other words, how it can be used to improve performance. In addition, it also describes how to configure the database engine to efficiently support it.
• Edition-Based Redefinition: Das Upgraden von kritischen Applikationen kann sehr schwierig sein. Eines der Hauptprobleme besteht darin, dass aus Verfügbarkeitsgründen regelmässige und lange Downtimes nicht eingeplant werden können. Deshalb ist es wünschenswert online Verfahren für solche Upgrades zu implementieren. Dies bedingt nicht nur eine Applikation die dafür vorgesehen ist, sondern auch dass jede benutzte Software, wie z.B. der Datenbank Server, online Upgrades zulässt. Oracle hat dieses Problem seit Jahren erkannt. Leider wurde dies bis und mit Database 11g Release 1 nicht umgesetzt. Ab Oracle Database 11g Release 2 hat sich diese Situation sehr stark geändert. Mit „Edition-Based Redefinition“ bietet Oracle eine echte Unterstützung um online Upgrades zu implementieren. In diesem Vortrag wird diese neue Funktionalität im Detail präsentiert.

Oracle Database provides two extent management options: locally managed and dictionary managed. Today, when creating a new database, most DBAs use the former for all tablespaces. This is a good thing. What is less obvious is the choice between uniform extent size and system managed extent size. Both of these options have pros and cons. The tendency is to use uniform extent size only when the size of the segments to be stored in a tablespace is (well) known. Otherwise, it is better to delegate the choice of an “optimal” extent size to the database engine. In fact, the aim of system managed extent size is to adjust the size of the extents to the size of the segments to which they are associated. In other words, a large segment should have large extents, a small segment should have small extents. In this way it should be possible to avoid both fragmentation and very high number of extents. To do so, the size of the extents is normalized to a limited number of sizes: 64KB, 1MB, 8MB or 64MB.

Now, let’s discuss two enhancements that have been (silently?) introduced in 11.1.0.7… Yes, in 11.1.0.6 they are not available!

But, before that, let’s create a tablespace and a view that will be used for the tests I’ll show you…

SQL> CREATE TABLESPACE test
  2  DATAFILE '/u01/oradata/DBM11106/test01.dbf' SIZE 1G
  3  BLOCKSIZE 8K
  4  EXTENT MANAGEMENT LOCAL AUTOALLOCATE
  5  SEGMENT SPACE MANAGEMENT AUTO;

SQL> CREATE OR REPLACE VIEW v AS
  2  SELECT bytes, extent_id-lag(extent_id,1,-1) OVER (ORDER BY extent_id) AS extents
  3  FROM (
  4    SELECT bytes, extent_id, decode(bytes,lead(bytes) OVER (ORDER BY extent_id),0,1) AS last
  5    FROM user_extents
  6    WHERE segment_name = 'T'
  7  )
  8  WHERE last = 1
  9  ORDER BY extent_id;

Improvement #1

Up to 11.1.0.6, INITIAL (the attribute that can be specified in the storage clause) is only partially considered when creating a new segment. In fact, as the following example shows, even if a segment of 1MB is created, sixteen extents of 64KB are associated to it.

SQL> CREATE TABLE t (id NUMBER, pad VARCHAR2(1000))
  2  TABLESPACE test
  3  STORAGE (INITIAL 1M);

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
     65536         16

One might think that INITIAL is not considered at all. However, it is easy to show that it’s actually used. To do so it’s sufficient to create a segment of 2MB. As the following example shows, two extents of 1MB are associated to it. In other words, even if the value of INITIAL is considered, the size of the first extent is not directly derived from it.

SQL> CREATE TABLE t (id NUMBER, pad VARCHAR2(1000))
  2  TABLESPACE test
  3  STORAGE (INITIAL 2M);

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
   1048576          2

As of 11.1.0.7, however, the size of the first extent is directly derived from INITIAL. The only and obvious limitation is that the extent size is normalized to either 64KB, 1MB, 8MB or 64MB. To do so the database engine uses the extent size which is equal or smaller to INITIAL. Therefore, when the same SQL statements as before are executed, for a segment of 1MB only one extent of 1MB is associated to it.

SQL> CREATE TABLE t (id NUMBER, pad VARCHAR2(1000))
  2  TABLESPACE test
  3  STORAGE (INITIAL 1M);

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
   1048576          1

A curios side effect of this new behavior is that it’s much common to see segments for which the first extent is larger than the second one. Such situations are not new… but, they are much more common than before. The following example illustrates this. Notice that, for a 10MB segment, the first extent is 8MB and the subsequent two are only 1MB each.

SQL> CREATE TABLE t (id NUMBER, pad VARCHAR2(1000))
  2  TABLESPACE test
  3  STORAGE (INITIAL 10M);

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
   8388608          1
   1048576          2

In summary, as of 11.1.0.7, if you set INITIAL to either 64KB, 1MB, 8MB or 64MB, the first extent will have the specified size. So, if you know what the size of an segment will be, it is not bad to provide a sensible value through INITIAL.

Improvement #2

As you might guess, the second improvement is related to another attribute that can be specified in the storage clause: NEXT. The improvement, however, is a not what you might expect in first place. In fact, NEXT is not simply used to specify the size of any extent allocated after the first one. According to my observations NEXT is only used when a parallel load is performed.

Up to 11.1.0.6, when a parallel load is performed, every parallel slave allocates extents from a temporary segment and loads the data into it. In other words, the parallel slaves do not modify the target table. Then, when the transaction is committed, the temporary segment is merged to the target table. The following example illustrates this behavior. Notice three things. First, NEXT is set to 1MB. Second, the insert loads about 10MB of data. Third, I forced the utilization of two parallel slaves. Since each parallel slave allocated its own extents, every parallel slave allocates sixteen 64KB extents, four 1MB extents and one 832KB extent (for a total of about 6MB per parallel slave). Simply put, the extent allocation for the temporary segment follows the rules we are used to.

SQL> CREATE TABLE t (id NUMBER, pad VARCHAR2(1000))
  2  TABLESPACE test
  3  STORAGE (NEXT 1M);

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
     65536          1

SQL> ALTER SESSION FORCE PARALLEL DML PARALLEL 2;

SQL> INSERT INTO t
  2  SELECT rownum, rpad('*',1000,'*')
  3  FROM dual
  4  CONNECT BY level <= 10000;

SQL> SELECT bytes, extent_id-lag(extent_id,1,-1) OVER (ORDER BY extent_id) AS extents
  2  FROM (
  3    SELECT bytes, extent_id, decode(bytes,lead(bytes) OVER (ORDER BY extent_id),0,1) AS last
  4    FROM user_extents
  5    WHERE segment_type = 'TEMPORARY'
  6  )
  7  WHERE last = 1
  8  ORDER BY extent_id;

     BYTES    EXTENTS
---------- ----------
     65536         16
   1048576          4
    851968          1
     65536         16
   1048576          4
    851968          1

SQL> COMMIT;

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
     65536         17
   1048576          4
    851968          1
     65536         16
   1048576          4
    851968          1

As of 11.1.0.7, NEXT is used for sizing the extents of the temporary segment. As a result, if you know that are loading a lot of data, you can avoid the small extents (that might lead to suboptimal performance when the data will be accessed…). Let’s re-execute the same SQL statement as before to see what the difference is. Notice that the only extent of 64KB is the original one that was initially associated to the table.

SQL> CREATE TABLE t (id NUMBER, pad VARCHAR2(1000))
  2  TABLESPACE test
  3  STORAGE (NEXT 1M);

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
     65536          1

SQL> ALTER SESSION FORCE PARALLEL DML PARALLEL 2;

SQL> INSERT INTO t
  2  SELECT rownum, rpad('*',1000,'*')
  3  FROM dual
  4  CONNECT BY level <= 10000;

SQL> SELECT bytes, extent_id-lag(extent_id,1,-1) OVER (ORDER BY extent_id) AS extents
  2  FROM (
  3    SELECT bytes, extent_id, decode(bytes,lead(bytes) OVER (ORDER BY extent_id),0,1) AS last
  4    FROM user_extents
  5    WHERE segment_type = 'TEMPORARY'
  6  )
  7  WHERE last = 1
  8  ORDER BY extent_id;

     BYTES    EXTENTS
---------- ----------
   1048576          5
    786432          1
   1048576          5
    786432          1

SQL> COMMIT;

SQL> SELECT * FROM v;

     BYTES    EXTENTS
---------- ----------
     65536          1
   1048576          5
    786432          1
   1048576          5
    786432          1

In summary, as of 11.1.0.7, with NEXT you can control the sizing of the temporary extents used during parallel loads.

In the first post about this topic I wrote: “What I don’t like about the column “A-Rows” (or the underlying columns LAST_OUTPUT_ROWS in the V$ views), is that for the operations modifying a table 0 is shown. By the way, according to the documentation it is not a bug.”

What I forgot to mention is that depending on how you interpret the documentation, another behavior might also be seen as buggy. In fact, in the documentation you can read the following description for the column LAST_OUTPUT_ROWS of the view V$SQL_PLAN_STATISTICS: “Number of rows produced by the row source, during the last execution”. The question is: what does “produced” in this context mean?

According to the interpretation given by Oracle, for “top-level” operations (e.g. SELECT, UPDATE, DELETE, …) it’s the number of rows retrieved through a SELECT statement.

Another interpretation could be the number of rows returned through any SQL statement. And that, independently on how the rows are produced. For example, because of the RETURNING clause, the UPDATE statement in the following PL/SQL block actually returns 14 rows to the PL/SQL engine. But, as you can see, also in this case 0 is shown.

SQL> DECLARE
  2    TYPE t_emp IS TABLE OF scott.emp%ROWTYPE;
  3    l_emp t_emp;
  4  BEGIN
  5    UPDATE /*+ gather_plan_statistics */ scott.emp SET sal = sal * 1.15
  6    RETURNING empno, ename, job, mgr, hiredate, sal, comm, deptno
  7    BULK COLLECT INTO l_emp;
  8  END;
  9  /

SQL> SELECT sql_id
  2  FROM v$sqlarea
  3  WHERE sql_text LIKE 'UPDATE%RETURNING%';

SQL_ID
-------------
02x15ba008dt9

SQL> SELECT *
  2  FROM table(dbms_xplan.display_cursor(sql_id=>'02x15ba008dt9', format=>'iostats last'));

SQL_ID  02x15ba008dt9, child number 0
-------------------------------------
UPDATE /*+ gather_plan_statistics */ SCOTT.EMP SET SAL = SAL * 1.15
RETURNING EMPNO, ENAME, JOB, MGR, HIREDATE, SAL, COMM, DEPTNO INTO :O0
,:O1 ,:O2 ,:O3 ,:O4 ,:O5 ,:O6 ,:O7

Plan hash value: 1494045816

-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT   |      |      1 |        |      0 |00:00:00.01 |      23 |
|   1 |  UPDATE            | EMP  |      1 |        |      0 |00:00:00.01 |      23 |
|   2 |   TABLE ACCESS FULL| EMP  |      1 |     14 |     14 |00:00:00.01 |       7 |
-------------------------------------------------------------------------------------

Either these things that are returned cannot be called rows, or the current implementation is not very consistent. I already shared your opinion with you… I don’t like the current situation.