Oracle Scratchpad

December 7, 2012

Update Error

Filed under: Execution plans,Oracle,subqueries,Troubleshooting — Jonathan Lewis @ 5:10 pm UTC Dec 7,2012

When doing updates with statements that use correlated subqueries, it’s important to make sure that your brackets (parentheses) are in the right place. Here are two statements that look fairly similar but have remarkably different results – and sometimes people don’t realise how different the statements are:

update t1
set
        padding = (
                select
                        t2.padding
                from    t2
                where   t2.id = t1.id
        )
where   t1.small_vc <= lpad(20,10,'0')
;

update t1
set
        padding = (
                select
                        t2.padding
                from    t2
                where   t2.id = t1.id
                and     t1.small_vc <= lpad(20,10,'0')
        )
;

The first statement will update rows in t1 where t1.small_vc <= lpad(20,10,’0′), copying the value of padding from t2 where (if) the id columns match, but setting t1.padding to null if there is no match.

The second statement will update every single row in t1 – some of the rows will probably be updated as expected (i.e. to get the same result as the first statement) but every row where t1.small_vc is greater than lpad(20,10,’0′) will have the padding column set to null.

Originally I created this little demo to respond to a question on OTN – but when I ran it with rowsource execution statistics enabled, I discovered that it also happened to demonstrate an odd bug in that feature – even in 11.2.0.3. Here are the two plans corresponding to the above two statements. The update is supposed to update 20 rows in t1, the incorrect form of the code will update all 10,000 rows in the table:


20 rows updated.

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID  73tz2pqv4z8rc, child number 0
-------------------------------------
update t1 set  padding = (   select    t2.padding   from t2   where
t2.id = t1.id  ) where t1.small_vc &lt;= lpad(20,10,'0')

Plan hash value: 417405447

------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT             |       |      1 |        |      0 |00:00:00.01 |     219 |
|   1 |  UPDATE                      | T1    |      1 |        |      0 |00:00:00.01 |     219 |
|*  2 |   TABLE ACCESS FULL          | T1    |      1 |     20 |     20 |00:00:00.01 |     173 |
|   3 |   TABLE ACCESS BY INDEX ROWID| T2    |     20 |      1 |     20 |00:00:00.01 |      45 |
|*  4 |    INDEX UNIQUE SCAN         | T2_PK |     20 |      1 |     20 |00:00:00.01 |      25 |
------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter(&quot;T1&quot;.&quot;SMALL_VC&quot;&lt;='0000000020')
   4 - access(&quot;T2&quot;.&quot;ID&quot;=:B1)

10000 rows updated.

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID  ax22zpj8xdwpn, child number 0
-------------------------------------
update t1 set  padding = (   select    t2.padding   from t2   where
t2.id = t1.id   and t1.small_vc &lt;= lpad(20,10,'0')  )

Plan hash value: 2442374960

-------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT              |       |      3 |        |      0 |00:00:00.27 |   21576 |
|   1 |  UPDATE                       | T1    |      3 |        |      0 |00:00:00.27 |   21576 |
|   2 |   TABLE ACCESS FULL           | T1    |      3 |  10000 |  29692 |00:00:00.03 |     514 |
|*  3 |   FILTER                      |       |  19692 |        |     40 |00:00:00.01 |      85 |
|   4 |    TABLE ACCESS BY INDEX ROWID| T2    |     40 |      1 |     40 |00:00:00.01 |      85 |
|*  5 |     INDEX UNIQUE SCAN         | T2_PK |     40 |      1 |     40 |00:00:00.01 |      45 |
-------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(:B1&lt;='0000000020')
   5 - access(&quot;T2&quot;.&quot;ID&quot;=:B1)

Note, in both cases, how the number of rows reported in the update operation (line 1) is zero although we might expect it to match the A-rows value reported in the table access full operation (line 2) which tells us how many rows were identified for update. But something strange has happened in the line reporting the table access full in the second case – clearly there’s a bug somewhere because there were only 10,000 rows in the table, yet the tablescan has (apparently) identified 29,692 rows for update.

Not only is the tablescan line reporting silly numbers, the filter line is as well (because that should only start 10,000 times – once per row in the table) moreover the subquery lines (4 and 5) should only start 20 times each because the filter should eliminate the need to run the subquery for all rows except the 20 where “T1″.”SMALL_VC”<=’0000000020. Even stranger is the fact that when I ran this test several times in a row (recreating the tables each time), the starts and A-rows values for the filter and table access full lines changed (decreasing) every time!

