Oracle Scratchpad

December 22, 2021

Explain Plan

Filed under: Execution plans,Oracle,Troubleshooting — Jonathan Lewis @ 1:26 pm GMT Dec 22,2021

Here’s a little example that appeared on the Oracle database forum a few years ago (2013, 11.2.0.3 – it’s another of my drafts that waited a long time for completion) which captures a key problem with execution plans:

you need to make sure you look at the right one.

We have the tkprof output from an SQL statement that has been traced because it needs to go faster.


select clndr_id , count(*)
from
 task where (clndr_id = :"SYS_B_0") group by clndr_id
union
select clndr_id , count(*) from project where (clndr_id = :"SYS_B_1") group by clndr_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.01       0.00          0          0          0           0
Fetch        2     53.32     612.03      81650      58920          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     53.34     612.04      81650      58920          0           2

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 34  (PX)
Number of plan statistics captured: 1


Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         2          2          2  SORT UNIQUE (cr=58923 pr=81650 pw=22868 time=113329109 us cost=58277 size=24 card=2)
         2          2          2   UNION-ALL  (cr=58923 pr=81650 pw=22868 time=113329001 us)
         1          1          1    SORT GROUP BY NOSORT (cr=58330 pr=81070 pw=22868 time=104312437 us cost=58128 size=7 card=1)
   5589739    5589739    5589739     VIEW  index$_join$_003 (cr=58330 pr=81070 pw=22868 time=619784236 us cost=57240 size=38875249 card=5553607)
   5589739    5589739    5589739      HASH JOIN  (cr=58330 pr=81070 pw=22868 time=617373467 us)
   5590158    5590158    5590158       INDEX RANGE SCAN NDX_TASK_CALENDAR (cr=21676 pr=21676 pw=0 time=113637058 us cost=11057 size=38875249 card=5553607)(object id 24749)
   6673774    6673774    6673774       INDEX FAST FULL SCAN NDX_TASK_PROJ_RSRC (cr=36651 pr=36526 pw=0 time=213370625 us cost=21921 size=38875249 card=5553607)(object id 217274)
         1          1          1    SORT GROUP BY NOSORT (cr=593 pr=580 pw=0 time=9016527 us cost=149 size=17 card=1)
    136390     136390     136390     INDEX FAST FULL SCAN NDX_PROJECT_CALENDAR (cr=593 pr=580 pw=0 time=165434 us cost=132 size=2315876 card=136228)(object id 154409)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      2   SORT (UNIQUE)
      2    UNION-ALL
      1     SORT (GROUP BY NOSORT)
5589739      TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'TASK' (TABLE)
5589739       INDEX   MODE: ANALYZED (RANGE SCAN) OF 'NDX_TASK_CALENDAR' (INDEX)
5590158     SORT (GROUP BY NOSORT)
6673774      INDEX   MODE: ANALYZED (RANGE SCAN) OF 'NDX_PROJECT_CALENDAR' (INDEX)

One of the first things you should notice from the tkprof output is that the “Rowsource Operation” section and the “Execution Plan” section do not match. Remember that tkprof is simply calling explain plan when it generates the “Execution Plan” section of the output and has no information about the type and value of bind variables, so it’s easy for it to generate a plan that didn’t happen. (There are other reasons why the two sets of output might differ – but this is the commonest one.)

Another thing you might note in passing is that the system has cursor_sharing set to force or similar – a detail you can infer from the bind variable names having the form :SYS_B_nnn. This, alone, might be enough to convince you to ignore the Execution Plan because of its potential to mislead.

Despite the tendancy to mislead there is (in this case) a very important clue in the Execution Plan. In lines 2 and 3 we can see the “sort unique” and “union all” that the optimizer has used to implement the UNION operator in the query. Then we see that the “union all” has two “sort group by (nosort)” children, one for each of the aggregate query blocks – the “nosort” in both cases because the query blocks ensure that only a single value of clndr_id is selected in each case anyway.

The interesting thing in the Execution Plan is that the range scan of ndx_task_calendar in the first query block tells us that the optimizer thinks that all the information we need can be found in that index. So why does the Rowsource Operation tell us that at run-time the optimizer thought it needed to include the ndx_task_proj_rsrc index in an index join as well?

Assuming we haven’t found a bug the answer must be that there is another predicate hidden somewhere behind the query. There may be a security predicate, or it may simply be that task is actually a view with a definition like “select {list of columns} from task_t where {some predicate}”.

The mismatch between Execution Plan and Rowsource Operation gives us a clue, but the output from tkprof (and even the underlying trace file) is incomplete – we need to see what predicates Oracle has used to execute this query, and where it used them. So here’s the plan for the query pulled from memory by a call to dbms_xplan.display_cursor():

