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.
Data ... as usual 