29 November, 2015

Trace Files -- 8c : Still More Performance Evaluation from Trace File

In previous blog posts here and here, I have demonstrated Full Table Scans of a table called ALL_OBJECTS_MANY_LIST being executed via Direct Path Reads (shown as 'direct path read') in the Wait Events.

This sort of read does NOT use the Buffer Cache and the read from disk directly goes to the user's server process PGA.  Thus, the blocks read are not shareable with other users.  Multiple users reading the same table(s) via Direct Path Read are not able to share the Buffer Cache, resulting in Disk Reads being repeated for every Full Table Scan request.  (Note : The OS may be using a File System Buffer Cache or the Storage may be using a Storage Cache to service the Disk Reads, but Oracle will always see every re-read of the table as a Disk Read).

Pre-11g, this behaviour could only be possible for Parallel Query.
However, 11g introduced the feature of "serial_direct_read" which allows non-PQ FullTableScans  to bypass the Buffer Cache.  This behaviour is predicated by the size of the table (segment) vis-a-vis the Buffer Cache, in relation to what is called "small_table_threshold".  A table exceeding a certain multiple of the "small_table_threshold" (which, by default, is a certain ratio of the Buffer Cache) is read via Direct Path Reads.

The Pre-11g and the 11g behaviour for smaller tables is to use Disk Reads that feed into the Buffer Cache, making the buffers shareable for repeated reads by either the same session or other sessions.  This obviates the need to make Disk Read calls for subsequent requests (as long as the blocks are still in the Buffer Cache).  The Wait Event we'd see for such Disk Reads is the (well known) "db file scattered read".

Here's a demo with a smaller table ALL_OBJECTS_SHORT_LIST.

SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> select count(*) from all_objects_short_list;

  COUNT(*)
----------
     28117

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_3029.trc

SQL> exit
[oracle@ora11204 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3029.trc \
> SHORT_LIST.PRF aggregate=NO sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 29 23:13:43 2015

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


[oracle@ora11204 ~]$ 

SQL ID: 69hzxtrb3dv1b Plan Hash: 1680768796

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
  NVL(SUM(C2),:"SYS_B_1")
FROM
 (SELECT /*+ NO_PARALLEL("ALL_OBJECTS_SHORT_LIST")
  FULL("ALL_OBJECTS_SHORT_LIST") NO_PARALLEL_INDEX("ALL_OBJECTS_SHORT_LIST")
  */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM
  "HEMANT"."ALL_OBJECTS_SHORT_LIST" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5")
  SEED (:"SYS_B_6") "ALL_OBJECTS_SHORT_LIST") SAMPLESUB


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        1      0.00       0.11        437         72          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.11        437         72          0           1

Misses in library cache during parse: 1
isses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=72 pr=437 pw=0 time=110985 us)
      3289       3289       3289   TABLE ACCESS SAMPLE ALL_OBJECTS_SHORT_LIST (cr=72 pr=437 pw=0 time=173325 us cost=19 size=61752 card=5146)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         7        0.04          0.05
  db file scattered read                          9        0.02          0.05
--------------------------------------------------------------------------------



SQL ID: 5ayuqj4djbjxh Plan Hash: 3180576180

select count(*)
from
 all_objects_short_list


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02          2          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.09        140        580          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.11        142        582          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=580 pr=140 pw=0 time=90644 us)
     28117      28117      28117   TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=140 pw=0 time=110678 us cost=158 size=0 card=30071)


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
  db file scattered read                         21        0.02          0.07
  db file sequential read                         3        0.00          0.00
  SQL*Net message from client                     2        9.76          9.76
********************************************************************************

The first query is the Dynamic Sampling query (because no statistics exist on the target table).  As in example 8a, this is done with a mix of single block ("db file sequential read") and multiblock ("db file scattered read") waits.  Here is a sampling of the waits for the Dynamic Sampling query :
WAIT #139712598070504: nam='db file sequential read' ela= 16 file#=1 block#=61344 blocks=1 obj#=35064 tim=1448809955554822
WAIT #139712598070504: nam='db file sequential read' ela= 951 file#=1 block#=61350 blocks=1 obj#=35064 tim=1448809955555840
WAIT #139712598070504: nam='db file scattered read' ela= 956 file#=1 block#=61362 blocks=6 obj#=35064 tim=1448809955556893
WAIT #139712598070504: nam='db file sequential read' ela= 720 file#=1 block#=61370 blocks=1 obj#=35064 tim=1448809955557710
WAIT #139712598070504: nam='db file sequential read' ela= 837 file#=1 block#=61378 blocks=1 obj#=35064 tim=1448809955558589
WAIT #139712598070504: nam='db file scattered read' ela= 1020 file#=1 block#=61385 blocks=7 obj#=35064 tim=1448809955559711
WAIT #139712598070504: nam='db file sequential read' ela= 804 file#=1 block#=61392 blocks=1 obj#=35064 tim=1448809955560643
WAIT #139712598070504: nam='db file scattered read' ela= 1270 file#=1 block#=61400 blocks=8 obj#=35064 tim=1448809955562000


This is the execution of the actual FullTableScan (the count(*) query submitted by me) :
EXEC #139712598962024:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3180576180,tim=1448809955666350
WAIT #139712598962024: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=35064 tim=1448809955666420
WAIT #139712598962024: nam='db file scattered read' ela= 28044 file#=1 block#=61345 blocks=5 obj#=35064 tim=1448809955695578
WAIT #139712598962024: nam='db file sequential read' ela= 1691 file#=1 block#=61351 blocks=1 obj#=35064 tim=1448809955697475
WAIT #139712598962024: nam='db file scattered read' ela= 11 file#=1 block#=61352 blocks=8 obj#=35064 tim=1448809955697539
WAIT #139712598962024: nam='db file scattered read' ela= 64 file#=1 block#=61360 blocks=2 obj#=35064 tim=1448809955697790
WAIT #139712598962024: nam='db file scattered read' ela= 468 file#=1 block#=61368 blocks=2 obj#=35064 tim=1448809955698673
WAIT #139712598962024: nam='db file scattered read' ela= 1493 file#=1 block#=61371 blocks=5 obj#=35064 tim=1448809955700255
WAIT #139712598962024: nam='db file scattered read' ela= 64 file#=1 block#=61376 blocks=2 obj#=35064 tim=1448809955700510
WAIT #139712598962024: nam='db file scattered read' ela= 1856 file#=1 block#=61379 blocks=5 obj#=35064 tim=1448809955702457
WAIT #139712598962024: nam='db file sequential read' ela= 11 file#=1 block#=61384 blocks=1 obj#=35064 tim=1448809955702568
WAIT #139712598962024: nam='db file scattered read' ela= 1184 file#=1 block#=61393 blocks=7 obj#=35064 tim=1448809955703916
WAIT #139712598962024: nam='db file scattered read' ela= 5970 file#=1 block#=61408 blocks=8 obj#=35064 tim=1448809955710042
WAIT #139712598962024: nam='db file scattered read' ela= 263 file#=1 block#=61424 blocks=7 obj#=35064 tim=1448809955710475
WAIT #139712598962024: nam='db file scattered read' ela= 2461 file#=1 block#=82176 blocks=8 obj#=35064 tim=1448809955713060
WAIT #139712598962024: nam='db file scattered read' ela= 2585 file#=1 block#=82184 blocks=8 obj#=35064 tim=1448809955715814
WAIT #139712598962024: nam='db file scattered read' ela= 70 file#=1 block#=82192 blocks=8 obj#=35064 tim=1448809955716030
WAIT #139712598962024: nam='db file scattered read' ela= 687 file#=1 block#=82200 blocks=3 obj#=35064 tim=1448809955716832
WAIT #139712598962024: nam='db file scattered read' ela= 28205 file#=1 block#=82204 blocks=4 obj#=35064 tim=1448809955745140
WAIT #139712598962024: nam='db file scattered read' ela= 13 file#=1 block#=82208 blocks=8 obj#=35064 tim=1448809955745285
WAIT #139712598962024: nam='db file scattered read' ela= 1070 file#=1 block#=82216 blocks=8 obj#=35064 tim=1448809955746453
WAIT #139712598962024: nam='db file sequential read' ela= 5960 file#=1 block#=82304 blocks=1 obj#=35064 tim=1448809955752560
WAIT #139712598962024: nam='db file scattered read' ela= 15 file#=1 block#=82538 blocks=5 obj#=35064 tim=1448809955754269
WAIT #139712598962024: nam='db file scattered read' ela= 15 file#=1 block#=82560 blocks=8 obj#=35064 tim=1448809955754481
WAIT #139712598962024: nam='db file scattered read' ela= 22 file#=1 block#=82674 blocks=14 obj#=35064 tim=1448809955755267
WAIT #139712598962024: nam='db file scattered read' ela= 18 file#=1 block#=82688 blocks=12 obj#=35064 tim=1448809955755460
FETCH #139712598962024:c=9997,e=90650,p=140,cr=580,cu=0,mis=0,r=1,dep=0,og=1,plh=3180576180,tim=1448809955757097
STAT #139712598962024 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=580 pr=140 pw=0 time=90644 us)'
STAT #139712598962024 id=2 cnt=28117 pid=1 pos=1 obj=35064 op='TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=140 pw=0 time=110678 us cost=158 size=0 card=30071)'


The Segment Header is in Block#61344 which has already been read into the Buffer Cache by the Dynamic Sampling query. So, we don't see a Wait Event for it in the count(*) query.  The Disk Reads start from Block#61345. From 61345 onwards, 5 blocks are read from disk (61345 to 61349). Block#61350 has already been read into the Buffer Cache by the Dynamic Sampling query.  Block#61351 is the last block of the Extents (8 blocks beginning at #61344) so it is a singe block read ("db file sequential read").  Even when Extents are contigous, Oracle will not make a read call that spans Extents.  The next Extent starts at Block#61352 and Oracle does a proper 8 block read.
At Block#61360, Oracle does a 2 block read because Block#61362 has already been read by the Dynamic Sampling query and is in the Buffer Cache.
All the Extents for this table are very small

Thus, you can see that multiblock reads using the "db file scattered read" wait event are reads that also rely on knowing which blocks are already present in the Buffer Cache.  Oracle does not do a "db file scattered read" read for a block that is already present in the Buffer Cache.

(What about Blocks 61363 to 61367 ?    Unfortunately, not every read call does get reported into the trace file, sometimes there may be "holes".  Not every Read Call is reported as being read to the last block in the Extent.
If you look at the Block# IDs being reported above and compare them with the Extents allocated, you will see that Oracle may not have reported every block as a Read Wait Event.
SQL> l
  1  select extent_id, file_id, block_id, blocks
  2  from dba_extents
  3  where
  4  owner = 'HEMANT'
  5  and segment_name = 'ALL_OBJECTS_SHORT_LIST'
  6* order by 1, 2, 3
SQL> /

 EXTENT_ID    FILE_ID BLOCK_ID     BLOCKS
---------- ---------- ---------- ----------
  0     1    61344   8
  1     1    61352   8
  2     1    61360   8
  3     1    61368   8
  4     1    61376   8
  5     1    61384   8
  6     1    61392   8
  7     1    61400   8
  8     1    61408   8
  9     1    61424   8
 10     1    82176   8
 11     1    82184   8
 12     1    82192   8
 13     1    82200   8
 14     1    82208   8
 15     1    82216   8
 16     1    82304 128
 17     1    82432 128
 18     1    82560 128
 19     1    82688 128

20 rows selected.

SQL> 

Also, once again note that file#1 indicates that these are in the SYSTEM Tablespace. .
.
.

22 November, 2015

Trace Files -- 8b : More Performance Evaluation from Trace File

Continuing with the same table as in the previous example, but with the addition of
(a) Statistics on the table
(b) An Index on the CREATED column

SQL> select count(*) from all_objects_many_list;

  COUNT(*)
----------
   7197952

SQL> 
SQL> select min(created) from all_objects_many_list;

MIN(CREAT
---------
28-AUG-11

SQL> 
SQL> select min(created), max(created) from all_objects_many_list;

MIN(CREAT MAX(CREAT
--------- ---------
28-AUG-11 15-NOV-15

SQL> 
SQL> 

Let's examine the tkprof output first.

[oracle@ora11204 Hemant]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2982.trc QRYS_22NOV.PRF aggregate=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 22 17:44:13 2015

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


[oracle@ora11204 Hemant]$ 

SQL ID: cwdmaym4gk0y2 Plan Hash: 2662061148

select count(*)
from
 all_objects_many_list


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      1.79      34.67      97793      97798          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.79      34.70      97793      97798          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=97798 pr=97793 pw=0 time=34677183 us)
   7197952    7197952    7197952   TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97793 pw=0 time=48480880 us cost=26777 size=0 card=7197952)

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
  direct path read                             1542        0.20         33.81
  SQL*Net message from client                     2        0.00          0.00
********************************************************************************




SQL ID: 72fjkwbds0wxf Plan Hash: 3190284407

select min(created)
from
 all_objects_many_list


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.01          3          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.02          3          3          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=3 pr=3 pw=0 time=17972 us)
         1          1          1   INDEX FULL SCAN (MIN/MAX) ALL_OBJ_M_L_CRTD_NDX (cr=3 pr=3 pw=0 time=17950 us cost=3 size=8 card=1)(object id 35037)


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
  db file sequential read                         3        0.00          0.01
  SQL*Net message from client                     2        0.00          0.00
********************************************************************************



SQL ID: dcrcwkktu08mv Plan Hash: 2662061148

select min(created), max(created)
from
 all_objects_many_list


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      1.31       1.27      97792      97797          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.31       1.28      97792      97797          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=97797 pr=97792 pw=0 time=1278898 us)
   7197952    7197952    7197952   TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97797 pr=97792 pw=0 time=17474658 us cost=26854 size=57583616 card=7197952)


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
  direct path read                             1542        0.00          0.16
  SQL*Net message from client                     3       14.02         14.02
  SQL*Net break/reset to client                   2        0.00          0.00
********************************************************************************


