What is the difference between Consistent Gets in Autotrace and Consistent Read in SQL Trace?
Run the SQL on the Oracle demo HR schema and run Autotrace and SQL Trace (bottom). I expected the number of the block read would be the same, however Autotrace Consistent Gets is 21 and SQL Trace Consistent Read is 15. I wonder what makes the differences.
There was no update to the tables and the traces say there was no cache miss, hence I think the blocks the SQL needed were all in the cache.
The table data blocks from USER_INDEXES are both 5 for EMPLOYESS and DEPARTMENTS. The rows 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;
Oracle 11G R2 on Windows x64 HR demo schema.
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(e d) */ 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*
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)
Entire TKPROF output TKPROF: Release 11.2.0.1.0 - Development on Sat 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.
The previous Autotrace was executed from SQLPlus Release 11.2.0.1.0 and the SQL Trace was from SQL Developer 4.0.1.14. By running the SQL Trace from the same SQLPlus, the results matched...
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.
The difference is that the tkprof output shows your single SELECT statement, but the Statistics section of autotrace output summarizes 2 statements, your SELECT plus 1 recursive calls, as indicated by the first line of that section.
A few examples for recursive calls are: triggers (INSERT, UPDATE, DELETE), dynamic sampling (in case of missing table statistics) or internal statements querying data from the data dictionary on the first execution.
Try running the statement at least twice with autotrace, and check if this 1 recursive call persists on consecutive executions. If it does, the SQL trace should contain both your SELECT statement and the recursive SQL. You should compare the sum of them with the autotrace output. Tkprof reports the recursive level for the SQL statements found in the trace file and the total summary also.