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 
Another great submit thanks for the tips as well as very good study.