The first query (the count(*) did a Full Table Scan and read 7.198million rows reading 97,793 blocks from disk and 97,798 consistent gets. The "pr" count is the count of Physical Reads and the "cr" is the count of Logical Reads (there are no "cur" -- current mode block gets -- in this example). The Logical Reads count includes the Physical Reads count, do not attempt to add them.
During a Full Table Scan, Oracle may have to read the Segment Header and/or additional blocks to read the Extent Map.  Thus, some blocks may be read multiple times, the first reading may have been from Disk, subsequent readings from the Buffer Cache.
In this case, the Segment Header is identified as :
SQL> select header_file, header_block from dba_segments where owner = 'HEMANT' and segment_name = 'ALL_OBJECTS_MANY_LIST';

HEADER_FILE HEADER_BLOCK
----------- ------------
   4      330

SQL> 

and identified from the trace file as the 'db file sequential read' (single block read) as the first disk read before the 'direct path reads':
PARSING IN CURSOR #140647645766312 len=42 dep=0 uid=87 oct=3 lid=87 tim=1448185243704201 hv=3371762626 ad='6bd59a08' sqlid='cwdmaym4gk0y2'
select count(*) from all_objects_many_list
END OF STMT
PARSE #140647645766312:c=5999,e=33833,p=3,cr=39,cu=0,mis=1,r=0,dep=0,og=1,plh=2662061148,tim=1448185243704195
EXEC #140647645766312:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2662061148,tim=1448185243704326
WAIT #140647645766312: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1448185243704401
WAIT #140647645766312: nam='Disk file operations I/O' ela= 39 FileOperation=2 fileno=4 filetype=2 obj#=35014 tim=1448185243704787
WAIT #140647645766312: nam='db file sequential read' ela= 6291 file#=4 block#=330 blocks=1 obj#=35014 tim=1448185243711101
--------------------------------------------------------------------------------------------------------------------------
WAIT #140647645766312: nam='direct path read' ela= 3626 file number=4 first dba=331 block cnt=13 obj#=35014 tim=1448185243714977
WAIT #140647645766312: nam='direct path read' ela= 5029 file number=4 first dba=345 block cnt=15 obj#=35014 tim=1448185243720084

Note the underlined 'db file sequential read' of block#=330 from file number=4.
The third query also does a Full Table Scan but doesn't show a 'db file sequential read' wait for this block.  This Segment Header block was persisted in the Buffer Cache.  All the other blocks of the table read via 'direct path read' in the first Full Table Scan query were not persisted in the Buffer Cache.

The raw trace file in this case will NOT show the individual Logical Reads, only the Physical Reads when there are Waits.  However, the Logical Reads are visible in the STAT lines in the raw trace file.  These STAT lines for the first Full Table Scan query are visible as :
STAT #140647645766312 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=97798 pr=97793 pw=0 time=34677183 us)'
STAT #140647645766312 id=2 cnt=7197952 pid=1 pos=1 obj=35014 op='TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97793 pw=0 time=48480880 us cost=26777 size=0 card=7197952)'

These STAT lines show
(a) The Object ID for the Table being 35014
(b) The estimated COST for the Execution Plan was 26,777 (shown as "cost=").
(c) The estimated CARDINALITY (Number of Rows from the step in the Execution Plan was 7,197,952 (shown as "card=")
(d) The elapsed time for the Full Table Scan was 48.481million microseconds.
Note : Particularly on short-running steps in an Execution Plan and rounding of time, there may be some mismatch between the time reported individually in the raw trace and tkprof and the actual time.

If we look at the STAT line for the third query doing a Full Table Scan
STAT #140647645766312 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=97797 pr=97792 pw=0 time=1278898 us)'
STAT #140647645766312 id=2 cnt=7197952 pid=1 pos=1 obj=35014 op='TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97797 pr=97792 pw=0 time=17474658 us cost=26854 size=57583616 card=7197952)'

we note that the second Full Table Scan took 17.475million microseconds. This is much less time than the first Full Table Scan (48.481million). Thus, we can see that there was some impact of caching either in the Storage Cache or Server / FileSystem Cache which enabled these Disk Reads to be faster.

Note the difference in the "cost=" and "size=" values between the first Full Table Scan and the second Full Table Scan.  The first Full Table Scan had cost=26,777 and size=0.  The second Full Table Scan had cost=26,854 and size=57,583,616.  The additional "size" and "cost" in the second Full Table Scan is for reading the actual values in the "CREATED" column.  The first Full Table Scan only had to count the number of rows and did not have to return any column values.  The second query had to interpret the rows and return the "CREATED" values.  This is evident if we see the difference in the Explain Plans and note the "BYTES"

SQL> explain plan for select count(*) from all_objects_many_list;

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2662061148

------------------------------------------------------------------------------------
| Id  | Operation    | Name     | Rows  | Cost (%CPU)| Time    |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |  1 | 26777   (1)| 00:05:22 |
|   1 |  SORT AGGREGATE    |      |  1 |  |    |
|   2 |   TABLE ACCESS FULL| ALL_OBJECTS_MANY_LIST |  7197K| 26777   (1)| 00:05:22 |
------------------------------------------------------------------------------------

9 rows selected.

SQL> explain plan for select min(created), max(created) from all_objects_many_list;

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2662061148

--------------------------------------------------------------------------------------------
| Id  | Operation    | Name     | Rows  | Bytes | Cost (%CPU)| Time    |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |  1 |  8 | 26854   (1)| 00:05:23 |
|   1 |  SORT AGGREGATE    |      |  1 |  8 |  |    |
|   2 |   TABLE ACCESS FULL| ALL_OBJECTS_MANY_LIST |  7197K| 54M| 26854   (1)| 00:05:23 |
--------------------------------------------------------------------------------------------

9 rows selected.

SQL> 

Note how the query on MIN(CREATED), MAX(CREATED) shows that it returns 54million bytes (reading the CREATED column values for all the rows) and, therefore, has a higher Cost.



The Full Table Scans are executed as 'direct path read' operations and *not* reads from the database instance Buffer Cache in the SGA.  These Direct Reads are a result of the "serial direct read" behaviour of 11g used for large tables --as noted in my previous blog post, this table is larger than the Buffer Cache.  Had it been a small table (or pre-11g), the reads would have been executed with 'db file scattered read' waits and loaded into the Buffer Cache and it is possible that some of the blocks may have been present in the Buffer Cache for the third query.


The second query, using an Index on the CREATED column did 3 block reads as 'db file sequential read'.

PARSING IN CURSOR #140647645766312 len=46 dep=0 uid=87 oct=3 lid=87 tim=1448185278404154 hv=3682628526 ad='7f931480' sqlid='72fjkwbds0wxf'
select min(created) from all_objects_many_list
END OF STMT
PARSE #140647645766312:c=4999,e=4087,p=1,cr=30,cu=0,mis=1,r=0,dep=0,og=1,plh=3190284407,tim=1448185278404148
EXEC #140647645766312:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3190284407,tim=1448185278404230
WAIT #140647645766312: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=35014 tim=1448185278404299
WAIT #140647645766312: nam='db file sequential read' ela= 5021 file#=1 block#=61217 blocks=1 obj#=35037 tim=1448185278409390
WAIT #140647645766312: nam='db file sequential read' ela= 6886 file#=1 block#=63109 blocks=1 obj#=35037 tim=1448185278416360
WAIT #140647645766312: nam='db file sequential read' ela= 5782 file#=1 block#=61218 blocks=1 obj#=35037 tim=1448185278422228
FETCH #140647645766312:c=0,e=17979,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3190284407,tim=1448185278422304
STAT #140647645766312 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=3 pw=0 time=17972 us)'
STAT #140647645766312 id=2 cnt=1 pid=1 pos=1 obj=35037 op='INDEX FULL SCAN (MIN/MAX) ALL_OBJ_M_L_CRTD_NDX (cr=3 pr=3 pw=0 time=17950 us cost=3 size=8 card=1)'


The three single block reads (Root, Branch, Leaf) for object 35037 (the Index) are from file=1 which happens to be the SYSTEM tablespace.
SQL> l
  1* select tablespace_name , blevel from dba_indexes where owner = 'HEMANT' and table_name = 'ALL_OBJECTS_MANY_LIST'
SQL> /

TABLESPACE_NAME      BLEVEL
------------------------------ ----------
SYSTEM     2

SQL> 
 

tkprof does not show this information about the index being in the different (actually wrong !) Tablespace.  Only a reading of the trace file identifies this.  There are 3 blocks (Root, Branch, Leaf) to be read and the BLEVEL indicates this.  Block 61217 is the block immediately after the Segment Head Block (61216).  Block 63109 is a Branch Block and Block 61218 is a Leaf Block.  This query was fully satisfied from the Index alone and didn't have to read any Table blocks.

.
.
.


15 November, 2015

Trace Files -- 8a : Using SQL Trace for Performance Evaluations

All previous examples of tracing are only to demonstrate enabling tracing and viewing the results.

Now, I present a case where we can use tracing to evaluate performance of queries.  There may be a follow-up post(s) to expand on or add example(s).

I start with a table with 7million rows and more than 750MB in size (larger than the database buffer cache).  This is a multiplied copy of DBA_OBJECTS.  Statistics have not been gathered on the Table.  The Table has no Indexes.

[oracle@ora11204 ~]$ sqlplus hemant/hemant

SQL*Plus: Release 11.2.0.4.0 Production on Sun Nov 15 22:51:15 2015

Copyright (c) 1982, 2013, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> select count(*) from all_objects_many_list where owner = 'HEMANT';

  COUNT(*)
----------
       256

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_8944.trc

SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@ora11204 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_8944.trc MY_ALL_OBJ_M_L_QRY.PRF sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 15 22:53:12 2015

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


[oracle@ora11204 ~]$ 

We expect a Full Table Scan against the Table.  But the tkprof output shows something else as well.

SQL ID: 9s5xc0z5khvq7 Plan Hash: 3546461632

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
  NVL(SUM(C2),:"SYS_B_1")
FROM
 (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("ALL_OBJECTS_MANY_LIST")
  FULL("ALL_OBJECTS_MANY_LIST") NO_PARALLEL_INDEX("ALL_OBJECTS_MANY_LIST") */
  :"SYS_B_2" AS C1, CASE WHEN "ALL_OBJECTS_MANY_LIST"."OWNER"=:"SYS_B_3" THEN
  :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "HEMANT"."ALL_OBJECTS_MANY_LIST"
  SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8")
  "ALL_OBJECTS_MANY_LIST") SAMPLESUB


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        1      0.00       0.88        123         65          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.88        123         65          0           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Optimizer mode: ALL_ROWS
Parsing user id: 87     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=65 pr=123 pw=0 time=887883 us)
      3289       3289       3289   TABLE ACCESS SAMPLE ALL_OBJECTS_MANY_LIST (cr=65 pr=123 pw=0 time=20429 us cost=19 size=149234 card=5146)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                        35        0.08          0.70
  db file scattered read                         11        0.07          0.17
********************************************************************************

SQL ID: bpgst4ajh1wb2 Plan Hash: 2662061148

select count(*)
from
 all_objects_many_list where owner = 'HEMANT'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.03          2          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.68      12.88      97792      97798          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.68      12.91      97794      97800          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=97798 pr=97792 pw=0 time=12886862 us)
       256        256        256   TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97792 pw=0 time=37649164 us cost=26772 size=26520 card=1560)

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
  reliable message                                1        0.03          0.03
  enq: KO - fast object checkpoint                1        0.00          0.00
  direct path read                             1542        0.18         12.54
  SQL*Net message from client                     2       18.06         18.06
