Trace Files -- 6 : Multiple Executions of the same SQL

In the previous two posts, I demonstrated a single execution of an SQL query and interpreting the raw trace and the tkprof summary for it.  The demonstration also showed the Hard Parsing for the first execution of the query.

What if
(a) We have multiple executions of the same SQL ?  Likely the first execution, if the Plan doesn't already exist in the Shared Pool, requires a Hard Parse  (Also, the first execution immediately after enabling Tracing itself requires a Hard Parse).
(b) Row Counts change for subsequent executions.
(c) Something happens that causes a fresh Hard Parse for a subsequent execution.  That something could be a DDL against the source table causing Invalidation of the SQL.  Possibly even a change of the Execution Plan


I'll create a demo here.  I am taking exactly the same SQL as in the previous demo.

SQL> connect hr/oracle
Connected.
SQL> exec DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE);

PL/SQL procedure successfully completed.

SQL> select count(*) from employees;

  COUNT(*)
----------
       107

SQL> select count(*) from employees;

  COUNT(*)
----------
       214

SQL> select count(*) from employees;

  COUNT(*)
----------
       214

SQL> exec DBMS_SESSION.SESSION_TRACE_DISABLE;

PL/SQL procedure successfully completed.

SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3119.trc

SQL> 

What are the changes I made for the second and third executions ?  Quite obviously, I have duplicated the number of rows before the second execution of the query.  Then, some other change before the third execution.
These are the two changes made from another session :

SQL> insert into employees
  2  select employee_id+1000, first_name||'_A', last_name||'_B', email||'.XYZ', phone_number, hire_date+1, job_id, salary, commission_pct,
  3  manager_id, department_id
  4  from employees 
  5  /

107 rows created.

SQL> commit;

Commit complete.

SQL> alter table employees drop constraint emp_email_uk;

Table altered.

SQL> drop index emp_email_uk;
drop index emp_email_uk
           *
ERROR at line 1:
ORA-01418: specified index does not exist


SQL> 

The first change added 107 rows to the table. The second change dropped the index that was being used by the initial Execution Plan.

Let's look at a tkprof of the trace file.  Here, I use the option aggregate=NO to separately report each execution of the query.

[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3119.trc \
> My_3_Queries.PRF aggregate=NO sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 1 21:27:15 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 Desktop]$ 

The aggregate=NO separates the three executions of the same SQL_ID. Extracting the lines from the tkprof, we see that each individual execution is reported separately

SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
from
 employees


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          1          1          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          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=235 us)
       107        107        107   INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=412 us cost=1 size=0 card=107)(object id 16404)


SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
from
 employees


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          1          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          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=0 pw=0 time=66 us)
       214        214        214   INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=0 pw=0 time=447 us cost=1 size=0 card=107)(object id 16404)


SQL ID: 7c1rnh08dp922 Plan Hash: 1426549735

select count(*)
from
 employees


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          1          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          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=0 pw=0 time=63 us)
       214        214        214   INDEX FULL SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=554 us cost=1 size=0 card=107)(object id 16405)

We can see that the first execution read 107 Rows (ROWIDs) from the Index EMP_EMAIL_UK (a Unique Key Index on the EMAIL_ADDRESS).  This also matched the expected cardinality of 107 rows (shown by "card=107").

However, the second execution, reading the same EMP_EMAIL_UK index and expected cardinality of 107 actually read 214 Rows (ROWIDs).  (Because of the additional 107 rows inserted and committed by the separate session)

The third execution used a different Index EMP_EMP_ID_PK (because the EMP_EMAIL_UK index was no longer present).  Here, too, there was a mismatch between the expected cardinality ("card=107") and the actual Rows (ROWIDs) count of 214.

The mismatch between cardinality and actual Rows (ROWIDs) from the indexes in the 2nd and 3rd executions occur because although 107 new rows are inserted, index statistics are not updated.

Did you also note that the second execution had a Parse and a "Misses in library cache during parse:" ?  The trace file (not presented in this post) shows that the cursor for the first execution had been closed but does not show Hard Parsing (no recursive SQLs).  That parse was a Soft Parse.



What if I had *NOT* used the aggregate=NO option in tkprof ?  The default is aggregate=YES.  This is what it would present  (I can take the same raw trace file and generate a new tkprof output file) :

[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3119.trc \
> My_3_Queries_AGGREGATED.PRF sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 1 21:51:51 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 Desktop]$ 

SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
from
 employees


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        4      0.00       0.00          1          2          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.00       0.00          1          2          0           2

Misses in library cache during parse: 2
Optimizer mode: ALL_ROWS
Parsing user id: 43
Number of plan statistics captured: 2

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=1 pr=0 pw=0 time=150 us)
       107        160        214   INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=0 pw=0 time=430 us cost=1 size=0 card=107)(object id 16404)


SQL ID: 7c1rnh08dp922 Plan Hash: 1426549735

select count(*)
from
 employees


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          1          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          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=0 pw=0 time=63 us)
       214        214        214   INDEX FULL SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=554 us cost=1 size=0 card=107)(object id 16405)

Here it shows the SQL twice.

The first entry is for *2* executions, with the same Plan Hash Value.  The Rows statistics shows statistics for the 1st execution, the average and the last execution.  Thus, we can discern that not all the executions had the same Row Statistics.  The first execution read 107 Rows (ROWIDs) from the Index, the last execution read 214 from the same Index (using the same Execution Plan).  Therefore, it is important to understand that execution statistics for the same Execution Plan can vary !  If you suspect that execution statistics are varying, I recommend that you use the aggregate=NO option to tkprof.  {I suggest that you create a test case where you have 3 or more executions with the same Plan Hash Value and Execution Plan and yet have different statistics (e.g. simply Row Counts) and see how the Plan / Row statistics are reported}
Note : Earlier versions of Oracle wouldn't report "Rows (1st) Rows (avg) Rows (max)" but would likely have reported Row Source statistics only for the last execution.

The second entry is for the 3rd execution, with a different Plan Hash Value and Execution Plan (using the EMP_EMP_ID_PK index).

Conclusion :  Thus, we have one SQL with one SQL_ID, two different Execution Plans and three sets of Execution Statistics.  Simply because the underlying data or DDL can change between executions of the same SQL in the same session.

.
.
.