The processes going on as mentioned in post “Saving XML data directly to disk” got me thinking so I started testing. Why did the processes take 100% CPU time…? To be honest I still don’t know for sure (I suspect the assembling of the XML instance), because I am unsure if I didn’t mix up apples with oranges after all. I suspect there is maybe still an NLS conversion thing going on. I found the whole exercise interesting, also because it gave me a little bit more insight in the internals.
Follow me on my tracing adventure.
DBMS_XSLPROCESSOR
In post “Saving XML data directly to disk” I used two methods to load the data. Both were using 100% CPU. As I actually saw during tests, the writing of the XML document is only a small fraction at the end of the process. Every time the most part of the process is used for or assembling all data or creating the XML document. As said only at the end, a small portion is used creating the file and filling it with the data.
Conclusion so far is that the XML data is filled more efficiently, with less extra whitespace, via DBMS_XSLPROCESSOR and less efficiently with DBMS_XMLDOM. I am unsure if there is a NLS conversion factor playing part in this, despite the implicit conversions.
Running the following multiple times (optimizing caching and get rid this out of the overall timing) the data is as follows
alter session set sql_trace=true ;
declare
rc sys_refcursor;
doc DBMS_XMLDOM.DOMDocument;
begin
open rc for select * from ( select rownum from dual connect by level < 500000 );
doc := DBMS_XMLDOM.NewDOMDocument(xmltype( rc ));
DBMS_XMLDOM.WRITETOFILE(doc, 'UTLDATA/marco.xml');
end;
/
The created raw trace file was filled for 99% with lines like the following (SIZE 35 MB).
*** 2008-02-15 14:52:53.312
=====================
PARSING IN CURSOR #4 len=252 dep=0 uid=122 oct=47 lid=122 tim=3817748532751 hv=1292321496 ad='23530104' sqlid='bfa042j6hfhqs'
declare
rc sys_refcursor;
doc DBMS_XMLDOM.DOMDocument;
begin
open rc for select * from ( select rownum from dual connect by level < 500000 );
doc := DBMS_XMLDOM.NewDOMDocument(xmltype( rc ));
DBMS_XMLDOM.WRITETOFILE(doc, 'UTLDATA/marco.xml');
end;
END OF STMT
PARSE #4:c=0,e=1090,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3817748532728
=====================
PARSING IN CURSOR #3 len=67 dep=1 uid=122 oct=3 lid=122 tim=3817748533546 hv=2221561984 ad='283a4258' sqlid='bzf089u26nq40'
SELECT * FROM ( SELECT ROWNUM FROM DUAL CONNECT BY LEVEL < 500000 )
END OF STMT
PARSE #3:c=0,e=148,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3817748533537
EXEC #3:c=0,e=104,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3817748533784
FETCH #3:c=0,e=162,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748539498
FETCH #3:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748539708
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748539782
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748539852
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748539920
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748539988
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540057
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540226
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540297
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540366
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540434
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540502
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540570
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540638
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540706
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540775
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540843
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540911
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748540979
FETCH #3:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748541149
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748541259
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748541329
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748541397
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748541465
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817748541533
...
etc
...
Using TKPROF to analyze it in a more readable form.
TKPROF: Release 11.1.0.6.0 - Production on Fri Feb 15 14:55:20 2008
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: workshop_ora_4088.trc
Sort options: prsela exeela fchela
********************************************************************************
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
********************************************************************************
declare
rc sys_refcursor;
doc DBMS_XMLDOM.DOMDocument;
begin
open rc for select * from ( select rownum from dual connect by level < 500000 );
doc := DBMS_XMLDOM.NewDOMDocument(xmltype( rc ));
DBMS_XMLDOM.WRITETOFILE(doc, 'UTLDATA/marco.xml');
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 65.71 73.88 0 247362 1266677 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 65.71 73.88 0 247362 1266677 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
SQL ID : bzf089u26nq40
SELECT *
FROM
( SELECT ROWNUM FROM DUAL CONNECT BY LEVEL < 500000 )
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 500000 7.93 7.54 0 0 0 499999
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 500002 7.93 7.54 0 0 0 499999
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
499999 VIEW (cr=0 pr=0 pw=0 time=99413 us cost=2 size=13 card=1)
499999 COUNT (cr=0 pr=0 pw=0 time=63393 us)
499999 CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 time=28895 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
499999 VIEW
499999 COUNT
499999 CONNECT BY (WITHOUT FILTERING)
1 FAST DUAL
********************************************************************************
SQL ID : cb21bacyh3c7d
select metadata
from
kopm$ where name='DB_FDO'
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 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
...
etc
...
It delivered a file with the following size and CPU% Used. The long red line in the picture mark, every time the processing part (creating the content), the small red line at the end the creating of the file and filling it with data part.
Click the picture to enlarge
DBMS_XMLDOM
Almost in the same way, the DBMS_XMLDOM procedure, behaved only now it takes more time processing and the overall file size of the XML document is bigger.
Running the following multiple times (optimizing caching and to get rid off this in the overall timing) the data is as follows
alter session set sql_trace=true ;
declare
rc sys_refcursor;
begin
open rc FOR SELECT * FROM ( SELECT rownum FROM dual connect BY level < 500000 );
dbms_xslprocessor.clob2file( xmltype( rc ).getclobval( ) , 'UTLDATA','anton.xml');
end;
/
The created raw trace file was filled for 99% with lines like the following (SIZE 35 MB!).
=====================
PARSING IN CURSOR #4 len=204 dep=0 uid=122 oct=47 lid=122 tim=3817426906351 hv=550158645 ad='2f6de2e4' sqlid='crw8j84hcph9p'
declare
rc sys_refcursor;
begin
open rc FOR SELECT * FROM ( SELECT rownum FROM dual connect BY level < 500000 );
dbms_xslprocessor.clob2file( xmltype( rc ).getclobval( ) , 'UTLDATA','anton.xml');
end;
END OF STMT
PARSE #4:c=15625,e=22421,p=0,cr=41,cu=0,mis=1,r=0,dep=0,og=1,tim=3817426906340
=====================
PARSING IN CURSOR #8 len=67 dep=1 uid=122 oct=3 lid=122 tim=3817426907142 hv=2221561984 ad='283a4258' sqlid='bzf089u26nq40'
SELECT * FROM ( SELECT ROWNUM FROM DUAL CONNECT BY LEVEL < 500000 )
END OF STMT
PARSE #8:c=0,e=262,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3817426907085
EXEC #8:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3817426907448
FETCH #8:c=0,e=152,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426913450
FETCH #8:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426913625
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426913697
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426913766
FETCH #8:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426913834
FETCH #8:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426913902
FETCH #8:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914157
FETCH #8:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914257
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914327
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914395
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914483
FETCH #8:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914552
FETCH #8:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914632
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914702
FETCH #8:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=3817426914771
...
etc
...
Using TKPROF to analyze it in a more readable form.
C:\>tkprof workshop_ora_2628.trc workshop_ora_2628.trc.tkprof.txt explain=test/a
vanti sys=yes record=workshop_ora_2628.trc.recordfile.txt waits=yes sort=prsel
a,exeela,fchela
TKPROF: Release 11.1.0.6.0 - Production on Fri Feb 15 14:49:36 2008
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: workshop_ora_2628.trc
Sort options: prsela exeela fchela
********************************************************************************
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
********************************************************************************
declare
rc sys_refcursor;
begin
open rc FOR SELECT * FROM ( SELECT rownum FROM dual connect BY level < 500000 );
dbms_xslprocessor.clob2file( xmltype( rc ).getclobval( ) , 'UTLDATA','anton.xml');
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.02 0 39 0 0
Execute 1 48.56 53.06 0 273186 1392400 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 48.57 53.08 0 273225 1392400 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
SQL ID : bzf089u26nq40
SELECT *
FROM
( SELECT ROWNUM FROM DUAL CONNECT BY LEVEL < 500000 )
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 500000 7.14 7.47 0 0 0 499999
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 500002 7.14 7.47 0 0 0 499999
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
499999 VIEW (cr=0 pr=0 pw=0 time=96149 us cost=2 size=13 card=1)
499999 COUNT (cr=0 pr=0 pw=0 time=61913 us)
499999 CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 time=27306 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
499999 VIEW
499999 COUNT
499999 CONNECT BY (WITHOUT FILTERING)
1 FAST DUAL
********************************************************************************
SQL ID : cb21bacyh3c7d
select metadata
from
kopm$ where name='DB_FDO'
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 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
...
etc
...
Again file size and CPU behavior.
Click the picture to enlarge
The content of the XML files, seen via notepad, will be like the following.
Click on the picture to enlarge
Overhead?
I wanted to get rid of the overhead in the equation, regarding the generation of filling the xml data via creating a table (CLOB based storage) so it would hopefully be, “as is”: Whitespaces and all.
So I did the following;
SQL> CREATE TABLE test
2 (xmldata xmltype);
Table created.
SQL> select dbms_metadata.get_ddl('TABLE','TEST') from dual;
DBMS_METADATA.GET_DDL('TABLE','TEST')
--------------------------------------------------------------------------------
CREATE TABLE "TEST"."TEST"
( "XMLDATA" "XMLTYPE"
) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 NOCOMPRESS LOGGING
STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "USERS"
XMLTYPE COLUMN "XMLDATA" STORE AS BASICFILE CLOB (
TABLESPACE "USERS" ENABLE STORAGE IN ROW CHUNK 8192 PCTVERSION 10
NOCACHE LOGGING
STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT))
1 row selected.
SQL> @bytes
Enter value for username: TEST
Enter value for objectname: TEST
Enter value for objecttype: TABLE
..
OBJECT_NAME = TEST
---------------------------
TOTAL_BLOCKS = 8
TOTAL_BYTES = 65536
UNUSED_BLOCKS = 5
UNUSED_BYTES = 40960
PL/SQL procedure successfully completed.
SQL> get bytes
1 SET SERVEROUTPUT ON
2 PROMPT
3 PROMPT
4 UNDEFINE USERNAME
5 UNDEFINE OBJECTNAME
6 UNDEFINE OBJECTYPE
7 declare
8 v_total_blocks number;
9 v_total_bytes number;
10 v_unused_blocks number;
11 v_unused_bytes number;
12 v_last_ext_fileid number;
13 v_last_ext_blocid number;
14 v_last_used_block number;
15 begin
16 dbms_output.put_line('..');
17 dbms_space.unused_space (upper('&USERNAME')
18 ,upper('&&OBJECTNAME')
19 ,upper('&OBJECTTYPE')
20 ,v_total_blocks
21 ,v_total_bytes
22 ,v_unused_blocks
23 ,v_unused_bytes
24 ,v_last_ext_fileid
25 ,v_last_ext_blocid
26 ,v_last_used_block
27 );
28 dbms_output.put_line('OBJECT_NAME = &&OBJECTNAME');
29 dbms_output.put_line('---------------------------');
30 dbms_output.put_line('TOTAL_BLOCKS = '||v_total_blocks);
31 dbms_output.put_line('TOTAL_BYTES = '||v_total_bytes);
32 dbms_output.put_line('UNUSED_BLOCKS = '||v_unused_blocks);
33 dbms_output.put_line('UNUSED_BYTES = '||v_unused_bytes);
34 end;
35 /
36* UNDEFINE OBJECTNAME
37 .
SQL> select * from user_lobs where table_name='TEST';
TABLE_NAME
------------------------------
COLUMN_NAME
------------------------------------------------------------------------------------------------------------------------------------
Segment TABLESPACE_NAME INDEX_NAME CHUNK PCTVERSION RETENTION
------------------------------ ------------------------------ ------------------------------ --------- ---------- ---------
FREEPOOLS CACHE LOGGING ENCR COMPRE DEDUPLICATION IN_ FORMAT PAR SEC
--------- ---------- ------- ---- ------ --------------- --- --------------- --- ---
TEST
SYS_NC00002$
SYS_LOB0000074819C00002$$ USERS SYS_IL0000074819C00002$$ 8192 10
NO YES NONE NONE NONE YES ENDIAN NEUTRAL NO NO
1 row selected.
SQL> @bytes
Enter value for username: TEST
Enter value for objectname: SYS_LOB0000074819C00002$$
Enter value for objecttype: LOB
..
OBJECT_NAME = SYS_LOB0000074819C00002$$
---------------------------
TOTAL_BLOCKS = 8
TOTAL_BYTES = 65536
UNUSED_BLOCKS = 5
UNUSED_BYTES = 40960
PL/SQL procedure successfully completed.
SQL> set timing on
SQL> -- INFO about bfilename
SQL> -- http://download.oracle.com/docs/cd/B28359_01/server.111/b28286/functions012.htm#SQLRF00610
SQL> -- http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28393/adlob_bfile_ops.htm#i1006319
SQL> INSERT INTO test
2 (xmldata)
3 VALUES
4 (XMLTYPE(bfilename('UTLDATA','anton.xml'),NLS_CHARSET_ID('AL32UTF8')));
1 row created.
Elapsed: 00:00:43.68
SQL> set timing off
SQL> commit;
Commit complete.
SQL> @bytes
Enter value for username: TEST
Enter value for objectname: TEST
Enter value for objecttype: TABLE
..
OBJECT_NAME = TEST
---------------------------
TOTAL_BLOCKS = 8
TOTAL_BYTES = 65536
UNUSED_BLOCKS = 0
UNUSED_BYTES = 0
PL/SQL procedure successfully completed.
SQL> @segment
Segments:
Enter value for segment_name: SYS_LOB0000074819C00002$$
Enter value for segment_type:
Enter value for owner: TEST
Enter value for extents:
Enter value for tablespace_name:
Segment Type Bytes Tot.Ext IniSize NextSize %Inc MinE MaxE Owner TABLESPACE_NAME
------------------------------ --------------- ------------ -------- ------------ ------------ ----- ----- ------- --------------- ---------------------
SYS_LOB0000074819C00002$$ LOBSEGMENT 46137344 59 65536 1 ####### TEST USERS
------------
sum 46137344
SQL> @bytes
Enter value for username: TEST
Enter value for objectname: SYS_LOB0000074819C00002$$
Enter value for objecttype: LOB
..
OBJECT_NAME = SYS_LOB0000074819C00002$$
---------------------------
TOTAL_BLOCKS = 5632
TOTAL_BYTES = 46137344
UNUSED_BLOCKS = 0
UNUSED_BYTES = 0
PL/SQL procedure successfully completed.
SQL> select * from test
XMLDATA
---------------------------------
< ?xml version="1.0"?>
1
2
3
4
5
6
7
8
9
...
...
etc
...
49999
Overhead DBMS_XSLPROCESSOR?
Done this, I re-run my exercise via doing the same, BUT this time, selecting directly from table test with the anton.xml data in, it but naming the output differently, in this case: anton_tab_select.xml
alter session set sql_trace=true ;
declare
rc sys_refcursor;
begin
open rc FOR SELECT * FROM test;
dbms_xslprocessor.clob2file( xmltype( rc ).getclobval( ) , 'UTLDATA','anton_tab_select.xml');
end;
/
The created raw trace file shows the following lines (total size raw trace file: 4 KB!).
Trace file f:\oracle\diag\rdbms\workshop\workshop\trace\workshop_ora_2184.trc
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows Server 2003 Version V5.2
CPU : 1 - type 586, 1 Physical Cores
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:282M/1023M, Ph+PgF:2043M/2885M, VA:1202M/2047M
Instance name: workshop
Redo thread mounted by this instance: 1
Oracle process number: 42
Windows thread id: 2184, image: ORACLE.EXE (SHAD)
*** 2008-02-15 15:54:40.265
*** SESSION ID:(170.1847) 2008-02-15 15:54:40.265
*** CLIENT ID:() 2008-02-15 15:54:40.265
*** SERVICE NAME:(workshop.amis.nl) 2008-02-15 15:54:40.265
*** MODULE NAME:(SQL*Plus - OraDBA) 2008-02-15 15:54:40.265
*** ACTION NAME:() 2008-02-15 15:54:40.265
=====================
PARSING IN CURSOR #5 len=32 dep=0 uid=122 oct=42 lid=122 tim=3821455478316 hv=0 ad='cb3fc04' sqlid='0000000000000'
alter session set sql_trace=true
END OF STMT
EXEC #5:c=0,e=70,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=3821455478308
*** 2008-02-15 15:55:00.250
=====================
PARSING IN CURSOR #4 len=165 dep=0 uid=122 oct=47 lid=122 tim=3821475464618 hv=2459772364 ad='259fe7b0' sqlid='a40j8hy99u9fc'
declare
rc sys_refcursor;
begin
open rc FOR SELECT * FROM test;
dbms_xslprocessor.clob2file( xmltype( rc ).getclobval( ) , 'UTLDATA','anton_tab_select.xml');
end;
END OF STMT
PARSE #4:c=0,e=781,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3821475464569
=====================
PARSING IN CURSOR #3 len=18 dep=1 uid=122 oct=3 lid=122 tim=3821475465610 hv=3451517534 ad='2a1849a0' sqlid='fbsbmzm6vmyky'
SELECT * FROM TEST
END OF STMT
PARSE #3:c=0,e=129,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3821475465603
EXEC #3:c=0,e=84,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3821475465836
=====================
PARSING IN CURSOR #5 len=47 dep=1 uid=0 oct=3 lid=0 tim=3821475471125 hv=1023521005 ad='2f5cdde0' sqlid='cb21bacyh3c7d'
select metadata from kopm$ where name='DB_FDO'
END OF STMT
PARSE #5:c=0,e=178,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3821475471115
EXEC #5:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3821475471403
FETCH #5:c=0,e=95,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3821475471556
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=539 op='TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=0 us cost=1 size=108 card=1)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=540 op='INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'
FETCH #3:c=0,e=530,p=0,cr=5,cu=0,mis=0,r=1,dep=1,og=1,tim=3821475473995
*** 2008-02-15 15:55:49.312
FETCH #3:c=0,e=150,p=0,cr=1,cu=0,mis=0,r=1,dep=1,og=1,tim=3821524527627
FETCH #3:c=0,e=30,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,tim=3821524527986
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=74819 op='TABLE ACCESS FULL TEST (cr=8 pr=0 pw=0 time=0 us cost=3 size=4030 card=2)'
*** 2008-02-15 15:56:04.765
EXEC #4:c=40687500,e=64513603,p=53049,cr=592479,cu=1916385,mis=0,r=1,dep=0,og=1,tim=3821539978794
*** 2008-02-15 16:01:54.921
=====================
PARSING IN CURSOR #3 len=34 dep=0 uid=122 oct=42 lid=122 tim=3821890136750 hv=0 ad='cb3fc04' sqlid='0000000000000'
alter session set sql_trace=false
END OF STMT
PARSE #3:c=46875,e=46095,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=3821890136714
EXEC #3:c=0,e=1845,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3821890151814
Using TKPROF to analyze it in a more readable form.
TKPROF: Release 11.1.0.6.0 - Production on Fri Feb 15 15:58:04 2008
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: workshop_ora_2184.trc
Sort options: prsela exeela fchela
********************************************************************************
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
********************************************************************************
declare
rc sys_refcursor;
begin
open rc FOR SELECT * FROM test;
dbms_xslprocessor.clob2file( xmltype( rc ).getclobval( ) , 'UTLDATA','anton_tab_select.xml');
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 40.68 64.51 53049 592469 1916385 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 40.68 64.51 53049 592469 1916385 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
SQL ID : fbsbmzm6vmyky
SELECT *
FROM
TEST
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 3 0.00 0.00 0 8 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 8 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
2 TABLE ACCESS FULL TEST (cr=8 pr=0 pw=0 time=0 us cost=3 size=4030 card=2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
2 TABLE ACCESS (FULL) OF 'TEST' (TABLE)
********************************************************************************
SQL ID : cb21bacyh3c7d
select metadata
from
kopm$ where name='DB_FDO'
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 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=0 us cost=1 size=108 card=1)
1 INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)(object id 540)
********************************************************************************
SQL ID : 0000000000000
alter session set sql_trace=true
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
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 40.68 64.51 53049 592469 1916385 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 40.68 64.51 53049 592469 1916385 1
Misses in library cache during parse: 0
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
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 4 0.00 0.00 0 10 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 10 0 3
Misses in library cache during parse: 0
3 user SQL statements in session.
1 internal SQL statements in session.
4 SQL statements in session.
1 statement EXPLAINed in this session.
********************************************************************************
Trace file: workshop_ora_2184.trc
Trace file compatibility: 11.01.00
Sort options: prsela exeela fchela
1 session in tracefile.
3 user SQL statements in trace file.
1 internal SQL statements in trace file.
4 SQL statements in trace file.
4 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
TEST.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
61 lines in trace file.
84 elapsed seconds in trace file.
Click the picture to enlarge
To my surprise the file size was equal to “marco.xml” !
Overhead DBMS_XMLDOM?
Now I again did the same procedure but this time with DBMS_XMLDOM. The result would is a file called: marco_tab_select.xml
alter session set sql_trace=true ;
declare
rc sys_refcursor;
doc DBMS_XMLDOM.DOMDocument;
begin
open rc for SELECT * FROM test;
doc := DBMS_XMLDOM.NewDOMDocument(xmltype( rc ));
DBMS_XMLDOM.WRITETOFILE(doc, 'UTLDATA/marco_tab_select.xml');
end;
/
alter session set sql_trace=false ;
The created raw trace file shows the following (total size raw file: 45 KB!).
Trace file f:\oracle\diag\rdbms\workshop\workshop\trace\workshop_ora_2628.trc
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows Server 2003 Version V5.2
CPU : 1 - type 586, 1 Physical Cores
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:287M/1023M, Ph+PgF:2046M/2885M, VA:1203M/2047M
Instance name: workshop
Redo thread mounted by this instance: 1
Oracle process number: 42
Windows thread id: 2628, image: ORACLE.EXE (SHAD)
*** 2008-02-15 16:05:39.656
*** SESSION ID:(120.11685) 2008-02-15 16:05:39.656
*** CLIENT ID:() 2008-02-15 16:05:39.656
*** SERVICE NAME:(workshop.amis.nl) 2008-02-15 16:05:39.656
*** MODULE NAME:(SQL*Plus - OraDBA) 2008-02-15 16:05:39.656
*** ACTION NAME:() 2008-02-15 16:05:39.656
=====================
PARSING IN CURSOR #3 len=32 dep=0 uid=122 oct=42 lid=122 tim=3822114878750 hv=0 ad='cabfc04' sqlid='0000000000000'
alter session set sql_trace=true
END OF STMT
EXEC #3:c=0,e=70,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=3822114878742
*** 2008-02-15 16:08:07.828
=====================
PARSING IN CURSOR #3 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822263042937 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
PARSE #3:c=0,e=102,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263042926
EXEC #3:c=0,e=133,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263043531
FETCH #3:c=0,e=89,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263043699
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=0 us cost=4 size=82 card=1)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=37 op='INDEX RANGE SCAN I_OBJ2 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822263044360 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #3:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263044353
FETCH #3:c=0,e=235,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263044750
=====================
PARSING IN CURSOR #3 len=46 dep=1 uid=0 oct=3 lid=0 tim=3822263045097 hv=1343089354 ad='2f4cfce8' sqlid='1mjd9xp80vuqa'
select node,owner,name from syn$ where obj#=:1
END OF STMT
PARSE #3:c=0,e=220,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263045090
EXEC #3:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263045321
FETCH #3:c=0,e=15684,p=2,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263061057
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=68 op='TABLE ACCESS BY INDEX ROWID SYN$ (cr=3 pr=2 pw=2 time=0 us cost=2 size=35 card=1)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=77 op='INDEX UNIQUE SCAN I_SYN1 (cr=2 pr=1 pw=1 time=0 us cost=1 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=185 dep=1 uid=0 oct=3 lid=0 tim=3822263061650 hv=1850944673 ad='2f5e7798' sqlid='3ktacv9r56b51'
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#, nvl(property,0),subname,type#,d_attrs from dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#
END OF STMT
PARSE #3:c=0,e=130,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263061642
EXEC #3:c=0,e=184,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263062038
*** 2008-02-15 16:08:07.875
FETCH #3:c=0,e=34653,p=4,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263096753
FETCH #3:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263097060
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=7 pr=4 pw=4 time=0 us cost=11 size=327 card=3)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=7 pr=4 pw=4 time=0 us cost=10 size=327 card=3)'
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=103 op='TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=4 pr=3 pw=3 time=0 us cost=4 size=81 card=3)'
STAT #3 id=4 cnt=1 pid=3 pos=1 obj=105 op='INDEX RANGE SCAN I_DEPENDENCY1 (cr=3 pr=2 pw=2 time=0 us cost=3 size=0 card=3)'
STAT #3 id=5 cnt=1 pid=2 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=1 pw=1 time=0 us cost=2 size=82 card=1)'
STAT #3 id=6 cnt=1 pid=5 pos=1 obj=36 op='INDEX RANGE SCAN I_OBJ1 (cr=2 pr=1 pw=1 time=0 us cost=1 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=56 dep=1 uid=0 oct=3 lid=0 tim=3822263097537 hv=3993603298 ad='2f5e6cec' sqlid='8swypbbr0m372'
select order#,columns,types from access$ where d_obj#=:1
END OF STMT
PARSE #3:c=0,e=72,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263097529
EXEC #3:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263097778
FETCH #3:c=0,e=6547,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263104377
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=104 op='TABLE ACCESS BY INDEX ROWID ACCESS$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=161 card=7)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=107 op='INDEX RANGE SCAN I_ACCESS1 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=7)'
=====================
PARSING IN CURSOR #3 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822263104823 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #3:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263104815
FETCH #3:c=0,e=153,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263105131
=====================
PARSING IN CURSOR #3 len=51 dep=1 uid=0 oct=3 lid=0 tim=3822263105563 hv=1523794037 ad='2f5862cc' sqlid='b1wc53ddd6h3p'
select audit$,options from procedure$ where obj#=:1
END OF STMT
PARSE #3:c=0,e=307,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263105555
EXEC #3:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263105758
FETCH #3:c=0,e=10765,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263116568
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=212 op='TABLE ACCESS BY INDEX ROWID PROCEDURE$ (cr=3 pr=1 pw=1 time=0 us cost=2 size=46 card=1)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=222 op='INDEX UNIQUE SCAN I_PROCEDURE1 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=185 dep=1 uid=0 oct=3 lid=0 tim=3822263117118 hv=1850944673 ad='2f5e7798' sqlid='3ktacv9r56b51'
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#, nvl(property,0),subname,type#,d_attrs from dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#
END OF STMT
PARSE #3:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263117109
EXEC #3:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263117416
FETCH #3:c=0,e=636,p=0,cr=15,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263118106
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263118206
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263118286
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263118356
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263118425
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263118495
FETCH #3:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263118568
STAT #3 id=1 cnt=6 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=15 pr=0 pw=0 time=0 us cost=11 size=327 card=3)'
STAT #3 id=2 cnt=6 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=15 pr=0 pw=0 time=93 us cost=10 size=327 card=3)'
STAT #3 id=3 cnt=6 pid=2 pos=1 obj=103 op='TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=4 pr=0 pw=0 time=13 us cost=4 size=81 card=3)'
STAT #3 id=4 cnt=6 pid=3 pos=1 obj=105 op='INDEX RANGE SCAN I_DEPENDENCY1 (cr=3 pr=0 pw=0 time=4 us cost=3 size=0 card=3)'
STAT #3 id=5 cnt=6 pid=2 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=11 pr=0 pw=0 time=0 us cost=2 size=82 card=1)'
STAT #3 id=6 cnt=6 pid=5 pos=1 obj=36 op='INDEX RANGE SCAN I_OBJ1 (cr=8 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=56 dep=1 uid=0 oct=3 lid=0 tim=3822263119085 hv=3993603298 ad='2f5e6cec' sqlid='8swypbbr0m372'
select order#,columns,types from access$ where d_obj#=:1
END OF STMT
PARSE #3:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263119077
EXEC #3:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263119314
FETCH #3:c=0,e=9241,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263128607
FETCH #3:c=0,e=106,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263128871
FETCH #3:c=0,e=17,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263128947
FETCH #3:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263129015
FETCH #3:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263129082
FETCH #3:c=0,e=11,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263129145
STAT #3 id=1 cnt=5 pid=0 pos=1 obj=104 op='TABLE ACCESS BY INDEX ROWID ACCESS$ (cr=12 pr=1 pw=1 time=0 us cost=3 size=161 card=7)'
STAT #3 id=2 cnt=5 pid=1 pos=1 obj=107 op='INDEX RANGE SCAN I_ACCESS1 (cr=7 pr=0 pw=0 time=88 us cost=2 size=0 card=7)'
=====================
PARSING IN CURSOR #3 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822263129834 hv=2328831744 ad='2f584d48' sqlid='ga9j9xk5cy9s0'
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=389,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263129825
EXEC #3:c=0,e=90,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263130124
FETCH #3:c=0,e=6940,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263137119
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=219 op='TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=19 card=1)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=230 op='INDEX RANGE SCAN I_IDL_SB41 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822263137761 hv=4260389146 ad='2f584468' sqlid='cvn54b7yz0s8u'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=282,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263137753
EXEC #3:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263138049
FETCH #3:c=0,e=5847,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263143953
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=216 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=18 card=1)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=227 op='INDEX RANGE SCAN I_IDL_UB11 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=135 dep=1 uid=0 oct=3 lid=0 tim=3822263144501 hv=1115215392 ad='2f583b88' sqlid='c6awqs517jpj0'
select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=224,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263144492
EXEC #3:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263144785
FETCH #3:c=0,e=7428,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263152269
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=217 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=20 card=1)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=228 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822263152840 hv=1684122946 ad='2f5832a8' sqlid='39m4sx9k63ba2'
select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=254,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263152832
EXEC #3:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263155159
FETCH #3:c=0,e=10496,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263165733
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=218 op='TABLE ACCESS BY INDEX ROWID IDL_UB2$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=40 card=2)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=229 op='INDEX RANGE SCAN I_IDL_UB21 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=2)'
=====================
PARSING IN CURSOR #3 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822263166108 hv=2328831744 ad='2f584d48' sqlid='ga9j9xk5cy9s0'
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263166100
EXEC #3:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263166373
FETCH #3:c=0,e=6856,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263173283
FETCH #3:c=0,e=35,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263173691
FETCH #3:c=0,e=13,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263173765
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=219 op='TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=6 pr=1 pw=1 time=0 us cost=3 size=19 card=1)'
STAT #3 id=2 cnt=2 pid=1 pos=1 obj=230 op='INDEX RANGE SCAN I_IDL_SB41 (cr=4 pr=0 pw=0 time=12 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822263173979 hv=4260389146 ad='2f584468' sqlid='cvn54b7yz0s8u'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263173972
EXEC #3:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263174222
FETCH #3:c=0,e=4745,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263179018
FETCH #3:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263179244
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=216 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=4 pr=1 pw=1 time=0 us cost=3 size=18 card=1)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=227 op='INDEX RANGE SCAN I_IDL_UB11 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=135 dep=1 uid=0 oct=3 lid=0 tim=3822263179487 hv=1115215392 ad='2f583b88' sqlid='c6awqs517jpj0'
select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263179479
EXEC #3:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263179727
FETCH #3:c=0,e=8598,p=2,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263188376
FETCH #3:c=0,e=153,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263189174
FETCH #3:c=0,e=15,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263189312
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=217 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=6 pr=1 pw=1 time=0 us cost=3 size=20 card=1)'
STAT #3 id=2 cnt=2 pid=1 pos=1 obj=228 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=4 pr=0 pw=0 time=113 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822263189529 hv=1684122946 ad='2f5832a8' sqlid='39m4sx9k63ba2'
select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #3:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263189521
EXEC #3:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263189770
FETCH #3:c=0,e=10204,p=2,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263200027
FETCH #3:c=0,e=57283,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263258719
FETCH #3:c=0,e=936,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263259845
FETCH #3:c=0,e=744,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263260675
FETCH #3:c=0,e=654,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263261407
FETCH #3:c=0,e=20266,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263281746
FETCH #3:c=0,e=45,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263282043
STAT #3 id=1 cnt=7 pid=0 pos=1 obj=218 op='TABLE ACCESS BY INDEX ROWID IDL_UB2$ (cr=15 pr=6 pw=6 time=0 us cost=3 size=40 card=2)'
STAT #3 id=2 cnt=7 pid=1 pos=1 obj=229 op='INDEX RANGE SCAN I_IDL_UB21 (cr=8 pr=0 pw=0 time=258 us cost=2 size=0 card=2)'
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263283388 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
PARSE #3:c=0,e=274,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263283380
EXEC #3:c=0,e=147,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263283740
FETCH #3:c=0,e=4513,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263288381
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=2 pr=1 pw=1 time=0 us cost=4 size=15 card=1)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=61 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=15 card=1)'
STAT #3 id=3 cnt=0 pid=2 pos=1 obj=63 op='INDEX RANGE SCAN I_OBJAUTH2 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263288837 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=90,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263288829
FETCH #3:c=0,e=48,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263289037
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263289235 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263289228
FETCH #3:c=0,e=97,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263289482
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263289692 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263289681
FETCH #3:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263289896
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263290042 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263290034
FETCH #3:c=0,e=11866,p=1,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263302055
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263302399 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263302388
FETCH #3:c=0,e=47,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263302612
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263302765 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263302758
FETCH #3:c=0,e=40,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263302953
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263303098 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263303090
FETCH #3:c=0,e=37,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263303282
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263303548 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263303538
FETCH #3:c=0,e=42,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263303810
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263304070 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263304062
FETCH #3:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263304268
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263304443 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263304436
FETCH #3:c=0,e=37,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263304629
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263304826 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263304818
FETCH #3:c=0,e=38,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263305012
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263305160 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263305152
FETCH #3:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263305428
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263305575 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263305567
FETCH #3:c=0,e=37,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263305758
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263305898 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263305891
FETCH #3:c=0,e=37,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263306082
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263306265 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263306255
FETCH #3:c=0,e=38,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263306452
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263306594 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263306587
FETCH #3:c=0,e=979,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263307719
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263307931 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263307923
FETCH #3:c=0,e=9569,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263317651
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263317941 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263317931
FETCH #3:c=0,e=49,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263318179
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263318329 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263318321
FETCH #3:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263318515
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263318656 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263318648
FETCH #3:c=0,e=37,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263318839
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263319083 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263319072
FETCH #3:c=15625,e=10005,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263329251
=====================
PARSING IN CURSOR #3 len=131 dep=1 uid=0 oct=3 lid=0 tim=3822263329541 hv=1389591971 ad='2f58bca8' sqlid='3g7sxtj9d6zd3'
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
END OF STMT
EXEC #3:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263329533
FETCH #3:c=0,e=12255,p=2,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263341975
FETCH #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263342173
=====================
PARSING IN CURSOR #6 len=47 dep=1 uid=0 oct=3 lid=0 tim=3822263343220 hv=1023521005 ad='2f5cdde0' sqlid='cb21bacyh3c7d'
select metadata from kopm$ where name='DB_FDO'
END OF STMT
PARSE #6:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263343211
EXEC #6:c=0,e=72,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822263343540
FETCH #6:c=0,e=51,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822263343644
STAT #6 id=1 cnt=1 pid=0 pos=1 obj=539 op='TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=0 us cost=1 size=108 card=1)'
STAT #6 id=2 cnt=1 pid=1 pos=1 obj=540 op='INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'
=====================
PARSING IN CURSOR #4 len=214 dep=0 uid=122 oct=47 lid=122 tim=3822263351520 hv=1892811092 ad='258d5d5c' sqlid='76pf0gtsd40an'
declare
rc sys_refcursor;
doc DBMS_XMLDOM.DOMDocument;
begin
open rc for SELECT * FROM test;
doc := DBMS_XMLDOM.NewDOMDocument(xmltype( rc ));
DBMS_XMLDOM.WRITETOFILE(doc, 'UTLDATA/marco_tab_select.xml');
end;
END OF STMT
PARSE #4:c=46875,e=311307,p=36,cr=211,cu=0,mis=1,r=0,dep=0,og=1,tim=3822263351510
=====================
PARSING IN CURSOR #8 len=18 dep=1 uid=122 oct=3 lid=122 tim=3822263352254 hv=3451517534 ad='2a1849a0' sqlid='fbsbmzm6vmyky'
SELECT * FROM TEST
END OF STMT
PARSE #8:c=0,e=253,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3822263352245
EXEC #8:c=0,e=91,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=3822263352485
FETCH #8:c=0,e=668,p=0,cr=5,cu=0,mis=0,r=1,dep=1,og=1,tim=3822263359675
*** 2008-02-15 16:09:02.859
FETCH #8:c=0,e=649,p=0,cr=1,cu=0,mis=0,r=1,dep=1,og=1,tim=3822318074413
FETCH #8:c=0,e=108,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,tim=3822318074974
STAT #8 id=1 cnt=2 pid=0 pos=1 obj=74819 op='TABLE ACCESS FULL TEST (cr=8 pr=0 pw=0 time=0 us cost=3 size=4030 card=2)'
*** 2008-02-15 16:09:06.687
=====================
PARSING IN CURSOR #10 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822321910666 hv=2328831744 ad='2f584d48' sqlid='ga9j9xk5cy9s0'
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=411,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321910655
EXEC #10:c=0,e=181,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321911332
FETCH #10:c=0,e=11019,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321922472
FETCH #10:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321922894
STAT #10 id=1 cnt=1 pid=0 pos=1 obj=219 op='TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=4 pr=1 pw=1 time=0 us cost=3 size=19 card=1)'
STAT #10 id=2 cnt=1 pid=1 pos=1 obj=230 op='INDEX RANGE SCAN I_IDL_SB41 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #10 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822321923385 hv=4260389146 ad='2f584468' sqlid='cvn54b7yz0s8u'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=190,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321923377
EXEC #10:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321923683
FETCH #10:c=0,e=13585,p=2,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321937327
FETCH #10:c=0,e=493,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321938018
FETCH #10:c=0,e=12923,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321951032
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822321951809 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
PARSE #11:c=0,e=125,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321951800
EXEC #11:c=0,e=141,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321952239
FETCH #11:c=0,e=144,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321952530
STAT #11 id=1 cnt=1 pid=0 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=4 pr=0 pw=0 time=0 us cost=4 size=82 card=1)'
STAT #11 id=2 cnt=1 pid=1 pos=1 obj=37 op='INDEX RANGE SCAN I_OBJ2 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)'
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822321961601 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321961591
FETCH #11:c=0,e=59,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321961891
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822321962517 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=72,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321962507
FETCH #11:c=0,e=65,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321962785
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822321963243 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321963235
FETCH #11:c=0,e=52,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321963456
STAT #10 id=1 cnt=3 pid=0 pos=1 obj=216 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=7 pr=3 pw=3 time=0 us cost=3 size=18 card=1)'
STAT #10 id=2 cnt=3 pid=1 pos=1 obj=227 op='INDEX RANGE SCAN I_IDL_UB11 (cr=4 pr=0 pw=0 time=12 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #10 len=135 dep=1 uid=0 oct=3 lid=0 tim=3822321964067 hv=1115215392 ad='2f583b88' sqlid='c6awqs517jpj0'
select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=229,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321964056
EXEC #10:c=0,e=78,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321964390
FETCH #10:c=0,e=140,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321964588
STAT #10 id=1 cnt=0 pid=0 pos=1 obj=217 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=2 pr=0 pw=0 time=0 us cost=3 size=20 card=1)'
STAT #10 id=2 cnt=0 pid=1 pos=1 obj=228 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=2 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #10 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822321964892 hv=1684122946 ad='2f5832a8' sqlid='39m4sx9k63ba2'
select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321964885
EXEC #10:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321965227
FETCH #10:c=0,e=138,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321965424
STAT #10 id=1 cnt=0 pid=0 pos=1 obj=218 op='TABLE ACCESS BY INDEX ROWID IDL_UB2$ (cr=2 pr=0 pw=0 time=0 us cost=3 size=40 card=2)'
STAT #10 id=2 cnt=0 pid=1 pos=1 obj=229 op='INDEX RANGE SCAN I_IDL_UB21 (cr=2 pr=0 pw=0 time=0 us cost=2 size=0 card=2)'
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822321966295 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321966287
FETCH #11:c=0,e=136,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321966594
=====================
PARSING IN CURSOR #10 len=51 dep=1 uid=0 oct=3 lid=0 tim=3822321966886 hv=1523794037 ad='2f5862cc' sqlid='b1wc53ddd6h3p'
select audit$,options from procedure$ where obj#=:1
END OF STMT
PARSE #10:c=0,e=159,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321966878
EXEC #10:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321967101
FETCH #10:c=0,e=5952,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321973098
STAT #10 id=1 cnt=1 pid=0 pos=1 obj=212 op='TABLE ACCESS BY INDEX ROWID PROCEDURE$ (cr=3 pr=1 pw=1 time=0 us cost=2 size=46 card=1)'
STAT #10 id=2 cnt=1 pid=1 pos=1 obj=222 op='INDEX UNIQUE SCAN I_PROCEDURE1 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
=====================
PARSING IN CURSOR #11 len=185 dep=1 uid=0 oct=3 lid=0 tim=3822321973438 hv=1850944673 ad='2f5e7798' sqlid='3ktacv9r56b51'
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#, nvl(property,0),subname,type#,d_attrs from dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#
END OF STMT
PARSE #11:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321973431
EXEC #11:c=0,e=216,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321973911
FETCH #11:c=0,e=1377,p=0,cr=30,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321975353
FETCH #11:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321975514
FETCH #11:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321983478
FETCH #11:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321983868
FETCH #11:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984027
FETCH #11:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984157
FETCH #11:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984337
FETCH #11:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984468
FETCH #11:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984693
FETCH #11:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984770
FETCH #11:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321984934
FETCH #11:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321985031
FETCH #11:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321985130
FETCH #11:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321985229
FETCH #11:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321985327
FETCH #11:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321985483
STAT #11 id=1 cnt=15 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=30 pr=0 pw=0 time=0 us cost=11 size=327 card=3)'
STAT #11 id=2 cnt=15 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=30 pr=0 pw=0 time=152 us cost=10 size=327 card=3)'
STAT #11 id=3 cnt=15 pid=2 pos=1 obj=103 op='TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=4 pr=0 pw=0 time=11 us cost=4 size=81 card=3)'
STAT #11 id=4 cnt=15 pid=3 pos=1 obj=105 op='INDEX RANGE SCAN I_DEPENDENCY1 (cr=3 pr=0 pw=0 time=4 us cost=3 size=0 card=3)'
STAT #11 id=5 cnt=15 pid=2 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=26 pr=0 pw=0 time=0 us cost=2 size=82 card=1)'
STAT #11 id=6 cnt=15 pid=5 pos=1 obj=36 op='INDEX RANGE SCAN I_OBJ1 (cr=14 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
=====================
PARSING IN CURSOR #11 len=56 dep=1 uid=0 oct=3 lid=0 tim=3822321985958 hv=3993603298 ad='2f5e6cec' sqlid='8swypbbr0m372'
select order#,columns,types from access$ where d_obj#=:1
END OF STMT
PARSE #11:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321985951
EXEC #11:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321986212
FETCH #11:c=0,e=211,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986479
FETCH #11:c=0,e=25,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986591
FETCH #11:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986663
FETCH #11:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986732
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986800
FETCH #11:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986869
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321986937
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321987005
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321987073
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321987141
FETCH #11:c=0,e=19,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321987215
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321987284
FETCH #11:c=0,e=13,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321987353
FETCH #11:c=0,e=7065,p=1,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321994521
STAT #11 id=1 cnt=13 pid=0 pos=1 obj=104 op='TABLE ACCESS BY INDEX ROWID ACCESS$ (cr=28 pr=1 pw=1 time=0 us cost=3 size=161 card=7)'
STAT #11 id=2 cnt=13 pid=1 pos=1 obj=107 op='INDEX RANGE SCAN I_ACCESS1 (cr=15 pr=1 pw=1 time=10 us cost=2 size=0 card=7)'
=====================
PARSING IN CURSOR #10 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822321994873 hv=2328831744 ad='2f584d48' sqlid='ga9j9xk5cy9s0'
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321994865
EXEC #10:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321995141
FETCH #10:c=0,e=464,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822321995661
FETCH #10:c=0,e=22,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321995842
STAT #10 id=1 cnt=1 pid=0 pos=1 obj=219 op='TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=4 pr=1 pw=1 time=0 us cost=3 size=19 card=1)'
STAT #10 id=2 cnt=1 pid=1 pos=1 obj=230 op='INDEX RANGE SCAN I_IDL_SB41 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #10 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822321996048 hv=4260389146 ad='2f584468' sqlid='cvn54b7yz0s8u'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321996041
EXEC #10:c=0,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822321996396
FETCH #10:c=0,e=17457,p=3,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322013935
*** 2008-02-15 16:09:06.812
FETCH #10:c=0,e=18182,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322032251
FETCH #10:c=0,e=7754,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322040249
FETCH #10:c=0,e=493,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322040949
FETCH #10:c=0,e=502,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322041550
FETCH #10:c=0,e=487,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322042147
FETCH #10:c=0,e=11845,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322054152
FETCH #10:c=0,e=810,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322055157
FETCH #10:c=0,e=571,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322055869
FETCH #10:c=0,e=616,p=2,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322063079
FETCH #10:c=0,e=23,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322063223
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822322064019 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322064011
FETCH #11:c=0,e=111,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322064301
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822322064744 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322064736
FETCH #11:c=0,e=48,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322064954
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822322065252 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322065244
FETCH #11:c=0,e=44,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322065452
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822322065909 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322065901
FETCH #11:c=0,e=47,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=3822322066119
STAT #10 id=1 cnt=11 pid=0 pos=1 obj=216 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=23 pr=11 pw=11 time=0 us cost=3 size=18 card=1)'
STAT #10 id=2 cnt=11 pid=1 pos=1 obj=227 op='INDEX RANGE SCAN I_IDL_UB11 (cr=12 pr=1 pw=1 time=59 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #10 len=135 dep=1 uid=0 oct=3 lid=0 tim=3822322066449 hv=1115215392 ad='2f583b88' sqlid='c6awqs517jpj0'
select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322066441
EXEC #10:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322066770
FETCH #10:c=0,e=73,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322066898
STAT #10 id=1 cnt=0 pid=0 pos=1 obj=217 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=2 pr=0 pw=0 time=0 us cost=3 size=20 card=1)'
STAT #10 id=2 cnt=0 pid=1 pos=1 obj=228 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=2 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #10 len=132 dep=1 uid=0 oct=3 lid=0 tim=3822322067086 hv=1684122946 ad='2f5832a8' sqlid='39m4sx9k63ba2'
select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece from idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #10:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322067079
EXEC #10:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322067349
FETCH #10:c=0,e=31,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=3822322067435
STAT #10 id=1 cnt=0 pid=0 pos=1 obj=218 op='TABLE ACCESS BY INDEX ROWID IDL_UB2$ (cr=2 pr=0 pw=0 time=0 us cost=3 size=40 card=2)'
STAT #10 id=2 cnt=0 pid=1 pos=1 obj=229 op='INDEX RANGE SCAN I_IDL_UB21 (cr=2 pr=0 pw=0 time=0 us cost=2 size=0 card=2)'
*** 2008-02-15 16:09:17.796
=====================
PARSING IN CURSOR #11 len=198 dep=1 uid=0 oct=3 lid=0 tim=3822333009434 hv=4125641360 ad='2f5eb4b0' sqlid='04xtrk7uyhknh'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #11:c=0,e=141,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3822333009422
FETCH #11:c=0,e=115,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=3822333009920
*** 2008-02-15 16:09:29.125
EXEC #4:c=46343750,e=80985039,p=62899,cr=588150,cu=1969579,mis=0,r=1,dep=0,og=1,tim=3822344336894
*** 2008-02-15 16:27:29.046
=====================
PARSING IN CURSOR #10 len=33 dep=0 uid=122 oct=42 lid=122 tim=3823424272365 hv=0 ad='cabfc04' sqlid='0000000000000'
alter session set sql_trace=false
END OF STMT
PARSE #10:c=0,e=3081,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=3823424272331
EXEC #10:c=0,e=604,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3823424273769
*** 2008-02-15 16:41:14.218
KGX cleanup...
KGX Atomic Operation Log 28284E30
Mutex 2A19A37C(120, 0) idn 48425783 oper EXAM
Cursor Parent uid 120 efd 5 whr 26 slp 0
oper=OPERATION_DEFAULT pt1=00000000 pt2=00000000 pt3=00000000
pt4=00000000 u41=0 stt=0
Using TKPROF to analyze it in a more readable form (again displayed here in full).
TKPROF: Release 11.1.0.6.0 - Production on Fri Feb 15 16:37:58 2008
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: workshop_ora_2628.trc
Sort options: prsela exeela fchela
********************************************************************************
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
********************************************************************************
declare
rc sys_refcursor;
doc DBMS_XMLDOM.DOMDocument;
begin
open rc for SELECT * FROM test;
doc := DBMS_XMLDOM.NewDOMDocument(xmltype( rc ));
DBMS_XMLDOM.WRITETOFILE(doc, 'UTLDATA/marco_tab_select.xml');
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.03 0.03 0 48 0 0
Execute 1 46.34 80.86 62870 587969 1969579 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 46.37 80.90 62870 588017 1969579 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
SQL ID : 39m4sx9k63ba2
select /*+ index(idl_ub2$ i_idl_ub21) +*/ piece#,length,piece
from
idl_ub2$ where obj#=:1 and part=:2 and version=:3 order by piece#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 10 0.00 0.10 13 34 0 7
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 18 0.00 0.10 13 34 0 7
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID IDL_UB2$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=40 card=2)
0 INDEX RANGE SCAN I_IDL_UB21 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=2)(object id 229)
********************************************************************************
SQL ID : cvn54b7yz0s8u
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece
from
idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 17 0.00 0.09 27 62 0 15
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 25 0.00 0.09 27 62 0 15
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=18 card=1)
0 INDEX RANGE SCAN I_IDL_UB11 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)(object id 227)
********************************************************************************
SQL ID : 3g7sxtj9d6zd3
select privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 and grantee#=:2 group by privilege#,nvl(col#,0)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 23 0.00 0.00 0 0 0 0
Fetch 24 0.01 0.04 7 50 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 48 0.01 0.05 7 50 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY (cr=2 pr=1 pw=1 time=0 us cost=4 size=15 card=1)
0 TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=15 card=1)
0 INDEX RANGE SCAN I_OBJAUTH2 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)(object id 63)
********************************************************************************
SQL ID : 3ktacv9r56b51
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#,
nvl(property,0),subname,type#,d_attrs
from
dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#
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 25 0.00 0.03 4 52 0 22
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 31 0.00 0.03 4 52 0 22
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT ORDER BY (cr=7 pr=4 pw=4 time=0 us cost=11 size=327 card=3)
1 NESTED LOOPS OUTER (cr=7 pr=4 pw=4 time=0 us cost=10 size=327 card=3)
1 TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=4 pr=3 pw=3 time=0 us cost=4 size=81 card=3)
1 INDEX RANGE SCAN I_DEPENDENCY1 (cr=3 pr=2 pw=2 time=0 us cost=3 size=0 card=3)(object id 105)
1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=1 pw=1 time=0 us cost=2 size=82 card=1)
1 INDEX RANGE SCAN I_OBJ1 (cr=2 pr=1 pw=1 time=0 us cost=1 size=0 card=1)(object id 36)
********************************************************************************
SQL ID : ga9j9xk5cy9s0
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece
from
idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 8 0.00 0.02 4 20 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 16 0.00 0.02 4 20 0 4
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=19 card=1)
0 INDEX RANGE SCAN I_IDL_SB41 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)(object id 230)
********************************************************************************
SQL ID : 8swypbbr0m372
select order#,columns,types
from
access$ where d_obj#=: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 21 0.00 0.02 3 42 0 18
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 27 0.00 0.02 3 42 0 18
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID ACCESS$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=161 card=7)
0 INDEX RANGE SCAN I_ACCESS1 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=7)(object id 107)
********************************************************************************
SQL ID : b1wc53ddd6h3p
select audit$,options
from
procedure$ 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.01 2 6 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.01 2 6 0 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID PROCEDURE$ (cr=3 pr=1 pw=1 time=0 us cost=2 size=46 card=1)
1 INDEX UNIQUE SCAN I_PROCEDURE1 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 222)
********************************************************************************
SQL ID : c6awqs517jpj0
select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece
from
idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.01 3 15 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.00 0.01 3 15 0 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=2 pr=1 pw=1 time=0 us cost=3 size=20 card=1)
0 INDEX RANGE SCAN I_IDL_CHAR1 (cr=2 pr=1 pw=1 time=0 us cost=2 size=0 card=1)(object id 228)
********************************************************************************
SQL ID : 1mjd9xp80vuqa
select node,owner,name
from
syn$ where obj#=: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.01 2 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.01 2 3 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID SYN$ (cr=3 pr=2 pw=2 time=0 us cost=2 size=35 card=1)
1 INDEX UNIQUE SCAN I_SYN1 (cr=2 pr=1 pw=1 time=0 us cost=1 size=0 card=1)(object id 77)
********************************************************************************
SQL ID : 0000000000000
alter session set sql_trace=false
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: 1
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
SQL ID : 04xtrk7uyhknh
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
spare2
from
obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
and linkname is null and subname is null
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 13 0.00 0.00 0 0 0 0
Fetch 13 0.00 0.00 0 50 0 11
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 28 0.00 0.00 0 50 0 11
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=0 us cost=4 size=82 card=1)
0 INDEX RANGE SCAN I_OBJ2 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)(object id 37)
********************************************************************************
SQL ID : fbsbmzm6vmyky
SELECT *
FROM
TEST
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 3 0.00 0.00 0 8 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 8 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST) (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
2 TABLE ACCESS FULL TEST (cr=8 pr=0 pw=0 time=0 us cost=3 size=4030 card=2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
2 TABLE ACCESS (FULL) OF 'TEST' (TABLE)
********************************************************************************
SQL ID : cb21bacyh3c7d
select metadata
from
kopm$ where name='DB_FDO'
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 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=0 us cost=1 size=108 card=1)
1 INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)(object id 540)
********************************************************************************
SQL ID : 0000000000000
alter session set sql_trace=true
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
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 122 (TEST)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.03 0.03 0 48 0 0
Execute 3 46.34 80.86 62870 587969 1969579 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 46.37 80.90 62870 588017 1969579 1
Misses in library cache during parse: 2
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 30 0.00 0.00 0 0 0 0
Execute 63 0.00 0.00 0 0 0 0
Fetch 131 0.01 0.38 65 344 0 86
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 224 0.01 0.39 65 344 0 86
Misses in library cache during parse: 0
4 user SQL statements in session.
62 internal SQL statements in session.
66 SQL statements in session.
1 statement EXPLAINed in this session.
********************************************************************************
Trace file: workshop_ora_2628.trc
Trace file compatibility: 11.01.00
Sort options: prsela exeela fchela
1 session in tracefile.
4 user SQL statements in trace file.
62 internal SQL statements in trace file.
66 SQL statements in trace file.
15 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
TEST.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
608 lines in trace file.
1309 elapsed seconds in trace file.
File sizes and CPU behavior.
Click the picture to enlarge
To my surprise, this time the file size was even BIGGER than “marco.xml” or “anton_tab_select.xml”! (30 MB against 21 MB).
Raw content / Finishing up
If you look at the raw content of the files via notepad that the following can be seen.
Click the picture to enlarge
The differences in spaces and new lines can be seen here:
Click the picture to enlarge
So in short the following combinations in different whitespace placing can be seen: anton.xml (2:1:1), marco.xml (4:2:2), anton_tab_select.xml (4:2:2), marco_tab_select.xml (10:8:8).
In all you can conclude that DBMS_XSLPROCESSOR is the winner in this contest regarding CPU% “overhead and space efficiency. I still have to figure out all the details in the raw trace file of the last example using DBMS_XMLDOM but clear is that this example (the case presented, despite if it is the smartest way to do it), is doing a lot of extra work converting and serializing XML data to file.
While I think about it, my believe is that both methods shown, should not use pretty print. This is space inefficient, causes parsing overhead and in the end could be done, for instance, via a browser as well, the moment it presents the XML document to the viewer.
I hope you found it worthwhile reading this.
😎
M.
Related posts
Also see the comments here:
http://www.liberidu.com/blog/?p=365#comment-4126