It took me a little while to figure out what was going on – but the doubling of the starts for the subquery gave me a hint, confirmed when I took a snapshot of how the session stats changed when I ran the second update. It’s just another variant of the odd “write consistency” behaviour that can appear when running tablescan through a large volume of data and updating it (although I have to say that I hadn’t seen it happening for a mere 10,000 rows before).  Oracle starts the tablescan and update, and after a while decides that it has to rollback and restart the update – the 20 rows that were subject to the subquery were the first 20 rows of the table, which is why they were almost sure to trigger the subquery twice each, had they appeared half way through the table the effect might not have been so consistent).

Footnote:

If you want to repeat my test for yourselves, here’s the code to generate the data sets:

create table t1
as
with generator as (
        select  --+ materialize
                rownum id
        from dual
        connect by
                level &lt;= 1e4
)
select
        rownum                  id,
        lpad(rownum,10,'0')     small_vc,
        rpad('x',100)           padding
from
        generator       v1,
        generator       v2
where
        rownum &lt;= 1e4
;

create table t2
as
select * from t1
;

alter table t1 add constraint t1_pk primary key(id);
alter table t2 add constraint t2_pk primary key(id);

November 21, 2012

Plan Order

Filed under: Execution plans,Oracle,subqueries — Jonathan Lewis @ 6:53 pm UTC Nov 21,2012

The previous post reminded me of another (fairly special) case where the order of operations in an execution plan seems to be wrong according to the “traditional” strategy for reading execution plans. Here’s a simple select statement with its execution plan to demonstrate the point:

select
	small_vc
from
	t1
where
	exists (
		select	null
		from	f1
		where	f1.id       = t1.id
		and	f1.small_vc = t1.small_vc
	)
and
	exists (
		select	null
		from	f2
		where	f2.id = 21
	)
;

------------------------------------------------------------------------------
| Id  | Operation             | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |     1 |    29 |    51   (2)| 00:00:01 |
|*  1 |  FILTER               |       |       |       |            |          |
|*  2 |   HASH JOIN RIGHT SEMI|       |     1 |    29 |    51   (2)| 00:00:01 |
|   3 |    TABLE ACCESS FULL  | F1    |    20 |   280 |     2   (0)| 00:00:01 |
|   4 |    TABLE ACCESS FULL  | T1    | 10000 |   146K|    48   (0)| 00:00:01 |
|*  5 |   INDEX UNIQUE SCAN   | F2_PK |     1 |    13 |     0   (0)| 00:00:01 |
-------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( EXISTS (SELECT /*+ */ 0 FROM "F2" "F2" WHERE "F2"."ID"=21))
   2 - access("F1"."ID"="T1"."ID" AND "F1"."SMALL_VC"="T1"."SMALL_VC")
   5 - access("F2"."ID"=21)

The traditional strategy for reading this plan (recursively operate the child rows of each parent row in the order that they appear) would say: we scan table F1 and buildilng a hash table in memory, then scan table T1 probing the hash table to perform the hash semi join of line 2. For each row that survives the hash join, the filter operation at line 1 tells us to run the subquery against F2 to see if the row should be passed forward as an output of the select statement.

You might like to pause briefly at this point to convince yourself that this is the way we usually interpret the indentation of an execution plan.

It’s not what happens in this special case. Notice that the second subquery isn’t correlated – it need only run once for Oracle to decide whether or not it will return any data. As a side effect of this special case, the plan operates “upside down”. Here’s the same execution plan pulled from memory after enabling rowsource execution statistics. It’s implrtant to be aware that in my test case the data in F2 doesn’t have a row where id = 21.

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID  5bd1m72cz4awy, child number 0
-------------------------------------
select  small_vc from  t1 where  exists (   select null   from f1   where f1.id       = t1.id   and
f1.small_vc = t1.small_vc  ) and  exists (   select null   from f2   where f2.id = 21  )

Plan hash value: 1423735592

--------------------------------------------------------------------------------------------------------------------
| Id  | Operation             | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------
|*  1 |  FILTER               |       |      1 |        |      0 |00:00:00.01 |       1 |       |       |          |
|*  2 |   HASH JOIN RIGHT SEMI|       |      0 |      1 |      0 |00:00:00.01 |       0 |   825K|   825K|          |
|   3 |    TABLE ACCESS FULL  | F1    |      0 |     20 |      0 |00:00:00.01 |       0 |       |       |          |
|   4 |    TABLE ACCESS FULL  | T1    |      0 |  10000 |      0 |00:00:00.01 |       0 |       |       |          |
|*  5 |   INDEX UNIQUE SCAN   | F2_PK |      1 |      1 |      0 |00:00:00.01 |       1 |       |       |          |
--------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( IS NOT NULL)
   2 - access("F1"."ID"="T1"."ID" AND "F1"."SMALL_VC"="T1"."SMALL_VC")
   5 - access("F2"."ID"=21)

