One of my customers had a problem with a very slow TRUNCATE TABLE operation on a partitioned table having 22 000 partitions. The problem has raised after a test migration to database 12c. I’ve prepared a little demo to address this issue and show the walkaround for it.
Oracle Database 12c (12.1.0.2):
[oracle@skiper ~]$ sqlplus hr/hr
SQL*Plus: Release 12.1.0.2.0 Production on Tue Jan 27 10:11:23 2015
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Mon Jan 26 2015 17:56:53 +01:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics
and Real Application Testing options
SQL> select count(1)
2 from user_tab_partitions
3 where table_name='TRUNCATE_TEST';
COUNT(1)
----------
22000
SQL> set timing on
SQL> truncate table TRUNCATE_TEST;
Table truncated.
Elapsed: 00:05:33.71
Oracle Database 11g (11.2.0.4)
[oracle@skiper ~]$ sqlplus hr/hr
SQL*Plus: Release 11.2.0.4.0 Production on Tue Jan 27 10:15:05 2015
Copyright (c) 1982, 2013, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Data Mining
and Real Application Testing options
SQL> select count(1)
2 from user_tab_partitions
3 where table_name='TRUNCATE_TEST';
COUNT(1)
----------
22000
SQL> set timing on
SQL> truncate table TRUNCATE_TEST;
Table truncated.
Elapsed: 00:00:06.16
What the hell? On 12c the truncate took 00:05:33.71 and on 11g it was only 00:00:06.16
To understand the problem I’ve used the 10046 event on level 12 to generate trace with bind variables and wait events:
SQL> get spid 1 select spid 2 from v$process p, v$session s 3 where p.addr=s.paddr 4* and s.username='HR' SQL> / SPID ------------------------ 4797 SQL> oradebug setospid 4797 Oracle pid: 28, Unix process pid: 4797, image: oracle@skiper (TNS V1-V3) SQL> oradebug event 10046 trace name context forever, level 12 Statement processed. SQL> oradebug tracefile_name /u01/app/oracle/diag/rdbms/rico/rico/trace/rico_ora_4797.trc
A quick look on the size of the trace files assures me that in 12c there is a lot more operations during the "TRUNCATE TABLE".
[oracle@skiper truncate_test]$ wc -l raw_truncate11g.trc 1113 raw_truncate11g.trc [oracle@skiper truncate_test]$ wc -l raw_truncate12c.trc 4313645 raw_truncate12c.trc
Further investigations shows the SQLs which are the reason of a slow TRUNCATE execution in the 12c database.
select inserts, deletes from sys.mon_mods$ where obj# = :objn call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 44000 2.18 2.70 0 0 0 0 Execute 44000 8.56 9.89 0 0 0 0 Fetch 44000 3.14 4.03 0 110000 0 22000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 132000 13.88 16.62 0 110000 0 22000
SQL ID: bb926a5dcb8kr Plan Hash: 3530933756
merge into sys.mon_mods$ m
using dual
on (m.obj# = :objn and
(:pobjn = 0 or
m.obj# = :pobjn or
m.obj# in (select obj#
from tabpart$
where bo# = :pobjn and obj# = :objn
union all
select obj#
from tabcompart$
where bo# = :pobjn and obj# = :objn
union all
select tsp.obj#
from tabsubpart$ tsp, tabcompart$ tcp
where tsp.pobj# = tcp.obj#
and (tcp.bo# = :pobjn or tcp.obj# = :pobjn)
and tsp.obj# = :objn))) when matched
then update
set inserts =
inserts + :ins, updates = updates + :upd, deletes =
deletes + :del, flags =
(decode(bitand(flags, :flag), :flag, flags, flags + :flag)),
drop_segments = drop_segments + :dropseg,
timestamp = :time when
NOT matched then
insert (obj#, inserts, updates, deletes,
timestamp, flags, drop_segments)
values (:objn, :ins, :upd, :del, :time, :flag, :dropseg)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 44000 2.01 2.28 0 0 0 0
Execute 44000 57.61 65.34 0 264100 133393 44000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 88000 59.62 67.63 0 264100 133393 44000
The MON_MODS$ table is related to the following views:
- USER_TAB_MODIFICATIONS
- ALL_TAB_MODIFICATIONS
- DBA_TAB_MODIFICATIONS
- ALL_TAB_STATISTICS
- DBA_TAB_STATISTICS
- USER_TAB_STATISTICS
- ALL_IND_STATISTICS
- DBA_IND_STATISTICS
- USER_IND_STATISTICS
- _user_stat
So it looks like that this behavior is related to the DML monitoring feature. Is it possible? The "TRUNCATE TABLE" is a DDL, not a DML operation!
Let’s check it by turning off the DML monitoring feature:
[oracle@skiper ~]$ sqlplus / as sysdba SQL*Plus: Release 12.1.0.2.0 Production on Tue Jan 27 11:08:03 2015 Copyright (c) 1982, 2014, Oracle. All rights reserved. Connected to: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options SQL> alter system set "_dml_monitoring_enabled"=FALSE scope=memory; System altered. SQL> conn hr/hr Connected. SQL> set timing on SQL> truncate table TRUNCATE_TEST; Table truncated. Elapsed: 00:00:00.18
WOW! So the conclusion is: TRUNCATE TABLE in database 12c is using the DML monitoring feature for some reason! Why? I don’t know it yet but I have a hypothesis that this is somehow related to the new features in the database 12c, regarding online operations on partitioned tables:
http://docs.oracle.com/database/121/VLDBG/to_vldbg14107_d290.htm#VLDBG14107
The problem is: my test table has no indexes and no data. It’s just an empty table with 22000 partitions. And database knows it, because I’ve gathered statistics:
SQL> select last_analyzed, num_rows 2 from user_tables 3 where table_name='TRUNCATE_TEST'; LAST_ANAL NUM_ROWS --------- ---------- 26-JAN-15 0 SQL> select sum(num_rows), sum(blocks) 2 from user_tab_partitions 3 where table_name='TRUNCATE_TEST'; SUM(NUM_ROWS) SUM(BLOCKS) ------------- ----------- 0 0
So what to do? As always: keep calm and use hidden parameters 🙂