--------------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name                 | E-Rows |  OMem |  1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |                      |        |       |       |          |         |
|   1 |  SORT UNIQUE              |                      |      2 |  2048 |  2048 | 2048  (0)|         |
|   2 |   UNION-ALL               |                      |        |       |       |          |         |
|   3 |    SORT GROUP BY NOSORT   |                      |      1 |       |       |          |         |
|*  4 |     VIEW                  | index$_join$_003     |   5553K|       |       |          |         |
|*  5 |      HASH JOIN            |                      |        |   207M|    11M|  176M (1)|     181K|
|*  6 |       INDEX RANGE SCAN    | NDX_TASK_CALENDAR    |   5553K|       |       |          |         |
|*  7 |       INDEX FAST FULL SCAN| NDX_TASK_PROJ_RSRC   |   5553K|       |       |          |         |
|   8 |    SORT GROUP BY NOSORT   |                      |      1 |       |                  |         |
|*  9 |     INDEX FAST FULL SCAN  | NDX_PROJECT_CALENDAR |    136K|       |       |          |         |
--------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - filter("CLNDR_ID"=:SYS_B_0)
   5 - access(ROWID=ROWID)
   6 - access("CLNDR_ID"=:SYS_B_0)
   7 - filter("DELETE_SESSION_ID" IS NULL)
   9 - filter(("CLNDR_ID"=:SYS_B_1 AND "DELETE_SESSION_ID" IS NULL))

And there in the Predicate Information section we see two extra predicates “delete_session_id is null” – one on each table. Presumably the index ndx_project_calendar includes this column, but ndx_task_calendar does not – hence the need for the index join.

Given that the predicate has been attached to both tables, it seems fairly likely (from an outsider’s perspecetive) that this is row-level security (RLS / FGAC / VPD) in place. Regardless of whether it is RLS, or just a view layer, it looks like the only options to improve the performance of this query is to persuade it into using a full tablescan, or to find an alternatice index access path (which might mean adding delete_session_id to the index it’s already using – and checking whether this change would have any nasty side effects).

Footnote

A potentially significant, but easy to miss detail is the “Misses in library cache during parse:” – this statement had to be “hard parsed” (i.e. optimised) before execution; if you see a trace file where a statement has executed and parsed many times and the Misses is greater than one then it’s worth asking yourself why that might be.

3 Comments »

  1. Jonathan,*

    One way I use to link an RLS (Row Level Security) to a hard parse is by getting the non-sharing reason from v$sql_shared_cursor by using Tanel Poder nonshared script for example:

    SQL> @nonshared 27uhu2q2xuu7r
    
    Show why existing SQL child cursors were not reused (V$SQL_SHARED_CURSOR)...
    
    SQL_ID                        : 27uhu2q2xuu7r
    ADDRESS                       : 0000000075912CD0
    CHILD_ADDRESS                 : 0000000075912578
    CHILD_NUMBER                  : 0
    REASON                        : <ChildNode><ChildNumber>0</ChildNumber>
                                    <ID>36</ID>
                                    <reason>Authorization Checkfailed(9)</reason>
                                    <size>0x0</size>
                                   <details>row_level_access_control_mismatch</details>
                                   </ChildNode>
    CON_ID                        : 1
    -----------------
    SQL_ID                        : 27uhu2q2xuu7r
    ADDRESS                       : 0000000075912CD0
    CHILD_ADDRESS                 : 0000000068B7DE88
    CHILD_NUMBER                  : 1
    AUTH_CHECK_MISMATCH           : Y
    REASON                        :
    CON_ID                        : 1
    -----------------
    

    A hard parse due to an RLS policy is generally identified via the couple (AUTH_CHECK_MISMATCH, Authorization Checkfailed(9)). The value 9 refers to RLS while 4 in (AUTH_CHECK_MISMATCH, Authorization Checkfailed(4)) will refer to a hard parse because of the same object (table/index) but belonging to different users.

    Best regards
    Mohamed

    Comment by hourim — December 22, 2021 @ 2:49 pm GMT Dec 22,2021 | Reply

  2. […] A case study about looking at the right execution plan in a tkprof output (Dec 2021) […]

    Pingback by Execution Plans Catalogue | Oracle Scratchpad — January 28, 2022 @ 4:46 pm GMT Jan 28,2022 | Reply


RSS feed for comments on this post. TrackBack URI

Comments and related questions are welcome.

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Website Powered by WordPress.com.

%d bloggers like this: