Oracle … as usual

Oracle by Laurent Leturgez

Trace Oracle Internal triggers

When you create a replication between two tables, a snapshot log for your materialized views, etc. Oracle creates and manages internal triggers that execute SQL statements. For example, when you insert a row in a table with a snapshot log, sql statements are executed in the related snapshot log table (MLOG$ table).

But if you trace it with 10046 event, nothing will appear in the trace file.

SQL> create materialized view log on OBJ$CLONE;

Materialized view log created.

SQL> select * from mlog$_OBJ$CLONE;

no rows selected

SQL> @10046_on.sql

Session altered.

SQL> delete from OBJ$CLONE where obj#=3000;

1 row deleted.

SQL> insert into OBJ$CLONE select * from sys.obj$ where obj#=3000;

1 row created.

SQL> commit;

Commit complete.

SQL> @10046_off.sql
The tracefile doesn’t mention  any DML operation on the table MLOG$_OBJ$CLONE (see the tkprof output below):
SQL ID: 46m19q6258mvs Plan Hash: 4136978372

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),0), NVL(SUM(C2),0)
FROM
 (SELECT /*+ NO_PARALLEL("MLOG$_OBJ$CLONE") FULL("MLOG$_OBJ$CLONE")
  NO_PARALLEL_INDEX("MLOG$_OBJ$CLONE") */ 1 AS C1, 1 AS C2 FROM
  "LAURENT"."MLOG$_OBJ$CLONE" "MLOG$_OBJ$CLONE") SAMPLESUB

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.05          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0         14          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.05          0         14          0           2

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 2)
Number of plan statistics captured: 2

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=7 pr=0 pw=0 time=204 us)
         4          4          5   TABLE ACCESS FULL MLOG$_OBJ$CLONE (cr=7 pr=0 pw=0 time=105 us cost=2 size=0 card=82)

********************************************************************************

SQL ID: 2ya3sb8sagzxw Plan Hash: 3957508444

delete from OBJ$CLONE
where
 obj#=3000

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.07          0          8          0           0
Execute      1      0.00       0.00          0          3          8           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       0.07          0         11          8           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 90
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  OBJ$CLONE (cr=3 pr=0 pw=0 time=372 us)
         1          1          1   INDEX UNIQUE SCAN PK_OBJ$CLONE (cr=2 pr=0 pw=0 time=34 us cost=1 size=13 card=1)(object id 127619)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        3.68          3.68
********************************************************************************

SQL ID: 4n7u7f6u7kd2y Plan Hash: 1218588913

insert into OBJ$CLONE select * from sys.obj$ where obj#=3000

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          8          4           0
Execute      1      0.00       0.00          0          5          8           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0         13         12           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 90
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=5 pr=0 pw=0 time=518 us)
         1          1          1   TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=75 us cost=3 size=86 card=1)
         1          1          1    INDEX RANGE SCAN I_OBJ1 (cr=2 pr=0 pw=0 time=46 us cost=2 size=0 card=1)(object id 36)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        2.44          2.44
********************************************************************************

SQL ID: 23wm3kz7rps5y Plan Hash: 0

commit

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0

Misses in library cache during parse: 0
Parsing user id: 90

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        4.10          4.10
********************************************************************************
but there are some datas in this table:
SQL> select * from mlog$_OBJ$CLONE;

      OBJ# SNAPTIME$ D O CHANGE_VECTOR$$                     XID$$
---------- --------- - - ------------------------------ ----------
      3000 01-JAN-00 D O 000000                         5.6296E+15
      3000 01-JAN-00 I N FEFFFF                         5.6296E+15
And internal triggers is created to do this:
SQL> select * from user_internal_triggers;

