Mark Rittman, March 2005
The next step in my OWB Performance Tuning Framework is to get trace working across a complete process flow. Before I start looking at this though, I need to get Workflow installed.
I'm running an Oracle 10g 10.1.0.3 Enterprise Edition database on Windows XP SP2. The first task is to actually locate the Workflow installation files - in the end I found them here and the corresponding instructions here. Basically, to install Workflow Server in an existing 10.1.0.3 database, you need to carry out the following steps:
I then went in to the OWB Client, and created a new process flow that ran two mappings, one of which was the INSERT from yesterday, the other one a MERGE.
I then ran the process flow from within the Deployment Manager, and the mappings
executed successfully. As each of the mappings had the pre- and post-mapping
triggers within them that enabled the extended SQL trace, I ended up with two
trace files within my UDUMP directory
with of course the reason there were two (rather than one) being that each mapping established it's own Oracle session (the 3668 and 4680's in the trace file name) when connecting to Oracle.
So, this is a good start and I could then use TKPROF to analyze each of these trace files in turn. However, what will actually happen in reality is that there will be many trace files within the UDUMP directory, generated by either myself or other people using OWB, so what I really need is a way of piecing together these individual trace files into one "logical" process.
As I'm using Oracle 10g, there's a new build in package that I can use that'll allow me to create a trace file spanning multiple sessions. The package is called DBMS_MONITOR, it comes preinstalled with 10g (although you'll need to grant execute on DBMS_MONITOR to whatever user needs to execute it), and it allows you to set up a trace based on something called a "client id", as well as the traditional session ID that was used before. The trick here is that each of our mappings is going to register itself using the same client ID, so later on we can use another new tool (trcsess) to create a single, aggregated trace file out of all the ones that had trace data for our client ID. For some background information on DBMS_MONITOR, trcsess and client IDs, see this OTN article by Kimberly Floss.
The first step is to create two OWB transformations, to enable us to enable and disable extended SQL trace. Note the parameter that I'm bringing in to the transformations, which will be used as our client ID and will be passed to the mapping by the Oracle Workflow process flow. The PL/SQL for the two transformations is as follows:
PROCEDURE "DBMS_MONITOR_EN_CLIENT_TRC"("TRC_ID" IN VARCHAR2)
IS
BEGIN
dbms_session.set_identifier(trc_id);
dbms_monitor.client_id_trace_enable (client_id=>trc_id);
EXCEPTION
WHEN OTHERS THEN
NULL; -- enter any exception code here
END;
and
PROCEDURE "DBMS_MONITOR_DIS_CLIENT_TRC"("TRC_ID" IN VARCHAR2)
IS
BEGIN
dbms_monitor.client_id_trace_disable(client_id=>trc_id);
EXCEPTION
WHEN OTHERS THEN
NULL; -- enter any exception code here
END;
Then, these two transformations are added to a mapping as pre- and post-mapping triggers, together with a mapping input parameter which we map to the transformation inputs. Call the output attribute of the input parameter "TRC_ID".
The next step is to add the same pre- and post-mapping triggers, and the mapping input parameter, to any other mappings that will be part of our process flow. We should then be in a position where all of our mappings have code within them to set a common client ID (which we'll pass to each of the mappings from within the workflow process flow), start an extended SQL trace and then stop it at the end of the mapping.
Next, using the OWB Client you need to create a process flow to sequence together the mappings that you're interested in. My process flow looked like this (don't worry about transitions yet):
Next, add three parameters to the process start activity, and give them these names and values:
like this:
Then, for each of the mapping activities, bind the mapping input parameter to the start activity TRC_ID parameter you just created, like this:
Now, each of our mappings will receive the TRC_ID parameter value that we give a value to when we run the process flow. Next, we need to add an External Process to our process flow, which will run the trcsess executable and process the trace files generated by each mapping (remember, each mapping will generate it's own trace file, with the session ID embedded in the file name, and we're then going to use the client ID to stitch all of these together).
Add an External Process to your process flow, add the following parameters, and bind them to the specified start activity parameters
then enter the following values into the Activity View window (note : all of this assumes you're running Windows XP on the server. If you're not, you'll need to adjust for your version of Windows/Unix)
and you should end up with something like this:
Then, create transitions between all of your mappings, with the external process run at the end.
Now that we have created our process flow, and put in place parameters that will define the client ID and specify the location of the UDUMP directory and the trcsess executable, we can load up the Deployment Manager, generate and deploy the process flow, and then execute it. When we run the process flow, a dialog box comes up to ask for the TRC_ID (our client ID, which we'll use to tie out traces together), and with out default UDUMP and trcsess path values:
Note that MYTRACE01 is the client ID I'm passing in to the process flow. Finally, press Execute and the process flow should run. If all goes OK, you should end up with a report like this:
If you take a look in your UDUMP directory, you should now see individual trace files for each of the individual mappings, and a consolidated trace file (using your TRC_ID value for the file name), in the directory.
Then, it's just a case of formatting the trace file using TKPROF (TKPROF trace_file_name output_file_name) and you can then take a look and see all the SQL for a process flow within the same trace file output.
TKPROF: Release 10.1.0.3.0 - Production on Tue Mar 8 17:50:29 2005
Copyright (c) 1982, 2004, Oracle. All rights reserved.
Trace file: C:\oracle\admin\markr10g\udump\MYTRACE01.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
********************************************************************************
The following statement encountered a error during parse:
SELECT 1 FROM DUAL WHERE "CUSTOMER_ORDERS"."ORDER_ID" = "MERGEQUERY_904"."ORDER_ID$1"
Error encountered: ORA-00904
********************************************************************************
COMMIT
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 21 0.00 0.00 0 0 0 0
Execute 21 0.03 0.07 2 526 1661 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 42 0.03 0.07 2 526 1661 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 11 0.01 0.01
rdbms ipc reply 1 0.00 0.00
log file sync 4 0.00 0.00
PX Deq: Signal ACK 4 0.01 0.01
enq: PS - contention 1 0.00 0.00
********************************************************************************
SELECT WB_RT_MAP_AUDIT_DETAIL_SEQ.NEXTVAL
FROM
DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3
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 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 3 24 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 3 24 3
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (recursive depth: 1)
********************************************************************************
SELECT USER
FROM
SYS.DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 12 0.00 0.00 0 0 0 0
Fetch 12 0.00 0.00 0 0 0 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 24 0.00 0.00 0 0 0 12
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 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 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 t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,
nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,
t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,
t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),
nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),
nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,
ts.logicalread
from
tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
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 0 0 0
Fetch 2 0.00 0.00 0 8 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 8 0 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,
i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,
i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,
null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,
ist.logicalread
from
ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,
min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))
valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where
i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1
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 0 0 0
Fetch 2 0.00 0.00 0 6 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 6 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
nvl(spare3,0)
from
col$ where obj#=:1 order by intcol#
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 0 0 0
Fetch 35 0.00 0.00 0 6 0 33
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 39 0.00 0.00 0 6 0 33
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
select con#,obj#,rcon#,enabled,nvl(defer,0)
from
cdef$ where robj#=:1
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 0 0 0
Fetch 2 0.00 0.00 0 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),
rowid,cols,nvl(defer,0),mtime,nvl(spare1,0)
from
cdef$ where obj#=:1
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 0 0 0
Fetch 2 0.00 0.00 0 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 and col# is not null group by privilege#, col#,
grantee# order by col#, grantee#
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 0 0 0
Fetch 2 0.00 0.05 1 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.05 1 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.05 0.05
********************************************************************************
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by
grantee#
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 0 0 0
Fetch 2 0.00 0.00 0 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 4 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled
from
obj$ o,user$ u,trigger$ t where t.baseobject=:1 and t.obj#=o.obj# and
o.owner#=u.user# order by o.obj#
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 0 0 0
Fetch 2 0.00 0.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 2 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT ORDER BY (cr=1 pr=0 pw=0 time=97 us)
0 NESTED LOOPS (cr=1 pr=0 pw=0 time=63 us)
0 NESTED LOOPS (cr=1 pr=0 pw=0 time=55 us)
0 TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=1 pr=0 pw=0 time=47 us)
0 INDEX RANGE SCAN I_TRIGGER1 (cr=1 pr=0 pw=0 time=25 us)(object id 128)
0 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)
0 INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)(object id 36)
0 TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)
0 INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)(object id 11)
********************************************************************************
select condition
from
cdef$ where rowid=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 10 0.00 0.00 0 21 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 30 0.00 0.00 0 21 0 10
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)
********************************************************************************
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 33 0.00 0.00 0 0 0 0
Fetch 33 0.01 0.04 2 99 0 33
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 68 0.01 0.04 2 99 0 33
Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 2)
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 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 0 2 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 0 2 2
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=0 pw=0 time=1350 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=9 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 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 2 4 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 2 4 2
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=0 pw=0 time=212 us)
1 INDEX UNIQUE SCAN I_SEQ1 (cr=1 pr=0 pw=0 time=20 us)(object id 106)
********************************************************************************
INSERT /*+ APPEND PARALLEL(CUSTOMER_PROMOS, DEFAULT, DEFAULT) */ INTO
"CUSTOMER_PROMOS" ("CUST_FIRST_NAME", "CUST_LAST_NAME", "PROMO_NAME")
(SELECT "CUSTOMERS_OE2"."CUST_FIRST_NAME" "CUST_FIRST_NAME$1",
"CUSTOMERS_OE2"."CUST_LAST_NAME" "CUST_LAST_NAME$1",
"PROMOTIONS_OE2"."PROMO_NAME" "PROMO_NAME$1" FROM "OE"."CUSTOMERS"
"CUSTOMERS_OE2", "OE"."PROMOTIONS" "PROMOTIONS_OE2", (SELECT
"ORDERS_OE2"."ORDER_ID" "ORDER_ID", "ORDERS_OE2"."ORDER_MODE" "ORDER_MODE",
"ORDERS_OE2"."CUSTOMER_ID" "CUSTOMER_ID", "ORDERS_OE2"."ORDER_STATUS"
"ORDER_STATUS", "ORDERS_OE2"."ORDER_TOTAL" "ORDER_TOTAL",
"ORDERS_OE2"."SALES_REP_ID" "SALES_REP_ID", "ORDERS_OE2"."PROMOTION_ID"
"PROMOTION_ID" FROM "OE"."ORDERS" "ORDERS_OE2" ) "INGRP2" WHERE (
"CUSTOMERS_OE2"."CUSTOMER_ID" = "INGRP2"."CUSTOMER_ID" (+) ) AND (
"INGRP2"."PROMOTION_ID" = "PROMOTIONS_OE2"."PROMO_ID" ) )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.03 0.01 0 0 0 0
Execute 1 0.00 0.22 0 20 2 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.03 0.24 0 20 2 0
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 ---------- ------------
process startup 3 0.00 0.00
PX Deq: Join ACK 2 0.00 0.00
PX qref latch 2 0.00 0.01
PX Deq: Parse Reply 1 0.01 0.01
PX Deq: Execute Reply 6 0.06 0.08
PX Deq: Signal ACK 2 0.10 0.10
********************************************************************************
ALTER SESSION DISABLE PARALLEL DML
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 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)
********************************************************************************
delete from wri$_tracing_enabled
where
trace_type = :1 AND primary_id = :2 AND qualifier_id1 IS NULL AND
qualifier_id2 IS NULL AND instance_name IS NULL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 3 15 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 3 15 3
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (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") (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.01 0.35 3 944 43 665
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.35 3 944 43 665
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 3 0.02 0.02
PX Deq: Join ACK 1 0.00 0.00
PX Deq: Parse Reply 3 0.00 0.00
PX qref latch 4 0.00 0.03
PX Deq: Execute Reply 7 0.10 0.23
PX Deq Credit: send blkd 5 0.01 0.01
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.00 0.00 0 10 2 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 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=228 us)
1 TABLE ACCESS CLUSTER SEG$ (cr=5 pr=0 pw=0 time=115 us)
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=30 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 11 2 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 11 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=157 us)
1 TABLE ACCESS CLUSTER SEG$ (cr=5 pr=0 pw=0 time=84 us)
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=20 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=165 us)
1 TABLE ACCESS CLUSTER TSQ$ (cr=3 pr=0 pw=0 time=66 us)
1 INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=18 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 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.01 0.00 0 72 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.01 0.00 0 72 0 3
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
********************************************************************************
SELECT NVL(NUM_ROWS, 0)
FROM
ALL_TABLES WHERE TABLE_NAME = :B2 AND OWNER = :B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.01 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 72 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.01 0.00 0 72 0 3
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 3 0.00 0.00 0 0 0 0
Execute 3 0.01 0.00 0 6 9 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.00 0 6 9 3
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 78 (recursive depth: 1)
********************************************************************************
select /*+ rule */ bucket, endpoint, col#, epvalue
from
histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by bucket
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.02 1 12 0 73
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.02 1 12 0 73
Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 2)
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
********************************************************************************
MERGE /*+ APPEND PARALLEL(CUSTOMER_ORDERS, DEFAULT, DEFAULT) */ INTO
"CUSTOMER_ORDERS" USING (SELECT "ORDERS_OE2"."ORDER_ID" "ORDER_ID$1",
"ORDERS_OE2"."ORDER_MODE" "ORDER_MODE$1", "ORDERS_OE2"."CUSTOMER_ID"
"CUSTOMER_ID$1", "ORDERS_OE2"."ORDER_STATUS" "ORDER_STATUS$1",
"ORDERS_OE2"."ORDER_TOTAL" "ORDER_TOTAL$1", "ORDERS_OE2"."SALES_REP_ID"
"SALES_REP_ID$1", "ORDERS_OE2"."PROMOTION_ID" "PROMOTION_ID$1",
"CUSTOMERS_SH2"."CUST_ID" "CUST_ID$1", "CUSTOMERS_SH2"."CUST_FIRST_NAME"
"CUST_FIRST_NAME$1", "CUSTOMERS_SH2"."CUST_LAST_NAME" "CUST_LAST_NAME$1",
"CUSTOMERS_SH2"."CUST_GENDER" "CUST_GENDER$1",
"CUSTOMERS_SH2"."CUST_YEAR_OF_BIRTH" "CUST_YEAR_OF_BIRTH$1",
"CUSTOMERS_SH2"."CUST_MARITAL_STATUS" "CUST_MARITAL_STATUS$1",
"CUSTOMERS_SH2"."CUST_STREET_ADDRESS" "CUST_STREET_ADDRESS$1",
"CUSTOMERS_SH2"."CUST_POSTAL_CODE" "CUST_POSTAL_CODE$1",
"CUSTOMERS_SH2"."CUST_CITY" "CUST_CITY$1", "CUSTOMERS_SH2"."CUST_CITY_ID"
"CUST_CITY_ID$1", "CUSTOMERS_SH2"."CUST_STATE_PROVINCE"
"CUST_STATE_PROVINCE$1", "CUSTOMERS_SH2"."CUST_STATE_PROVINCE_ID"
"CUST_STATE_PROVINCE_ID$1", "CUSTOMERS_SH2"."COUNTRY_ID" "COUNTRY_ID$1",
"CUSTOMERS_SH2"."CUST_MAIN_PHONE_NUMBER" "CUST_MAIN_PHONE_NUMBER$1",
"CUSTOMERS_SH2"."CUST_INCOME_LEVEL" "CUST_INCOME_LEVEL$1",
"CUSTOMERS_SH2"."CUST_CREDIT_LIMIT" "CUST_CREDIT_LIMIT$1",
"CUSTOMERS_SH2"."CUST_EMAIL" "CUST_EMAIL$1", "CUSTOMERS_SH2"."CUST_TOTAL"
"CUST_TOTAL$1", "CUSTOMERS_SH2"."CUST_TOTAL_ID" "CUST_TOTAL_ID$1",
"CUSTOMERS_SH2"."CUST_SRC_ID" "CUST_SRC_ID$1",
"CUSTOMERS_SH2"."CUST_EFF_FROM" "CUST_EFF_FROM$1",
"CUSTOMERS_SH2"."CUST_EFF_TO" "CUST_EFF_TO$1", "CUSTOMERS_SH2"."CUST_VALID"
"CUST_VALID$1" FROM "OE"."ORDERS" "ORDERS_OE2", "SH"."CUSTOMERS"
"CUSTOMERS_SH2" WHERE ( "ORDERS_OE2"."ORDER_MODE" = 'direct' ) AND (
"ORDERS_OE2"."CUSTOMER_ID" = "CUSTOMERS_SH2"."CUST_ID" ) ) "MERGEQUERY_904"
ON ( "CUSTOMER_ORDERS"."ORDER_ID" = "MERGEQUERY_904"."ORDER_ID$1" ) WHEN
MATCHED THEN UPDATE SET "ORDER_MODE" = "MERGEQUERY_904"."ORDER_MODE$1",
"CUSTOMER_ID" = "MERGEQUERY_904"."CUSTOMER_ID$1", "ORDER_STATUS" =
"MERGEQUERY_904"."ORDER_STATUS$1", "ORDER_TOTAL" =
"MERGEQUERY_904"."ORDER_TOTAL$1", "SALES_REP_ID" =
"MERGEQUERY_904"."SALES_REP_ID$1", "PROMOTION_ID" =
"MERGEQUERY_904"."PROMOTION_ID$1", "CUST_ID" = "MERGEQUERY_904"."CUST_ID$1",
"CUST_FIRST_NAME" = "MERGEQUERY_904"."CUST_FIRST_NAME$1", "CUST_LAST_NAME"
= "MERGEQUERY_904"."CUST_LAST_NAME$1", "CUST_GENDER" =
"MERGEQUERY_904"."CUST_GENDER$1", "CUST_YEAR_OF_BIRTH" =
"MERGEQUERY_904"."CUST_YEAR_OF_BIRTH$1", "CUST_MARITAL_STATUS" =
"MERGEQUERY_904"."CUST_MARITAL_STATUS$1", "CUST_STREET_ADDRESS" =
"MERGEQUERY_904"."CUST_STREET_ADDRESS$1", "CUST_POSTAL_CODE" =
"MERGEQUERY_904"."CUST_POSTAL_CODE$1", "CUST_CITY" =
"MERGEQUERY_904"."CUST_CITY$1", "CUST_CITY_ID" =
"MERGEQUERY_904"."CUST_CITY_ID$1", "CUST_STATE_PROVINCE" =
"MERGEQUERY_904"."CUST_STATE_PROVINCE$1", "CUST_STATE_PROVINCE_ID" =
"MERGEQUERY_904"."CUST_STATE_PROVINCE_ID$1", "COUNTRY_ID" =
"MERGEQUERY_904"."COUNTRY_ID$1", "CUST_MAIN_PHONE_NUMBER" =
"MERGEQUERY_904"."CUST_MAIN_PHONE_NUMBER$1", "CUST_INCOME_LEVEL" =
"MERGEQUERY_904"."CUST_INCOME_LEVEL$1", "CUST_CREDIT_LIMIT" =
"MERGEQUERY_904"."CUST_CREDIT_LIMIT$1", "CUST_EMAIL" =
"MERGEQUERY_904"."CUST_EMAIL$1", "CUST_TOTAL" =
"MERGEQUERY_904"."CUST_TOTAL$1", "CUST_TOTAL_ID" =
"MERGEQUERY_904"."CUST_TOTAL_ID$1", "CUST_SRC_ID" =
"MERGEQUERY_904"."CUST_SRC_ID$1", "CUST_EFF_FROM" =
"MERGEQUERY_904"."CUST_EFF_FROM$1", "CUST_EFF_TO" =
"MERGEQUERY_904"."CUST_EFF_TO$1", "CUST_VALID" =
"MERGEQUERY_904"."CUST_VALID$1" WHEN NOT MATCHED THEN INSERT
("CUSTOMER_ORDERS"."ORDER_ID", "CUSTOMER_ORDERS"."ORDER_MODE",
"CUSTOMER_ORDERS"."CUSTOMER_ID", "CUSTOMER_ORDERS"."ORDER_STATUS",
"CUSTOMER_ORDERS"."ORDER_TOTAL", "CUSTOMER_ORDERS"."SALES_REP_ID",
"CUSTOMER_ORDERS"."PROMOTION_ID", "CUSTOMER_ORDERS"."CUST_ID",
"CUSTOMER_ORDERS"."CUST_FIRST_NAME", "CUSTOMER_ORDERS"."CUST_LAST_NAME",
"CUSTOMER_ORDERS"."CUST_GENDER", "CUSTOMER_ORDERS"."CUST_YEAR_OF_BIRTH",
"CUSTOMER_ORDERS"."CUST_MARITAL_STATUS",
"CUSTOMER_ORDERS"."CUST_STREET_ADDRESS",
"CUSTOMER_ORDERS"."CUST_POSTAL_CODE", "CUSTOMER_ORDERS"."CUST_CITY",
"CUSTOMER_ORDERS"."CUST_CITY_ID", "CUSTOMER_ORDERS"."CUST_STATE_PROVINCE",
"CUSTOMER_ORDERS"."CUST_STATE_PROVINCE_ID", "CUSTOMER_ORDERS"."COUNTRY_ID",
"CUSTOMER_ORDERS"."CUST_MAIN_PHONE_NUMBER",
"CUSTOMER_ORDERS"."CUST_INCOME_LEVEL",
"CUSTOMER_ORDERS"."CUST_CREDIT_LIMIT", "CUSTOMER_ORDERS"."CUST_EMAIL",
"CUSTOMER_ORDERS"."CUST_TOTAL", "CUSTOMER_ORDERS"."CUST_TOTAL_ID",
"CUSTOMER_ORDERS"."CUST_SRC_ID", "CUSTOMER_ORDERS"."CUST_EFF_FROM",
"CUSTOMER_ORDERS"."CUST_EFF_TO", "CUSTOMER_ORDERS"."CUST_VALID") VALUES
("MERGEQUERY_904"."ORDER_ID$1", "MERGEQUERY_904"."ORDER_MODE$1",
"MERGEQUERY_904"."CUSTOMER_ID$1", "MERGEQUERY_904"."ORDER_STATUS$1",
"MERGEQUERY_904"."ORDER_TOTAL$1", "MERGEQUERY_904"."SALES_REP_ID$1",
"MERGEQUERY_904"."PROMOTION_ID$1", "MERGEQUERY_904"."CUST_ID$1",
"MERGEQUERY_904"."CUST_FIRST_NAME$1", "MERGEQUERY_904"."CUST_LAST_NAME$1",
"MERGEQUERY_904"."CUST_GENDER$1", "MERGEQUERY_904"."CUST_YEAR_OF_BIRTH$1",
"MERGEQUERY_904"."CUST_MARITAL_STATUS$1",
"MERGEQUERY_904"."CUST_STREET_ADDRESS$1",
"MERGEQUERY_904"."CUST_POSTAL_CODE$1", "MERGEQUERY_904"."CUST_CITY$1",
"MERGEQUERY_904"."CUST_CITY_ID$1", "MERGEQUERY_904"."CUST_STATE_PROVINCE$1",
"MERGEQUERY_904"."CUST_STATE_PROVINCE_ID$1",
"MERGEQUERY_904"."COUNTRY_ID$1",
"MERGEQUERY_904"."CUST_MAIN_PHONE_NUMBER$1",
"MERGEQUERY_904"."CUST_INCOME_LEVEL$1",
"MERGEQUERY_904"."CUST_CREDIT_LIMIT$1", "MERGEQUERY_904"."CUST_EMAIL$1",
"MERGEQUERY_904"."CUST_TOTAL$1", "MERGEQUERY_904"."CUST_TOTAL_ID$1",
"MERGEQUERY_904"."CUST_SRC_ID$1", "MERGEQUERY_904"."CUST_EFF_FROM$1",
"MERGEQUERY_904"."CUST_EFF_TO$1", "MERGEQUERY_904"."CUST_VALID$1")
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.08 0.11 0 0 0 0
Execute 1 0.01 0.49 5 251 2 73
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.09 0.60 5 251 2 73
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 1 0.03 0.03
PX Deq: Join ACK 2 0.00 0.00
PX qref latch 8 0.01 0.08
PX Deq: Parse Reply 2 0.00 0.00
PX Deq: Execute Reply 3 0.01 0.01
db file scattered read 2 0.06 0.13
PX Deq Credit: send blkd 12 0.06 0.08
PX Deq: Signal ACK 3 0.10 0.10
********************************************************************************
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
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
reliable message 4 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 86 0.12 0.14 0 0 0 0
Execute 132 0.06 1.16 10 1779 1765 754
Fetch 119 0.02 0.13 4 314 2 174
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 337 0.20 1.43 14 2093 1767 928
Misses in library cache during parse: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 8 0.05 0.16
process startup 3 0.00 0.00
PX Deq: Join ACK 5 0.00 0.00
PX qref latch 14 0.01 0.13
PX Deq: Parse Reply 6 0.01 0.03
PX Deq: Execute Reply 27 0.10 0.35
PX Deq: Signal ACK 9 0.10 0.22
log file sync 4 0.00 0.00
PX Deq Credit: send blkd 17 0.06 0.09
rdbms ipc reply 2 0.00 0.00
enq: PS - contention 1 0.00 0.00
db file scattered read 2 0.06 0.13
48 user SQL statements in session.
41 internal SQL statements in session.
89 SQL statements in session.
********************************************************************************
Trace file: C:\oracle\admin\markr10g\udump\MYTRACE01.trc
Trace file compatibility: 10.01.00
Sort options: default
0 session in tracefile.
48 user SQL statements in trace file.
41 internal SQL statements in trace file.
89 SQL statements in trace file.
29 unique SQL statements in trace file.
885 lines in trace file.
3 elapsed seconds in trace file.
Some couple of final points to note:
However, what we've got here is a way of tracing across an entire process flow, and creating a single trace file that contains all the DML for a particular process. One thing those people who are alert might have spotted is that we do still miss out some SQL even using this process - the SQL issued by the workflow process, which is itself a PL/SQL application - but for the time being this should be enough, as I don't think Workflow adds too much to the process (famous last words).
As ever, any feedback and so on please send through to me, or add to the article comments.