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):
1 | [oracle@skiper ~]$ sqlplus hr/hr |
3 | SQL*Plus: Release 12.1.0.2.0 Production on Tue Jan 27 10:11:23 2015 |
5 | Copyright (c) 1982, 2014, Oracle. All rights reserved. |
7 | Last Successful login time: Mon Jan 26 2015 17:56:53 +01:00 |
10 | Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production |
11 | With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics |
12 | and Real Application Testing options |
15 | 2 from user_tab_partitions |
16 | 3 where table_name='TRUNCATE_TEST'; |
23 | SQL> truncate table TRUNCATE_TEST; |
Oracle Database 11g (11.2.0.4)
1 | [oracle@skiper ~]$ sqlplus hr/hr |
3 | SQL*Plus: Release 11.2.0.4.0 Production on Tue Jan 27 10:15:05 2015 |
5 | Copyright (c) 1982, 2013, Oracle. All rights reserved. |
9 | Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production |
10 | With the Partitioning, Automatic Storage Management, OLAP, Data Mining |
11 | and Real Application Testing options |
14 | 2 from user_tab_partitions |
15 | 3 where table_name='TRUNCATE_TEST'; |
22 | SQL> truncate table TRUNCATE_TEST; |
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:
3 | 2 from v$process p, v$session s |
9 | ------------------------ |
12 | SQL> oradebug setospid 4797 |
13 | Oracle pid: 28, Unix process pid: 4797, image: oracle@skiper (TNS V1-V3) |
14 | SQL> oradebug event 10046 trace name context forever, level 12 |
16 | SQL> oradebug tracefile_name |
17 | /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".
1 | [oracle@skiper truncate_test]$ wc -l raw_truncate11g.trc |
2 | 1113 raw_truncate11g.trc |
3 | [oracle@skiper truncate_test]$ wc -l raw_truncate12c.trc |
4 | 4313645 raw_truncate12c.trc |
Further investigations shows the SQLs which are the reason of a slow TRUNCATE execution in the 12c database.
3 | sys.mon_mods$ where obj# = :objn |
6 | call count cpu elapsed disk query current rows |
7 | ------- ------ -------- ---------- ---------- ---------- ---------- ---------- |
8 | Parse 44000 2.18 2.70 0 0 0 0 |
9 | Execute 44000 8.56 9.89 0 0 0 0 |
10 | Fetch 44000 3.14 4.03 0 110000 0 22000 |
11 | ------- ------ -------- ---------- ---------- ---------- ---------- ---------- |
12 | total 132000 13.88 16.62 0 110000 0 22000 |
1 | SQL ID: bb926a5dcb8kr Plan Hash: 3530933756 |
3 | merge into sys.mon_mods$ m |
10 | where bo# = :pobjn and obj# = :objn |
14 | where bo# = :pobjn and obj# = :objn |
17 | from tabsubpart$ tsp, tabcompart$ tcp |
18 | where tsp.pobj# = tcp.obj# |
19 | and (tcp.bo# = :pobjn or tcp.obj# = :pobjn) |
20 | and tsp.obj# = :objn))) when matched |
23 | inserts + :ins, updates = updates + :upd, deletes = |
24 | deletes + :del, flags = |
25 | (decode(bitand(flags, :flag), :flag, flags, flags + :flag)), |
26 | drop_segments = drop_segments + :dropseg, |
27 | timestamp = :time when |
29 | insert (obj#, inserts, updates, deletes, |
30 | timestamp, flags, drop_segments) |
31 | values (:objn, :ins, :upd, :del, :time, :flag, :dropseg) |
34 | call count cpu elapsed disk query current rows |
35 | ------- ------ -------- ---------- ---------- ---------- ---------- ---------- |
36 | Parse 44000 2.01 2.28 0 0 0 0 |
37 | Execute 44000 57.61 65.34 0 264100 133393 44000 |
38 | Fetch 0 0.00 0.00 0 0 0 0 |
39 | ------- ------ -------- ---------- ---------- ---------- ---------- ---------- |
40 | 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:
1 | [oracle@skiper ~]$ sqlplus / as sysdba |
3 | SQL*Plus: Release 12.1.0.2.0 Production on Tue Jan 27 11:08:03 2015 |
5 | Copyright (c) 1982, 2014, Oracle. All rights reserved. |
9 | Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production |
10 | With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics |
11 | and Real Application Testing options |
13 | SQL> alter system set "_dml_monitoring_enabled"=FALSE scope=memory; |
20 | SQL> truncate table TRUNCATE_TEST; |
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:
1 | SQL> select last_analyzed, num_rows |
3 | 3 where table_name='TRUNCATE_TEST'; |
9 | SQL> select sum(num_rows), sum(blocks) |
10 | 2 from user_tab_partitions |
11 | 3 where table_name='TRUNCATE_TEST'; |
13 | SUM(NUM_ROWS) SUM(BLOCKS) |
14 | ------------- ----------- |
So what to do? As always: keep calm and use hidden parameters 🙂
