Posts Tagged 'enqueue'

Append Hint Serializes Applications

The append hint is highly touted for its ability to minimize database overhead during insert operations. While true, one drawback of the append hint is commonly overlooked: it requires a table-level DML lock. This can cause serious enqueue waits for multi-user or multi-threaded applications.

Oracle databases use row-level locking for normal DML statements. Typically, a session that issues an insert, update, or delete statement locks the records, and only the records, that are being modified. Select statements do not require row-level locks but subsequent DML operations must wait for the previous transaction to complete before the same rows can be locked again.

The append hint changes this behavior by instructing the database to place new records above a table’s high water mark. This improves performance by heading off the inspection of existing blocks for free space; the database creates new blocks to hold the records instead. Such “direct-path” operations have the added benefit of preventing the creation of undo blocks, which further reduces the overhead of the insert operation. If the table is in NOLOGGING mode, redo generation is minimized as well.

But these benefits are not free, and apart from a tendency to waste space (less of a concern considering the ever-decreasing price for disks), the append hint’s major drawback is that it requires a table-level DML lock. This lock may not be problematic for insert statements that run quickly and are committed immediately thereafter. But long running transactions will prevent other sessions from modifying any records at all since a table-level lock prevents the acquisition of individual row locks.

Consider the following example run against a 64-bit 10.2.0.4 database on RHEL5. First, we’ll need to create a table with the same column definitions as DBA_OBJECTS:

CREATE TABLE append_test AS
SELECT *
FROM dba_objects
WHERE 1 = 2;

Then we’ll need two scripts, append.sql and noappend.sql:

append.sql

set timing on

INSERT /*+ APPEND */ INTO append_test
SELECT *
FROM dba_objects;

set timing off

COMMIT;

exit

noappend.sql

set timing on

INSERT INTO append_test
SELECT *
FROM dba_objects;

set timing off

COMMIT;

exit

The command below runs multiple, parallel SQL*Plus sessions for each script. The Linux “wait” command causes the parent session to wait for it’s backgrounded children to complete before continuing to the next command. The “grep” instruction pulls the elapsed time out of each sqlplus command’s standard output. (Note that for readability I manually excluded the job numbers and backgrounded process ids from the output below.)

> for scriptName in noappend.sql append.sql; do
>   echo; echo
>   echo $scriptName
>   for((i=1;i<=8;i++)); do
>     sqlplus / < ${scriptName} | grep Elapsed &
>   done
>   wait
> done

noappend.sql
Elapsed: 00:00:03.78
Elapsed: 00:00:03.93
Elapsed: 00:00:03.95
Elapsed: 00:00:03.96
Elapsed: 00:00:04.24
Elapsed: 00:00:04.28
Elapsed: 00:00:04.31
Elapsed: 00:00:04.61

append.sql
Elapsed: 00:00:02.22
Elapsed: 00:00:04.06
Elapsed: 00:00:06.08
Elapsed: 00:00:08.18
Elapsed: 00:00:10.13
Elapsed: 00:00:12.09
Elapsed: 00:00:14.18
Elapsed: 00:00:16.46

Note how the first append session completes 1.5 seconds before the first noappend.sql script. But then all of the remaining noappend.sql executions go on to complete within a second after that, whereas the subsequent append.sql executions finish in regular two second intervals. So the append operations run faster individually but queue up as a group. The non-append scripts take longer to run on the whole, but yield a faster overall response time.

To see specifically where this additional time was going, I added the ALTER SESSION SET events = ‘10046 TRACE NAME CONTEXT FOREVER, LEVEL 8′ command to each script and reran the bash loops above. I generated the TKPROF output below from the longest running session for each script (execution plans removed for readability):

noappend.sql TKPROF output:

INSERT INTO append_test
SELECT *
FROM dba_objects

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.36          0          0          0           0
Execute      1      3.13       4.23         15       6260       7042      185418
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      3.13       4.60         15       6260       7042      185418

.
.
.

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  cursor: pin S wait on X                        34        0.01          0.36
  read by other session                          82        0.03          0.49
  db file sequential read                        10        0.01          0.03
  db file scattered read                          1        0.00          0.00
  latch: cache buffers chains                   110        0.00          0.01
  buffer busy waits                            1431        0.04          0.24
  enq: HW - contention                          321        0.06          0.20
  enq: TX - contention                           20        0.07          0.10
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00

append.sql TKPROF output

INSERT /*+ APPEND */ INTO append_test
SELECT *
FROM dba_objects

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      2.07      16.07          0       2814        727      185418
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      2.07      16.07          0       2814        727      185418

.
.
.

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: TM - contention                            5        2.93         13.84
  control file sequential read                    4        0.00          0.00
  direct path write                               2        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00

So the final append.sql session, the one unfortunate enough to acquire the table-level DML lock after all the others, waits for 14 seconds on the “enq: TM – contention” event (the table-level DML lock). Contrast this with theĀ  4.6 seconds in longest running noappend.sql trace, most of which was CPU time along with small waits on a variety of events.

In this case, it’s better to accept the normal insert overhead rather than queue up multiple sessions that are forced to wait for each other. Your application’s design and response time requirements will determine whether the serialization forced by the append hint is acceptable or not. But be aware of this effect before you make the decision.

(Special thanks to my friend Prasad Kattula for pointing out that the term “serialization” is a better description of this phenomenon than “single-threaded”, as I orginally had it.)