TABLE_NAME                     INTERNAL_TRIGGER_TY
------------------------------ -------------------
OBJ$CLONE                      MVIEW LOG
By searching in USER_INTERNAL_TRIGGERS  code, we can see that this view references internal triggers on ‘DEFERRED RPC QUEUE’, ‘MVIEW LOG’, ‘UPDATABLE MVIEW LOG’ and ‘CONTEXT’. (based on the TAB$ table’s TRIGFLAG column).
select dbms_metadata.get_ddl('VIEW','USER_INTERNAL_TRIGGERS','SYS') ddl from dual

DDL
------------------------------------------------------------------------------------------------------------------------

  CREATE OR REPLACE FORCE VIEW "SYS"."USER_INTERNAL_TRIGGERS" ("TABLE_NAME", "INTERNAL_TRIGGER_TYPE") AS
  select o.name, 'DEFERRED RPC QUEUE'
from sys.tab$ t, sys.obj$ o
where o.owner# = userenv('SCHEMAID')
      and t.obj# = o.obj#
      and bitand(t.trigflag,1) = 1
union
select o.name, 'MVIEW LOG'
from sys.tab$ t, sys.obj$ o
where o.owner# = userenv('SCHEMAID')
      and t.obj# = o.obj#
      and bitand(t.trigflag,2) = 2
union
select o.name, 'UPDATABLE MVIEW LOG'
from sys.tab$ t, sys.obj$ o
where o.owner# = userenv('SCHEMAID')
       and t.obj# = o.obj#
       and bitand(t.trigflag,4) = 4
union
select o.name, 'CONTEXT'
from sys.tab$ t, sys.obj$ o
where o.owner# = userenv('SCHEMAID')
      and t.obj# = o.obj#
      and bitand(t.trigflag,8) = 8
If you want to trace what is really done by the internal trigger, you have a bunch of undocumented events that will trace specific triggers (Note there are events for repcat or synchronous replication for which there is no trigflag definition in USER_INTERNAL_TRIGGERS view code):
10302, 00000, "trace create or drop internal trigger"
// *Document: NO
// *Cause:
// *Action:

10303, 00000, "trace loading of library cache for internal triggers"
// *Document: NO
// *Cause:
// *Action:

10304, 00000, "trace replication trigger"
// *Document: NO
// *Cause:
// *Action:

10305, 00000, "trace updatable materialized view trigger"
// *Document: NO
// *Cause:
// *Action:

10306, 00000, "trace materialized view log trigger"
// *Document: NO
// *Cause:
// *Action:

10307, 00000, "trace RepCat execution"
// *Document: NO
// *Cause:
// *Action:

10308, 00000, "replication testing event"
// *Document: NO
// *Cause:
// *Action:

10309, 00000, "Trigger Debug event"
// *Document: NO
// *Cause:
// *Action:
// *Comment: This event replaces the earlier event number 10250
//           which had multiple definitions

10310, 00000, "trace synchronous change table trigger"
// *Document: NO
// *Cause:
// *Action:
I have chosen the 10306 event to trace internal triggers on Materialized view log (but you can use others depending on what you want to trace):
SQL> create materialized view log on OBJ$CLONE;

Materialized view log created.

SQL> select * from user_internal_triggers;

TABLE_NAME                     INTERNAL_TRIGGER_TY
------------------------------ -------------------
OBJ$CLONE                      MVIEW LOG

SQL> alter session set events '10306 trace name context forever, level 10';

Session altered.

SQL> delete from OBJ$CLONE where obj#=3000;

1 row deleted.

SQL> insert into OBJ$CLONE select * from sys.obj$ where obj#=3000;

1 row created.

SQL> commit;

Commit complete.
The related trace file shows SQL statements now executed on MLOG$_OBJ$CLONE table:
kntgslm()+
  ccl_kntsl = 1
  kntzcid =
        1
  lcc_kntsl = 0
  kntzlcs =
  kntzlcm =
  cpk_kntsl = 1
  pkc_kntsl =
        1
  flg_kntsl = 270434
  len_kntsl = 220
  sql_kntsl = INSERT /*+ IDX(%d) */ INTO "LAURENT"."MLOG$_OBJ$CLONE" (dmltype$$,old_new$$,snaptime$$,change_vector$$,xid$$,"OBJ#") VALUES (:d,:o,to_date('4000-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS'),:c,:x%s,:1)
  len2_kntsl = 0
  sql2_kntsl =
