Monday, January 19, 2009

Oracle LONG to CLOB Performance Tests

I have seen performance problems when converting a LONG column to a CLOB. I decided to determine the underlying problem and see if I can get it to convert faster. Here are the test results.

To get started, here is the platform and table information.

OS: Windows 2003 Enterprise Edition SP2 32-bit
Memory: 4G
CPU: 3Ghz
Oracle: 10.2.0.4
Table: 298,809 records
Table Size: 5.186 GB
Prior to conducting the tests the following conditions where met:

  • I ran a conversion to set the size of the tablespace's datafiles to avoid the overhead of autoextending.
  • The database was in archive log mode.
  • Flashback Database was not enabled.

ALTER TABLE MODIFY (column CLOB)

The initial test was to provide a base conversion time in which to compare subsequent tests.

Time: 2713 seconds

********************************************************************************
alter table klong modify (segment clob)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1    422.53    2713.20    1399930    5548436    9620418      298809
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2    422.53    2713.21    1399930    5548437    9620418      298809

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 118

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
control file sequential read                    4        0.00          0.00
db file scattered read                      27507        0.46        364.71
direct path write                         1092663        0.40        672.39
db file sequential read                    721900        0.42        931.23
direct path read                           298752        0.40        160.06
log file switch completion                    652        0.50         78.82
log buffer space                              208        0.26         10.91
rdbms ipc reply                               202        0.47          0.49
latch: object queue header operation            1        0.00          0.00
log file sync                                   1        0.00          0.00
SQL*Net message to client                       1        0.00          0.00
SQL*Net message from client                     1        0.00          0.00
********************************************************************************


The second test performs the conversion with table logging and lob segment logging turned off. To my surprise the suppression of the redo generation did not result in a faster time. In fact it was slower. This was due to the fact that Oracle records the unlogged blocks in the control file. This caused wait events on writing and read from the control files.

Time: 3888 seconds
********************************************************************************
alter table klong modify (segment clob) lob (segment) store as (nocache nologging)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1    734.59    3888.37    1356793    5548407    9620018      298809
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2    734.59    3888.37    1356793    5548409    9620018      298809

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 118

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
control file sequential read              3287560        0.36       1880.21
direct path write                         1100750        0.22        215.74
control file parallel write               1200108        0.22        589.89
db file sequential read                    728089        0.24        362.76
direct path read                           298752        0.17         54.59
rdbms ipc reply                               149        0.11          0.12
log file switch completion                     16        0.15          1.03
enq: CF - contention                          226        0.63          6.68
db file scattered read                      20648        0.09        163.87
latch: object queue header operation            1        0.00          0.00
latch: enqueue hash chains                      1        0.00          0.00
enq: RO - fast object reuse                     2        0.15          0.15
log file sync                                   1        0.00          0.00
SQL*Net message to client                       1        0.00          0.00
SQL*Net message from client                     1        0.02          0.02
********************************************************************************



TO_LOB

Results using TO_LOB coming soon.
DBMS_REDEFINITIONInitial test without parallelism.

Time: 2732 seconds

create table klong_lob
(
  ownerid number(10),
  longid number(10),
  segmentid number(10),
  segment clob
);

declare
  col_mapping varchar2(1000);
begin
  col_mapping := 'ownerid ownerid, ' ||
                 'longid longid, ' ||
                 'segmentid segmentid, ' ||
                 'to_lob(segment) segment';
  dbms_redefinition.start_redef_table('DBUSER',
                                      'KLONG',
                                      'KLONG_LOB',
                                      col_mapping,
                                      dbms_redefinition.cons_use_rowid,
                                      null,
                                      null);
end;
/

declare
  error_count pls_integer := 0;
begin
  dbms_redefinition.copy_table_dependents('DBUSER',
                                          'KLONG',
                                          'KLONG_LOB',
                                          1,
                                          true,
                                          true,
                                          true,
                                          false,
                                          error_count);
  dbms_output.put_line('errors := ' || to_char(error_count));
end;
/

exec dbms_redefinition.finish_redef_table('DBUSER',
                                          'KLONG',
                                          'KLONG_LOB');

drop table klong_lob;

The second test is performed using parallel DML and parallel QUERY using a degree of 2. The process took longer but I suspect it is due to a single CPU and single disk. I will conduct these tests on a server with more resources.

Time: 3855 seconds
create table klong_lob
(
ownerid number(10),
longid number(10),
segmentid number(10),
segment clob
);

alter session force parallel dml parallel 2;

alter session force parallel query parallel 2;

declare
col_mapping varchar2(1000);
begin
col_mapping := 'ownerid ownerid, ' ||
               'longid longid, ' ||
               'segmentid segmentid, ' ||
               'to_lob(segment) segment';
dbms_redefinition.start_redef_table('DBUSER',
                                    'KLONG',
                                    'KLONG_LOB',
                                    col_mapping,
                                    dbms_redefinition.cons_use_rowid,
                                    null,
                                    null);
end;
/

declare
error_count pls_integer := 0;
begin
dbms_redefinition.copy_table_dependents('DBUSER',
                                        'KLONG',
                                        'KLONG_LOB',
                                        1,
                                        true,
                                        true,
                                        true,
                                        false,
                                        error_count);
dbms_output.put_line('errors := ' || to_char(error_count));
end;
/

exec dbms_redefinition.finish_redef_table('DBUSER',
                                        'KLONG',
                                        'KLONG_LOB');

drop table klong_lob;

1 comment:

  1. I have same issue now with non-partitioned table("long" is really surprising in 2012 and 11.2.0.3 :))

    and i discovered that if we doing it in parallel (i tested it with dop 16 and 32 on 40 processors), modify causing high count of "row cache locking" events.

    So i tested
    insert/*+ append parallel(32) */
    into NEW_PARTITIONED_TABLE
    select/*+ parallel(32) */ ...
    with rename and recreating indexes, constraints and fk.
    i found, that it is much more preferable than "modify", but still it is very long on non parallel "load as select" plan row (also with high sequential reads count)
    Table 390 GB, 61 mln rows, and i should have time to do all it for half an hour).

    Tomorrow i'll test it with CTAS, but what another variants i could test?

    ReplyDelete