********************************************************************************

Note the additional SQL that was executed before my query. That is the Dynamic Sampling query identified by the OPT_DYN_SAMP comment.  This query, although being recursive (indicated by "dep=1" in the raw trace file) is not excluded by the SYS=NO, because it is actually executed by the user "HEMANT" (indicated by "uid=87", "lid=87", where 87 is the userid of  database user 'HEMANT').

Let's see a portion of the raw trace file relating to this Dynamic Sampling query.

PARSING IN CURSOR #140417579320304 len=616 dep=1 uid=87 oct=3 lid=87 tim=1447599117299160 hv=3408424647 ad='7f8bb8f0' sqlid='9s5xc0z5khvq7'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("ALL_OBJECTS_MANY_LIST") FULL("ALL_OBJECTS_MANY_LIST") NO_PARALLEL_INDEX("ALL_OBJECTS_MANY_LIST") */ :"SYS_B_2" AS C1, CASE WHEN "ALL_OBJECTS_MANY_LIST"."OWNER"=:"SYS_B_3" THEN :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "HEMANT"."ALL_OBJECTS_MANY_LIST" SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8") "ALL_OBJECTS_MANY_LIST") SAMPLESUB
END OF STMT
PARSE #140417579320304:c=1000,e=670,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1447599117299155
EXEC #140417579918768:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1447599117300059
FETCH #140417579918768:c=1000,e=20,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1447599117300113
CLOSE #140417579918768:c=0,e=7,dep=2,type=3,tim=1447599117300148
EXEC #140417579320304:c=1000,e=1319,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=1,plh=3546461632,tim=1447599117300542
WAIT #140417579320304: nam='db file sequential read' ela= 17 file#=4 block#=330 blocks=1 obj#=35014 tim=1447599117300633
WAIT #140417579320304: nam='db file sequential read' ela= 12384 file#=4 block#=1044 blocks=1 obj#=35014 tim=1447599117313168
WAIT #140417579320304: nam='db file sequential read' ela= 30217 file#=4 block#=1839 blocks=1 obj#=35014 tim=1447599117343572
WAIT #140417579320304: nam='db file sequential read' ela= 14367 file#=4 block#=4273 blocks=1 obj#=35014 tim=1447599117358103
WAIT #140417579320304: nam='db file sequential read' ela= 26739 file#=4 block#=4666 blocks=1 obj#=35014 tim=1447599117384964
WAIT #140417579320304: nam='db file sequential read' ela= 15278 file#=4 block#=8352 blocks=1 obj#=35014 tim=1447599117400429
WAIT #140417579320304: nam='db file scattered read' ela= 55038 file#=4 block#=14030 blocks=8 obj#=35014 tim=1447599117455816

