Once again: why guess when you can know?

I recently was asked to review a bit of SQL that was performing poorly. By poorly I mean that a single execution of the query may take hours to complete (that's pretty poor). The SQL was quite simple:

SELECT ph.cust_bus_nm
     , ph.clup_fmt1
     , ph.batch_period_month_yr_dt
     , ph.batch_sys_id
     , ph.our_prem_amt
     , ph.liab_amt
     , ph.code
     , ph.pol_effect_dt
     , ph.pol_nbr
     , ph.agent_prem_amt
     , ph.uw_sys_id
     , ph.cost_cntr_sys_id
     , ph.state_cd
     , ph.loc_rep_sys_id
     , ph.cust_sys_id
     , ph.clup_sys_id
     , ph.item_type
     , NVL(ph.pol_type_cd, p.pol_type_cd) AS pol_type_cd
     , ph.acct_period_month_yr_dt
     , ph.hist_rev_ind
     , ph.validation_dts
  FROM tr_pol_h_endr_h_v ph 
             INNER JOIN tr_policy p ON ph.pol_sys_id = p.pol_sys_id
 WHERE ph.liab_amt >= 2500000
   AND TRUNC(ph.acct_period_month_yr_dt) BETWEEN TO_DATE ('200902', 'YYYYMM') AND TO_DATE ('200902', 'YYYYMM')                                    
   AND DECODE (0
             , 0, ph.uw_sys_id
             , 0) = ph.uw_sys_id
   AND DECODE (0
             , 0, ph.cost_cntr_sys_id
             , 0) = ph.cost_cntr_sys_id
   AND DECODE ('ALL'
             , 'ALL', ph.state_cd
             , 'ALL') = ph.state_cd
   AND DECODE (0
             , 0, NVL (ph.loc_rep_sys_id, 0)
             , 0) = NVL (ph.loc_rep_sys_id, 0)
   AND DECODE (0
             , 0, ph.cust_sys_id
             , 0) = ph.cust_sys_id
   AND DECODE (0
             , 0, ph.clup_sys_id
             , 0) = ph.clup_sys_id
/

Note that the DECODEs look a bit odd but are there to accommodate how Crystal Reports has to handle (or doesn't handle well) variables. That wasn't really part of the problem.

The query used a view (tr_pol_h_endr_h_v) so I started by reviewing the view source. In the view source I found a few things that were suspect.
1) The view source included a join between tr_policy_history (alias pol_hist) and tr_policy (note that these tables are both 70 million+ rows each and are growing in size). This is the table being joined to the view in the offending SQL. As a matter of fact, the view source join was identical to the join in the SQL (INNER JOIN tr_policy p ON (pol_hist.pol_sys_id = p.pol_sys_id).
2) The view source defined the acct_period_month_yr_dt column as TRUNC(pol_hist.acct_period_month_yr_dt). There was a function-based index on TRUNC(pol_hist.acct_period_month_yr_dt).
3) The execution plan indicated a full scan using a filter on acct_period_month_yr_dt was occurring on the pol_hist table even though the FBI was in place.

Here's where I question whether this was an oversight or just a lack of understanding.

First, since the view source accesses the tr_policy table, why not perform the NVL check on pol_hist.pol_type_cd in the view source? Why join back to tr_policy again in the SQL that uses the view to make the NVL check?

