Picking up the same SQL Trace file from my previous post, I run (the well known) utility tkprof on it.
With the "sys=no" command-line flag, I have excluded reporting the recursive (SQL) calls although the summary statistics on them do appear. There were a total of 43 executions of recursive calls. The SQL*Net message from client is a wait of 13.27seconds (which is normally considered as an "idle wait"). We see this also in the previous post on the raw trace as the wait event before Tracing is disabled.
The only significant wait event was "db file sequential read" which is less than 1centisecond so is reported as 0.00second. However, from the previous post, we can see that the raw trace file shows a wait time of 6,784 microseconds
.
.
.
[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc My_Query.PRF sys=no
TKPROF: Release 11.2.0.4.0 - Development on Wed Oct 28 22:53:46 2015
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
[oracle@ora11204 Desktop]$
[oracle@ora11204 Desktop]$ cat My_Query.PRF
TKPROF: Release 11.2.0.4.0 - Development on Wed Oct 28 22:53:46 2015
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.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
********************************************************************************
SQL ID: dc03x7r071fvn Plan Hash: 0
BEGIN DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.03 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.03 0 0 0 1
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43
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 11.45 11.45
********************************************************************************
SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945
select count(*)
from
employees
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 2 0.00 0.01 1 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.03 1 1 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=1 pw=0 time=14407 us)
107 107 107 INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=14577 us cost=1 size=0 card=107)(object id 16404)
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
Disk file operations I/O 1 0.00 0.00
db file sequential read 1 0.00 0.00
SQL*Net message from client 2 13.27 13.27
********************************************************************************
SQL ID: 9wuhwhad81d36 Plan Hash: 0
BEGIN DBMS_SESSION.SESSION_TRACE_DISABLE; END;
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 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.02 0 0 0 0
Execute 3 0.00 0.03 0 0 0 2
Fetch 2 0.00 0.01 1 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.01 0.06 1 1 0 3
Misses in library cache during parse: 2
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 to client 3 0.00 0.00
SQL*Net message from client 3 13.27 24.73
db file sequential read 1 0.00 0.00
Disk file operations I/O 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 43 0.00 0.00 0 0 0 0
Fetch 90 0.00 0.01 3 165 0 68
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 133 0.00 0.01 3 165 0 68
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 3 0.01 0.01
3 user SQL statements in session.
12 internal SQL statements in session.
15 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
12 internal SQL statements in trace file.
15 SQL statements in trace file.
15 unique SQL statements in trace file.
284 lines in trace file.
24 elapsed seconds in trace file.
[oracle@ora11204 Desktop]$
With the "sys=no" command-line flag, I have excluded reporting the recursive (SQL) calls although the summary statistics on them do appear. There were a total of 43 executions of recursive calls. The SQL*Net message from client is a wait of 13.27seconds (which is normally considered as an "idle wait"). We see this also in the previous post on the raw trace as the wait event before Tracing is disabled.
The only significant wait event was "db file sequential read" which is less than 1centisecond so is reported as 0.00second. However, from the previous post, we can see that the raw trace file shows a wait time of 6,784 microseconds
.
.
.