An interesting little problem appeared on the Oracle-L mailing list earlier on this week – a query ran fairly quickly when statistics hadn’t been collected on the tables, but then ran rather slowly after stats collection even though the plan hadn’t changed, and the tkprof results were there to prove the point. Here are the two outputs (edited slightly for width – the original showed three sets of row stats, the 1st, avg and max, but since the query had only been run once the three columns showed the same results in each case):
Rows (max) Row Source Operation
---------- ---------------------------------------------------
0 UPDATE CXT_FAKT_PROVISIONSBUCHUNG (cr=2039813 pr=3010 pw=0 time=47745718 us)
15456 TABLE ACCESS FULL CXT_FAKT_PROVISIONSBUCHUNG (cr=1328 pr=1325 pw=0 time=40734 us cost=370 size=880992 card=15456)
11225 VIEW CXV_HAUPT_VU_SPARTE (cr=2038477 pr=1684 pw=0 time=47297497 us cost=10 size=4293 card=1)
11225 SORT UNIQUE (cr=2038477 pr=1684 pw=0 time=47284436 us cost=10 size=824 card=1)
126457 VIEW (cr=2038167 pr=1669 pw=0 time=27753402 us cost=9 size=824 card=1)
126457 WINDOW SORT (cr=2038167 pr=1669 pw=0 time=27667835 us cost=9 size=853 card=1)
126457 WINDOW SORT (cr=2038167 pr=1669 pw=0 time=26884699 us cost=9 size=853 card=1)
126457 NESTED LOOPS (cr=2038167 pr=1669 pw=0 time=26342292 us)
126457 NESTED LOOPS (cr=1995241 pr=1615 pw=0 time=26192173 us cost=7 size=853 card=1)
141581 NESTED LOOPS (cr=642683 pr=1066 pw=0 time=3039331 us cost=5 size=499 card=1)
11225 TABLE ACCESS BY INDEX ROWID POP_INFO (cr=22473 pr=32 pw=0 time=109767 us cost=2 size=16 card=1)
11225 INDEX UNIQUE SCAN PK_POP_INFO (cr=11248 pr=4 pw=0 time=51796 us cost=1 size=0 card=1)(object id 1790009)
141581 TABLE ACCESS BY INDEX ROWID TMP_VU_SPARTE (cr=620210 pr=1034 pw=0 time=2889850 us cost=3 size=483 card=1)
1732978 INDEX RANGE SCAN IDX_TMP_VU_SPARTE (cr=140952 pr=204 pw=0 time=2094982 us cost=2 size=0 card=1)(object id 1795724)
126457 INDEX RANGE SCAN IDX_TMP_VU_SPARTE (cr=1352558 pr=549 pw=0 time=23078816 us cost=1 size=0 card=1)(object id 1795724)
126457 TABLE ACCESS BY INDEX ROWID TMP_VU_SPARTE (cr=42926 pr=54 pw=0 time=94791 us cost=2 size=354 card=1)
Rows (max) Row Source Operation
---------- ---------------------------------------------------
0 UPDATE CXT_FAKT_PROVISIONSBUCHUNG (cr=89894995 pr=1701 pw=0 time=318766975 us)
15456 TABLE ACCESS FULL CXT_FAKT_PROVISIONSBUCHUNG (cr=1328 pr=1031 pw=0 time=46975 us cost=370 size=880992 card=15456)
11225 VIEW CXV_HAUPT_VU_SPARTE (cr=89893656 pr=670 pw=0 time=1553653734 us cost=11 size=4293 card=1)
11225 SORT UNIQUE (cr=89893656 pr=670 pw=0 time=1553640071 us cost=11 size=419 card=1)
126457 VIEW (cr=89893656 pr=670 pw=0 time=1533733864 us cost=10 size=419 card=1)
126457 WINDOW SORT (cr=89893656 pr=670 pw=0 time=1533646166 us cost=10 size=155 card=1)
126457 WINDOW SORT (cr=89893656 pr=670 pw=0 time=1532847028 us cost=10 size=155 card=1)
126457 NESTED LOOPS (cr=89893656 pr=670 pw=0 time=1532238656 us)
3501658 NESTED LOOPS (cr=89167767 pr=665 pw=0 time=1529652013 us cost=8 size=155 card=1)
5300707 NESTED LOOPS (cr=1339312 pr=480 pw=0 time=9657987 us cost=5 size=81 card=1)
11225 TABLE ACCESS BY INDEX ROWID POP_INFO (cr=22473 pr=32 pw=0 time=119070 us cost=2 size=16 card=1)
11225 INDEX UNIQUE SCAN PK_POP_INFO (cr=11248 pr=3 pw=0 time=54707 us cost=1 size=0 card=1)(object id 1790009)
5300707 TABLE ACCESS BY INDEX ROWID TMP_VU_SPARTE (cr=1316839 pr=448 pw=0 time=8359987 us cost=3 size=65 card=1)
5300707 INDEX RANGE SCAN IDX_TMP_VU_SPARTE (cr=140971 pr=87 pw=0 time=3603882 us cost=2 size=0 card=1)(object id 1795724)
3501658 INDEX RANGE SCAN IDX_TMP_VU_SPARTE (cr=87828455 pr=185 pw=0 time=1518016475 us cost=2 size=0 card=1)(object id 1795724)
126457 TABLE ACCESS BY INDEX ROWID TMP_VU_SPARTE (cr=725889 pr=5 pw=0 time=1829196 us cost=3 size=74 card=1)
As you can see, the first run took 48 seconds (time=47,745,718 us in the first line) while the second execution took 319 seconds (time=318766975 us). If you check the execution plans carefully they appear to be the same plan and, in fact, the trace file showed that the two plans had the same plan hash value. Clearly, though, they do vastly different amounts of work – the most eye-catching detail, perhaps, is the way the bad plan blows the row count up to 5 million before collapsing it back to 126,000). What do you have to do to get the change in performance (and it’s a totally reproducible change) – create or drop stats: if you have stats on the tables you get a slow execution, if you delete the stats you get the fast execution.So what’s the problem ? Look carefully at the plan(s) – they’re not actually the same plan, but you can’t see the difference you can only see clues that they must be different. Notice in the last four lines that you access the same table (TMP_VU_SPARTE) twice using the same index (IDX_TMP_VU_SPARTE) – when you collect stats you access the two tables in the opposite order, and it makes a difference to the work you do.
To demonstrate the point I’ve created a simplified model of the problem, based on some extra information supplied in the mail thread. The model requires a correlated update, based on a view which joins a table to itself, and range-based predicates. Here’s the data generation:
execute dbms_random.seed(0) create table t1 as with generator as ( select --+ materialize rownum id from dual connect by level <= 1e4 ) select trunc(dbms_random.value(0,1e4)) contract, sysdate - 300 + trunc(dbms_random.value(0,300)) date_from, sysdate - 300 + trunc(dbms_random.value(0,300)) date_to, sysdate - 300 + trunc(dbms_random.value(0,300)) created, sysdate - 300 + trunc(dbms_random.value(0,300)) replaced from generator v1, generator v2 where rownum <= 1e5 ; create index t1_i1 on t1(contract, date_from, date_to); create or replace view v1 as select t1a.* from t1 t1a, t1 t1b where t1b.contract = t1a.contract and t1b.date_from <= t1a.date_from and t1b.date_to > t1a.date_from and t1b.created < t1a.replaced and t1b.replaced > t1a.created ; rem rem We are going to update t2 from v1 using rem equality on all columns in the index rem create table t2 as with generator as ( select --+ materialize rownum id from dual connect by level <= 1e4 ) select trunc(dbms_random.value(0,1e4)) contract, sysdate - 300 + trunc(dbms_random.value(0,300)) date_from, sysdate - 300 + trunc(dbms_random.value(0,300)) date_to, sysdate - 300 + trunc(dbms_random.value(0,300)) replaced from generator v1, generator v2 where rownum <= 1e5 ; begin dbms_stats.gather_table_stats( ownname => user, tabname =>'T1', method_opt =>'for all columns size 1' ); dbms_stats.gather_table_stats( ownname => user, tabname =>'T2', method_opt =>'for all columns size 1' ); end; /I haven’t crafted my data particularly carefully and from the point of view of realism the content is a little bizarre (I’ve got “to” dates earlier than “from” dates, for example) – but all I’m interested in is getting the right sort of shape to demonstrate a point about the plan, I’m not trying to model the actual variation in activity.
I’ve created a view with a self-join that starts with equality on first column of the index I’ve created, but uses range-based predicates on the other columns in the table – that’s probably quite important as far as the real-world performance was concerned – partly because of the nature of the data (interesting skews when comparing “valid to/from dates”) and partly because Oracle is going to have to use its 5% guess for join selectivities for range based selectivities.
And now the update – two versions with their execution plans; starting with the plan where the correlated subquery visits t1 aliased as t1a first:
explain plan for
update t2 set
replaced = (
select
/*+ leading(v1.t1a v1.t1b) */
max(replaced)
from v1
where
v1.contract = t2.contract
and v1.date_from = t2.date_from
and v1.date_to = t2.date_to
)
;
select * from table(dbms_xplan.display(null,null,'alias'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2328412027
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | 100K| 2734K| 500K (20)| 00:41:41 |
| 1 | UPDATE | T2 | | | | |
| 2 | TABLE ACCESS FULL | T2 | 100K| 2734K| 64 (8)| 00:00:01 |
| 3 | SORT AGGREGATE | | 1 | 72 | | |
| 4 | NESTED LOOPS | | | | | |
| 5 | NESTED LOOPS | | 1 | 72 | 4 (0)| 00:00:01 |
| 6 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 36 | 2 (0)| 00:00:01 |
|* 7 | INDEX RANGE SCAN | T1_I1 | 1 | | 1 (0)| 00:00:01 |
|* 8 | INDEX RANGE SCAN | T1_I1 | 1 | | 1 (0)| 00:00:01 |
|* 9 | TABLE ACCESS BY INDEX ROWID | T1 | 1 | 36 | 2 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - UPD$1
2 - UPD$1 / T2@UPD$1
3 - SEL$F5BB74E1
6 - SEL$F5BB74E1 / T1A@SEL$2
7 - SEL$F5BB74E1 / T1A@SEL$2
8 - SEL$F5BB74E1 / T1B@SEL$2
9 - SEL$F5BB74E1 / T1B@SEL$2
Predicate Information (identified by operation id):
---------------------------------------------------
7 - access("T1A"."CONTRACT"=:B1 AND "T1A"."DATE_FROM"=:B2 AND
"T1A"."DATE_TO"=:B3)
8 - access("T1B"."CONTRACT"=:B1 AND "T1B"."DATE_TO">:B2 AND
"T1B"."DATE_FROM"<=:B3)
filter("T1B"."DATE_TO">:B1 AND "T1B"."CONTRACT"="T1A"."CONTRACT" AND
"T1B"."DATE_FROM"<="T1A"."DATE_FROM" AND "T1B"."DATE_TO">"T1A"."DATE_FROM")
9 - filter("T1B"."CREATED"<"T1A"."REPLACED" AND
"T1B"."REPLACED">"T1A"."CREATED")
Notice that there’s nothing in the body of the plan that tells you which copy of t1 is visited first – you can’t tell unless you look carefully at the predicate information, or unless you’ve requested the alias section that lets you see very easily that the t1 at line 6 (the first one accessed) is aliased as t1a and the t1 at line 9 is aliased as t1b. While you’re at it, check the plan hash value from the top of the plan output.Now the plan when we hint the two tables into the reverse order:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2328412027
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | 100K| 2734K| 600K (17)| 00:50:01 |
| 1 | UPDATE | T2 | | | | |
| 2 | TABLE ACCESS FULL | T2 | 100K| 2734K| 64 (8)| 00:00:01 |
| 3 | SORT AGGREGATE | | 1 | 72 | | |
| 4 | NESTED LOOPS | | | | | |
| 5 | NESTED LOOPS | | 1 | 72 | 5 (0)| 00:00:01 |
| 6 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 36 | 3 (0)| 00:00:01 |
|* 7 | INDEX RANGE SCAN | T1_I1 | 1 | | 2 (0)| 00:00:01 |
|* 8 | INDEX RANGE SCAN | T1_I1 | 1 | | 1 (0)| 00:00:01 |
|* 9 | TABLE ACCESS BY INDEX ROWID | T1 | 1 | 36 | 2 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - UPD$1
2 - UPD$1 / T2@UPD$1
3 - SEL$F5BB74E1
6 - SEL$F5BB74E1 / T1B@SEL$2
7 - SEL$F5BB74E1 / T1B@SEL$2
8 - SEL$F5BB74E1 / T1A@SEL$2
9 - SEL$F5BB74E1 / T1A@SEL$2
Predicate Information (identified by operation id):
---------------------------------------------------
7 - access("T1B"."CONTRACT"=:B1 AND "T1B"."DATE_TO">:B2 AND
"T1B"."DATE_FROM"<=:B3)
filter("T1B"."DATE_TO">:B1)
8 - access("T1B"."CONTRACT"="T1A"."CONTRACT" AND "T1A"."DATE_FROM"=:B1 AND
"T1A"."DATE_TO"=:B2)
filter("T1A"."CONTRACT"=:B1 AND "T1B"."DATE_FROM"<="T1A"."DATE_FROM" AND
"T1B"."DATE_TO">"T1A"."DATE_FROM")
9 - filter("T1B"."CREATED"<"T1A"."REPLACED" AND
"T1B"."REPLACED">"T1A"."CREATED")
The plan hash value is the same – but if you look at the alias section you can see that the t1 we access first is the one with alias t1b.Now compare the predicate sections, just for line 7 (the initial index access line):
First Plan
7 - access("T1A"."CONTRACT"=:B1 AND "T1A"."DATE_FROM"=:B2 AND "T1A"."DATE_TO"=:B3)
Second Plan
7 - access("T1B"."CONTRACT"=:B1 AND "T1B"."DATE_TO">:B2 AND "T1B"."DATE_FROM"<=:B3)
filter("T1B"."DATE_TO">:B1)
Although my model data is random garbage, it’s easy to imagine that with a large data set the selectivities of these two predicates could be dramatically different, and there is clearly some “real-world” meaning to the date_to/date_from columns for a given row that the optimizer is unlikely to recognise when looking at the individual column stats for the table. It’s not surprising that a plan with no stats (which results in dynamic sampling) could find a better plan than a table with stats that leaves the optimizer using its default “call it 5% and hope for the best” strategy for range-based joins.Conclusion
When you reference a table more than once in an execution plan, make sure you look very carefully at the predicate section – or even call for the alias section – so that you know exactly which copy of the table appears at which point in the plan.Footnote
Although the results don’t mean much for my example, here’s my output from tracing my queries – rather than report the whole query in each case, I’ve just given the hint to show the table order:/*+ leading(v1.t1a v1.t1b) */
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 6.01 0.00 0 200722 204119 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 6.01 0.00 0 200722 204119 100000
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 UPDATE T2 (cr=200773 pr=0 pw=0 time=0 us)
100000 100000 100000 TABLE ACCESS FULL T2 (cr=459 pr=0 pw=0 time=0 us cost=64 size=2800000 card=100000)
100000 100000 100000 SORT AGGREGATE (cr=200248 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=200248 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=200248 pr=0 pw=0 time=0 us cost=4 size=72 card=1)
0 0 0 TABLE ACCESS BY INDEX ROWID T1 (cr=200248 pr=0 pw=0 time=0 us cost=2 size=36 card=1)
0 0 0 INDEX RANGE SCAN T1_I1 (cr=200248 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 81082)
0 0 0 INDEX RANGE SCAN T1_I1 (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 81082)
0 0 0 TABLE ACCESS BY INDEX ROWID T1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=36 card=1)
/*+ leading(v1.t1b v1.t1a) */
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 6.09 0.00 0 613372 200000 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 6.09 0.00 0 613372 200000 100000
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 UPDATE T2 (cr=613372 pr=0 pw=0 time=1 us)
100000 100000 100000 TABLE ACCESS FULL T2 (cr=459 pr=0 pw=0 time=0 us cost=64 size=2800000 card=100000)
100000 100000 100000 SORT AGGREGATE (cr=612913 pr=0 pw=0 time=1 us)
0 0 0 NESTED LOOPS (cr=612913 pr=0 pw=0 time=1 us)
0 0 0 NESTED LOOPS (cr=612913 pr=0 pw=0 time=1 us cost=5 size=72 card=1)
166078 166078 166078 TABLE ACCESS BY INDEX ROWID T1 (cr=368051 pr=0 pw=0 time=0 us cost=3 size=36 card=1)
166078 166078 166078 INDEX RANGE SCAN T1_I1 (cr=202108 pr=0 pw=0 time=0 us cost=2 size=0 card=1)(object id 81082)
0 0 0 INDEX RANGE SCAN T1_I1 (cr=244862 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 81082)
0 0 0 TABLE ACCESS BY INDEX ROWID T1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=36 card=1)
There isn’t a lot of difference in the run-time (which is mostly due to the tablescan) – but three’s an obvious difference in the number of buffer visits and the amount of data found for the first t1 access.Just like the OP my plan varied with stats – though in my case I got the better plan when I had stats, and the worse plan when I deleted stats and the optimizer used dynamic sampling.
DIGITAL JUICE
No comments:
Post a Comment
Thank's!