*** 2015-11-15 22:51:57.527
WAIT #140417579320304: nam='db file sequential read' ela= 71363 file#=4 block#=14417 blocks=1 obj#=35014 tim=1447599117527415
WAIT #140417579320304: nam='db file sequential read' ela= 81866 file#=4 block#=18668 blocks=1 obj#=35014 tim=1447599117609519
WAIT #140417579320304: nam='db file sequential read' ela= 65981 file#=4 block#=23052 blocks=1 obj#=35014 tim=1447599117675718
WAIT #140417579320304: nam='db file sequential read' ela= 14640 file#=4 block#=25282 blocks=1 obj#=35014 tim=1447599117690503
WAIT #140417579320304: nam='db file sequential read' ela= 65302 file#=4 block#=26230 blocks=1 obj#=35014 tim=1447599117755921
WAIT #140417579320304: nam='db file scattered read' ela= 51919 file#=4 block#=27340 blocks=8 obj#=35014 tim=1447599117808090
WAIT #140417579320304: nam='db file scattered read' ela= 70379 file#=4 block#=27479 blocks=8 obj#=35014 tim=1447599117878651

Note the mix of single-block 'db file sequential read' waits and multi-block 'db file scattered read' waits.  Also, note from the block numbers (indicated by "block#") that the reads are not really sequential blocks from disk.  The first block read is block 330 of file 4.  That is the header block of the Table (i.e. Segment) (we could query DBA_SEGMENTS to confirm this).  After that, Oracle has randomly identified blocks to scan.  The multi-block reads can be identified by "blocks=8"  (in this extract we see only 3 multi-block reads, as I haven't presented the entire raw trace file here.  The Dynamic Sampling had 35 'db file sequential read' waits and 11 'db file scattered read waits' -- which we see in the tkprof output.  The tkprof shows that although there were physical block read requests for 123 blocks, only 65 were actually sampled.  Dynamic Sampling took 0.88seconds (i.e. added 0.88seconds to the time to execute my query0.

Dynamic Sampling is done using Buffered reads.  However, the Full Table Scan of the large table is executed using Direct Path reads.  That is why the wait event for the count(*) query is different -- it is a 'direct path read' wait that occurs many times.

ARSING IN CURSOR #140417579185064 len=65 dep=0 uid=87 oct=3 lid=87 tim=1447599118188941 hv=2734748002 ad='7f956058' sqlid='bpgst4ajh1wb2'
select count(*) from all_objects_many_list where owner = 'HEMANT'
END OF STMT
PARSE #140417579185064:c=24996,e=1098676,p=127,cr=184,cu=0,mis=1,r=0,dep=0,og=1,plh=2662061148,tim=1447599118188936
EXEC #140417579185064:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2662061148,tim=1447599118189025
WAIT #140417579185064: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=35014 tim=1447599118189093
WAIT #140417579185064: nam='reliable message' ela= 33598 channel context=2123970008 channel handle=2123913464 broadcast message=2125033832 obj#=35014 tim=1447599118223060
WAIT #140417579185064: nam='enq: KO - fast object checkpoint' ela= 3905 name|mode=1263468550 2=65560 0=1 obj#=35014 tim=1447599118227031
WAIT #140417579185064: nam='direct path read' ela= 32287 file number=4 first dba=331 block cnt=13 obj#=35014 tim=1447599118259487
WAIT #140417579185064: nam='direct path read' ela= 97 file number=4 first dba=345 block cnt=15 obj#=35014 tim=1447599118259681
WAIT #140417579185064: nam='direct path read' ela= 9530 file number=4 first dba=361 block cnt=15 obj#=35014 tim=1447599118269284
WAIT #140417579185064: nam='direct path read' ela= 81 file number=4 first dba=377 block cnt=15 obj#=35014 tim=1447599118269448
WAIT #140417579185064: nam='direct path read' ela= 4879 file number=4 first dba=393 block cnt=15 obj#=35014 tim=1447599118274418
WAIT #140417579185064: nam='direct path read' ela= 18847 file number=4 first dba=409 block cnt=15 obj#=35014 tim=1447599118293388
WAIT #140417579185064: nam='direct path read' ela= 3692 file number=4 first dba=425 block cnt=15 obj#=35014 tim=1447599118297175
WAIT #140417579185064: nam='direct path read' ela= 2612 file number=4 first dba=441 block cnt=15 obj#=35014 tim=1447599118299862
WAIT #140417579185064: nam='direct path read' ela= 42872 file number=4 first dba=514 block cnt=62 obj#=35014 tim=1447599118342814
WAIT #140417579185064: nam='direct path read' ela= 12735 file number=4 first dba=576 block cnt=64 obj#=35014 tim=1447599118355614
WAIT #140417579185064: nam='direct path read' ela= 41997 file number=4 first dba=642 block cnt=62 obj#=35014 tim=1447599118397975
WAIT #140417579185064: nam='direct path read' ela= 11584 file number=4 first dba=704 block cnt=64 obj#=35014 tim=1447599118409765
WAIT #140417579185064: nam='direct path read' ela= 10909 file number=4 first dba=770 block cnt=62 obj#=35014 tim=1447599118420916
WAIT #140417579185064: nam='direct path read' ela= 10969 file number=4 first dba=832 block cnt=64 obj#=35014 tim=1447599118432086

Before we look at the 'direct path read' waits, please see the 'reliable message' and 'enq: KO - fast object checkpoint' waits.  Oracle will always cause a segment checkpoint before it starts doing Direct Path reads.  This is to ensure that any dirty buffers for that segment (the table "all_objects_many_list") are flushed to disk before Oracle starts using Direct Path reads to bypass the Buffer Cache. 

Next, if we look at the 'direct path read' waits, we see that they are reported differently from the 'db file sequential || scattered read' waits.  Instead of reporting "block#" and "blocks", this wait event reports "dba" ("data block address") and "block cnt".  Note the first read is of 13 blocks starting at block number 331 (after the Segment Header).  The next read starts at block number 345 (which is 331+13+1).  This is a 15 block read.  The third read starts at block 361 (which is 345+15+1).  Thus, we can see that the Table is laid out contiguous extents in the same datafile (file=4).

The "ela=" time is the time in micrseconds for each read.  The obj# is the Object ID of the table.
During the Full Table Scan, there were 1,542 occurrences of the 'direct path read' wait event.  The average read time for 'direct path read' waits can be computed by dividing the 12.54seconds over the 1,542 occurrences.  But we must note that some of these reads were 16 or fewer blocks and others were 64 or so blocks. The first read was 32,287microseconds,  the next was 97microseconds.  It is possible that either the OS or the Storage Cache did some pre-fetching of blocks.  But note the fluctuations in read wait times.  Averages can be misleading.  It is a good idea to sometimes walk through the trace file (preferably using a tool) to determine a Histogram of these waits.

If we look at the small extract of the trace file that I've pasted here, we can see that the reads were growing.  There were 64 blocks read in the last wait event that I've pasted.  Reviewing the entire trace file, I see that "64" is the highest  reported "block cnt" figure.  However, the distribution of extent size goes upto 8MB (1024 blocks), yet the largest read was 64 blocks because of how Oracle has auto-configured 'db_file_multiblock_read_count'.  Remember, tkprof does NOT show you the sizes of the multi-block reads either as 'db file scattered read' or 'direct path read'.  You have to read or parse the raw trace file to identify this.


SQL> select blocks, count(*) 
  2  from dba_extents
  3  where owner = 'HEMANT'
  4  and segment_name = 'ALL_OBJECTS_MANY_LIST'
  5  group by blocks
  6  order by 1;

    BLOCKS   COUNT(*)
---------- ----------
  8    16
       128    63
      1024    88

SQL>      
SQL> show parameter db_file_multi

NAME         TYPE  VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count      integer  106
SQL> 

The DBA here had not specifically configured db_file_multiblock_read_count to 128 (I would certainly have done so, and would have got better performance on the Full Table Scan).
,
,
,

08 November, 2015

Trace Files -- 7 : SQL in PL/SQL

So far, all my examples of Tracing have been 'pure' SQL.  What does a Trace File show for SQL that is executed from within PL/SQL ?

I run this code  where I trace only the execution of the stored procedure :

SQL> drop table departmental_salary purge;

Table dropped.

SQL> drop procedure my_dept_salary_proc ;

Procedure dropped.

SQL> 
SQL> create table departmental_salary (department_id number, total_salary number);

Table created.

SQL> 
SQL> create or replace procedure my_dept_salary_proc as
  2  l_dept_id number(4);
  3  l_tot_salary number(10,2);
  4  cursor get_dept_id is select distinct department_id from employees;
  5  
  6  begin
  7  open get_dept_id;
  8  loop
  9  fetch get_dept_id into l_dept_id;
 10  exit when get_dept_id%notfound;
 11  
 12  -- get the sum(salary)
 13  select sum(salary) into l_tot_salary from employees where department_id = l_dept_id ;
 14  -- the developer mistakenly entered the same query twice in the procedure
 15  -- the second SELECT is textually different
 16  SELECT  SUM(SALARY) into l_tot_salary FROM    employees WHERE DEPARTMENT_ID = l_dept_id ;
 17  
 18  insert into departmental_salary values (l_dept_id, l_tot_salary);
 19  -- again, the developer mistakenly entered the same INSERT twice
 20  -- not exactly the same text
 21  INSERT into   DEPARTMENTAL_SALARY values (L_DEPT_ID, L_TOT_SALARY);
 22  
 23  end loop;
 24  
 25  commit;
 26  
 27  end;
 28  /

Procedure created.

SQL> 
SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> 
SQL> execute my_dept_salary_proc;

PL/SQL procedure successfully completed.

SQL> 
SQL> exec dbms_session.session_trace_disable;

PL/SQL procedure successfully completed.

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

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

SQL> 


Note the repetition of the SELECT and INSERT statements.  In "normal" SQL, the two SELECTs for SUM(SALARY) would have two different SQL_IDs because any SQL that differs by Case or blank characters is a different SQL_ID.  As also, the two INSERTs should have different SQL_IDs.

What does a tkprof show ?

[oracle@ora11204 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3927.trc \
> EXEC_MY_DEPT_SALARY_PROC.PRF sys=NO aggregate=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 8 23:23:42 2015

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


[oracle@ora11204 ~]$ 



Note that I've set SYS=NO to exclude Parse Recursive SQLs.

Selectively reporting from the tkprof, I see :

SQL ID: 0wan8zwsb8000 Plan Hash: 0

BEGIN dbms_session.session_trace_enable(waits=>TRUE); END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43


SQL ID: a8p49fngpats5 Plan Hash: 0

BEGIN my_dept_salary_proc; 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


SQL ID: 4xts9z878v4yb Plan Hash: 3042654289

SELECT DISTINCT DEPARTMENT_ID
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       13      0.00       0.00          0          6          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15      0.00       0.00          0          6          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
        12         12         12  HASH UNIQUE (cr=6 pr=0 pw=0 time=743 us cost=4 size=33 card=11)
       214        214        214   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=917 us cost=3 size=642 card=214)


SQL ID: bnr7u92kg18ak Plan Hash: 1756381138

SELECT SUM(SALARY)
FROM
 EMPLOYEES WHERE DEPARTMENT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12      0.00       0.00          0         66          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25      0.00       0.00          0         66          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=6 pr=0 pw=0 time=73 us)
        12         12         12   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=64 us cost=3 size=133 card=19)


