Tracing AUTOEXTEND tablespace

In this blog post I will try to examine how AUTOEXTEND operation can affect on performance. Hemant K Chitale already wrote nice article on this subject : AUTOEXTEND ON Next Size, where he wrote about Oracle "default" Autoextend NEXT size.

This topic "Autoextend or not?" from Oracle-L mailing list is great addition to this blog post. You can read there about different usages of AUTOEXTEND option in real life experience of some very good DBA's.



I will perform small test case using 10046 trace to get more information.

For my testing purposes I will use:

SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Prod
PL/SQL Release 10.2.0.4.0 - Production
CORE    10.2.0.4.0      Production
TNS for Linux: Version 10.2.0.4.0 - Production
NLSRTL Version 10.2.0.4.0 - Production


SQL> select log_mode from v$database;

LOG_MODE
------------
NOARCHIVELOG


$ uname -a
Linux linux2.loc 2.6.18-128.el5 #1 SMP Wed Jan 21 07:58:05 EST 2009 i686 i686 i386 GNU/Linux

First to create three different tablespaces with one table in each tablespace.

CREATE TABLESPACE TESTTBS1 DATAFILE
'/oradata/testtbs1.dbf' SIZE 5M AUTOEXTEND ON NEXT 56K MAXSIZE UNLIMITED
LOGGING
ONLINE
PERMANENT
EXTENT MANAGEMENT LOCAL AUTOALLOCATE
BLOCKSIZE 8K
SEGMENT SPACE MANAGEMENT AUTO
FLASHBACK ON;

create table big_table1 tablespace testtbs1
as
select rownum id, a.*
from all_objects a
where 1=0
/



CREATE TABLESPACE TESTTBS2 DATAFILE
'/oradata/testtbs3.dbf' SIZE 5M AUTOEXTEND ON NEXT 25M MAXSIZE UNLIMITED
LOGGING
ONLINE
PERMANENT
EXTENT MANAGEMENT LOCAL AUTOALLOCATE
BLOCKSIZE 8K
SEGMENT SPACE MANAGEMENT AUTO
FLASHBACK ON;

create table big_table2 tablespace testtbs2
as
select rownum id, a.*
from all_objects a
where 1=0
/


CREATE TABLESPACE TESTTBS3 DATAFILE
'/oradata/testtbs2.dbf' SIZE 500M AUTOEXTEND OFF
LOGGING
ONLINE
PERMANENT
EXTENT MANAGEMENT LOCAL AUTOALLOCATE
BLOCKSIZE 8K
SEGMENT SPACE MANAGEMENT AUTO
FLASHBACK ON;

create table big_table3 tablespace testtbs3
as
select rownum id, a.*
from all_objects a
where 1=0
/

I will execute script below to insert 2000000 rows in every table (about 232 MB). This is script from Tom Kyte but just little modified.

SQL> declare
2          l_cnt number;
3          l_rows number := &1;
4  begin
5          insert
6          into big_table1
7          select rownum, a.*
8          from all_objects a
9          where rownum <= &1;
10
11          l_cnt := sql%rowcount;
12
13          commit;
14
15          while (l_cnt < l_rows)
16          loop
17                  insert into big_table1
18                  select rownum+l_cnt,
19                  OWNER,OBJECT_NAME,SUBOBJECT_NAME,OBJECT_ID, DATA_OBJECT_ID,OBJECT_TYPE,
20                  CREATED,LAST_DDL_TIME,TIMESTAMP,STATUS,TEMPORARY,GENERATED,SECONDARY
21                  from big_table1
22                  where rownum <= l_rows - l_cnt;
23                  l_cnt := l_cnt + sql%rowcount;
24                  commit;
25          end loop;
26  end;
27  /
Enter value for 1: 2000000
old   3:         l_rows number := &1;
new   3:         l_rows number := 2000000;
Enter value for 1: 2000000
old   9:         where rownum <= &1;
new   9:         where rownum <= 2000000;

My intention is to trace every script execution and to extract wait statistics from trace file using tkprof tool. First execution with AUTOEXTEND ON NEXT 56K:

Elapsed: 00:00:51.40

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
control file sequential read                 2187        0.40         24.20
db file sequential read                       162        0.06          1.29
change tracking file synchronous read         891        0.03          1.72
Data file init write                          390        0.34          5.99
db file single write                           81        0.00          0.02
control file parallel write                   243        0.00          0.17
rdbms ipc reply                                81        0.07          0.86
log file switch completion                      7        0.97          1.28
enq: CF - contention                            1        0.00          0.00
log buffer space                                1        0.04          0.04
log file switch (checkpoint incomplete)         3        0.97          1.09

Second execution with AUTOEXTEND ON NEXT 25M:

Elapsed: 00:00:35.13

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
db file sequential read                        26        0.03          0.28
control file sequential read                  243        0.23          4.91
change tracking file synchronous read          99        0.01          0.19
Data file init write                          243        0.31          6.52
db file single write                            9        0.00          0.00
control file parallel write                    27        0.00          0.01
rdbms ipc reply                                 9        0.16          0.25
log buffer space                               38        0.41          6.72
log file switch completion                      5        0.97          1.74
log file switch (checkpoint incomplete)         5        0.97          1.16

Third execution with AUTOEXTEND OFF:

Elapsed: 00:00:33.93

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
log file switch completion                      8        0.97          3.50
log file switch (checkpoint incomplete)        12        0.97          5.38
log buffer space                               42        0.82         13.58

About main wait events in my test cases: "control file sequential read" - process is waiting for blocks to be read from control file. "Data file init write" - occurs when Oracle auto extends datafile and formats the newly created space within the datafile. ... Interesting results if you ask me. I expected "Data file int write" wait event because it is closely related to datafile extensions, but "control file sequential read" event little surprised me. To get some better explanation why "control file sequential read" is related to auto extensions I tried to use Metalink but Metalink is not working very well during weekend because of upgrade process. Maybe I'll find more info later using newly upgraded Metalink. To conclude, different autoextend next sizes can significantly affect on overall performance so it is important to set proper value. References: Ask DBSpecialists: 'Data file init write' wait event