Look carefully at the starts column. Line 1 (filter) started once; line 5 (the second child to the filter) started once and returned no rows; line 2 (the first child to the filter) never started – it didn’t have to because by this point Oracle had already determined that any data it generated would be eliminated by the non-existence of a match from line 5.

Summary

There are a few special case plans where the normal “first child first” rule (“… more what you’d call guidelines than actual rules.” — Captain Barbossa) for reading execution plans doesn’t apply. The “constant subquery” introduces one of them.

Footnote:

If you want to repeat the experiment on different versions of Oracle, here’s the code to generate my test data:

create table t1
as
with generator as (
	select	--+ materialize
		rownum 	id
	from	all_objects
	where	rownum <= 3000
)
select
	rownum			id,
	lpad(rownum,10,'0')	small_vc,
	rpad('x',100)		padding
from
	generator	v1,
	generator	v2
where
	rownum <= 10000
;

create table f1 as select * from t1 where id <= 20;
create table f2 as select * from t1 where id <= 20;

alter table f1 add constraint f1_pk primary key(id);
alter table f2 add constraint f2_pk primary key(id);

-- collect stats (compute, no histograms)

November 19, 2012

Plan timing

Filed under: Execution plans,Oracle,subqueries — Jonathan Lewis @ 9:59 pm UTC Nov 19,2012

I’ve copied the following question up from a recent comment because it’s a useful generic type of question, and I think I can answer it in the few minutes I have to spare.

Hi Jonathan. I have a query plan where I cannot explain how time adds up. I did the ALTER SESSION trick but it changed nothing. I ran this, and got the following plan. I have two questions (I appoligize for not being able to format this code and plan but I saw not formatting buttons on the insert box).

1) @ step #8 in the plan, the query jumps to 3 and 1/2 minutes. This step says VIEW but gives no indication of what it did that actually took 3 and 1/2 minutes. Can you explain or give me some idea how to find out what is being done on this line that takes that long. Especially with so few rows.

2) the total elapsed time of the query was 3 minutes 45 seconds. This jives with step #1 that says 3:44.54. But if A-TIME is supposed to be among other things, the sum of child steps, then how to we explain step #2. Step #2 says 3 minutes 3 minutes 44 seconds. But the sum of its child steps (#3 and #8) is7 minutes and 25 seconds. Did this query do these steps “in parallel” so to speak? Or is there something really off in the numbers and if so how to I prove it?

This is not something that is super pressing but I sure would like to be able to explain the differences to people. It is making it somewhat harder to get people to believe I know what I am doing when I cannot such obvious issues as these two things.

Thanks, Kevin Meade

Fortunately Kevin included enough information to allow me to understand what was going on. In this case that means Here’s the query and the execution plan pulled from memory – showing the execution statistics. As follows:

ALTER SESSION SET STATISTICS_LEVEL=ALL
/

drop table kevtemp1
/

create table kevtemp1
nologging
as
SELECT SRCE_EFF_START_TMSP,
       AGGREGATECLAIMUID
FROM (
     SELECT  A.AGGREGATECLAIMUID,
             A.SNAPSHOT_DT,
             MAX(A.SRCE_EFF_START_TMSP) SRCE_EFF_START_TMSP
     FROM (SELECT PI.AGGREGATECLAIMUID,
                  PI.SRCE_EFF_START_TMSP,
                  (SELECT DISTINCT BW.SNAPSHOT_DT
                   FROM RRS_SHR.RRS_ETL_BATCH_WINDOW BW, RRS_SHR.RRS_LOAD_STATUS RLS
                   WHERE RLS.ASTG_LOAD_STATUS = 'STARTED'
                   AND RLS.SNAPSHOT_DT = BW.SNAPSHOT_DT
                   AND BW.RPTG_WINDOW_TYPE = 'D'
                   AND BW.OBJECT_NM = 'R_AGGREGATE_CLAIM_SEED'
                   AND PI.SRCE_EFF_START_TMSP
                       BETWEEN
                       BW.BEGIN_TMSP
                       AND
                       BW.END_TMSP
                  ) AS SNAPSHOT_DT
           FROM RRS_PSTG.P_PCD_AGGREGATECLAIM PI
           WHERE PI.BATCH_ID IN
                 (SELECT src_batch_id
                  FROM batch_processing_queue
                  WHERE dm_batch_id =
                        batch_id_pkg.get_current_batch_id('PCD','ATM')
                 )
          ) A
          GROUP BY A.AGGREGATECLAIMUID, A.SNAPSHOT_DT
     )