SQL ID: bnr7u92kg18ak Plan Hash: 1756381138

SELECT SUM(SALARY)
FROM
 EMPLOYEES WHERE DEPARTMENT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12      0.00       0.00          0         66          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25      0.00       0.00          0         66          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=6 pr=0 pw=0 time=50 us)
        12         12         12   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=40 us cost=3 size=133 card=19)


SQL ID: b6yyghrcpvy4y Plan Hash: 0

INSERT INTO DEPARTMENTAL_SALARY
VALUES
 (:B2 , :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          4         55          12
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0          4         55          12

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=2 pr=0 pw=0 time=479 us)


SQL ID: b6yyghrcpvy4y Plan Hash: 0

INSERT INTO DEPARTMENTAL_SALARY
VALUES
 (:B2 , :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          1         14          12
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0          1         14          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=63 us)


SQL ID: 8ggw94h7mvxd7 Plan Hash: 0

COMMIT


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

Misses in library cache during parse: 0
Parsing user id: 43     (recursive depth: 1)


SQL ID: 4pzfk82288xrc 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: 0
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.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.01          0          0          0           3

Misses in library cache during parse: 1



OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       15      0.00       0.00          0          0          0           0
Execute     59      0.00       0.00          0         17         77          28
Fetch       40      0.00       0.00          0        148          0          37
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      114      0.01       0.01          0        165         77          65

Misses in library cache during parse: 1
Misses in library cache during execute: 1





Note 1 : The first query for DISTINCT DEPARTMENT_IDs returned 12 rows (12 distinct Department_IDs).  Therefore, each of the SELECT and INSERT statements was executed 12 times.
There are some very interesting observations to be made.

Note 2 : The Rows (1st), (avg), (max) statistics for the SELECT SUM(SALARY) are not accurate as the trace file has not captured Row Source Statistics individually for each execution of the query.  Different DEPARTMENT_IDs actually have different Row Counts.  You have to be careful when interpreting these statistics.  Check the trace file to see if Row Source Statistics (indicated by "STAT" lines) are captured.


Firstly : The SQLs called from the PLSQL procedure are not accounted under "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS". This can be surmised by looking at the "Execute" and "Fetch" count statistics. The SQLs called from the PLSQL procedure are reported under "OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS".  That is why it can sometimes be very important to *not* ignore the "Recursive Statements" statistics.  Here, all the effort is in what are identified by tkprof as "Recursive Statements".  Some of the 59 Executions under "Recursive Statements" are NOT Parse overheads but actual User SQLs (called from the PLSQL procedure) !
I can also see from the raw trace file that my SELECT and INSERT statements appear with "dep=1" (and not "dep=0").  So, they are tracked as Recursive Depth SQLs, not Parent level SQLs.

PARSING IN CURSOR #139685522349264 len=44 dep=1 uid=43 oct=3 lid=43 tim=1446996115239966 hv=244159435 ad='70eaa1c0' sqlid='4xts9z878v4yb'
SELECT DISTINCT DEPARTMENT_ID FROM EMPLOYEES
END OF STMT

PARSING IN CURSOR #139685521574368 len=60 dep=1 uid=43 oct=3 lid=43 tim=1446996115241015 hv=2767233362 ad='70f496b0' sqlid='bnr7u92kg18ak'
SELECT SUM(SALARY) FROM EMPLOYEES WHERE DEPARTMENT_ID = :B1
END OF STMT

PARSING IN CURSOR #139685521624960 len=51 dep=1 uid=43 oct=2 lid=43 tim=1446996115241988 hv=3646814366 ad='6e08dea0' sqlid='b6yyghrcpvy4y'
INSERT INTO DEPARTMENTAL_SALARY VALUES (:B2 , :B1 )
END OF STMT


Secondly : those CASE-Sensitive SQL statements that I had in the procedure which should have generated different SQL_IDs are all transformed to ALL-UPPERCASE SQL statements with the additional blank spaces stripped out.  Thus, although we have two different sets of SELECT statements for the SUM(SALARY), they appear exactly the same (transformed to ALL-UPPERCASE) with the *same* SQL_ID in the raw trace.  Similarly, the two different INSERT statements appear exactly the same ALL-UPPERCASE statements.
This is in optimization that Oracle applies to SQL statements inside PLSQL.  They effectively become case-insensitive and similar.  Also, you can see that Oracle automatically assigns Bind Variables (:B1, :B2) in place of the placeholders I used (l_dept_id, l_tot_salary).


Note  :  SELECT statement statistics (consistent gets, disk reads,  rows etc are accounted under FETCH, while DML (e.g. INSERT) statement statistics are accounted under EXECUTE.


I can verify that the INSERTs were executed twice for each DEPARTMENT_ID :

SQL> select department_id, total_salary from departmental_salary order by 1;

DEPARTMENT_ID TOTAL_SALARY
------------- ------------
    10       8800
    10       8800
    20      38000
    20      38000
    30      49800
    30      49800
    40      13000
    40      13000
    50     312800
    50     312800
    60      57600
    60      57600
    70      20000
    70      20000
    80     609000
    80     609000
    90     116000
    90     116000
   100     103216
   100     103216
   110      40616
   110      40616



24 rows selected.

SQL> 


.
.
.

02 November, 2015

SSL Support

This blog now supports SSL connections.

Browse this blog using https://   instead of http://   for a secure connection when accessing a specific page.


.
.
.

01 November, 2015

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.

.
.
.