Next, the view source uses TRUNC(pol_hist.acct_period_month_yr_dt) to create the column acct_period_month_yr_dt. But, in the SQL statement, the coder used TRUNC again. Why? By using it again, the effect is like writing TRUNC(TRUNC(acct_period_month_yr_dt). Since the function-based index is based on the expression using a single TRUNC() function, the index is ignored for use since the expressions don't match.

So, what to do?

Change the view source to execute NVL(pol_hist.pol_type_cd, p.pol_type_cd) AS pol_type_cd. Then, change the SQL as follows:

SELECT ph.cust_bus_nm
     , ph.clup_fmt1
     , ph.batch_period_month_yr_dt
     , ph.batch_sys_id
     , ph.our_prem_amt
     , ph.liab_amt
     , ph.code
     , ph.pol_effect_dt
     , ph.pol_nbr
     , ph.agent_prem_amt
     , ph.uw_sys_id
     , ph.cost_cntr_sys_id
     , ph.state_cd
     , ph.loc_rep_sys_id
     , ph.cust_sys_id
     , ph.clup_sys_id
     , ph.item_type
     , ph.pol_type_cd
     , ph.acct_period_month_yr_dt
     , ph.hist_rev_ind
     , ph.validation_dts
  FROM tr_pol_h_endr_h_v ph 
 WHERE ph.liab_amt >= 2500000
   AND ph.acct_period_month_yr_dt BETWEEN TO_DATE ('200902', 'YYYYMM') AND TO_DATE ('200902', 'YYYYMM')                                    
   AND DECODE (0
             , 0, ph.uw_sys_id
             , 0) = ph.uw_sys_id
   AND DECODE (0
             , 0, ph.cost_cntr_sys_id
             , 0) = ph.cost_cntr_sys_id
   AND DECODE ('ALL'
             , 'ALL', ph.state_cd
             , 'ALL') = ph.state_cd
   AND DECODE (0
             , 0, NVL (ph.loc_rep_sys_id, 0)
             , 0) = NVL (ph.loc_rep_sys_id, 0)
   AND DECODE (0
             , 0, ph.cust_sys_id
             , 0) = ph.cust_sys_id
   AND DECODE (0
             , 0, ph.clup_sys_id
             , 0) = ph.clup_sys_id
/

I also added the liab_amt column to the FBI so that both conditions could be satisfied/matched in the index to eliminate a TABLE ACCESS to filter on liab_amt.

The result was execution times that fell into the 4-6 second range. From hours to seconds. Not bad.

But, I really wonder how something so simple was overlooked for so long. Apparently, this query had been on the top of the "bad SQL" list for ages and multiple attempts had been made to optimize it. But, within just a few minutes, I noted the issues and was able to recommend the fix. I don't think the fix was that hard but it seemed to be a stumper for some time. Why?

I think it may have been both a bit of oversight and a bit of lack of understanding. The oversight was in accessing a table (tr_policy) twice. Mantra => Never do anything more than absolutely necessary.

It may have also been oversight that the FBI wasn't getting used. But for that one, I'm going to point the finger at lack of understanding. The expression in the index definition must match the expression in the SQL. I don't think the coder realized that when the view source used TRUNC, that was all that was needed. And, I think that the reason nobody caught it was that nobody was looking at an actual execution plan for the query. They may have either only been looking at an explain plan (which may have shown an index use???) or they didn't look at a plan at all and just assumed the index was in use (this is what I think is most likely).

So, the moral of the story once again is: why guess when you can know? I haven't included the tests I conducted here for the sake of brevity (well OK... this post is not short, but it could've been a lot longer!), but with the test data and actual execution plan information in front of me, this one seemed quite easy. Guessing at the problem and possible solutions had allowed an easy fix to be overlooked for months. With good data, the problem was quite obvious and the solution easy to implement.

Repeat after me: why guess when you can know?!

Strange parsing behavior

My friend Jan is cool. He sends me lots of neat SQL performance issues he's working on so I canto take a look at. I love it when I get to see performance problems get fixed and have the before/after data to show the differences. Like I said, Jan is cool and sends me lots of good stuff like this.

What he sent me yesterday was interesting because I'd never seen it before. The query that was having problems was a UNION of 30 or so different SELECTs. Many of the SELECTs were similar except for the WHERE clause. Here's what Jan said in his email to me:

[Jan]
Now the fun thing is to follow it during execution. This seems to be happening:

