Oracle … as usual

Oracle by Laurent Leturgez

Monthly Archives: January 2013

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