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.
We expect a Full Table Scan against the Table. But the tkprof output shows something else as well.
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.
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.
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.
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).
,
,
,
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:
Post a Comment