Showing posts with label Oracle analytic functions. Show all posts
Showing posts with label Oracle analytic functions. Show all posts

Thursday, July 17, 2008

Analytics to the rescue - followup

I thought I'd do a follow-up post to yesterday's "Analytics to the rescue" post as the discussion in the comments brought up a couple of things that needed more info than could be easily included in the comment section. So...

What you'll see below is a more complete text of the tests I executed that were discussed in yesterday's post. First, the original query, then for the rewritten query. What I show for each is the actual STAT lines from the 10046 trace data, the EXPLAIN PLAN and some additional stats (collected with a SQL test harness set of scripts I use).

Test for original query

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 = 1320908
and ucbsvco_prem_code = '507601'
and ucbsvco_stus_code = 'C'
and ucbsvco_dispatch_ind is not null)
and ucbsvco_stus_code = 'C'
and ucbsvco_dispatch_ind is not null


STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=106693 r=59924 w=0 time=19518419 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=74130 op='TABLE ACCESS FULL UCBSVCO (cr=106691 r=59924 w=0 time=19518381 us)'
STAT #3 id=3 cnt=1 pid=2 pos=2 obj=0 op='SORT AGGREGATE (cr=13 r=0 w=0 time=145 us)'
STAT #3 id=4 cnt=2 pid=3 pos=1 obj=74130 op='TABLE ACCESS BY INDEX ROWID UCBSVCO (cr=13 r=0 w=0 time=138 us)'
STAT #3 id=5 cnt=9 pid=4 pos=1 obj=82187 op='INDEX RANGE SCAN UCBSVCO_CUST_INDEX (cr=3 r=0 w=0 time=45 us)'
STAT #3 id=6 cnt=1 pid=1 pos=2 obj=74368 op='TABLE ACCESS BY INDEX ROWID UTRSOTP (cr=2 r=0 w=0 time=22 us)'
STAT #3 id=7 cnt=1 pid=6 pos=1 obj=81903 op='INDEX UNIQUE SCAN UTRSOTP_KEY_INDEX (cr=1 r=0 w=0 time=12 us)'


Explain Plan
--------------------------------------------------------------------------------------
| 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 | | |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - filter("UCBSVCO"."UCBSVCO_STUS_CODE"='C' AND "UCBSVCO"."UCBSVCO_DISPATCH_IND"
IS NOT NULL AND "UCBSVCO"."UCBSVCO_DISPATCH_DATE"= (SELECT /*+ */
MAX("UCBSVCO"."UCBSVCO_DISPATCH_DATE") FROM "UIMSMGR"."UCBSVCO" "UCBSVCO" WHERE
"UCBSVCO"."UCBSVCO_CUST_CODE"=1320908 AND "UCBSVCO"."UCBSVCO_PREM_CODE"='507601' AND
"UCBSVCO"."UCBSVCO_STUS_CODE"='C' AND "UCBSVCO"."UCBSVCO_DISPATCH_IND" IS NOT NULL))
4 - filter("UCBSVCO"."UCBSVCO_PREM_CODE"='507601' AND
"UCBSVCO"."UCBSVCO_STUS_CODE"='C' AND "UCBSVCO"."UCBSVCO_DISPATCH_IND" IS NOT NULL)
5 - access("UCBSVCO"."UCBSVCO_CUST_CODE"=1320908)
7 - access("UCBSVCO"."UCBSVCO_SOTP_CODE"="UTRSOTP"."UTRSOTP_CODE")


Statistics Snapshot

Type Statistic Name Value
----- ---------------------------------------- --------------
Latch cache buffers chains 2,142,103
library cache 116,725
row cache objects 19,592

Stats buffer is pinned count 8
consistent gets 106,693
db block gets 56
execute count 16
parse count (hard) 1
physical reads 59,924
physical writes 0
redo size 9,524
session logical reads 106,749
session pga memory 594,008
session pga memory max 0
sorts (disk) 0
sorts (memory) 0
sorts (rows) 0
table fetch by rowid 10
table scan blocks gotten 106,669

Time elapsed time (centiseconds) 2,016



Test for rewritten query

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 = 1320908
and ucbsvco_prem_code = '507601'
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


STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=15 r=0 w=0 time=249 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=0 op='VIEW (cr=13 r=0 w=0 time=228 us)'
STAT #3 id=3 cnt=2 pid=2 pos=1 obj=0 op='WINDOW BUFFER (cr=13 r=0 w=0 time=218 us)'
STAT #3 id=4 cnt=2 pid=3 pos=1 obj=74130 op='TABLE ACCESS BY INDEX ROWID UCBSVCO (cr=13 r=0 w=0 time=145 us)'
STAT #3 id=5 cnt=9 pid=4 pos=1 obj=82187 op='INDEX RANGE SCAN UCBSVCO_CUST_INDEX (cr=3 r=0 w=0 time=37 us)'
STAT #3 id=6 cnt=1 pid=1 pos=2 obj=74368 op='TABLE ACCESS BY INDEX ROWID UTRSOTP (cr=2 r=0 w=0 time=16 us)'
STAT #3 id=7 cnt=1 pid=6 pos=1 obj=81903 op='INDEX UNIQUE SCAN UTRSOTP_KEY_INDEX (cr=1 r=0 w=0 time=9 us)'


