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

No comments: