Search My Oracle Blog

Custom Search

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

1 comment:

Foued said...

Big thanks for all those wonderful insights you share ,
Kind regards,
Foued

Aggregated by orafaq.com

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

Top 50 Oracle SQL Blogs 2016

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