kntgslm()-
kntkca()
  ccl_kntsl = 1
  kntzcid =
        1
  lcc_kntsl = 0
  kntzlcs =
  kntzlcm =
  cpk_kntsl = 1
  pkc_kntsl =
        1
  flg_kntsl = 270434
  len_kntsl = 220
  sql_kntsl = INSERT /*+ IDX(%d) */ INTO "LAURENT"."MLOG$_OBJ$CLONE" (dmltype$$,old_new$$,snaptime$$,change_vector$$,xid$$,"OBJ#") VALUES (:d,:o,to_date('4000-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS'),:c,:x%s,:1)
  len2_kntsl = 0
  sql2_kntsl =
kntxslt()
  ccl_kntsl = 1
  kntzcid =
        1
  lcc_kntsl = 0
  kntzlcs =
  kntzlcm =
  cpk_kntsl = 1
  pkc_kntsl =
        1
  flg_kntsl = 270434
  len_kntsl = 220
  sql_kntsl = INSERT /*+ IDX(%d) */ INTO "LAURENT"."MLOG$_OBJ$CLONE" (dmltype$$,old_new$$,snaptime$$,change_vector$$,xid$$,"OBJ#") VALUES (:d,:o,to_date('4000-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS'),:c,:x%s,:1)
  len2_kntsl = 0
  sql2_kntsl =

*** 2013-01-16 11:53:21.065
kntkca()
  ccl_kntsl = 1
  kntzcid =
        1
  lcc_kntsl = 0
  kntzlcs =
  kntzlcm =
  cpk_kntsl = 1
  pkc_kntsl =
        1
  flg_kntsl = 270434
  len_kntsl = 220
  sql_kntsl = INSERT /*+ IDX(%d) */ INTO "LAURENT"."MLOG$_OBJ$CLONE" (dmltype$$,old_new$$,snaptime$$,change_vector$$,xid$$,"OBJ#") VALUES (:d,:o,to_date('4000-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS'),:c,:x%s,:1)
  len2_kntsl = 0
  sql2_kntsl =
kntxslt()
  ccl_kntsl = 1
  kntzcid =
        1
  lcc_kntsl = 0
  kntzlcs =
  kntzlcm =
  cpk_kntsl = 1
  pkc_kntsl =
        1
  flg_kntsl = 270434
  len_kntsl = 220
  sql_kntsl = INSERT /*+ IDX(%d) */ INTO "LAURENT"."MLOG$_OBJ$CLONE" (dmltype$$,old_new$$,snaptime$$,change_vector$$,xid$$,"OBJ#") VALUES (:d,:o,to_date('4000-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS'),:c,:x%s,:1)
  len2_kntsl = 0
  sql2_kntsl =
You can notice we have 5 instructions in sql_kntsl for 2 rows modified. Each statement seems to be controlled by 2 internal functions:  kntkca() and kntxslt(). There is one more function used to start this sequence kntgslm().
If I trace only one DML instruction in my OBJ$CLONE table, the result is one call to kntgslm() followed by a call to kntkca() and kntxslt().
So the sequence might start with a call to kntgslm followed by a call to  kntkca() and kntxslt() per row in the source table.
Finally, there’s a last problem: the sql text mentioned in sql_kntsl. It seems to be incomplete because of %d or %s in text but with those events, we can find in the sql statements executed we didn’t fin in the sql trace of the original statement.
Advertisements

One response to “Trace Oracle Internal triggers

  1. lawyers February 13, 2013 at 11:22 AM

    Another great submit thanks for the tips as well as very good study.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: