Oracle Tips and Tricks — David Fitzjarrell

October 25, 2018

Tuning Time

Filed under: General,Performance — dfitzjarrell @ 15:42

"“You see,” he continued, beginning to feel better, “once there was no time at all, and people found it very inconvenient.
They never knew whether they were eating lunch or dinner, and they were always missing trains. So time was invented to
help them keep track of the day and get places when they should. When they began to count all the time that was available,
what with 60 seconds in a minute and 60 minutes in an hour and 24 hours in a day and 365 days in a year, it seemed as if
there was much more than could ever be used. ‘If there’s so much of it, it couldn’t be very valuable,’ was the general
opinion, and it soon fell into disrepute. People wasted it and even gave it away. Then we were given the job of seeing
that no one wasted time again,” he said, sitting up proudly.” 
-- Norton Juster, The Phantom Tollbooth

DBAs usually get questions on query performance when one runs slower than the user would like and. as a result, questions on how best to go about tuning a query soon follow. End-users usually don’t like waiting for results and queries that take longer than a few seconds tend to be considered as suspect. What many end-users don’t know is that query tuning is a combination of art, science and (gasp) intuition. Elegant tuning solutions are art, based on science, and that science uses two of Oracle’s events, 10046 and 10053, to provoide more detailed information. Which one is more beneficial depends on the query and the ‘bad’ execution plan. A 10046 trace can show what Oracle is waiting on and where time is being spent in the execution phase of running a query. Sometimes, however, the waits and elapsed time breakdowns aren’t enough, which is where the 10053 trace can be extremely helpful. Note that this post takes one particular situation and gives abbreviated steps in solving it; it’s not meant to be a treatise on the subject nor a detailed case study. With that in mind let’s look at a plan where that event can provide much-needed information.

Queries using nested subqueries can take a number of paths to return data; one possibility involves what Oracle calls ‘subquery unnesting’, a process where Oracle re-writes the nested query into an unnested join with the intent that this will improve data access and thus query performance. This can be done for several nested subqueries, resulting in one or more NESTED LOOP joins in the execution plan. This is where the road can take a less than desirable turn; joins consume time, making the query execution longer than it probably should be. If the query in question is a ‘one-off’, run once, maybe twice in a day, this may not be a real problem as a few seconds here and there won’t throw off the regular day’s work. If, on the other hand, this is a regularly run statement, the longer run times can stack up on each other and cause delays in processing, and, as the old addage states: “Time is money.” Since the query plan won’t give details on how Oracle eventually generated it one course of action is setting the 10053 event in the current session and executing the problem statement.

The first step in tuning is to obtain the current execution plan and see if it makes ‘sense’. A query with joins will likely produce NESTED LOOP JOIN or HASH JOIN steps. In this case the plan produced a NESTED LOOPS SEMI step that, on the face of it, made no sense as the query contained no join conditions as originally written. This could be a clue that the optimizer did something different and posibly unexpected with the plan. That is exactly what prompted this investigation which used a 10053 event trace to ‘track down’ what the optimizer chose to do. This, in turn, caused a slight rewrite of the query to include the necessary hints to ‘nudge’ the optimizer toward a more efficient plan.

Setting event 10053 is not a difficult task; let’s look at a script that does this and then executes several SELECT statements before turning the 10053 ‘switch’ off (unfortunately the actual queries can’t be published as they are proprietary so placeholders will be used):

alter session set tracefile_identifier='MAILQUEUE';
alter session set events = '10053 trace name context forever, level 2';

[First query statement here]

[Second query statement here]

[Third query statement here]

[Fourth query statement here]

alter system set events = '10053 trace name context off';

The important parts of the above example are the lines prior to any query statements, which turn on the 10053 event and set a trace file identifier so the generated trace file can be easily identified, and the statement after the queries have run, which stops the 10053 event. Unlike the 10046 event, which is more easily read after processing through the tkprof utility, the 10053 trace file needs no additional work. It can be a bit daunting at first since it’s like no other trace file most DBAs have seen. Let’s go through the example, using the actual trace file generated by the unobfuscated script, and see what it reveals.

The beginning of the trace file provides some basic information on the environment and provides query ‘signatures’ that the optimizer uses to identify query and subquery blocks:

Trace file ....
Oracle Database 12c Enterprise Edition Release - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
System name:	SunOS
Node name:	...
Release:	5.10
Version:	Generic_150400-61
Machine:	sun4v
Instance name: ...
Redo thread mounted by this instance: 1
Oracle process number: 1134
Unix process pid: 22631, image: oracle@... (TNS V1-V3)

Query Block Registry:
SEL$2 0x77a10ca0 (PARSER)
  SEL$F5BB74E1 0x77a198b0 (VIEW MERGE SEL$1; SEL$2) [FINAL]
SEL$1 0x77a198b0 (PARSER)
  SEL$F5BB74E1 0x77a198b0 (VIEW MERGE SEL$1; SEL$2) [FINAL]

    call(in-use=12456, alloc=347568), compile(in-use=95008, alloc=158520), execution(in-use=15312, alloc=16200)