-- parse whole query => v$sql shows sql_id child_number 0
-- start parallel slaves for
-- parallel slaves do work
-- when done, parallel slaves for this part of query wait: 'PX Deq: Execution Msg'
...
-- start new set of parallel slaves for
-- slaves wait 'cursor: pin S wait on X'
-- Query coordinator shows wait: 'PX Deq: Parse Reply' => v$sql shows sql_id child_number 1
-- parallel slaves do work
-- when done, parallel slaves for this part of query wait: 'PX Deq: Execution Msg'
...
-- start new set of parallel slaves for
-- slaves wait 'cursor: pin S wait on X'
-- Query coordinator shows wait: 'PX Deq: Parse Reply' => v$sql shows sql_id child_number 2
-- parallel slaves do work
-- when done, parallel slaves for this part of query wait: 'PX Deq: Execution Msg'
etc, etc

By the time the whole query is done we have child_number 0..30, and about 360 sessions because of all the parallel slaves!

Weirdest part is the 'cursor: pin S wait on X' plus 'PX Deq: Parse Reply' waits, they take > 8 seconds every time! Why would it parse over and over again???

When I start the query a second time, it's way faster, since those parsing waits don't happen (if the plan's still there):
First time: Selected 109 records in 712.485 Secs
Second time: Selected 109 records in 142.829 Secs
[/Jan]

The two things about this that interested me where the cursor: pin S wait on X events and the parsing waits. I had just seen the 'pin S' timed event the day before while reviewing a trace file with another customer. I find it funny how I'll often see 2 or 3 of the same kind of error in a short time frame. I guess it really is true that things happen in multiples, huh? Anyway, the 'pin S' events are related to mutex pinning issues. Admittedly, I didn't know much about that until the issue I researched the day before. Here's what I learned:

The timed event for 'cursor: pin S wait on X' (I'm just going to call this pinS for short from now on) is an event that started in occurring in v10 when Oracle added mutex pins into the scheme in addition to latches. Basically, a mutex is kind of like a latch, but just a simpler, faster version. When you get the pinS wait, it's caused by a session holding an exclusive mutex pin on a cursor for which another session wishes to get a shared mutex pin on the same cursor object. From the looks of things with your big UNION query and all the parallel slave processes, that makes sense. The p1-p3 values give you some info:

P1 Hash value of cursor
P2 Mutex value (top 2 bytes contains SID holding mutex in exclusive mode, and bottom two bytes usually hold the value 0)
P3 Mutex where (an internal code locator) OR'd with Mutex Sleeps

and there are a few dynamic system views that provide more information about this timed event: V$MUTEX_SLEEP and V$MUTEX_SLEEP_HISTORY. You just have to check those views while the problem is occurring to get the additional info.

There's not a whole lot of data on this floating around out there, but I found some interesting info from Tanel Poder and Jonathan Lewis that helped.

Anyway, the second issue was the PX Deq: Parse Reply waits. I was wondering why all the parsing was going on and guessing that if the parsing issue was resolved, that would also reduce or eliminate the pinS waits as well.

I wrote back to Jan about the small bit I knew and told him I thought that rewriting the query to combine several of the separate SELECTs together would likely help the problem. At a quick glance, there were 18 of the SELECTs that shared the same FROM clause and join conditions.

Today I did a bit more research to check out the 'PX Deq: Parse Reply' and came across a great write up at Doug Burn's blog about Parallel-specific wait events (the whole article starts here). Good stuff...check it out.

Then, just a few minutes ago, Jan sent me the update on how he was progressing.

[Jan]
After some more digging this is where we get multiple children (simplified case, I'm sure you can simulate it):

 
select /*+ test */ appln_jrnl_id, sum(payment_count) from fihub.tbl_voucher_acct_line  d
where appln_jrnl_id   = 'AP_PAYMENT'
and   fiscal_year_num = 2008
and   acct_period_cd  = 5
group by appln_jrnl_id
union
select /*+ test */ 'AP_PAYMENT', sum(payment_count) from fihub.tbl_voucher_acct_line  d
where appln_jrnl_id   = 'AP_PAYMENT'
and   fiscal_year_num = 2008
and   acct_period_cd  = 5;

BTW, this table is partitioned, so it's using parallelism.

The original query had mostly group by's. But there where a few SUMs without group by's. That's what is causing the trouble. v$sql_shared_cursor says it's because of a PQ_SLAVE_MISMATCH. When running serially it doesn't happen. After rewriting the troubling parts to do a group by, it's back to normal. After a total rewrite, the query is much faster.
[/Jan]

Again, I love stuff like this. I thought it would be an interesting case to share.

Thanks Jan!

Analytics to the rescue

I see a lot of SQL. Actually, I see a lot of bad SQL. I guess that's because my job is mainly to help people with performance problems and the majority of the time, the problems are rooted in one or more inefficient SQL statements. Yesterday I was doing a demo of our Profiler software and showed one case that I see over and over, so I thought I'd share it here.

I have a profile for a 4 hour and 44 minute trace of an application process that was taking too long. The top 3 events in the profile (accounting for 82% of the total overall response time) were:

CPU service, FETCH calls  8,357.40s (48.9%)
db file scattered read    3,075.95s (18.0%)
db file sequential read   2,577.67s (15.1%)

The SQL statement that topped the list taking 12,695.90s (74.3% of the total response time) was:

select utrsotp_desc
from utrsotp, ucbsvco
where ucbsvco_sotp_code = utrsotp_code
and ucbsvco_dispatch_date =
  (select max(ucbsvco_dispatch_date)
     from ucbsvco
    where ucbsvco_cust_code = :b1
      and ucbsvco_prem_code = :b2
      and ucbsvco_stus_code = 'C'
      and ucbsvco_dispatch_ind is not null)
and ucbsvco_stus_code = 'C'
and ucbsvco_dispatch_ind is not null;

Given the fact that this one statement accounted for 74% of the overall response time, with a quick look at the rest of the profile, you could see that this one query was responsible for almost all the response time consumed by the top 3 events in the profile. So, the cool thing about this profile is that it was easy to see that by fixing one SQL statement, we'd basically get rid of our dominant problem.

Now, a bit more info. This statement was executed 1,332 times during the almost 5 hour period captured by the trace. The query returned only 587 rows and did a total of 141,084,499 block accesses (LIOs). That means that on average it took almost 160,000 LIOs for each execution. Ummm...that's not good. It should be using something like 20 LIOs or less per row (based on a maximum tolerance of no more than 10 LIOs per joined table per row).

It kinda seems obvious that there's a big problem with this query doesn't it? So, why had this process been running for so long without someone catching it? I mean, if we could fix this one statement, we could cause as much as a 74% reduction in response time. That means the 4 hr and 44 minute process could drop down to about 1 hour and 15 minutes.

But the problem was in the way the code was being reviewed on the test instance. First, (mistake 1) only EXPLAIN PLAN was used to review the anticipated plan for the SQL and (mistake 2) the SQL was executed to make sure the response time (for a single execution), seemed reasonable. Another thing worth noting is (mistake 3) that the test instance had only about 10% of the volume of data as production, so virtually anything that was executed took only a second or so due to the lack of volume. So, the response time never was really noted as an issue because it always ran fast. The EXPLAIN PLAN didn't really rasie any eyebrows either because it looked like this:

--------------------------------------------------------------------------------------
| Id  | Operation                      |  Name               | Rows  | Bytes | Cost  |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                     |     1 |    38 |  1768 |
|   1 |  NESTED LOOPS                  |                     |     1 |    38 |  1768 |
|   2 |   TABLE ACCESS FULL            | UCBSVCO             |     1 |    12 |  1767 |
|   3 |    SORT AGGREGATE              |                     |     1 |    20 |       |
|   4 |     TABLE ACCESS BY INDEX ROWID| UCBSVCO             |     1 |    20 |     1 |
|   5 |      INDEX RANGE SCAN          | UCBSVCO_CUST_INDEX  |     8 |       |     1 |
|   6 |   TABLE ACCESS BY INDEX ROWID  | UTRSOTP             |     1 |    26 |     1 |
|   7 |    INDEX UNIQUE SCAN           | UTRSOTP_KEY_INDEX   |     1 |       |       |
--------------------------------------------------------------------------------------

Now, the TABLE ACCESS FULL step might have raised a few eyebrows, but since they saw Rows = 1 at that step, they figured it shouldn't be a problem. I mean, hey, if there's only going to be one row pulled from the table, they thought, how bad could it be? (Remember that they were seeing sub-second response times in test.)

But, once I was able to point out the combined effect of executing that SQL over 1300 times in their production, full volume environment, the problem was (all of a sudden) easy to see. Something needed to be done to make this SQL statement more efficient.

As I mentioned when I first started this post, I see SQL statements similar to this one over and over again. They are very typical in that lots of apps use tables that store both historical and current info in them. For instance, imagine that if you wanted to get the latest price from a product table that stored each price in a separate product row with an effective date column value used to indicate the date the price was put into effect. In order to do that, you'd have to make sure you retrieved the row which had the MAX effective date for that product. The way the query is most commonly formulated to do this is with this WHERE clause:

WHERE price_eff_dt = (SELECT MAX(price_eff_dt) FROM product_tab WHERE product_id = outer.product_id)

This is exactly what was going on in the problem query in this process.

Analytics to the rescue! By using an analytic MAX function instead, Oracle is able to make a single pass over the data to get the answer it needs. Here's the query rewritten to use an analytic MAX function instead:

select utrsotp_desc
 from utrsotp,
      (select ucbsvco_sotp_code sotp_cd, ucbsvco_dispatch_date dispatch_dt,
              max(ucbsvco_dispatch_date) over (partition by ucbsvco_cust_code,
      ucbsvco_prem_code) max_dispatch_dt
         from ucbsvco
        where ucbsvco_cust_code = :b1
          and ucbsvco_prem_code = :b2
          and ucbsvco_stus_code = 'C'
          and ucbsvco_dispatch_ind is not null) svco
where svco.dispatch_dt = svco.max_dispatch_dt
  and svco.sotp_cd = utrsotp_code;

The plan for this query was:

--------------------------------------------------------------------------------------
| Id  | Operation                      |  Name               | Rows  | Bytes | Cost  |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                     |     1 |    48 |     4 |
|   1 |  NESTED LOOPS                  |                     |     1 |    48 |     4 |
|*  2 |   VIEW                         |                     |     1 |    22 |     3 |
|   3 |    WINDOW BUFFER               |                     |     1 |    25 |     3 |
|*  4 |     TABLE ACCESS BY INDEX ROWID| UCBSVCO             |     1 |    25 |     1 |
|*  5 |      INDEX RANGE SCAN          | UCBSVCO_CUST_INDEX  |     8 |       |     1 |
|   6 |   TABLE ACCESS BY INDEX ROWID  | UTRSOTP             |     1 |    26 |     1 |
|*  7 |    INDEX UNIQUE SCAN           | UTRSOTP_KEY_INDEX   |     1 |       |       |
--------------------------------------------------------------------------------------

Tests of the two queries on a full volume data source (for a single set of bind values expected to return 1 row), had the following results:
Original query
160,693 LIOs
20.16s

New query
15 LIOs
.18s

That's a 99%+ reduction in LIOs and response time. Not bad, huh? :)

Simple change, massive difference. I didn't get to stay around long enough on the client site to see the fix implemented in production, but the expected benefit would mean, as mentioned above, that the response time should drop down from nearly 5 hours to just over 1 hour. Nice.

So, I'm always glad to see examples like this one pop up when I'm helping a customer with performance issues. The analytic function is a nice alternative to the traditional way of writing these types of queries that works extremely well and provides the performance needed for high numbers of executions in a high data volume environment.