Explain Plan
--------------------------------------------------------------------------------------
| 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 | | |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - filter("SVCO"."DISPATCH_DT"="SVCO"."MAX_DISPATCH_DT")
4 - filter("UCBSVCO"."UCBSVCO_PREM_CODE"='507601' AND
"UCBSVCO"."UCBSVCO_STUS_CODE"='C' AND "UCBSVCO"."UCBSVCO_DISPATCH_IND" IS NOT NULL)
5 - access("UCBSVCO"."UCBSVCO_CUST_CODE"=1320908)
7 - access("SVCO"."SOTP_CD"="UTRSOTP"."UTRSOTP_CODE")


Statistics Snapshot

Type Statistic Name Value
----- ---------------------------------------- --------------
Latch cache buffers chains 9,098
library cache 3,608
row cache objects 370

Stats buffer is pinned count 8
consistent gets 15
db block gets 53
execute count 15
parse count (hard) 1
physical reads 0
physical writes 0
redo size 9,008
session logical reads 68
session pga memory 0
session pga memory max 0
sorts (disk) 0
sorts (memory) 1
sorts (rows) 2
table fetch by rowid 10
table scan blocks gotten 0

Time elapsed time (centiseconds) 18


Difference Report

TYPE NAME original rewrite DIFFERENCE
----- --------------------------------------- --------------- --------------- ---------------
Latch cache buffers chains 2142103 9098 2133005
library cache 116725 3608 113117
row cache objects 19592 370 19222

Stats buffer is pinned count 8 8 0
consistent gets 106693 15 106678
db block gets 56 53 3
execute count 16 15 1
parse count (hard) 1 1 0
physical reads 59924 0 59924
physical writes 0 0 0
redo size 9524 9008 516
session logical reads 106749 68 106681
session pga memory 594008 0 594008
session pga memory max 0 0 0
sorts (disk) 0 0 0
sorts (memory) 0 1 -1
sorts (rows) 0 2 -2
table fetch by rowid 10 10 0
table scan blocks gotten 106669 0 106669


Time elapsed time (centiseconds) 2016 18 1998


Original

STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=106693 r=59924 w=0 time=19518419 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=74130 op='TABLE ACCESS FULL UCBSVCO (cr=106691 r=59924 w=0 time=19518381 us)'
STAT #3 id=3 cnt=1 pid=2 pos=2 obj=0 op='SORT AGGREGATE (cr=13 r=0 w=0 time=145 us)'
STAT #3 id=4 cnt=2 pid=3 pos=1 obj=74130 op='TABLE ACCESS BY INDEX ROWID UCBSVCO (cr=13 r=0 w=0 time=138 us)'
STAT #3 id=5 cnt=9 pid=4 pos=1 obj=82187 op='INDEX RANGE SCAN UCBSVCO_CUST_INDEX (cr=3 r=0 w=0 time=45 us)'
STAT #3 id=6 cnt=1 pid=1 pos=2 obj=74368 op='TABLE ACCESS BY INDEX ROWID UTRSOTP (cr=2 r=0 w=0 time=22 us)'
STAT #3 id=7 cnt=1 pid=6 pos=1 obj=81903 op='INDEX UNIQUE SCAN UTRSOTP_KEY_INDEX (cr=1 r=0 w=0 time=12 us)'


Rewrite

STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=15 r=0 w=0 time=249 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=0 op='VIEW (cr=13 r=0 w=0 time=228 us)'
STAT #3 id=3 cnt=2 pid=2 pos=1 obj=0 op='WINDOW BUFFER (cr=13 r=0 w=0 time=218 us)'
STAT #3 id=4 cnt=2 pid=3 pos=1 obj=74130 op='TABLE ACCESS BY INDEX ROWID UCBSVCO (cr=13 r=0 w=0 time=145 us)'
STAT #3 id=5 cnt=9 pid=4 pos=1 obj=82187 op='INDEX RANGE SCAN UCBSVCO_CUST_INDEX (cr=3 r=0 w=0 time=37 us)'
STAT #3 id=6 cnt=1 pid=1 pos=2 obj=74368 op='TABLE ACCESS BY INDEX ROWID UTRSOTP (cr=2 r=0 w=0 time=16 us)'
STAT #3 id=7 cnt=1 pid=6 pos=1 obj=81903 op='INDEX UNIQUE SCAN UTRSOTP_KEY_INDEX (cr=1 r=0 w=0 time=9 us)'


