Oracle - difference between consistent results in Autotrace and sequential read in SQL TRACE
Question
What is the difference between Autotrace sequential reads and SQL Trace sequential reads?
Background
Run SQL on the Oracle HR demo schema and run Autotrace and SQL Trace (below). I expected the block read count to be the same, however Autotrace Consistent Gets is 21 and SQL Trace Consistent Read is 15. I wonder what makes the difference.
There were no updates for the tables, and the traces say there was no cache miss, so I think the blocks that SQL needed were in the cache.
Table data blocks from USER_INDEXES are 5 for EMPLOYEES and DEPARTMENTS. Lines are 107 and 27, respectively.
SELECT /*+USE_HASH(e d) */ e.employee_id, e.first_name||' '||e.last_name as full_name, d.department_name
FROM
employees e, departments d
WHERE
e.department_id=d.department_id;
Environment
Oracle 11G R2 for Windows x64 HR Demo Diagram.
Autorouting
Execution Plan
-------------------------------------------------- --------
Plan hash value: 2052257371
-------------------------------------------------- --------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (% CPU) | Time |
-------------------------------------------------- --------------------------------
| 0 | SELECT STATEMENT | | 106 | 4028 | 7 (15) | 00:00:01 |
| * 1 | HASH JOIN | | 106 | 4028 | 7 (15) | 00:00:01 |
| 2 | TABLE ACCESS FULL | DEPARTMENTS | 27 | 432 | 3 (0) | 00:00:01 |
| 3 | TABLE ACCESS FULL | EMPLOYEES | 107 | 2354 | 3 (0) | 00:00:01 |
-------------------------------------------------- --------------------------------
Predicate Information (identified by operation id):
-------------------------------------------------- -
1 - access ("E". "DEPARTMENT_ID" = "D". "DEPARTMENT_ID")
Statistics
-------------------------------------------------- --------
1 recursive calls
0 db block gets
21 consistent gets
0 physical reads
0 redo size
4502 bytes sent via SQL * Net to client
601 bytes received via SQL * Net from client
9 SQL * Net roundtrips to / from client
0 sorts (memory)
0 sorts (disk)
106 rows processed
1 SELECT / * + USE_HASH (ed) * / e.employee_id, e.first_name || ' '|| e.last_name as full_name, d.department_name
2 FROM
3 employees e, departments d
4 WHERE
5 e.department_id = d.department_id
6 - AND d.department_name = 'IT'
7 *
SQL TRACE
SELECT / * + USE_HASH (ed) * / e.employee_id, e.first_name || ' '|| e.last_name as full_name, d.department_name
FROM
employees e, departments d
WHERE
e.department_id = d.department_id
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 2 0.00 0.00 0 15 0 106
------- ------ -------- ---------- ---------- --------- - ---------- ----------
total 4 0.00 0.00 0 15 0 106
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 85
Rows Row Source Operation
------- ------------------------------------------- --------
106 HASH JOIN (cr = 15 pr = 0 pw = 0 time = 105 us cost = 7 size = 4028 card = 106)
27 TABLE ACCESS FULL DEPARTMENTS (cr = 7 pr = 0 pw = 0 time = 26 us cost = 3 size = 432 card = 27)
107 TABLE ACCESS FULL EMPLOYEES (cr = 8 pr = 0 pw = 0 time = 106 us cost = 3 size = 2354 card = 107)
All TKPROF TKPROF Output: Release 11.2.0.1.0 - Development Saturday Nov 22 20:05:34 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: nr_ora_6352_HR.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: 909v6n80saka9
Plan Hash: 0
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: 85
********************************************************************************
SELECT /*+USE_HASH(e d) */ e.employee_id, e.first_name||' '||e.last_name as full_name, d.department_name
FROM
employees e, departments d
WHERE
e.department_id=d.department_id
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 2 0.00 0.00 0 15 0 106
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 15 0 106
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 85
Rows Row Source Operation
------- ---------------------------------------------------
106 HASH JOIN (cr=15 pr=0 pw=0 time=105 us cost=7 size=4028 card=106)
27 TABLE ACCESS FULL DEPARTMENTS (cr=7 pr=0 pw=0 time=26 us cost=3 size=432 card=27)
107 TABLE ACCESS FULL EMPLOYEES (cr=8 pr=0 pw=0 time=106 us cost=3 size=2354 card=107)
********************************************************************************
SQL ID: at7597y1bruv1
Plan Hash: 0
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: 85
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 15 0 106
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.00 0.00 0 15 0 106
Misses in library cache during parse: 1
Misses in library cache during execute: 1
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 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: nr_ora_6352_HR.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
48 lines in trace file.
0 elapsed seconds in trace file.
Update
The previous Autotrace was from SQLPlus Release 11.2.0.1.0 and SQL Trace was from SQL Developer 4.0.1.14. By running SQL Trace from the same SQLPlus, the results are mapped ...
TKPROF: Release 11.2.0.1.0 - Development on Sun Nov 23 11:22:13 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: nr_ora_2836_HR.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: 909v6n80saka9
Plan Hash: 0
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: 85
********************************************************************************
SELECT /*+USE_HASH(e d) */ e.employee_id, e.first_name||' '||e.last_name as full_name, d.department_name
FROM
employees e, departments d
WHERE
e.department_id=d.department_id
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 9 0.00 0.00 0 21 0 106
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11 0.00 0.00 0 21 0 106
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 85
Rows Row Source Operation
------- ---------------------------------------------------
106 HASH JOIN (cr=21 pr=0 pw=0 time=0 us cost=7 size=4028 card=106)
27 TABLE ACCESS FULL DEPARTMENTS (cr=7 pr=0 pw=0 time=26 us cost=3 size=432 card=27)
107 TABLE ACCESS FULL EMPLOYEES (cr=14 pr=0 pw=0 time=0 us cost=3 size=2354 card=107)
********************************************************************************
SQL ID: at7597y1bruv1
Plan Hash: 0
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: 85
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 9 0.00 0.00 0 21 0 106
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.00 0.00 0 21 0 106
Misses in library cache during parse: 1
Misses in library cache during execute: 1
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 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: nr_ora_2836_HR.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
55 lines in trace file.
0 elapsed seconds in trace file.
+3
source to share
1 answer
The difference is that the tkprof output shows your single SELECT statement, but the Statistics section for the autotrace output sums up 2 statements, your recursive SELECT plus 1 calls, as mentioned in the first line of this section.
A few examples for recursive calls: triggers (INSERT, UPDATE, DELETE), dynamic fetch (in the absence of table statistics), or internal statements that request data from the data dictionary on first execution.
Try to execute the statement at least twice with autotrace and check if this 1 recursive call persists across successive starts. If so, the SQL trace must contain both a SELECT statement and recursive SQL. You should compare their sum to the output of autotrace. Tkprof reports the recursive level for the SQL statements found in the trace file, and a general summary as well.
+3
source to share