Slow TRUNCATE TABLE due to operations on MON_MODS$


27.01.2015
by Kamil Stawiarski

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 🙂

Search:


Kontakt

Database Whisperers sp. z o. o. sp. k.
Al. Jerozolimskie 200
Wejście B, III piętro/ pokój 342
02-486 Warszawa
NIP: 5272744987
REGON:362524978
+48 508 943 051
+48 661 966 009
info@ora-600.pl

Newsletter zapisz się żeby być na bieżąco