In the original query, there was some question as to whether or not the SELECT MAX() was happening for each row. I had not included the predicate information section for the EXPLAIN PLAN which would have cleared this up. Note the filter on line 2 of the plan for the full table scan.

2 - filter("UCBSVCO"."UCBSVCO_STUS_CODE"='C' AND
"UCBSVCO"."UCBSVCO_DISPATCH_IND" IS NOT NULL AND
"UCBSVCO"."UCBSVCO_DISPATCH_DATE"=
(SELECT /*+ */ MAX("UCBSVCO"."UCBSVCO_DISPATCH_DATE")
FROM "UIMSMGR"."UCBSVCO" "UCBSVCO"
WHERE "UCBSVCO"."UCBSVCO_CUST_CODE"=1320908
AND "UCBSVCO"."UCBSVCO_PREM_CODE"='507601'
AND "UCBSVCO"."UCBSVCO_STUS_CODE"='C'
AND "UCBSVCO"."UCBSVCO_DISPATCH_IND" IS NOT NULL))


The SELECT MAX query is part of the filter on this step. That means that it will get executed once for every row that is examined. One thing to note is that it is most likely that there will be subquery caching that occurs since the MAX query remains the same. In other words, the MAX query will be executed once and the answer stored in a cached array so that it really won't get executed every time, only when the inputs are new. And, in this case, the inputs are always the same so the answer will be retrieved from cache on every check except for the first one. I've got a really good example of how subquery caching works that I'll post on another day. :)

So, the plan chosen does show that the SELECT MAX would occur as a filter for the full table scan and that means it could possibly execute once for each row. It was just "lucky" that the MAX query always used the same inputs and therefore didn't really require an actual execution of the MAX query for each row evaluated by the WHERE clause due to subquery caching.

But, the thing to notice about the original plan is that it does require 2 access operations against the UCBSVCO table where one should suffice. The new analytic syntax does only one access operation on that table. That's good! If you can do something once instead of twice to get the same end result, once is better. It's like needing to go to the store to get bread and milk and you make one trip and get the bread and bring it home, then you make a second trip to get the milk. You could've gotten both items in a single trip and saved yourself a lot of time and effort. It works the same way with Oracle. Don't send Oracle to the store twice if once will do.

There were a couple of other comments I wanted to discuss as well.
From Bundit: Is there any reason to avoid using analytic function due to performance issue?

I'd say that analytic functions aren't a fix for everything. They're just another tool in the toolbox to choose from. I like the saying "just because you have a hammer doesn't mean every problem is a nail". You can't use analytic functions to fix everything, but you can use them to help reduce the resource requirements for certain classes of problems like the one I've demonstrated. They won't always be the answer but they should be one of the syntax options to test when/where appropriate. Only through proper testing would you be able to prove which way of writing a particular query would be most efficient.

From Craig M: Are the columns in the partition by necessary? It seems like it isn't adding anything since you are filtering on those columns.

In this case, you're right. Since the WHERE clause is specifying only a single cust_code and prem_code, the partition by isn't really necessary. For me, it's just a habit I'm in of always clearly indicating on which columns I want grouping to occur.

Also from Craig M: Also, I use analytic functions frequently, however I am not sure I would have ever thought to this problem in this way. Would it provide an advantage over something like

with max_ucbsvco as
(select sotp_cd
from
( select ucbsvco_sotp_code sotp_cd
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_dispatch_date is not null
order by ucbsvco_dispatch_date desc
)
where rownum = 1
)
select utrsotp_desc
from utrsotp
where utrsotp_code =
( select sotp_cd
from max_ucbsvco);


The only way I can answer this now is to say we'd have to test it and see. But, I think the analytic version would still be better if this version did what I think you're expecting it to do and materialize a temp table with the result of the query against UCBSVCO. First, the plan for this version would require an "almost" sort. The use of ORDER BY to put the rows in descending order would mean the rows output from that step would need to come out in sorted order and Oracle would have to do that operation. Now, because of ROWNUM, it should do an in-line sort vs. a normal sort operation. In other words, as the rows are read, Oracle will check to see if the ucbsvco_dispatch_date column value is greater than the previous row's value. After all the rows are read, then it will have the one row which has the most current (MAX) value. So, I'd want to see how the bit of extra ordering work would be handled as compared to the analytic version.

The other thing is that if the result set is materialized for that query, there will be some small overhead to create that temp table and then read from it. That overhead doesn't exist in the analytic version.

So, my instinct on this one is that the analytic version would still win. I mean 15 LIOs and .18 seconds is likely going to be pretty hard to beat. But, it's just speculation unless I get a chance to visit that client again and test it out. :)


Thanks to everyone who commented on the original post and I hope this follow-up provides more info to clarify issues raised.

Wednesday, July 16, 2008

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.