End of Optimizer State Dump
Dumping Hints
====================== END SQL Statement Dump ======================
*** SESSION ID:(758.2581) 2018-08-21 09:40:23.286
Registered qb: SEL$1 0x77a198b0 (PARSER)
  signature (): qb_name=SEL$1 nbfros=1 flg=0
    fro(0): flg=4 objn=68513 hint_alias="DQ"@"SEL$1"

Registered qb: SEL$2 0x7751be68 (PARSER)
  signature (): qb_name=SEL$2 nbfros=1 flg=0
    fro(0): flg=4 objn=69663 hint_alias="WPV"@"SEL$2"

Registered qb: SEL$3 0x7751b188 (PARSER)
  signature (): qb_name=SEL$3 nbfros=1 flg=0
    fro(0): flg=4 objn=10290765 hint_alias="MRE"@"SEL$3"

SPM: statement not found in SMB
SPM: capture of plan baseline is OFF

This begins the portion of the trace file of interest, including the query [not posted due to confidentiality concerns] and the legend of abbreviations:

Automatic degree of parallelism (AUTODOP)
Automatic degree of parallelism is disabled: Parameter.
kkopqSetForceParallelProperties: Hint:no
Query: compute:yes forced:no forceDop:0
kkopqSetDopReason: Reason why we chose this DOP is: table property.
table property forces parallelism

Global Manual DOP: 1 - Rounded?: no
PM: Considering predicate move-around in query block SEL$1 (#0)
Predicate Move-Around (PM)

----- Current SQL Statement for this session (sql_id=*************) -----
[ Removed for confidentiality reasons ]
The following abbreviations are used by optimizer trace.
CBQT - cost-based query transformation
JPPD - join predicate push-down
OJPPD - old-style (non-cost-based) JPPD
FPD - filter push-down
PM - predicate move-around
CVM - complex view merging
SPJ - select-project-join
SJC - set join conversion
SU - subquery unnesting
OBYE - order by elimination
OST - old style star transformation
ST - new (cbqt) star transformation
CNT - count(col) to count(*) transformation
JE - Join Elimination
JF - join factorization
CBY - connect by
SLP - select list pruning
DP - distinct placement
VT - vector transformation
qb - query block
LB - leaf blocks
DK - distinct keys
LB/K - average number of leaf blocks per key
DB/K - average number of data blocks per key
CLUF - clustering factor
NDV - number of distinct values
Resp - response cost
Card - cardinality
Resc - resource cost
NL - nested loops (join)
SM - sort merge (join)
HA - hash (join)
IOTFRSPEED - I/O transfer speed
IOSEEKTIM - I/O seek time
SREADTIM - average single block read time
MREADTIM - average multiblock read time
MBRC - average multiblock read count
MAXTHR - maximum I/O system throughput
SLAVETHR - average slave I/O throughput
dmeth - distribution method
  1: no partitioning required
  2: value partitioned
  4: right is random (round-robin)
  128: left is random (round-robin)
  8: broadcast right and partition left
  16: broadcast left and partition right
  32: partition left using partitioning of right
  64: partition right using partitioning of left
  256: run the join in serial
  0: invalid distribution method
sel - selectivity
ptn - partition
AP - adaptive plans

Other areas of the trace file provide environment information that is not necessary for this discussion. Because the execution plan includes a NESTED LOOPS SEMI step the reason for this should be ascertained since the original query had no join conditions. Looking through the trace file doesn’t reveal anything that looks unusual to the modestly trained eye until the section provided below is examined. Searching through the trace file for indications of join activity allowed the DBA to eventually ‘zero in’ on the offending optimizer step. Subquery unnesting isn’t uaually an issue, but in this case it involved two similar nested subqueries that Oracle thought would perform better as joins. Unfortunately this optimizer decision ended up as the more costly alternative:

Cost-Based Subquery Unnesting
SU: Unnesting query blocks in query block SEL$1 (#1) that are valid to unnest.
Subquery removal for query block SEL$3 (#3)
RSW: Not valid for subquery removal SEL$3 (#3)
Subquery unchanged.
Subquery Unnesting on query block SEL$2 (#2)SU: Performing unnesting that does not require costing.
SU: Considering subquery unnest on query block SEL$2 (#2).
SU:   Checking validity of unnesting subquery SEL$3 (#3)
SU:   Passed validity checks.
SU:   Transforming ANY subquery to a join.
Registered qb: SEL$BE5C8E5F 0x755990f8 (SUBQUERY UNNEST SEL$2; SEL$3)

The query unnesting results in performance degradation because Oracle now must process a nested loop join; hinting the subqueries altered the nested loops path into two filter operations, speeding up the execution time considerably. Having this information allows the DBA to use the proper hint (no_unnest) on each of the nested subqueries to eliminate this behavior.

Sometimes query tuning can require a considerable amount of time, especially when searching a trace file for a cause with little more than an execution plan and the fact that the plan doesn’t match how the query was constructed. Even DBAs experienced with the oddities of the optimizer may miss the cause when it’s buried in a section that doesn’t appear to apply at first glance.

No post on any aspect of query tuning can provide an absolute, foolproof method for improving performance. There are simply too many variables and too many optimizer possibilities to consider. Hopefully this post has provided a starting point for query and statement tuning; remember that each query is different and that performance tuning is statement-specific. Consider each query on its own and major improvements may not be guaranteed, but sometimes even the smallest change can produce measurable results.

Only time will tell.


Blog at