Search My Oracle Blog

Custom Search

28 October, 2015

Trace Files -- 5.2 : Interpreting the SQL Trace Summary level

Picking up the same SQL Trace file from my previous post, I run (the well known) utility tkprof on it.

[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
.
.
.


No comments:

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com

Top 50 Oracle SQL Blogs 2016

Top 50 Oracle SQL Blogs 2016
Top 50 Oracle SQL Blogs 2016