/

Table created.

Elapsed: 00:03:45.14

Plan hash value: 3515505567

----------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                        | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | CREATE TABLE STATEMENT          |                             |      1 |        |      0 |00:03:44.54 |     246K|   8389 |    128 |       |       |          |
|   1 |  LOAD AS SELECT                 |                             |      1 |        |      0 |00:03:44.54 |     246K|   8389 |    128 |   530K|   530K|  530K (0)|
|   2 |   HASH GROUP BY                 |                             |      1 |  84487 |  48482 |00:03:44.41 |     245K|   8386 |      0 |  3128K|  1284K| 3538K (0)|
|   3 |    HASH UNIQUE                  |                             |  33524 |      1 |  33524 |00:03:40.98 |     236K|     12 |      0 |  1270K|  1270K|  523K (0)|
|   4 |     NESTED LOOPS                |                             |  33524 |      1 |  33524 |00:00:08.35 |     236K|     12 |      0 |       |       |          |
|*  5 |      TABLE ACCESS BY INDEX ROWID| RRS_ETL_BATCH_WINDOW        |  33524 |     11 |  33524 |00:00:07.84 |     203K|      9 |      0 |       |       |          |
|*  6 |       INDEX RANGE SCAN          | IDX1_RRS_ETL_BATCH_WINDOW   |  33524 |     41 |   5414K|00:00:04.09 |   86482 |      5 |      0 |       |       |          |
|*  7 |      INDEX UNIQUE SCAN          | IUK2_RRS_LOAD_STATUS        |  33524 |      1 |  33524 |00:00:00.31 |   33535 |      3 |      0 |       |       |          |
|   8 |    VIEW                         |                             |      1 |  84487 |  48484 |00:03:43.99 |     245K|   8386 |      0 |       |       |          |
|*  9 |     HASH JOIN                   |                             |      1 |  84487 |  48484 |00:00:02.63 |    9186 |   8374 |      0 |  1023K|  1023K| 1243K (0)|
|* 10 |      INDEX RANGE SCAN           | IAK1_BATCH_PROCESSING_QUEUE |      1 |      5 |    102 |00:00:00.22 |     855 |     44 |      0 |       |       |          |
|  11 |      TABLE ACCESS FULL          | P_PCD_AGGREGATECLAIM        |      1 |   1536K|   1536K|00:00:01.47 |    8331 |   8330 |      0 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------

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

   5 - filter(("BW"."BEGIN_TMSP"=:B1)
   7 - access("RLS"."SNAPSHOT_DT"="BW"."SNAPSHOT_DT" AND "RLS"."ASTG_LOAD_STATUS"='STARTED')
   9 - access("PI"."BATCH_ID"="SRC_BATCH_ID")
  10 - access("DM_BATCH_ID"="BATCH_ID_PKG"."GET_CURRENT_BATCH_ID"('PCD','ATM'))

46 rows selected.

Elapsed: 00:00:01.75

Working through the layers of the query, from the outside towards the middle, we have a simple select from an inline view. The inline view, however, is an aggregate view that selects from another inline view. One of the “columns” of the innermost inline view is an scalar subquery that joins two tables, and the view also uses an IN subquery. So we need to identify all these pieces in the execution plan.

Lines 9 – 11 of the plan show us that the IN subquery of the innermost view has been unnested, producing a hash join. The VIEW operator tells us that this join has been optimized as a “leaf” query block. Lines 3 – 7 give us the separately optimized execution plan for the “select distinct” inline scalar subquery; I am slightly surprised that this part of the plan doesn’t appear after the VIEW operator at line 8, indented at the same level as line 9, since it is a plan that generates a value for each row returned in the view.

Note: although the plan in lines 3 – 7 could be executed once for each row returned by the plan in lines 9 – 11, the number of executions could (and in this case is) fewer than the worst case thanks to scalar subquery caching.

The location of the scalar subquery in the overall plan does make it harder to understand the various time and resource usage figures – but once you understand what the query has to do, it is easier to work out why the numbers have a dislocated look. The time in line 8 is 3:43.99 because it includes the time in line 9 (2.63 seconds) that generates 48,484 rows, plus the time in line 3 (3:40.98) that comes from running the scalar subquery 33,524 times.

Summary

Subqueries can appear in various places in execution plans – when they are scalar subqueries representing columns in the select list, they appear ABOVE the query block that calls them. This can be very confusing when you’re trying to follow the trail of where the time and resources are first used when you’ve collected rowsource execution statistics.

August 9, 2012

Debugging

Filed under: Bugs,Execution plans,Oracle,subqueries — Jonathan Lewis @ 7:04 pm UTC Aug 9,2012

One of my recent assignments involved a company that had run into some performance problems after upgrading from 10.2.0.3 to 11.2.0.2. We had spent half an hour on the phone discussing the system before I had arrived, and I’d made a couple of suggestions that had solved most of their problems before I got on site – but they still wanted me to come in and give them some specific ideas about why the critical part of the solution had helped.

The most critical piece of advice I had given them (after listening very carefully to their description of the system) was to get rid of ALL the histograms they had on their system, and then watch very carefully for any signs that they might need to re-introduce a handful of histograms over the next few weeks.

One of their critical queries completed in less that 2 seconds when histograms were removed, but took 33 seconds to complete when histograms were in place. With their permission, the following notes record my investigation of this puzzle, the underlying Oracle bug (possibly not yet documented) that caused it, and the optimum workaround that was available to them.
(more…)

February 29, 2012

Missing Filter

Filed under: Bugs,Execution plans,Oracle,subqueries — Jonathan Lewis @ 9:30 pm UTC Feb 29,2012

I see that Christian Antognini posted a note about an interesting little defect in Enterprise Manager a little while ago - it doesn’t always know how to interpret execution plans. The problem appears in Christians’ example when a filter subquery predicate is applied during an index range scan – it’s a topic I wrote about a few months ago with the title “filter bug” because the plan shows (or, rather, fails to show) a “missing” filter operation, which has been subsumed into the predicate section of the thing that would otherwise have been the first child of the filter operation – the rule of recursive descent through the plan breaks, and the ordering that OEM gives for the operations goes wrong.

(more…)

February 21, 2012

Not In – 2

Filed under: CBO,Execution plans,Oracle,Performance,subqueries,Tuning — Jonathan Lewis @ 9:24 pm UTC Feb 21,2012

My note on “NOT IN” subqueries is one of the most popular on my blog, staying in the top 5 hits for the last five years – but it’s getting a bit old, so it’s about time I said something new about “NOT IN” – especially since the Null Aware Anti Join has been around such a long time. The example I want to talk about is, as so often, something that came up as a problem on a customer site. Here’s a bit of SQL to model the situation, which is currently running under Oracle 11.1.0.7:

(more…)

June 8, 2011

How to hint – 1

Filed under: dbms_xplan,Execution plans,Hints,Oracle,subqueries,Troubleshooting — Jonathan Lewis @ 3:00 pm UTC Jun 8,2011

Here’s a quick tutorial in hinting, promped by a question on the OTN database forum.
The OP has a hash semi-join and Oracle appears to be ignoring a hint to use a nested loop:

(more…)

April 27, 2011

Star Transformation – 2

Filed under: CBO,Oracle,subqueries,Tuning — Jonathan Lewis @ 6:13 pm UTC Apr 27,2011

After publishing my note about emulating star transformations when there was something blocking the optimizer’s ability to do them automatically I ended up having an interesting email conversation with Mark Farnham about variations on the theme, concluding with a completely different (and possibly more intuitive) SQL statement to achieve the same aim.
(more…)

September 7, 2010

CBO Surprise

Filed under: CBO,Execution plans,Oracle,subqueries — Jonathan Lewis @ 7:00 pm UTC Sep 7,2010

Well, it surprised me!

I’ve said for a very long time that in principle, ignoring bugs and restrictions, the optimizer will always choose the lowest cost option during its search for an execution path. It turns out that this isn’t true. In a comment attached to a note I had written about a possible bug relating to function-based indexes I was told that there are cases where the optimizer follows a rule that allows it to ignore the lowest cost path if it is derived from a range-based predicate involving unpeekable bind variables.
(more…)

August 31, 2010

Filter “Bug”

Filed under: Execution plans,Oracle,subqueries — Jonathan Lewis @ 7:01 pm UTC Aug 31,2010

Here’s an example to remind you how important it is to look at the “Predicate Information” supplied with an execution plan. Here are two execution plans that look very similar in shape – a continuous set of steps inwards and downwards from parent to child, with no “multi-child” parent rows:
(more…)

May 19, 2009

Odd Filter

Filed under: Execution plans,subqueries — Jonathan Lewis @ 6:39 pm UTC May 19,2009

A little while ago someone sent me a brief email about an odd section of execution plan that they had seen. To make things a little more challenging they didn’t send the SQL statement, and they only sent me a few lines from the middle of the plan to see if I could explain what was going on. This is what is looked like:
(more…)

Theme: Rubric. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 1,398 other followers