TKPROF: Release 11.2.0.2.0 - Development on Thu Sep 15 17:33:03 2011 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. Trace file: trace_arq_20110915-001.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 ******************************************************************************** begin if :enable = 0 then sys.dbms_output.disable; else sys.dbms_output.enable(:size); end if; end; 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 4 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 8 0.00 0.00 0 0 0 4 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 4 0.00 0.00 SQL*Net message from client 4 0.04 0.14 ******************************************************************************** SQL ID: 9m7787camwh4m Plan Hash: 0 begin :id := sys.dbms_transaction.local_transaction_id; end; call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 8 0.00 0.00 0 0 0 0 Execute 8 0.00 0.00 0 0 0 8 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 16 0.00 0.00 0 0 0 8 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 8 0.00 0.00 SQL*Net message from client 8 0.20 0.31 ******************************************************************************** SQL ID: 3nz260v5dwqnv Plan Hash: 581635839 select value from v$sesstat where sid = :sid order by statistic# call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 10 0.00 0.00 0 0 0 0 Execute 8 0.00 0.00 0 0 0 0 Fetch 8 0.01 0.01 0 0 0 5024 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 26 0.01 0.01 0 0 0 5024 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Number of plan statistics captured: 3 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 628 628 628 SORT ORDER BY (cr=0 pr=0 pw=0 time=2474 us cost=1 size=78 card=1) 628 628 628 FIXED TABLE FIXED INDEX X$KSUSESTA (ind:1) (cr=0 pr=0 pw=0 time=1045 us cost=0 size=78 card=1) 1 1 1 FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=7 us cost=0 size=13 card=1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 18 0.00 0.00 SQL*Net message from client 17 138.54 214.38 SQL*Net more data to client 8 0.00 0.00 ******************************************************************************** SQL ID: 1tgxugwvzmc3z Plan Hash: 592143611 select * from dba_tables call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.18 0.21 0 17 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.12 0.22 1 4889 0 100 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.31 0.44 1 4906 0 100 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 16 0.00 0.00 library cache lock 2 0.00 0.00 library cache pin 2 0.00 0.00 SQL*Net message to client 2 0.00 0.00 SQL*Net more data to client 3 0.00 0.00 SQL*Net message from client 2 0.02 0.02 asynch descriptor resize 6 0.00 0.00 db file sequential read 1 0.01 0.01 ******************************************************************************** SQL ID: dcjdyjwqttusf Plan Hash: 0 SELECT * FROM dba_tables call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.16 0.17 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 1 0.16 0.17 0 0 0 0 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 1 0.00 0.00 SQL*Net more data to client 1 0.00 0.00 SQL*Net message from client 1 0.17 0.17 ******************************************************************************** begin sys.dbms_output.get_line(line => :line, status => :status); end; 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 4 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 8 0.00 0.00 0 0 0 4 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 4 0.00 0.00 SQL*Net message from client 1 6.75 6.75 ******************************************************************************** SQL ID: dccm4dw93qy3b Plan Hash: 0 begin sys.dbms_application_info.set_module('PL/SQL Developer', :action); end; call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 2 0.00 0.00 0 0 0 2 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.00 0.00 0 0 0 2 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.00 ******************************************************************************** SQL ID: 37qymp91gf0v9 Plan Hash: 644658511 select sid, serial# from v$session where audsid = userenv('SESSIONID') 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 0 2 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6 0.00 0.00 0 0 0 2 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Number of plan statistics captured: 2 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 NESTED LOOPS (cr=0 pr=0 pw=0 time=1088 us cost=0 size=117 card=1) 1 1 1 NESTED LOOPS (cr=0 pr=0 pw=0 time=1068 us cost=0 size=104 card=1) 1 1 1 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=1008 us cost=0 size=78 card=1) 1 1 1 FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=54 us cost=0 size=26 card=1) 1 1 1 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=4 us cost=0 size=13 card=1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 4 0.00 0.00 SQL*Net message from client 4 0.00 0.00 ******************************************************************************** SQL ID: bc6ppu122b6x4 Plan Hash: 3762034736 select * from tab call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.01 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.00 0.00 0 24 0 11 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.00 0.01 0 24 0 11 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 11 11 11 FILTER (cr=24 pr=0 pw=0 time=1217 us) 11 11 11 NESTED LOOPS OUTER (cr=24 pr=0 pw=0 time=1146 us cost=380 size=373182 card=3362) 11 11 11 HASH JOIN (cr=4 pr=0 pw=0 time=919 us cost=115 size=349648 card=3362) 55 55 55 INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=96 us cost=1 size=1210 card=55)(object id 47) 11 11 11 INDEX RANGE SCAN I_OBJ5 (cr=3 pr=0 pw=0 time=61 us cost=113 size=275684 card=3362)(object id 40) 9 9 9 TABLE ACCESS CLUSTER TAB$ (cr=20 pr=0 pw=0 time=102 us cost=1 size=7 card=1) 11 11 11 INDEX UNIQUE SCAN I_OBJ# (cr=9 pr=0 pw=0 time=42 us cost=0 size=0 card=1)(object id 3) 0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=3 size=30 card=1) 0 0 0 INDEX SKIP SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)(object id 47) 0 0 0 INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=2 size=10 card=1)(object id 39) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ library cache lock 2 0.00 0.00 row cache lock 2 0.00 0.00 library cache pin 2 0.00 0.00 KJC: Wait for msg sends to complete 1 0.00 0.00 SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.01 ******************************************************************************** SQL ID: 6p1rzmhd7unrb Plan Hash: 0 SELECT * FROM tab call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 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 1 0.00 0.00 0 0 0 0 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 1 0.00 0.00 SQL*Net message from client 1 0.02 0.02 ******************************************************************************** SQL ID: c8sd629zc2fsz Plan Hash: 737349396 select * from pessoa 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.04 14 6 0 100 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.00 0.05 14 6 0 100 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 100 100 100 TABLE ACCESS FULL PESSOA (cr=6 pr=14 pw=0 time=45055 us cost=272 size=6791453 card=29657) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 3 0.00 0.00 SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.01 0.01 Disk file operations I/O 2 0.00 0.00 db file sequential read 1 0.01 0.01 enq: KO - fast object checkpoint 3 0.00 0.00 KJC: Wait for msg sends to complete 2 0.00 0.00 reliable message 1 0.00 0.00 direct path read 1 0.00 0.00 SQL*Net more data to client 11 0.00 0.00 ******************************************************************************** SQL ID: 70n5ng6nbw7m0 Plan Hash: 0 SELECT * FROM pessoa call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 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 2 0.00 0.00 0 0 0 0 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.10 0.11 ******************************************************************************** SQL ID: cf06fwacdmgfk Plan Hash: 1388734953 select 'x' from dual call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.00 0.03 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 2 0.00 0.00 0 0 0 2 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6 0.00 0.03 0 0 0 2 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Number of plan statistics captured: 2 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 4 0.00 0.00 SQL*Net message from client 5 334.72 334.72 ******************************************************************************** SQL ID: 6xnzqj1uggzsr Plan Hash: 1597989680 select count(1) from pessoa 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.04 0.98 1000 1004 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.04 0.98 1000 1004 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 52 Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SORT AGGREGATE (cr=1004 pr=1000 pw=0 time=982650 us) 29657 29657 29657 TABLE ACCESS FULL PESSOA (cr=1004 pr=1000 pw=0 time=91142 us cost=272 size=0 card=29657) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.01 db file scattered read 23 0.11 0.88 gc cr multi block request 15 0.00 0.01 ******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 38 0.38 0.45 0 17 0 0 Execute 34 0.00 0.00 0 0 0 18 Fetch 16 0.18 1.26 1015 5923 0 5240 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 88 0.56 1.73 1015 5940 0 5258 Misses in library cache during parse: 10 Misses in library cache during execute: 1 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message from client 54 334.90 891.61 SQL*Net message to client 56 0.00 0.00 row cache lock 21 0.00 0.01 library cache lock 4 0.00 0.00 library cache pin 4 0.00 0.00 KJC: Wait for msg sends to complete 3 0.00 0.00 SQL*Net more data to client 23 0.00 0.00 db file sequential read 2 0.01 0.02 asynch descriptor resize 6 0.00 0.00 Disk file operations I/O 2 0.00 0.00 enq: KO - fast object checkpoint 3 0.00 0.00 reliable message 1 0.00 0.00 direct path read 1 0.00 0.00 db file scattered read 23 0.11 0.88 gc cr multi block request 15 0.00 0.01 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 62 0.01 0.10 0 0 0 0 Execute 108 0.03 0.04 0 0 0 0 Fetch 281 0.01 0.22 13 364 0 367 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 451 0.06 0.37 13 364 0 367 Misses in library cache during parse: 26 Misses in library cache during execute: 26 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 10 0.00 0.00 library cache pin 1 0.00 0.00 KJC: Wait for msg sends to complete 1 0.00 0.00 gc cr grant 2-way 9 0.00 0.00 db file sequential read 13 0.01 0.11 26 user SQL statements in session. 56 internal SQL statements in session. 82 SQL statements in session. ******************************************************************************** Trace file: trace_arq_20110915-001.trc Trace file compatibility: 11.1.0.7 Sort options: default 0 session in tracefile. 26 user SQL statements in trace file. 56 internal SQL statements in trace file. 82 SQL statements in trace file. 40 unique SQL statements in trace file. 468280 lines in trace file. 214 elapsed seconds in trace file.