Mark Rittman, March 2005
If you've read my blog recently you'll know that I'm trying to do a bit of research on OWB performance tuning. One of the things I'm trying to do is put a framework in place to run Event 10046 Extended SQL traces on OWB mappings, the thinking being that we can later analyze the trace files and retrieve the SQL that was executed, the relevant explain plans, and the wait events that happened during the mapping execution. With this in mind, I had a look today at adding tracing facilities to an OWB mapping.
UPDATE: See also Using DBMS_MONITOR To Trace OWB Process Flows where I look at tracing a complete process flow using Using DBMS_MONITOR, DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE and trcsess.
The first step was to create an new OWB project, using OWB 10.1 on Windows XP SP2 running against a local Oracle 10g 10.1.0.3 Enterprise Edition database. I created three source modules, against the OE, HR and SH sample schemas, a target schema, DW_TARGET, which I registered as an OWB target module, and granted the DW_TARGET schema SELECT access on the OE, HR and SH schema tables.
Next, I created a mapping that joined the CUSTOMERS, ORDERS, ORDER_ITEMS and PRODUCT_INFORMATION tables and loaded them into a new, unbound table called ORDER_SUMMARY. After registering all the locations and connectors (why does this have to be so fiddly?) I generated and deployed the new table and the mapping, executed it and checked that it ran OK.
Then, to implement the event 10046 extended SQL trace facility, I created two transformations, ENABLE_10046_LVL_12 and DISABLE_10046, to turn extended trace on and off within a mapping. The code for the two transformations was:
CREATE OR REPLACE PROCEDURE enable_10046_lvl_12 (enable_y_n varchar2)
as
BEGIN
if enable_y_n = 'Y' then
begin
execute immediate 'alter session set timed_statistics = true';
execute immediate 'alter session set max_dump_file_size = unlimited';
execute immediate 'alter session set tracefile_identifier = ''owb_trc''';
execute immediate 'alter session set events ''10046 trace name context forever, level 12''';
end;
end if;
EXCEPTION
WHEN OTHERS THEN
NULL; -- enter any exception code here
END;
and
CREATE OR REPLACE PROCEDURE disable_10046
as
BEGIN
execute immediate 'alter session set events ''10046 trace name context off''';
EXCEPTION
WHEN OTHERS THEN
NULL; -- enter any exception code here
END;
which I then added to the mapping as pre- and post-mapping triggers. After adding the triggers to the mapping, and a constant that I passed to the ENABLE_10046_LVL_12 procedure to turn tracing on, the mapping looked like this:
The next step then was to run the mapping, and locate the trace file. I ran the mapping in "set based, fail over to row-based" mode which should generate a single INSERT INTO ... SELECT statement to implement my mapping, located the trace file in my UDUMP directory, ran it through TKPROF
tkprof C:\oracle\admin\markr10g\udump\markr10g_ora_5800_owb_trc.trc C:\oracle\admin\markr10g\udump\markr10g_ora_5800_owb_trc.txt
and took a look at the formatted trace file.
TKPROF: Release 10.1.0.3.0 - Production on Mon Mar 7 14:54:43 2005
Copyright (c) 1982, 2004, Oracle. All rights reserved.
Trace file: C:\oracle\admin\markr10g\udump\markr10g_ora_2884_owb_trc.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
alter session set events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
********************************************************************************
COMMIT
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 7 0.00 0.00 0 0 0 0
Execute 7 0.01 0.03 186 727 1559 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.01 0.03 186 727 1559 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PX Deq: Execute Reply 4 0.00 0.00
rdbms ipc reply 1 0.00 0.00
log file sync 1 0.00 0.00
PX Deq: Signal ACK 1 0.00 0.00
********************************************************************************
SELECT WB_RT_MAP_AUDIT_DETAIL_SEQ.NEXTVAL
FROM
DUAL
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 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (recursive depth: 1)
********************************************************************************
INSERT INTO WB_RT_AUDIT_DETAIL ( RTD_IID , RTA_IID , RTD_STEP , RTD_NAME ,
RTD_SOURCE , RTD_SOURCE_UOID , RTD_TARGET , RTD_TARGET_UOID , RTD_STATUS ,
RTD_STATEMENT , RTD_INFO , RTD_EXEC_MODE )
VALUES
( :1 , :1 , :1 , :1 , SUBSTR(:1 , 0 , 2000 ) , SUBSTR(:1 , 0 , 2000 ) ,
SUBSTR(:1 , 0 , 2000 ) , SUBSTR(:1 , 0 , 2000 ) , :1 , :1 , :1 , :1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 3 1 8 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 3 1 8 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 3 0.00 0.00
********************************************************************************
SELECT USER
FROM
SYS.DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 0 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 0 0 4
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (recursive depth: 2)
********************************************************************************
ALTER SESSION ENABLE PARALLEL DML
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 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
********************************************************************************
select condition
from
cdef$ where rowid=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 5 0.00 0.00 0 0 0 0
Execute 5 0.00 0.00 0 0 0 0
Fetch 5 0.00 0.03 2 11 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 15 0.00 0.03 2 11 0 5
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY USER ROWID CDEF$ (cr=0 pr=0 pw=0 time=0 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.01 0.03
********************************************************************************
SELECT ORA_TQ_BASE$.NEXTVAL
FROM
DUAL
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 0 0
Fetch 1 0.00 0.00 0 0 1 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 1 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
1 SEQUENCE (cr=1 pr=1 pw=0 time=28279 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=8 us)
********************************************************************************
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,
cache=:7,highwater=:8,audit$=:9,flags=:10
where
obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.02 1 1 2 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.02 1 1 2 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 3)
Rows Row Source Operation
------- ---------------------------------------------------
1 UPDATE (cr=1 pr=1 pw=0 time=12189 us)
1 INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=25 us)(object id 106)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.01 0.01
********************************************************************************
INSERT INTO "ORDER_SUMMARY" ("ORDER_ID", "ORDER_MODE", "CUSTOMER_ID",
"CUST_FIRST_NAME", "CUST_LAST_NAME", "UNIT_PRICE", "QUANTITY") (SELECT
"ORDERS_OE2"."ORDER_ID" "ORDER_ID$1", "ORDERS_OE2"."ORDER_MODE"
"ORDER_MODE$1", "ORDERS_OE2"."CUSTOMER_ID" "CUSTOMER_ID$1",
"CUSTOMERS_OE2"."CUST_FIRST_NAME" "CUST_FIRST_NAME$1",
"CUSTOMERS_OE2"."CUST_LAST_NAME" "CUST_LAST_NAME$1",
"ORDER_ITEMS_OE2"."UNIT_PRICE" "UNIT_PRICE$1", "ORDER_ITEMS_OE2"."QUANTITY"
"QUANTITY$1" FROM "OE"."ORDERS" "ORDERS_OE2", "OE"."CUSTOMERS"
"CUSTOMERS_OE2", "OE"."ORDER_ITEMS" "ORDER_ITEMS_OE2",
"OE"."PRODUCT_INFORMATION" "PRODUCT_INFORMATION_OE2" WHERE (
"ORDERS_OE2"."CUSTOMER_ID" = "CUSTOMERS_OE2"."CUSTOMER_ID" ) AND (
"ORDER_ITEMS_OE2"."PRODUCT_ID" = "PRODUCT_INFORMATION_OE2"."PRODUCT_ID" )
AND ( "ORDER_ITEMS_OE2"."ORDER_ID" = "ORDERS_OE2"."ORDER_ID" ) )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.02 0 0 0 0
Execute 1 0.01 3.43 50 736 43 665
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.03 3.46 50 736 43 665
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 32 0.03 0.21
process startup 2 0.00 0.00
PX Deq: Join ACK 1 0.00 0.00
PX Deq: Parse Reply 3 0.00 0.00
PX Deq: Execute Reply 8 2.04 3.04
db file scattered read 3 0.02 0.04
PX Deq Credit: need buffer 2 0.00 0.00
PX qref latch 1 0.00 0.00
rdbms ipc reply 1 0.00 0.00
********************************************************************************
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=
:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),
groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=
DECODE(:17,0,NULL,:17),scanhint=:18
where
ts#=:1 and file#=:2 and block#=:3
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.02 0.01 0 10 2 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.02 0.01 0 10 2 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE (cr=5 pr=0 pw=0 time=284 us)
1 TABLE ACCESS CLUSTER SEG$ (cr=5 pr=0 pw=0 time=141 us)
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=31 us)(object id 9)
********************************************************************************
delete from seg$
where
ts#=:1 and file#=:2 and block#=:3
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 12 2 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 12 2 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 DELETE (cr=6 pr=0 pw=0 time=215 us)
1 TABLE ACCESS CLUSTER SEG$ (cr=5 pr=0 pw=0 time=112 us)
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=24 us)(object id 9)
********************************************************************************
update tsq$ set blocks=:3,maxblocks=:4,grantor#=:5,priv1=:6,priv2=:7,priv3=:8
where
ts#=:1 and user#=:2
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 3 1 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 3 1 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE (cr=3 pr=0 pw=0 time=202 us)
1 TABLE ACCESS CLUSTER TSQ$ (cr=3 pr=0 pw=0 time=96 us)
1 INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=22 us)(object id 11)
********************************************************************************
SELECT COUNT (*)
FROM
ALL_TABLES WHERE OWNER = :1 AND TABLE_NAME = :1
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 0 0
Fetch 1 0.00 0.02 2 24 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.02 2 24 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.01 0.01
********************************************************************************
SELECT NVL(NUM_ROWS, 0)
FROM
ALL_TABLES WHERE TABLE_NAME = :B2 AND OWNER = :B1
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 0 0
Fetch 1 0.00 0.00 0 24 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 24 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
********************************************************************************
UPDATE WB_RT_AUDIT_DETAIL SET RTD_STATUS = :1,RTD_SELECT = NVL(:1 ,
RTD_SELECT ) ,RTD_INSERT = NVL(:1 , RTD_INSERT ) ,RTD_UPDATE = NVL(:1 ,
RTD_UPDATE ) ,RTD_DELETE = NVL(:1 , RTD_DELETE ) ,RTD_ERRORS = NVL(:1 ,
RTD_ERRORS ) ,RTD_DISCARDED = NVL(:1 , RTD_DISCARDED ) ,RTD_MERGE = NVL(:1 ,
RTD_MERGE )
WHERE
RTD_IID = :1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.00 1 2 1 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 1 2 1 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
ALTER SESSION DISABLE PARALLEL DML
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 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
********************************************************************************
alter session set events '10046 trace name context off'
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 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 28 0.02 0.02 0 0 0 0
Execute 33 0.06 3.54 241 1492 1618 673
Fetch 13 0.00 0.05 4 59 1 13
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 74 0.08 3.62 245 1551 1619 686
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 41 0.03 0.28
process startup 2 0.00 0.00
PX Deq: Join ACK 1 0.00 0.00
PX Deq: Parse Reply 3 0.00 0.00
PX Deq: Execute Reply 12 2.04 3.04
db file scattered read 3 0.02 0.04
PX Deq Credit: need buffer 2 0.00 0.00
PX qref latch 1 0.00 0.00
rdbms ipc reply 2 0.00 0.00
log file sync 1 0.00 0.00
PX Deq: Signal ACK 1 0.00 0.00
18 user SQL statements in session.
12 internal SQL statements in session.
30 SQL statements in session.
********************************************************************************
Trace file: C:\oracle\admin\markr10g\udump\markr10g_ora_2884_owb_trc.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
18 user SQL statements in trace file.
12 internal SQL statements in trace file.
30 SQL statements in trace file.
18 unique SQL statements in trace file.
599 lines in trace file.
3 elapsed seconds in trace file.
Some immediate points I noticed were:
So far, so good, although I was a bit concerned about the lack of an explain plan for the major DML statement in the trace file. I had a look through metalink and reran the TKPROF command, this time with the EXPLAIN=username/password@connectstring option, which runs an explain plan for each statement within the trace file. Note that this explain plan is generated at the time the trace file is analyzed, and isn't necessarily the same execution plan that was generated when the SQL was executed (indexes could have been dropped since, stats gathered and so on). Note also that I originally got an ORA-922 error when I first tried this, and had to follow the instructions in this metalink note to generate the PLAN_TABLE table within my target schema.
C:\>tkprof C:\oracle\admin\markr10g\udump\markr10g_ora_5800_owb_trc.trc C:\oracle\admin\markr10g\udump\markr10g_ora_5800_owb_trc.txt explain = dw_target/password@markr10g table=DW_TARGET.PLAN_TABLE
The formatted trace then contained explain plans for each of the SQL statements. In particular I was interested in the one for our main INSERT ... SELECT statement, which now looked like this:
INSERT /*+ APPEND PARALLEL(ORDER_SUMMARY, DEFAULT, DEFAULT) */ INTO
"ORDER_SUMMARY" ("ORDER_ID", "ORDER_MODE", "CUSTOMER_ID", "CUST_FIRST_NAME",
"CUST_LAST_NAME", "UNIT_PRICE", "QUANTITY") (SELECT
"ORDERS_OE2"."ORDER_ID" "ORDER_ID$1", "ORDERS_OE2"."ORDER_MODE"
"ORDER_MODE$1", "ORDERS_OE2"."CUSTOMER_ID" "CUSTOMER_ID$1",
"CUSTOMERS_OE2"."CUST_FIRST_NAME" "CUST_FIRST_NAME$1",
"CUSTOMERS_OE2"."CUST_LAST_NAME" "CUST_LAST_NAME$1",
"ORDER_ITEMS_OE2"."UNIT_PRICE" "UNIT_PRICE$1", "ORDER_ITEMS_OE2"."QUANTITY"
"QUANTITY$1" FROM "OE"."ORDERS" "ORDERS_OE2", "OE"."CUSTOMERS"
"CUSTOMERS_OE2", "OE"."ORDER_ITEMS" "ORDER_ITEMS_OE2",
"OE"."PRODUCT_INFORMATION" "PRODUCT_INFORMATION_OE2" WHERE (
"ORDERS_OE2"."CUSTOMER_ID" = "CUSTOMERS_OE2"."CUSTOMER_ID" ) AND (
"ORDER_ITEMS_OE2"."PRODUCT_ID" = "PRODUCT_INFORMATION_OE2"."PRODUCT_ID" )
AND ( "ORDER_ITEMS_OE2"."ORDER_ID" = "ORDERS_OE2"."ORDER_ID" ) )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.03 3.50 48 744 42 665
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.03 3.50 48 744 42 665
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT MODE: ALL_ROWS
0 LOAD AS SELECT
0 NESTED LOOPS
0 HASH JOIN
0 HASH JOIN
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'ORDERS' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'ORD_CUSTOMER_IX' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'CUSTOMERS'
(TABLE)
0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ORDER_ITEMS'
(TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'PRODUCT_INFORMATION_PK' (INDEX (UNIQUE))
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 30 0.05 0.30
process startup 2 0.00 0.00
PX Deq: Join ACK 2 0.00 0.00
PX qref latch 4 0.01 0.03
PX Deq: Parse Reply 2 0.04 0.05
PX Deq: Execute Reply 7 2.04 2.89
db file scattered read 3 0.04 0.08
PX Deq Credit: need buffer 2 0.00 0.00
PX Deq Credit: send blkd 2 0.01 0.01
rdbms ipc reply 2 0.00 0.00
********************************************************************************
So what we've got here is a way of automatically generating a log of SQL statements issued for a mapping, the explain plans for those statements, and the wait events that occurred whilst the commands were executing.
I was curious then as to what the trace file for the same mapping, executed in row-based mode, would look like. I configured the mapping to use "bulk processing code", which uses the BULK COLLECT and FORALL features to speed up processing:
TKPROF: Release 10.1.0.3.0 - Production on Mon Mar 7 16:43:46 2005
Copyright (c) 1982, 2004, Oracle. All rights reserved.
Trace file: C:\oracle\admin\markr10g\udump\markr10g_ora_7968_owb_trc.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
alter session set events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
********************************************************************************
COMMIT
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 7 0.00 0.00 0 0 0 0
Execute 33 0.02 0.01 0 0 15 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 40 0.02 0.01 0 0 15 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
********************************************************************************
ALTER SESSION DISABLE PARALLEL DML
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 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
********************************************************************************
SELECT WB_RT_MAP_AUDIT_DETAIL_SEQ.NEXTVAL
FROM
DUAL
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 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
error during execute of EXPLAIN PLAN statement
ORA-02289: sequence does not exist
parse error offset: 74
********************************************************************************
INSERT INTO WB_RT_AUDIT_DETAIL ( RTD_IID , RTA_IID , RTD_STEP , RTD_NAME ,
RTD_SOURCE , RTD_SOURCE_UOID , RTD_TARGET , RTD_TARGET_UOID , RTD_STATUS ,
RTD_STATEMENT , RTD_INFO , RTD_EXEC_MODE )
VALUES
( :1 , :1 , :1 , :1 , SUBSTR(:1 , 0 , 2000 ) , SUBSTR(:1 , 0 , 2000 ) ,
SUBSTR(:1 , 0 , 2000 ) , SUBSTR(:1 , 0 , 2000 ) , :1 , :1 , :1 , :1 )
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 1 8 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 1 8 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
error during execute of EXPLAIN PLAN statement
ORA-00942: table or view does not exist
parse error offset: 79
********************************************************************************
SELECT USER
FROM
SYS.DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 58 0.00 0.02 0 0 0 0
Fetch 58 0.00 0.00 0 0 0 58
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 116 0.00 0.02 0 0 0 58
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 FAST DUAL
********************************************************************************
SELECT "ORDERS_OE2"."ORDER_ID" "ORDER_ID", "ORDERS_OE2"."ORDER_MODE"
"ORDER_MODE", "ORDERS_OE2"."CUSTOMER_ID" "CUSTOMER_ID",
"CUSTOMERS_OE2"."CUST_FIRST_NAME" "CUST_FIRST_NAME",
"CUSTOMERS_OE2"."CUST_LAST_NAME" "CUST_LAST_NAME",
"ORDER_ITEMS_OE2"."UNIT_PRICE" "UNIT_PRICE", "ORDER_ITEMS_OE2"."QUANTITY"
"QUANTITY"
FROM
"OE"."ORDERS" "ORDERS_OE2", "OE"."CUSTOMERS" "CUSTOMERS_OE2",
"OE"."ORDER_ITEMS" "ORDER_ITEMS_OE2", "OE"."PRODUCT_INFORMATION"
"PRODUCT_INFORMATION_OE2" WHERE ( "ORDERS_OE2"."CUSTOMER_ID" =
"CUSTOMERS_OE2"."CUSTOMER_ID" ) AND ( "ORDER_ITEMS_OE2"."PRODUCT_ID" =
"PRODUCT_INFORMATION_OE2"."PRODUCT_ID" ) AND ( "ORDER_ITEMS_OE2"."ORDER_ID"
= "ORDERS_OE2"."ORDER_ID" )
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 0 0
Fetch 14 0.02 0.03 0 703 0 665
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 16 0.02 0.03 0 703 0 665
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 NESTED LOOPS
0 HASH JOIN
0 HASH JOIN
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'ORDERS'
(TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'ORD_CUSTOMER_IX'
(INDEX)
0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'CUSTOMERS' (TABLE)
0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ORDER_ITEMS' (TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'PRODUCT_INFORMATION_PK' (INDEX (UNIQUE))
********************************************************************************
select increment$,minvalue,maxvalue,cycle#,order$,cache,highwater,audit$,
flags
from
seq$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 28 0.01 0.03 0 0 0 0
Fetch 28 0.00 0.00 0 56 0 28
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 57 0.01 0.03 0 56 0 28
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB) */ NVL(SUM(C1),0),
NVL(SUM(C2),0)
FROM
(SELECT /*+ NO_PARALLEL("WB_RT_ROWKEY_LOCK") FULL("WB_RT_ROWKEY_LOCK")
NO_PARALLEL_INDEX("WB_RT_ROWKEY_LOCK") */ 1 AS C1, 1 AS C2 FROM
"WB_RT_ROWKEY_LOCK" "WB_RT_ROWKEY_LOCK") SAMPLESUB
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 28 0.00 0.00 0 0 0 0
Execute 28 0.00 0.00 0 0 0 0
Fetch 28 0.00 0.00 0 84 0 28
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 84 0.00 0.00 0 84 0 28
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=3 pr=0 pw=0 time=92 us)
1 TABLE ACCESS FULL WB_RT_ROWKEY_LOCK (cr=3 pr=0 pw=0 time=63 us)
error during execute of EXPLAIN PLAN statement
ORA-00942: table or view does not exist
parse error offset: 352
********************************************************************************
SELECT WB_RT_ROWKEY_SEQ.NEXTVAL
FROM
WB_RT_ROWKEY_LOCK FOR UPDATE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 2 0 0
Execute 28 0.10 0.12 0 110 84 0
Fetch 28 0.03 0.07 0 84 28 28
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 58 0.13 0.20 0 196 112 28
Misses in library cache during parse: 2
Misses in library cache during execute: 26
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
error during execute of EXPLAIN PLAN statement
ORA-00942: table or view does not exist
parse error offset: 105
********************************************************************************
update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,
cache=:7,highwater=:8,audit$=:9,flags=:10
where
obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 84 0.00 0.00 0 0 0 0
Execute 84 0.33 0.72 0 84 171 84
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 168 0.33 0.72 0 84 171 84
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
1 UPDATE (cr=1 pr=0 pw=0 time=199 us)
1 INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=24 us)(object id 106)
********************************************************************************
ALTER SEQUENCE wb_rt_rowkey_seq INCREMENT BY 49
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 13 0.01 0.00 0 0 13 0
Execute 13 0.08 0.11 0 0 53 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 26 0.09 0.12 0 0 66 0
Misses in library cache during parse: 13
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
********************************************************************************
update obj$ set obj#=:6,type#=:7,ctime=:8,mtime=:9,stime=:10,status=:11,
dataobj#=:13,flags=:14,oid$=:15,spare1=:16, spare2=:17
where
owner#=:1 and name=:2 and namespace=:3 and(remoteowner=:4 or remoteowner is
null and :4 is null)and(linkname=:5 or linkname is null and :5 is null)
and(subname=:12 or subname is null and :12 is null)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 28 0.00 0.00 0 0 0 0
Execute 28 0.15 0.30 0 56 28 28
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 56 0.15 0.30 0 56 28 28
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE (cr=2 pr=0 pw=0 time=246 us)
1 INDEX RANGE SCAN I_OBJ2 (cr=2 pr=0 pw=0 time=79 us)(object id 37)
********************************************************************************
ALTER SEQUENCE wb_rt_rowkey_seq INCREMENT BY 1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 14 0.01 0.00 0 0 14 0
Execute 14 0.12 0.10 0 0 56 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 28 0.13 0.11 0 0 70 0
Misses in library cache during parse: 14
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
********************************************************************************
INSERT /*+ APPEND PARALLEL(ORDER_SUMMARY, DEFAULT, DEFAULT) */ INTO
"ORDER_SUMMARY" ("ORDER_ID", "ORDER_MODE", "CUSTOMER_ID", "CUST_FIRST_NAME",
"CUST_LAST_NAME", "UNIT_PRICE", "QUANTITY")
VALUES
(:B1 , :B2 , :B3 , :B4 , :B5 , :B6 , :B7 ) RETURNING ROWID INTO :O0
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 14 0.03 0.13 6 17 791 665
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 15 0.03 0.13 6 17 791 665
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT MODE: ALL_ROWS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 6 0.02 0.06
********************************************************************************
UPDATE WB_RT_AUDIT_DETAIL SET RTD_SELECT = NVL(:1 , RTD_SELECT ) ,RTD_INSERT =
NVL(:1 , RTD_INSERT ) ,RTD_UPDATE = NVL(:1 , RTD_UPDATE ) ,RTD_DELETE =
NVL(:1 , RTD_DELETE ) ,RTD_ERRORS = NVL(:1 , RTD_ERRORS ) ,RTD_DISCARDED =
NVL(:1 , RTD_DISCARDED )
WHERE
RTD_IID = :1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 27 0.07 0.11 0 54 108 27
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 28 0.07 0.11 0 54 108 27
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
error during execute of EXPLAIN PLAN statement
ORA-00942: table or view does not exist
parse error offset: 74
********************************************************************************
ALTER SEQUENCE wb_rt_rowkey_seq INCREMENT BY 14
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 1 0
Execute 1 0.00 0.00 0 0 4 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 5 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
********************************************************************************
SELECT COUNT (*)
FROM
ALL_TABLES WHERE OWNER = :1 AND TABLE_NAME = :1
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 0 0
Fetch 1 0.00 0.00 0 24 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 24 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 SORT (AGGREGATE)
0 FILTER
0 NESTED LOOPS
0 MERGE JOIN (CARTESIAN)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS
0 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX
ROWID) OF 'USER$' (CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_USER1' (INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (BY INDEX
ROWID) OF 'OBJ$' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'I_OBJ2' (INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF
'TAB$' (CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_OBJ#' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF
'TS$' (CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_TS#' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF
'SEG$' (CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_FILE#_BLOCK#' (INDEX)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'I_OBJ1'
(INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'OBJ$' (TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'I_OBJ1'
(INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF 'USER$'
(CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'I_USER#'
(INDEX)
0 BUFFER (SORT)
0 FIXED TABLE (FULL) OF 'X$KSPPI' (TABLE (FIXED))
0 FIXED TABLE (FIXED INDEX) OF 'X$KSPPCV (ind:2)' (TABLE
(FIXED))
0 NESTED LOOPS
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'I_OBJAUTH1' (INDEX
(UNIQUE))
0 FIXED TABLE (FULL) OF 'X$KZSRO' (TABLE (FIXED))
0 FIXED TABLE (FULL) OF 'X$KZSPR' (TABLE (FIXED))
********************************************************************************
SELECT NVL(NUM_ROWS, 0)
FROM
ALL_TABLES WHERE TABLE_NAME = :B2 AND OWNER = :B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 1 0.00 0.00 0 24 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.01 0 24 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 FILTER
0 NESTED LOOPS
0 MERGE JOIN (CARTESIAN)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS (OUTER)
0 NESTED LOOPS
0 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX
ROWID) OF 'USER$' (CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_USER1' (INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (BY INDEX
ROWID) OF 'OBJ$' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'I_OBJ2' (INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF
'TAB$' (CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_OBJ#' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF 'TS$'
(CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_TS#' (INDEX)
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF 'SEG$'
(CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'I_FILE#_BLOCK#' (INDEX)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'I_OBJ1'
(INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'OBJ$' (TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'I_OBJ1'
(INDEX (UNIQUE))
0 TABLE ACCESS MODE: ANALYZED (CLUSTER) OF 'USER$'
(CLUSTER)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'I_USER#'
(INDEX)
0 BUFFER (SORT)
0 FIXED TABLE (FULL) OF 'X$KSPPI' (TABLE (FIXED))
0 FIXED TABLE (FIXED INDEX) OF 'X$KSPPCV (ind:2)' (TABLE
(FIXED))
0 NESTED LOOPS
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'I_OBJAUTH1' (INDEX
(UNIQUE))
0 FIXED TABLE (FULL) OF 'X$KZSRO' (TABLE (FIXED))
0 FIXED TABLE (FULL) OF 'X$KZSPR' (TABLE (FIXED))
********************************************************************************
UPDATE WB_RT_AUDIT_DETAIL SET RTD_STATUS = :1,RTD_SELECT = NVL(:1 ,
RTD_SELECT ) ,RTD_INSERT = NVL(:1 , RTD_INSERT ) ,RTD_UPDATE = NVL(:1 ,
RTD_UPDATE ) ,RTD_DELETE = NVL(:1 , RTD_DELETE ) ,RTD_ERRORS = NVL(:1 ,
RTD_ERRORS ) ,RTD_DISCARDED = NVL(:1 , RTD_DISCARDED ) ,RTD_MERGE = NVL(:1 ,
RTD_MERGE )
WHERE
RTD_IID = :1
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 2 4 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 2 4 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (OWB10G_RUNTIME) (recursive depth: 1)
error during execute of EXPLAIN PLAN statement
ORA-00942: table or view does not exist
parse error offset: 74
********************************************************************************
alter session set events '10046 trace name context off'
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 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (DW_TARGET) (recursive depth: 1)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 188 0.02 0.03 0 2 28 0
Execute 365 0.91 1.72 6 324 1322 806
Fetch 159 0.05 0.11 0 975 28 810
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 712 0.98 1.88 6 1301 1378 1616
Misses in library cache during parse: 30
Misses in library cache during execute: 26
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 6 0.02 0.06
77 user SQL statements in session.
113 internal SQL statements in session.
190 SQL statements in session.
5 statements EXPLAINed in this session.
********************************************************************************
Trace file: C:\oracle\admin\markr10g\udump\markr10g_ora_7968_owb_trc.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
77 user SQL statements in trace file.
113 internal SQL statements in trace file.
190 SQL statements in trace file.
21 unique SQL statements in trace file.
5 SQL statements EXPLAINed using schema:
DW_TARGET.PLAN_TABLE
Schema was specified.
Existing table was used.
6862 lines in trace file.
2 elapsed seconds in trace file.
Note the difference in the way the data was inserted, the higher number of executions, and the fact that (funnily enough) the elapsed time was lower than the set-based execution. If I had the time I'd take a look at how a row-based execution faired when the "bulk processing code" option was turned off, and a regular explicit cursor and for loop was used instead. However, what this has however shown is that we can trace an OWB mapping using pre-and post-mapping triggers, and we can get some useful information out of the resulting trace file.
The next steps, for when I get a chance, is to get the same tracing working when we put the mappings in a process flow. The kicker here is going to be the fact that each mapping uses it's own Oracle session, whereas what we want is one big Oracle session that contains the SQL for all of the mappings in sequence. Niall Litchfield dropped me a line over the weekend and suggested using DBMS_MONITOR instead of the "alter session" command, which would allow me to use the client info and module features to create an identifier across multiple trace files that could later be used to reconstruct the sequence of mappings.
The other step I'd like to look at is using Oracle Trace Analyzer to store the output of the trace files in a repository. What I'm aiming for here is something we can add to the post-mapping trigger that not only turns off trace, but processes the trace file and uploads the SQL plans, execution times, list of SQL executed and wait events to a repository, so that the OWB developer can have this to hand and use it to determine how "efficient" their mappings are. In the meantime, if you've got any feedback on this please feel free to drop me a line at mark@rittman.net and I'll be pleased to receive any suggestions.
UPDATE: See also Using DBMS_MONITOR To Trace OWB Process Flows where I look at tracing a complete process flow using Using DBMS_MONITOR, DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE and trcsess.