Oracle Scratchpad

July 12, 2018

Cardinality Puzzle

Filed under: Oracle,Statistics,Troubleshooting — Jonathan Lewis @ 12:57 pm BST Jul 12,2018

One of the difficulties of being a DBA and being required to solve performance problems is that you probably never have enough time to think about how you got to a solution and why the solution works; and if you don’t learn about the process itself , you just don’t get better at it. That’s why I try (at least some of the time) to write articles and books (as I did with CBO Fundamentals) that

  1. explain simple details that can be used as background facts
  2. walk through the steps of solving a problem

So here’s an example from a question on the ODC database forum asking about the cause and workaround for a bad cardinality estimate that is producing a poorly performing execution plan. It’s actually a type of problem that comes up quite frequently on large data sets and explains why a simple “gather stats” is almost guaranteed to leave you with a few headaches (regardless of whether or not you choose to include histograms as part of the process). I’m not going to offer “the answer” – I’m just going to talk about the inferences we can make from the facts supplied and where we have to go from there.

The DBA has a table holding 80,000,000,000 rows. It is list/hash partitioned with 2 partitions and 1,024 sub-partitions (per partition) but neither of the partitioning key columns appears in the query. The query runs parallel and the optimizer (presumably thanks to the specific settings of various parameters related to parallel execution uses dynamic sampling at level 3).

There is an inline view defined in the query and the DBA has isolated this as a key component of the problem and supplied a query and plan (from “explain plan”) against that view.


select * from TAB2 T
WHERE T.DT = to_date(:b1,'MM/DD/YYYY HH24:MI:SS');
 
------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name                     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                          |   479M|    76G|  1756K (14)| 05:51:14 |       |       |        |      |            |
|   1 |  PX COORDINATOR              |                          |       |       |            |          |       |       |        |      |            |
|   2 |   PX SEND QC (RANDOM)        | :TQ10000                 |   479M|    76G|  1756K (14)| 05:51:14 |       |       |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX PARTITION HASH ALL     |                          |   479M|    76G|  1756K (14)| 05:51:14 |     1 |  1024 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS STORAGE FULL| TAB1                     |   479M|    76G|  1756K (14)| 05:51:14 |     1 |  2048 |  Q1,00 | PCWP |            |
------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - storage(COALESCE("TB1"."DFG",'N')='N' AND TRUNC(INTERNAL_FUNCTION("TB1"."DT_TM"))=TO_DATE(:B1,'MM/DD/YYYY
              HH24:MI:SS'))
       filter(COALESCE("TB1"."DFG",'N')='N' AND TRUNC(INTERNAL_FUNCTION("TB1"."DT_TM"))=TO_DATE(:B1,'MM/DD/YYYY
              HH24:MI:SS'))

Note
-----
   - dynamic sampling used for this statement (level=3)

The DBA’s problem is that if the estimated cardinality of this extract goes over roughly 500M the optimizer chooses a bad plan for the overall query – and on occasion this extract has given an estimate of 5 billion rows. Moreover, the actual number of rows returned by this extract is typically in the order of 40M, so the estimate is a long way off even when it’s “good enough”.

So where do we start looking to work out what’s going wrong? You’ll note, of course, that after text expansion the user’s single predicate has changed, and an extra predicate (previously hidden inside the view) has appeared; instead of just T.DT = to_date(:b1,’MM/DD/YYYY HH24:MI:SS’) we now have (cosmetically adjusted):

        COALESCE(DFG,'N')='N' 
AND     TRUNC(DT_TM)=TO_DATE(:B1,'MM/DD/YYYY HH24:MI:SS')

There are two immediately obvious threats here – first that the combination of predicates means Oracle is likely to make a mistake because it will check the individual selectivities and multiply them together to get the combined selectivity, second that the appearance of predicates of the form “function(column) = constant” means that Oracle will guess 1% as the individual selectivities.

Without checking more details we might assume that a possible quick fix (that would require no changes to existing code) would be to create a couple of virtual columns (or extended stats) to represent the two expressions and gather stats on the resulting columns – though it is a restriction of extended stats that you can’t “double up” and create a column group on the two column expressions, so there’s still some scope for a cardinality estimate that is still sufficiently bad even with this approach. We also note that if we can change the coalesce(DFG,’N’) that must have been hidden in the view to nvl(DFG,’N’) then Oracle would be able to “or expand” the nvl() and use a more appropriate selectivity for that part of the predicate.

However, the points I’ve covered so far tend to produce estimates that are too small and often much too small. So maybe the key to the problem is in the Note section that tells us that Oracle has (successfully) used dynamic sampling for this statement. In other words, all the theory of how the optimizer calculates selectivity may be irrelevant – the estimate will be based on the luck of the sample.

So let’s take a look at the (slightly edited) table stats we’ve been given:

column_name data_type num_distinct low_value      high_value     density   num_null  histogram
DT_TM       DATE           6179571 78740B1E0A383C 7876020B01262B 1.6182E-7 0         NONE
DFG         VARCHAR2             1 4E             4E             1         0         NONE

Notice that the DFG (apparently) has the value ‘N’ for every row in the table (low_value = high_value = 0x4E, num_nulls = 0). The date range is 30-Nov-2016 to 11-Feb-2018, with no histogram but 6.18M distinct values for 80 Billion rows. Neither column has a histogram.

A little arithmetic tells us that (on average) there ought to be about 182M (= 80B / 438 days) rows for any one day – and that’s worth thinking about for three separate reasons.

First, an estimate of 479M against an average of 182M isn’t too surprising if it’s based on a fairly small sample, it’s only out by a factor of 2.6. On the other hand, getting an an estimate of 5 billion – which can happen on bad days – is extremely unlikely if the data is uniformly distributed across dates.

Secondly, the DBA supplied us with some data from the recent past with an aggregate query for “trunc(dt_tm)”, with the following results:

TRUNC(DT_TM)   COUNT(*)
------------ ----------
01-FEB-18    44,254,425
02-FEB-18    46,585,349
03-FEB-18    43,383,099
04-FEB-18    32,748,364
05-FEB-18    37,993,126
06-FEB-18    39,708,994
07-FEB-18    38,696,777
08-FEB-18    41,871,780
09-FEB-18    46,702,852
10-FEB-18    42,744,870
11-FEB-18    34,971,845
12-FEB-18    37,165,983

Recent data seems to follow an average of around 40M rows per day, so the estimate of 182M that we can derive from the stored statistics is a long way off: the present is behaving very differently from the past and that’s a relatively common problem with very large data sets – though it’s more usual for rolling averages to increase from the past to the present because the data is often representing the growth of a business over time. Can we create a hypothesis to explain the discrepancy, and could that hypothesis also account for the sample producing some very strange estimates ?

Finally, slightly more subtle and only included for completeness, if this column is supposed to hold date and time to the nearest second – which is what you might expect from an Oracle date type – there are 38 million possible values (438 x 86,400) it could be holding, and that’s more than the actual number of distinct values by a factor of 6. We can also work out that 80 billion rows over 438 days is 2,000 rows per second (on average). Averages are often misleading, of course, many systems have a pattern where a working day shows most of the data created in a 12 – 16 hour window with a couple of hours of more intense activity. For reference, though: average rows per second for the recent data is roughly 40M/86400 = 460; while the average we derive from the stored statistics is 80B / 6M = 13000 rows per second; this unlikely pattern needs a “non-uniform” explanation.

How do these three thoughts help us to understand or, to be more accurate, to make a sensible guess about why the optimizer can use dynamic sampling and get a wildly variable estimate which can be 1 or 2 orders of magnitude wrong. (varying between 479M and 5,000M compared to the recent actual 40M)?

Here’s one simple idea: extrapolate the 40M rows per day over 80B rows: that’s 2,000 days (possibly rather more since businesses tend to grow). What if the dt_tm is the timestamp for the moment the row was loaded into the database, and a couple of years ago (maybe around “30th Nov 2016”) the data was restructured and the existing five years of data was loaded over a very short period of time – let’s say one week. This would leave you with 17B rows of “new” data with a dt_tm spread at 40M rows per day for most of 438 days, and 63B rows of “historic” data packed into 7 days (at 9B rows per day).

I don’t know how Oracle would have randomly selected its sample from an extremely large table with 2,048 physical data segments but it’s totally believable that a small, widely scattered sample could end up with an extremely unrepresentative subset of the data. A completely random sample of the data would produce an estimate of around 500M rows for the predicate; but it would only take a fairly small variation in the sample (taking a few too many “historic” rows) to produce a large enough change in the estimate to change the execution plan, and a rare, but not extreme variation could easily take the estimate up to 5B.

Next Steps

It would be at this point in a performance assignment that I’d be asking around to find out if my guess about a massive data load operation was correct – if I couldn’t get the answer by talking to people I’d run a query against the whole data set to check the hypothesis, because there’s clearly some sort of skew in the data that’s causing a problem. I’d also run the critical part of the query a couple of times with events 10046/level 4 and 10053 set (but only fetching the first few rows) to find out from the trace file how large a sample Oracle was using, and then run the sampling query a few times to see what the sampled results looked like. Depending on the results I’d either find a way to stop Oracle from sampling for this query or I might create a virtual column (or just extended stats since it’s 11g) on just the trunc(dt_tm), possibly with a histogram in place (maybe coded by hand) if that could isolate the special dates and leave Oracle with a better estimate of the typical date. I might find I had to change the coalesce() to an nvl() as well – or create a virtual  column – to stop the sampling.

Finally, it’s worth noting that in 11g it’s possible to create pending (table preference “PUBLISH” = FALSE) stats for testing purposes; it’s also worth noting that the default histogram on trunc(dt_tm) would be a height-balanced histogram while we could create a frequency histogram in 12c since 12c allows us to specify up to 2,048 buckets.

Footnote

If you check the ODC thread you’ll see that the OP has marked as correct a suggestion to change:

    TRUNC (TB1.DT_TM)  = to_date(:b1,'MM/DD/YYYY HH24:MI:SS');  

to

    dt_tm >= trunc(to_date(:b1,'MM/DD/YYYY HH24:MI:SS'))
and dt_tm <  trunc(to_date(:b1,'MM/DD/YYYY HH24:MI:SS'))+1

Note that that’s “greater than or equal to” at one end and “strictly less than” at the other when using “date + 1”.

This has the effect of giving the optimizer a chance of using the low/high values of the column to produce a better (though perhaps still overlarge) and consistent estimate of the rows in the date range; and it may also stop the optimizer from doing dynamic sampling at level 3 (the “I’m guessing, let’s check” level) though it’s possible that the sampling would be disabled only if the coalesce() were changed to an nvl() as well.

Of course, from the information supplied, this looks like the OP would have to change a view definition and the run-time code to achieve the result. But in an ideal world doing things that avoid confusing the optimizer is usually the sensible strategy provided it doesn’t take an extreme amount of coding and testing.

 

June 23, 2018

Cursor_sharing force

Filed under: CBO,Infrastructure,Oracle,Troubleshooting — Jonathan Lewis @ 12:05 pm BST Jun 23,2018

Prompted by a recent ODC (OTN) question I’ve just written up an example of one case where setting the cursor_sharing parameter to force doesn’t work as you might expect. It’s a specific example of what I believe is a theme that can appear in several different circumstances: if your SQL mixes “genuine” bind variable with literals then the literals may not be substituted.

Here’s a simple data set to start with:


rem
rem     Script:         cursor_sharing_limit.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jun 2018
rem     Purpose:
rem
rem     Last tested
rem             18.1.0.0
rem             12.2.0.1
rem             12.1.0.2
rem

create table t1
as
select
        rownum            n1,
        rownum            n2,
        lpad(rownum,10)   small_vc,
        rpad('x',100,'x') padding
from dual
connect by
        level <= 1e4 -- > comment to avoid WordPress format issue
;

I haven’t bothered to gather stats – it’s not needed in trivial cases of CTAS.

Here’s one way to execute SQL that doesn’t get literal substitution when (apparently) it should:


alter system flush shared_pool;
alter session set cursor_sharing=force;

declare
        m_ct number;
        m_n1 number := 20;
begin
        execute immediate
                'select /*+ trace this */ count(*) from t1 where n2 = 15 and n1 = :b1'
                into m_ct using m_n1;
        dbms_output.put_line(m_ct);

        execute immediate
                'select /*+ trace this too */ count(*) from t1 where n1 = 15 and n2 = 15'
                into m_ct;
        dbms_output.put_line(m_ct);
end;
/

alter session set cursor_sharing=exact;

I’ve included a “hint” that allows me to find the SQL statements in v$sql very easily – and here they are, preceded by the query I used to find them:


select  sql_id, parse_calls, executions, rows_processed, sql_text 
from    v$sql
where   sql_text like 'select%trace this%'
and     sql_text not like '%v$sql%'
;


SQL_ID        PARSE_CALLS EXECUTIONS ROWS_PROCESSED
------------- ----------- ---------- --------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------------------
cbu4s78h5pfj5           1          1              1
select /*+ trace this too */ count(*) from t1 where n1 = :"SYS_B_0" and n2 = :"SYS_B_1"

cru67sufptx8x           1          1              1
select /*+ trace this */ count(*) from t1 where n2 = 15 and n1 = :b1

Notice how one statement – which used only literals – underwent bind variable transformation but the other – with its mix of literals and bind variables – didn’t. On the other hand, if I execute the mixed format statement from a basic SQL*Plus session then pull the plan from memory, this is what I get:


SQL> select /*+ SQL*Plus session */ count(*) from t1 where n2 = 15 and n1 = :b1;

  COUNT(*)
----------
         0

1 row selected.

SQL> select  sql_id, parse_calls, executions, rows_processed, sql_text
  2  from    v$sql
  3  where   sql_text like 'select%Plus session%'
  4  and     sql_text not like '%v$sql%'
  5  ;

SQL_ID        PARSE_CALLS EXECUTIONS ROWS_PROCESSED
------------- ----------- ---------- --------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------------------
gq2qy2a9yuta7           1          1              1
select /*+ SQL*Plus session */ count(*) from t1 where n2 = :"SYS_B_0" and n1 = :b1

When trying to take advantage of cursor_sharing = force, you have to think about how the SQL gets to the database engine – is it delivered directly, or is it sent through some layer of code that means the raw SQL statement is protected in some way from the substitution code.

Footnote:

I happen to have used an example that puts the bind variable into the where clause; you will see the same effect even if the bind variables are in the select list – for example if you’ve selected something like to_char(date_col, :formatting_variable).

April 6, 2018

SQL Monitor

Filed under: Execution plans,Oracle,Troubleshooting — Jonathan Lewis @ 7:50 am BST Apr 6,2018

I’ve mentioned the SQL Monitor report from time to time as a very useful way of reviewing execution plans – the feature is automatically enabled by parallel execution and by queries that are expected to take more than a few seconds to complete, and the inherent overheads of monitoring are less than the impact of enabling the rowsource execution statistics that allow you to use the ‘allstats’ format of dbms_xplan.display_cursor() to get detailed execution information for a query. The drawback to the SQL Monitor feature is that it doesn’t report predicate information. It’s also important to note that it falls under the performance and diagnostic licences: some of the available performance informtion comes from v$active_session_history, and the report is generated by a call to the dbms_sqltune package.

There are two basic calls – report_sql_monitor_list(), which appeared in 11.2, produces a summary of the statements and their individual executions (from the information that is still in memory, of course) and report_sql_monitor() shows detailed execution plans. Here’s a simple bit of SQL*Plus code showing basic use – it lists a summary of all the statements monitored in the last half hour, then (as it stands at present) the full monitoring details of the most recently completed monitored statement:


set long 250000
set longchunksize 65536

set linesize 254
set pagesize 100
set trimspool on

set heading off

column text_line format a254

spool report_sql_monitor

select 
        dbms_sqltune.report_sql_monitor_list(
                active_since_date       => sysdate - 30 / (24*60),
                type                    => 'TEXT'
        ) text_line 
from    dual
;

select 
        dbms_sqltune.report_sql_monitor(
--              sql_id                  => '&m_sql_id',
--              start_time_filter       => sysdate - 30/(24 * 60),
--              sql_exec_id             => &m_exec_id,
                type                    =>'TEXT'
        ) text_line 
from    dual
;

spool off




Here’s a variation that reports the details of the most recently completed execution of a query with the specified SQL_ID:

set linesize 255
set pagesize 200
set trimspool on
set long 200000

column text_line format a254
set heading off

define m_sql_id = 'fssk2xabr717j'

spool rep_mon

SELECT  dbms_sqltune.report_sql_monitor(
                sql_id=> v.sql_id,
                sql_exec_id => v.max_sql_exec_id
        ) text_line
from     (
        select
                sql_id,
                max(sql_exec_id)        max_sql_exec_id
        from
                v$sql_monitor
        where
                sql_id = '&m_sql_id'
        and     status like 'DONE%'
        group by
                sql_id
        )       v
;

spool off

set heading on
set linesize 132
set pagesize 60

And a sample of the text output, which is the result of monitoring the query “select * from dba_objects” (with an arraysize of 1,000 set in SQL*Plus):


SQL Monitoring Report

SQL Text
------------------------------
select /*+ monitor */ * from dba_objects

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  SYS (262:54671)
 SQL ID              :  7nqa1nnbav642
 SQL Execution ID    :  16777216
 Execution Started   :  04/05/2018 19:43:42
 First Refresh Time  :  04/05/2018 19:43:42
 Last Refresh Time   :  04/05/2018 19:45:04
 Duration            :  82s
 Module/Action       :  sqlplus@linux12 (TNS V1-V3)/-
 Service             :  SYS$USERS
 Program             :  sqlplus@linux12 (TNS V1-V3)
 Fetch Calls         :  93

Global Stats
===========================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
===========================================================================
|    0.31 |    0.29 |     0.00 |     0.02 |    93 |   6802 |   18 |   9MB |
===========================================================================

SQL Plan Monitoring Details (Plan Hash Value=2733869014)
=================================================================================================================================================================================
| Id |                Operation                 |       Name       |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read | Read  |  Mem  | Activity | Activity Detail |
|    |                                          |                  | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes | (Max) |   (%)    |   (# samples)   |
=================================================================================================================================================================================
|  0 | SELECT STATEMENT                         |                  |         |      |        83 |     +0 |     1 |    91314 |      |       |       |          |                 |
|  1 |   VIEW                                   | DBA_OBJECTS      |   91084 | 2743 |        83 |     +0 |     1 |    91314 |      |       |       |          |                 |
|  2 |    UNION-ALL                             |                  |         |      |        83 |     +0 |     1 |    91314 |      |       |       |          |                 |
|  3 |     TABLE ACCESS BY INDEX ROWID          | SUM$             |       1 |      |           |        |       |          |      |       |       |          |                 |
|  4 |      INDEX UNIQUE SCAN                   | I_SUM$_1         |       1 |      |           |        |       |          |      |       |       |          |                 |
|  5 |     TABLE ACCESS FULL                    | USER_EDITIONING$ |       1 |    2 |         1 |     +0 |   872 |        1 |      |       |       |          |                 |
|  6 |      TABLE ACCESS BY INDEX ROWID BATCHED | OBJ$             |       1 |    3 |           |        |       |          |      |       |       |          |                 |
|  7 |       INDEX RANGE SCAN                   | I_OBJ1           |       1 |    2 |           |        |       |          |      |       |       |          |                 |
|  8 |     FILTER                               |                  |         |      |        83 |     +0 |     1 |    91312 |      |       |       |          |                 |
|  9 |      HASH JOIN                           |                  |   91394 |  211 |        83 |     +0 |     1 |    91312 |      |       |    2M |          |                 |
| 10 |       TABLE ACCESS FULL                  | USER$            |     125 |    2 |         1 |     +0 |     1 |      125 |      |       |       |          |                 |
| 11 |       HASH JOIN                          |                  |   91394 |  207 |        83 |     +0 |     1 |    91312 |      |       |    1M |   100.00 | Cpu (1)         |
| 12 |        INDEX FULL SCAN                   | I_USER2          |     125 |    1 |         1 |     +0 |     1 |      125 |      |       |       |          |                 |
| 13 |        TABLE ACCESS FULL                 | OBJ$             |   91394 |  204 |        83 |     +0 |     1 |    91312 |   13 |   9MB |       |          |                 |
| 14 |      TABLE ACCESS FULL                   | USER_EDITIONING$ |       1 |    2 |         1 |     +0 |   872 |        1 |    2 | 16384 |       |          |                 |
| 15 |      NESTED LOOPS SEMI                   |                  |       1 |    2 |           |        |       |          |      |       |       |          |                 |
| 16 |       INDEX SKIP SCAN                    | I_USER2          |       1 |    1 |           |        |       |          |      |       |       |          |                 |
| 17 |       INDEX RANGE SCAN                   | I_OBJ4           |       1 |    1 |           |        |       |          |      |       |       |          |                 |
| 18 |      TABLE ACCESS FULL                   | USER_EDITIONING$ |       1 |    2 |           |        |       |          |      |       |       |          |                 |
| 19 |     HASH JOIN                            |                  |       2 |    4 |         1 |    +82 |     1 |        1 |      |       |       |          |                 |
| 20 |      NESTED LOOPS                        |                  |       2 |    4 |         1 |    +82 |     1 |        2 |      |       |       |          |                 |
| 21 |       STATISTICS COLLECTOR               |                  |         |      |         1 |    +82 |     1 |        2 |      |       |       |          |                 |
| 22 |        TABLE ACCESS FULL                 | LINK$            |       2 |    2 |         1 |    +82 |     1 |        2 |    2 | 16384 |       |          |                 |
| 23 |       TABLE ACCESS CLUSTER               | USER$            |       1 |    1 |         1 |    +82 |     2 |        2 |      |       |       |          |                 |
| 24 |        INDEX UNIQUE SCAN                 | I_USER#          |       1 |      |         1 |    +82 |     2 |        2 |    1 |  8192 |       |          |                 |
| 25 |      TABLE ACCESS FULL                   | USER$            |       1 |    1 |           |        |       |          |      |       |       |          |                 |
=================================================================================================================================================================================


1 row selected.


In a future note I’ll show an example of using one of these reports to identify the critical performance issue with an SQL statement that was raised recently on the ODC (OTN) database forum, but I’ll just point out one detail from this report. The “Time active (s)” says the query ran for about 83 seconds, but the Global Stats section tells us the elapsed time was 0.31 seconds. In this case the difference between these two is the time spent passing the data to the client.

Footnote

It is possible to force monitoring for an SQL statement with the /*+ monitor */ hint. Do be careful with this in production systems; each time the statement is executed the session will try to get the “Real-time descriptor latch” which is a latch with no latch children so if you monitor a lightweight statement that is called many times from many sessions you may find you lose a lot of time to latch contention and the attendant CPU spinning.

 

March 13, 2018

Deferred Invalidation

Filed under: 12c,CBO,Infrastructure,Oracle,Troubleshooting,Upgrades — Jonathan Lewis @ 6:30 pm BST Mar 13,2018

I was going to write an article on the way 12.2 has introduced the option for “deferred invalidation” for a number of DDL operations, but I did a quick google search before I started writing and found that both Franck Pachot and Richard Foote (yes, rebuild index is one of the operations) had got there long ago so here are a couple of links – as much for my own benefit as anything else:

Richard Foote:

Franck Pachot:

Franck’s 2nd example may be particularly relevant to some clients of mine who were having problems with SQL queries that were crashing (slowly and randomly) instead of running very efficiently because they were running queries against one subpartition of a table while another subpartition of the same table was subject to exchange. With a little bad luck in the timing an exchange that took place between a parse and an execute would cause a query to have its cursor invalidated and re-parsed in a way that failed to do (sub-)partition elimination the way it should have because the local indexes were in an indeterminate state.

 

March 12, 2018

Comparing Plans

Filed under: Execution plans,Oracle,Troubleshooting — Jonathan Lewis @ 8:01 am BST Mar 12,2018

It can be difficult to find the critical differences when comparing execution plans when you want to find out why the optimizer has changed its choice of plan and what may have happened to cause the change, and even the various diff_plan_xxx() functions in dbms_xplan don’t help very much, so I thought I’d write up an example that appeared recently on the ODC database forum to give people some ideas about how to approach the problem. There is, however, no simple algorithm that you can apply to narrow your focus down to the most probable cause of change, there are simply a few methods that have to be applied with a little flair and imagination.

We start with a query that has a “bad” plan and a “good” plan, with the implied questions: “What changed?” and “How do we get the good plan back?” If you’ve managed to capture the good plan the instant answer to “getting it back” is to create an SQL Plan Baseline for the query – but that’s really not a desirable thing to do every time a plan changes, and it’s not necessarily possible if the query keeps changing slightly over time. Ideally you should try identify why the plan can vary and work out how to manage that variation.

In theory you could collect all the statistics for all the tables and indexes involved in the query, making sure you’ve got both the “before” and “after” statistics; then you need to check for the actual values used for any bind variables just in case some specific values have a particular impact on the optimizer’s calculations; but gathering all that data is a lot of work, and having all the raw data that lets you (in theory) deduce why the plan has changed will probably not help very much unless you’re very lucky.

If you have to go through an exhaustive analysis to solve the problem it’s a lot of tedious work. (This, in part, is why tools like SQLd360 and SQLTXPLAIN are so helpful – as a first step they make it easy to collect a lot of the information you might need.) But with a simple text editor and a purely visual approach it’s often quite easy to narrow the focus down to the most relevant part of the plan – and that’s what I’m going to demonstrate with this example.

This posting is going to get quite long because the good and bad plans are 108 and 110 lines respectively, so I’m going to use the “hide/reveal” html codes inline as we work through a few steps of analysis that eliminate sections of the plan and make it easier to read and understand. So here’s the bad plan:

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                               |       |       |       |   244K(100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID               | ACCOUNT                       |     1 |    25 |       |     5  (20)| 00:00:01 |
|   2 |   BITMAP CONVERSION TO ROWIDS              |                               |       |       |       |            |          |
|   3 |    BITMAP AND                              |                               |       |       |       |            |          |
|   4 |     BITMAP INDEX SINGLE VALUE              | IDX_ACCOUNT_OBJ_SOURCE        |       |       |       |            |          |
|   5 |     BITMAP INDEX SINGLE VALUE              | IDX_ACCOUNT_OBJ_TYPE          |       |       |       |            |          |
|   6 |     BITMAP CONVERSION FROM ROWIDS          |                               |       |       |       |            |          |
|   7 |      SORT ORDER BY                         |                               |       |       |       |            |          |
|   8 |       INDEX RANGE SCAN                     | UQ_ACCOUNT                    |     5 |       |       |     2   (0)| 00:00:01 |
|   9 |   TABLE ACCESS BY INDEX ROWID              | ACCOUNT                       |     1 |    25 |       |     5  (20)| 00:00:01 |
|  10 |    BITMAP CONVERSION TO ROWIDS             |                               |       |       |       |            |          |
|  11 |     BITMAP AND                             |                               |       |       |       |            |          |
|  12 |      BITMAP INDEX SINGLE VALUE             | IDX_ACCOUNT_OBJ_SOURCE        |       |       |       |            |          |
|  13 |      BITMAP INDEX SINGLE VALUE             | IDX_ACCOUNT_OBJ_TYPE          |       |       |       |            |          |
|  14 |      BITMAP CONVERSION FROM ROWIDS         |                               |       |       |       |            |          |
|  15 |       SORT ORDER BY                        |                               |       |       |       |            |          |
|  16 |        INDEX RANGE SCAN                    | UQ_ACCOUNT                    |     5 |       |       |     2   (0)| 00:00:01 |
|  17 |  HASH JOIN RIGHT OUTER                     |                               | 93634 |    28M|       |   244K  (1)| 00:49:00 |
|  18 |   VIEW                                     | X_SECURITY_ACCOUNTS_V         |   434 | 12152 |       |   368   (2)| 00:00:05 |
|  19 |    HASH GROUP BY                           |                               |   434 |  7812 |       |   368   (2)| 00:00:05 |
|  20 |     VIEW                                   |                               |   434 |  7812 |       |   367   (2)| 00:00:05 |
|  21 |      SORT UNIQUE                           |                               |   434 |   101K|       |   367   (2)| 00:00:05 |
|  22 |       UNION-ALL                            |                               |       |       |       |            |          |
|  23 |        CONNECT BY WITH FILTERING (UNIQUE)  |                               |       |       |       |            |          |
|  24 |         CONCATENATION                      |                               |       |       |       |            |          |
|  25 |          INLIST ITERATOR                   |                               |       |       |       |            |          |
|  26 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |     1 |    69 |       |     7   (0)| 00:00:01 |
|  27 |            INDEX RANGE SCAN                | UQ_ACCOUNT                    |     1 |       |       |     6   (0)| 00:00:01 |
|  28 |          INLIST ITERATOR                   |                               |       |       |       |            |          |
|  29 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |     1 |    69 |       |     7   (0)| 00:00:01 |
|  30 |            INDEX RANGE SCAN                | UQ_ACCOUNT                    |     1 |       |       |     6   (0)| 00:00:01 |
|  31 |         NESTED LOOPS                       |                               |    36 |  4752 |       |    34   (0)| 00:00:01 |
|  32 |          CONNECT BY PUMP                   |                               |       |       |       |            |          |
|  33 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                       |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  34 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT            |    18 |       |       |     2   (0)| 00:00:01 |
|  35 |        CONNECT BY WITH FILTERING (UNIQUE)  |                               |       |       |       |            |          |
|  36 |         CONCATENATION                      |                               |       |       |       |            |          |
|  37 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                       |     1 |    69 |       |     4   (0)| 00:00:01 |
|  38 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT            |     1 |       |       |     3   (0)| 00:00:01 |
|  39 |          INLIST ITERATOR                   |                               |       |       |       |            |          |
|  40 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |    20 |  1380 |       |    47   (0)| 00:00:01 |
|  41 |            INDEX RANGE SCAN                | IDX_ACCOUNT_PARENT            |    20 |       |       |    39   (0)| 00:00:01 |
|  42 |         NESTED LOOPS                       |                               |   374 | 49368 |       |   261   (0)| 00:00:04 |
|  43 |          CONNECT BY PUMP                   |                               |       |       |       |            |          |
|  44 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                       |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  45 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT            |    18 |       |       |     2   (0)| 00:00:01 |
|  46 |        TABLE ACCESS BY INDEX ROWID         | ACCOUNT                       |     1 |    26 |       |     4   (0)| 00:00:01 |
|  47 |         INDEX RANGE SCAN                   | IDX_ACCOUNT_PARENT            |     1 |       |       |     3   (0)| 00:00:01 |
|  48 |   HASH JOIN RIGHT OUTER                    |                               | 52211 |    14M|       |   244K  (1)| 00:48:55 |
|  49 |    VIEW                                    | X_SECURITY_OBJECTS_V          |  1976 | 55328 |       |  3303   (1)| 00:00:40 |
|  50 |     HASH GROUP BY                          |                               |  1976 | 35568 |       |  3303   (1)| 00:00:40 |
|  51 |      VIEW                                  |                               |  1976 | 35568 |       |  3302   (1)| 00:00:40 |
|  52 |       SORT UNIQUE                          |                               |  1976 |   482K|       |  3302   (1)| 00:00:40 |
|  53 |        UNION-ALL                           |                               |       |       |       |            |          |
|  54 |         CONNECT BY WITH FILTERING (UNIQUE) |                               |       |       |       |            |          |
|  55 |          TABLE ACCESS FULL                 | ORGANIZATION                  |  1965 |   132K|       |   551   (2)| 00:00:07 |
|  56 |          HASH JOIN                         |                               |     5 |   675 |       |  1099   (1)| 00:00:14 |
|  57 |           CONNECT BY PUMP                  |                               |       |       |       |            |          |
|  58 |           TABLE ACCESS FULL                | ORGANIZATION                  | 76990 |  5939K|       |   547   (1)| 00:00:07 |
|  59 |         FILTER                             |                               |       |       |       |            |          |
|  60 |          CONNECT BY WITH FILTERING (UNIQUE)|                               |       |       |       |            |          |
|  61 |           TABLE ACCESS FULL                | ORGANIZATION                  |     4 |   272 |       |   548   (1)| 00:00:07 |
|  62 |           HASH JOIN                        |                               |     1 |   124 |       |  1096   (1)| 00:00:14 |
|  63 |            CONNECT BY PUMP                 |                               |       |       |       |            |          |
|  64 |            TABLE ACCESS FULL               | ORGANIZATION                  | 76990 |  5112K|       |   548   (1)| 00:00:07 |
|  65 |         INLIST ITERATOR                    |                               |       |       |       |            |          |
|  66 |          TABLE ACCESS BY INDEX ROWID       | ORGANIZATION                  |     1 |    37 |       |     5   (0)| 00:00:01 |
|  67 |           INDEX RANGE SCAN                 | UQ_ORGANIZATION_NATURAL       |     1 |       |       |     4   (0)| 00:00:01 |
|  68 |    HASH JOIN                               |                               | 52211 |    12M|       |   241K  (1)| 00:48:16 |
|  69 |     TABLE ACCESS FULL                      | CURRENCY                      |    40 |  2560 |       |     3   (0)| 00:00:01 |
|  70 |     HASH JOIN                              |                               | 52211 |  9993K|  3072K|   241K  (1)| 00:48:16 |
|  71 |      TABLE ACCESS FULL                     | ACCOUNT                       | 45570 |  2536K|       |   274   (1)| 00:00:04 |
|  72 |      HASH JOIN                             |                               | 52211 |  7087K|       |   240K  (1)| 00:48:06 |
|  73 |       TABLE ACCESS FULL                    | COMPANY                       |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  74 |       HASH JOIN RIGHT OUTER                |                               | 52211 |  6628K|       |   240K  (1)| 00:48:06 |
|  75 |        VIEW                                |                               |    19 |   247 |       |    18  (12)| 00:00:01 |
|  76 |         FILTER                             |                               |       |       |       |            |          |
|  77 |          CONNECT BY WITH FILTERING         |                               |       |       |       |            |          |
|  78 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |     1 |    69 |       |     3   (0)| 00:00:01 |
|  79 |            INDEX RANGE SCAN                | UQ_ACCOUNT                    |     1 |       |       |     2   (0)| 00:00:01 |
|  80 |           NESTED LOOPS                     |                               |    18 |  2376 |       |    13   (0)| 00:00:01 |
|  81 |            CONNECT BY PUMP                 |                               |       |       |       |            |          |
|  82 |            TABLE ACCESS BY INDEX ROWID     | ACCOUNT                       |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  83 |             INDEX RANGE SCAN               | IDX_ACCOUNT_PARENT            |    18 |       |       |     2   (0)| 00:00:01 |
|  84 |        HASH JOIN RIGHT OUTER               |                               | 52211 |  5965K|       |   240K  (1)| 00:48:06 |
|  85 |         VIEW                               |                               |     2 |    26 |       |    30   (7)| 00:00:01 |
|  86 |          FILTER                            |                               |       |       |       |            |          |
|  87 |           CONNECT BY WITH FILTERING        |                               |       |       |       |            |          |
|  88 |            TABLE ACCESS BY INDEX ROWID     | ORGANIZATION                  |     1 |    69 |       |    12   (0)| 00:00:01 |
|  89 |             BITMAP CONVERSION TO ROWIDS    |                               |       |       |       |            |          |
|  90 |              BITMAP AND                    |                               |       |       |       |            |          |
|  91 |               BITMAP INDEX SINGLE VALUE    | IDX_ORGANIZATION_OBJ_TYPE     |       |       |       |            |          |
|  92 |               BITMAP OR                    |                               |       |       |       |            |          |
|  93 |                BITMAP INDEX SINGLE VALUE   | IDX_ORGANIZATION_OBJ_COMPANY  |       |       |       |            |          |
|  94 |                BITMAP INDEX SINGLE VALUE   | IDX_ORGANIZATION_OBJ_COMPANY  |       |       |       |            |          |
|  95 |                BITMAP INDEX SINGLE VALUE   | IDX_ORGANIZATION_OBJ_COMPANY  |       |       |       |            |          |
|  96 |                BITMAP INDEX SINGLE VALUE   | IDX_ORGANIZATION_OBJ_COMPANY  |       |       |       |            |          |
|  97 |                BITMAP INDEX SINGLE VALUE   | IDX_ORGANIZATION_OBJ_COMPANY  |       |       |       |            |          |
|  98 |            NESTED LOOPS                    |                               |     1 |   135 |       |    15   (0)| 00:00:01 |
|  99 |             CONNECT BY PUMP                |                               |       |       |       |            |          |
| 100 |             TABLE ACCESS BY INDEX ROWID    | ORGANIZATION                  |     1 |    79 |       |     3   (0)| 00:00:01 |
| 101 |              INDEX RANGE SCAN              | IDX_ORGANIZATION_PARENT       |     1 |       |       |     2   (0)| 00:00:01 |
| 102 |         HASH JOIN                          |                               | 52211 |  5302K|       |   240K  (1)| 00:48:06 |
| 103 |          TABLE ACCESS FULL                 | TIME                          |     9 |   171 |       |     3   (0)| 00:00:01 |
| 104 |          NESTED LOOPS                      |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 105 |           NESTED LOOPS                     |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 106 |            NESTED LOOPS                    |                               |  5756 |   185K|       |   552   (1)| 00:00:07 |
| 107 |             FAST DUAL                      |                               |     1 |       |       |     2   (0)| 00:00:01 |
| 108 |             TABLE ACCESS FULL              | ORGANIZATION                  |  5756 |   185K|       |   550   (1)| 00:00:07 |
| 109 |            INDEX RANGE SCAN                | IDX_FACT_PLAN_SUPP_K_COMP_ORG |    65 |       |       |    19   (0)| 00:00:01 |
| 110 |           TABLE ACCESS BY INDEX ROWID      | FACT_PLAN_SUPP                |   110 |  5720 |       |    82   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------------------------

and the good plan

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                              |       |       |       |   545K(100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID               | ACCOUNT                      |     1 |    25 |       |     5  (20)| 00:00:01 |
|   2 |   BITMAP CONVERSION TO ROWIDS              |                              |       |       |       |            |          |
|   3 |    BITMAP AND                              |                              |       |       |       |            |          |
|   4 |     BITMAP INDEX SINGLE VALUE              | IDX_ACCOUNT_OBJ_SOURCE       |       |       |       |            |          |
|   5 |     BITMAP INDEX SINGLE VALUE              | IDX_ACCOUNT_OBJ_TYPE         |       |       |       |            |          |
|   6 |     BITMAP CONVERSION FROM ROWIDS          |                              |       |       |       |            |          |
|   7 |      SORT ORDER BY                         |                              |       |       |       |            |          |
|   8 |       INDEX RANGE SCAN                     | UQ_ACCOUNT                   |     5 |       |       |     2   (0)| 00:00:01 |
|   9 |   TABLE ACCESS BY INDEX ROWID              | ACCOUNT                      |     1 |    25 |       |     5  (20)| 00:00:01 |
|  10 |    BITMAP CONVERSION TO ROWIDS             |                              |       |       |       |            |          |
|  11 |     BITMAP AND                             |                              |       |       |       |            |          |
|  12 |      BITMAP INDEX SINGLE VALUE             | IDX_ACCOUNT_OBJ_SOURCE       |       |       |       |            |          |
|  13 |      BITMAP INDEX SINGLE VALUE             | IDX_ACCOUNT_OBJ_TYPE         |       |       |       |            |          |
|  14 |      BITMAP CONVERSION FROM ROWIDS         |                              |       |       |       |            |          |
|  15 |       SORT ORDER BY                        |                              |       |       |       |            |          |
|  16 |        INDEX RANGE SCAN                    | UQ_ACCOUNT                   |     5 |       |       |     2   (0)| 00:00:01 |
|  17 |  HASH JOIN RIGHT OUTER                     |                              |   539K|   162M|       |   545K  (2)| 01:49:03 |
|  18 |   VIEW                                     | X_SECURITY_ACCOUNTS_V        |   434 | 12152 |       |   368   (2)| 00:00:05 |
|  19 |    HASH GROUP BY                           |                              |   434 |  7812 |       |   368   (2)| 00:00:05 |
|  20 |     VIEW                                   |                              |   434 |  7812 |       |   367   (1)| 00:00:05 |
|  21 |      SORT UNIQUE                           |                              |   434 |   101K|       |   367   (1)| 00:00:05 |
|  22 |       UNION-ALL                            |                              |       |       |       |            |          |
|  23 |        CONNECT BY WITH FILTERING (UNIQUE)  |                              |       |       |       |            |          |
|  24 |         CONCATENATION                      |                              |       |       |       |            |          |
|  25 |          INLIST ITERATOR                   |                              |       |       |       |            |          |
|  26 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                      |     1 |    69 |       |     7   (0)| 00:00:01 |
|  27 |            INDEX RANGE SCAN                | UQ_ACCOUNT                   |     1 |       |       |     6   (0)| 00:00:01 |
|  28 |          INLIST ITERATOR                   |                              |       |       |       |            |          |
|  29 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                      |     1 |    69 |       |     7   (0)| 00:00:01 |
|  30 |            INDEX RANGE SCAN                | UQ_ACCOUNT                   |     1 |       |       |     6   (0)| 00:00:01 |
|  31 |         NESTED LOOPS                       |                              |    36 |  4752 |       |    34   (0)| 00:00:01 |
|  32 |          CONNECT BY PUMP                   |                              |       |       |       |            |          |
|  33 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  34 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |    18 |       |       |     2   (0)| 00:00:01 |
|  35 |        CONNECT BY WITH FILTERING (UNIQUE)  |                              |       |       |       |            |          |
|  36 |         CONCATENATION                      |                              |       |       |       |            |          |
|  37 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |     1 |    69 |       |     4   (0)| 00:00:01 |
|  38 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |     1 |       |       |     3   (0)| 00:00:01 |
|  39 |          INLIST ITERATOR                   |                              |       |       |       |            |          |
|  40 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                      |    20 |  1380 |       |    47   (0)| 00:00:01 |
|  41 |            INDEX RANGE SCAN                | IDX_ACCOUNT_PARENT           |    20 |       |       |    39   (0)| 00:00:01 |
|  42 |         NESTED LOOPS                       |                              |   374 | 49368 |       |   261   (0)| 00:00:04 |
|  43 |          CONNECT BY PUMP                   |                              |       |       |       |            |          |
|  44 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  45 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |    18 |       |       |     2   (0)| 00:00:01 |
|  46 |        TABLE ACCESS BY INDEX ROWID         | ACCOUNT                      |     1 |    26 |       |     4   (0)| 00:00:01 |
|  47 |         INDEX RANGE SCAN                   | IDX_ACCOUNT_PARENT           |     1 |       |       |     3   (0)| 00:00:01 |
|  48 |   HASH JOIN RIGHT OUTER                    |                              |   300K|    82M|       |   544K  (2)| 01:48:58 |
|  49 |    VIEW                                    | X_SECURITY_OBJECTS_V         |  1920 | 53760 |       |  3303   (1)| 00:00:40 |
|  50 |     HASH GROUP BY                          |                              |  1920 | 34560 |       |  3303   (1)| 00:00:40 |
|  51 |      VIEW                                  |                              |  1920 | 34560 |       |  3302   (1)| 00:00:40 |
|  52 |       SORT UNIQUE                          |                              |  1920 |   468K|       |  3302   (1)| 00:00:40 |
|  53 |        UNION-ALL                           |                              |       |       |       |            |          |
|  54 |         CONNECT BY WITH FILTERING (UNIQUE) |                              |       |       |       |            |          |
|  55 |          TABLE ACCESS FULL                 | ORGANIZATION                 |  1909 |   128K|       |   551   (2)| 00:00:07 |
|  56 |          HASH JOIN                         |                              |     5 |   675 |       |  1099   (1)| 00:00:14 |
|  57 |           CONNECT BY PUMP                  |                              |       |       |       |            |          |
|  58 |           TABLE ACCESS FULL                | ORGANIZATION                 | 76836 |  5927K|       |   547   (1)| 00:00:07 |
|  59 |         FILTER                             |                              |       |       |       |            |          |
|  60 |          CONNECT BY WITH FILTERING (UNIQUE)|                              |       |       |       |            |          |
|  61 |           TABLE ACCESS FULL                | ORGANIZATION                 |     4 |   272 |       |   548   (1)| 00:00:07 |
|  62 |           HASH JOIN                        |                              |     1 |   124 |       |  1096   (1)| 00:00:14 |
|  63 |            CONNECT BY PUMP                 |                              |       |       |       |            |          |
|  64 |            TABLE ACCESS FULL               | ORGANIZATION                 | 76836 |  5102K|       |   548   (1)| 00:00:07 |
|  65 |         INLIST ITERATOR                    |                              |       |       |       |            |          |
|  66 |          TABLE ACCESS BY INDEX ROWID       | ORGANIZATION                 |     1 |    37 |       |     5   (0)| 00:00:01 |
|  67 |           INDEX RANGE SCAN                 | UQ_ORGANIZATION_NATURAL      |     1 |       |       |     4   (0)| 00:00:01 |
|  68 |    HASH JOIN                               |                              |   300K|    74M|       |   541K  (2)| 01:48:18 |
|  69 |     TABLE ACCESS FULL                      | CURRENCY                     |    40 |  2560 |       |     3   (0)| 00:00:01 |
|  70 |     HASH JOIN RIGHT OUTER                  |                              |   300K|    56M|       |   541K  (2)| 01:48:18 |
|  71 |      VIEW                                  |                              |    19 |   247 |       |    18  (12)| 00:00:01 |
|  72 |       FILTER                               |                              |       |       |       |            |          |
|  73 |        CONNECT BY WITH FILTERING           |                              |       |       |       |            |          |
|  74 |         TABLE ACCESS BY INDEX ROWID        | ACCOUNT                      |     1 |    69 |       |     3   (0)| 00:00:01 |
|  75 |          INDEX RANGE SCAN                  | UQ_ACCOUNT                   |     1 |       |       |     2   (0)| 00:00:01 |
|  76 |         NESTED LOOPS                       |                              |    18 |  2376 |       |    13   (0)| 00:00:01 |
|  77 |          CONNECT BY PUMP                   |                              |       |       |       |            |          |
|  78 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  79 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |    18 |       |       |     2   (0)| 00:00:01 |
|  80 |      HASH JOIN                             |                              |   300K|    52M|  3072K|   541K  (2)| 01:48:18 |
|  81 |       TABLE ACCESS FULL                    | ACCOUNT                      | 45564 |  2536K|       |   274   (1)| 00:00:04 |
|  82 |       HASH JOIN                            |                              |   300K|    36M|  2576K|   539K  (2)| 01:47:50 |
|  83 |        TABLE ACCESS FULL                   | ORGANIZATION                 | 58577 |  1887K|       |   550   (1)| 00:00:07 |
|  84 |        HASH JOIN                           |                              |  6984K|   619M|       |   503K  (2)| 01:40:44 |
|  85 |         TABLE ACCESS FULL                  | COMPANY                      |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  86 |         HASH JOIN RIGHT OUTER              |                              |  6984K|   559M|       |   503K  (2)| 01:40:44 |
|  87 |          VIEW                              |                              |     2 |    26 |       |    29   (7)| 00:00:01 |
|  88 |           FILTER                           |                              |       |       |       |            |          |
|  89 |            CONNECT BY WITH FILTERING       |                              |       |       |       |            |          |
|  90 |             TABLE ACCESS BY INDEX ROWID    | ORGANIZATION                 |     1 |    69 |       |    12   (0)| 00:00:01 |
|  91 |              BITMAP CONVERSION TO ROWIDS   |                              |       |       |       |            |          |
|  92 |               BITMAP AND                   |                              |       |       |       |            |          |
|  93 |                BITMAP INDEX SINGLE VALUE   | IDX_ORGANIZATION_OBJ_TYPE    |       |       |       |            |          |
|  94 |                BITMAP OR                   |                              |       |       |       |            |          |
|  95 |                 BITMAP INDEX SINGLE VALUE  | IDX_ORGANIZATION_OBJ_COMPANY |       |       |       |            |          |
|  96 |                 BITMAP INDEX SINGLE VALUE  | IDX_ORGANIZATION_OBJ_COMPANY |       |       |       |            |          |
|  97 |                 BITMAP INDEX SINGLE VALUE  | IDX_ORGANIZATION_OBJ_COMPANY |       |       |       |            |          |
|  98 |                 BITMAP INDEX SINGLE VALUE  | IDX_ORGANIZATION_OBJ_COMPANY |       |       |       |            |          |
|  99 |                 BITMAP INDEX SINGLE VALUE  | IDX_ORGANIZATION_OBJ_COMPANY |       |       |       |            |          |
| 100 |             NESTED LOOPS                   |                              |     1 |   135 |       |    15   (0)| 00:00:01 |
| 101 |              CONNECT BY PUMP               |                              |       |       |       |            |          |
| 102 |              TABLE ACCESS BY INDEX ROWID   | ORGANIZATION                 |     1 |    79 |       |     3   (0)| 00:00:01 |
| 103 |               INDEX RANGE SCAN             | IDX_ORGANIZATION_PARENT      |     1 |       |       |     2   (0)| 00:00:01 |
| 104 |          HASH JOIN                         |                              |  6984K|   472M|       |   503K  (2)| 01:40:43 |
| 105 |           NESTED LOOPS                     |                              |     9 |   171 |       |     5   (0)| 00:00:01 |
| 106 |            FAST DUAL                       |                              |     1 |       |       |     2   (0)| 00:00:01 |
| 107 |            TABLE ACCESS FULL               | TIME                         |     9 |   171 |       |     3   (0)| 00:00:01 |
| 108 |           TABLE ACCESS FULL                | FACT_PLAN_SUPP               |    84M|  4207M|       |   503K  (2)| 01:40:37 |
-----------------------------------------------------------------------------------------------------------------------------------

You might want to cut and paste these into two separate windows in a text editor – which is how I worked the plans (using vi on a linux box).

I’ve highlighted two lines from the bad plan – operations 1 and 17, which are both indented one place; the level of indent tells me that operation 17 is the start of plan for the main query and operation 1 is the start of plan for an inline scalar subquery, so my first check is that operations 1 to 16 (highlighted in the good plan) are the same in both plans: they are, so they’re probably not the source of the problem and can be eliminated from the plans. In passing, you’ll notice that operation 9 is a table access which is indented one more place – depending on exact version of Oracle (and which patches have fixed which bugs) this might mean there are two scalar subqueries in the select list, it might mean there’s one scalar subquery with a “pushed” filter subquery, or (most likely on recent versions of Oracle) it might mean that there’s a case or decode() operator with two scalar subqueries invoked by the operator.

I’ve also highlighted two other chunks in both plans. Looking at the bad plan, operation 75 is an inline view derived from operations 76 – 83; this corresponds to the view at operation 71 in the good plan, derived from operations 72 – 79: a quick check shows that these two sets of lines are identical, so they can be eliminated and replaced with just a single VIEW operation which I’ll identify by adding in an object Name of VIEW_1.

Similarly I’ve highlighted operations 86 – 101 in the bad plan and 88 – 103 in the good plan – a visual check shows that they are identical (with just a tiny difference in the final VIEW cost) so I’ve eliminated those lines and given the controlling VIEW operation an object Name of VIEW_2.

With the three chunks removed, this is what the plans look like:

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                               |       |       |       |   244K(100)|          |
|  17 |  HASH JOIN RIGHT OUTER                     |                               | 93634 |    28M|       |   244K  (1)| 00:49:00 |
|  18 |   VIEW                                     | X_SECURITY_ACCOUNTS_V         |   434 | 12152 |       |   368   (2)| 00:00:05 |
|  19 |    HASH GROUP BY                           |                               |   434 |  7812 |       |   368   (2)| 00:00:05 |
|  20 |     VIEW                                   |                               |   434 |  7812 |       |   367   (2)| 00:00:05 |
|  21 |      SORT UNIQUE                           |                               |   434 |   101K|       |   367   (2)| 00:00:05 |
|  22 |       UNION-ALL                            |                               |       |       |       |            |          |
|  23 |        CONNECT BY WITH FILTERING (UNIQUE)  |                               |       |       |       |            |          |
|  24 |         CONCATENATION                      |                               |       |       |       |            |          |
|  25 |          INLIST ITERATOR                   |                               |       |       |       |            |          |
|  26 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |     1 |    69 |       |     7   (0)| 00:00:01 |
|  27 |            INDEX RANGE SCAN                | UQ_ACCOUNT                    |     1 |       |       |     6   (0)| 00:00:01 |
|  28 |          INLIST ITERATOR                   |                               |       |       |       |            |          |
|  29 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |     1 |    69 |       |     7   (0)| 00:00:01 |
|  30 |            INDEX RANGE SCAN                | UQ_ACCOUNT                    |     1 |       |       |     6   (0)| 00:00:01 |
|  31 |         NESTED LOOPS                       |                               |    36 |  4752 |       |    34   (0)| 00:00:01 |
|  32 |          CONNECT BY PUMP                   |                               |       |       |       |            |          |
|  33 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                       |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  34 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT            |    18 |       |       |     2   (0)| 00:00:01 |
|  35 |        CONNECT BY WITH FILTERING (UNIQUE)  |                               |       |       |       |            |          |
|  36 |         CONCATENATION                      |                               |       |       |       |            |          |
|  37 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                       |     1 |    69 |       |     4   (0)| 00:00:01 |
|  38 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT            |     1 |       |       |     3   (0)| 00:00:01 |
|  39 |          INLIST ITERATOR                   |                               |       |       |       |            |          |
|  40 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                       |    20 |  1380 |       |    47   (0)| 00:00:01 |
|  41 |            INDEX RANGE SCAN                | IDX_ACCOUNT_PARENT            |    20 |       |       |    39   (0)| 00:00:01 |
|  42 |         NESTED LOOPS                       |                               |   374 | 49368 |       |   261   (0)| 00:00:04 |
|  43 |          CONNECT BY PUMP                   |                               |       |       |       |            |          |
|  44 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                       |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  45 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT            |    18 |       |       |     2   (0)| 00:00:01 |
|  46 |        TABLE ACCESS BY INDEX ROWID         | ACCOUNT                       |     1 |    26 |       |     4   (0)| 00:00:01 |
|  47 |         INDEX RANGE SCAN                   | IDX_ACCOUNT_PARENT            |     1 |       |       |     3   (0)| 00:00:01 |
|  48 |   HASH JOIN RIGHT OUTER                    |                               | 52211 |    14M|       |   244K  (1)| 00:48:55 |
|  49 |    VIEW                                    | X_SECURITY_OBJECTS_V          |  1976 | 55328 |       |  3303   (1)| 00:00:40 |
|  50 |     HASH GROUP BY                          |                               |  1976 | 35568 |       |  3303   (1)| 00:00:40 |
|  51 |      VIEW                                  |                               |  1976 | 35568 |       |  3302   (1)| 00:00:40 |
|  52 |       SORT UNIQUE                          |                               |  1976 |   482K|       |  3302   (1)| 00:00:40 |
|  53 |        UNION-ALL                           |                               |       |       |       |            |          |
|  54 |         CONNECT BY WITH FILTERING (UNIQUE) |                               |       |       |       |            |          |
|  55 |          TABLE ACCESS FULL                 | ORGANIZATION                  |  1965 |   132K|       |   551   (2)| 00:00:07 |
|  56 |          HASH JOIN                         |                               |     5 |   675 |       |  1099   (1)| 00:00:14 |
|  57 |           CONNECT BY PUMP                  |                               |       |       |       |            |          |
|  58 |           TABLE ACCESS FULL                | ORGANIZATION                  | 76990 |  5939K|       |   547   (1)| 00:00:07 |
|  59 |         FILTER                             |                               |       |       |       |            |          |
|  60 |          CONNECT BY WITH FILTERING (UNIQUE)|                               |       |       |       |            |          |
|  61 |           TABLE ACCESS FULL                | ORGANIZATION                  |     4 |   272 |       |   548   (1)| 00:00:07 |
|  62 |           HASH JOIN                        |                               |     1 |   124 |       |  1096   (1)| 00:00:14 |
|  63 |            CONNECT BY PUMP                 |                               |       |       |       |            |          |
|  64 |            TABLE ACCESS FULL               | ORGANIZATION                  | 76990 |  5112K|       |   548   (1)| 00:00:07 |
|  65 |         INLIST ITERATOR                    |                               |       |       |       |            |          |
|  66 |          TABLE ACCESS BY INDEX ROWID       | ORGANIZATION                  |     1 |    37 |       |     5   (0)| 00:00:01 |
|  67 |           INDEX RANGE SCAN                 | UQ_ORGANIZATION_NATURAL       |     1 |       |       |     4   (0)| 00:00:01 |
|  68 |    HASH JOIN                               |                               | 52211 |    12M|       |   241K  (1)| 00:48:16 |
|  69 |     TABLE ACCESS FULL                      | CURRENCY                      |    40 |  2560 |       |     3   (0)| 00:00:01 |
|  70 |     HASH JOIN                              |                               | 52211 |  9993K|  3072K|   241K  (1)| 00:48:16 |
|  71 |      TABLE ACCESS FULL                     | ACCOUNT                       | 45570 |  2536K|       |   274   (1)| 00:00:04 |
|  72 |      HASH JOIN                             |                               | 52211 |  7087K|       |   240K  (1)| 00:48:06 |
|  73 |       TABLE ACCESS FULL                    | COMPANY                       |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  74 |       HASH JOIN RIGHT OUTER                |                               | 52211 |  6628K|       |   240K  (1)| 00:48:06 |
|  75 |        VIEW                                | --- VIEW_1                    |    19 |   247 |       |    18  (12)| 00:00:01 |
|  84 |        HASH JOIN RIGHT OUTER               |                               | 52211 |  5965K|       |   240K  (1)| 00:48:06 |
|  85 |         VIEW                               | --- VIEW_2                    |     2 |    26 |       |    30   (7)| 00:00:01 |
| 102 |         HASH JOIN                          |                               | 52211 |  5302K|       |   240K  (1)| 00:48:06 |
| 103 |          TABLE ACCESS FULL                 | TIME                          |     9 |   171 |       |     3   (0)| 00:00:01 |
| 104 |          NESTED LOOPS                      |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 105 |           NESTED LOOPS                     |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 106 |            NESTED LOOPS                    |                               |  5756 |   185K|       |   552   (1)| 00:00:07 |
| 107 |             FAST DUAL                      |                               |     1 |       |       |     2   (0)| 00:00:01 |
| 108 |             TABLE ACCESS FULL              | ORGANIZATION                  |  5756 |   185K|       |   550   (1)| 00:00:07 |
| 109 |            INDEX RANGE SCAN                | IDX_FACT_PLAN_SUPP_K_COMP_ORG |    65 |       |       |    19   (0)| 00:00:01 |
| 110 |           TABLE ACCESS BY INDEX ROWID      | FACT_PLAN_SUPP                |   110 |  5720 |       |    82   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------------------------

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                              |       |       |       |   545K(100)|          |
|  17 |  HASH JOIN RIGHT OUTER                     |                              |   539K|   162M|       |   545K  (2)| 01:49:03 |
|  18 |   VIEW                                     | X_SECURITY_ACCOUNTS_V        |   434 | 12152 |       |   368   (2)| 00:00:05 |
|  19 |    HASH GROUP BY                           |                              |   434 |  7812 |       |   368   (2)| 00:00:05 |
|  20 |     VIEW                                   |                              |   434 |  7812 |       |   367   (1)| 00:00:05 |
|  21 |      SORT UNIQUE                           |                              |   434 |   101K|       |   367   (1)| 00:00:05 |
|  22 |       UNION-ALL                            |                              |       |       |       |            |          |
|  23 |        CONNECT BY WITH FILTERING (UNIQUE)  |                              |       |       |       |            |          |
|  24 |         CONCATENATION                      |                              |       |       |       |            |          |
|  25 |          INLIST ITERATOR                   |                              |       |       |       |            |          |
|  26 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                      |     1 |    69 |       |     7   (0)| 00:00:01 |
|  27 |            INDEX RANGE SCAN                | UQ_ACCOUNT                   |     1 |       |       |     6   (0)| 00:00:01 |
|  28 |          INLIST ITERATOR                   |                              |       |       |       |            |          |
|  29 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                      |     1 |    69 |       |     7   (0)| 00:00:01 |
|  30 |            INDEX RANGE SCAN                | UQ_ACCOUNT                   |     1 |       |       |     6   (0)| 00:00:01 |
|  31 |         NESTED LOOPS                       |                              |    36 |  4752 |       |    34   (0)| 00:00:01 |
|  32 |          CONNECT BY PUMP                   |                              |       |       |       |            |          |
|  33 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  34 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |    18 |       |       |     2   (0)| 00:00:01 |
|  35 |        CONNECT BY WITH FILTERING (UNIQUE)  |                              |       |       |       |            |          |
|  36 |         CONCATENATION                      |                              |       |       |       |            |          |
|  37 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |     1 |    69 |       |     4   (0)| 00:00:01 |
|  38 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |     1 |       |       |     3   (0)| 00:00:01 |
|  39 |          INLIST ITERATOR                   |                              |       |       |       |            |          |
|  40 |           TABLE ACCESS BY INDEX ROWID      | ACCOUNT                      |    20 |  1380 |       |    47   (0)| 00:00:01 |
|  41 |            INDEX RANGE SCAN                | IDX_ACCOUNT_PARENT           |    20 |       |       |    39   (0)| 00:00:01 |
|  42 |         NESTED LOOPS                       |                              |   374 | 49368 |       |   261   (0)| 00:00:04 |
|  43 |          CONNECT BY PUMP                   |                              |       |       |       |            |          |
|  44 |          TABLE ACCESS BY INDEX ROWID       | ACCOUNT                      |    18 |  1368 |       |    10   (0)| 00:00:01 |
|  45 |           INDEX RANGE SCAN                 | IDX_ACCOUNT_PARENT           |    18 |       |       |     2   (0)| 00:00:01 |
|  46 |        TABLE ACCESS BY INDEX ROWID         | ACCOUNT                      |     1 |    26 |       |     4   (0)| 00:00:01 |
|  47 |         INDEX RANGE SCAN                   | IDX_ACCOUNT_PARENT           |     1 |       |       |     3   (0)| 00:00:01 |
|  48 |   HASH JOIN RIGHT OUTER                    |                              |   300K|    82M|       |   544K  (2)| 01:48:58 |
|  49 |    VIEW                                    | X_SECURITY_OBJECTS_V         |  1920 | 53760 |       |  3303   (1)| 00:00:40 |
|  50 |     HASH GROUP BY                          |                              |  1920 | 34560 |       |  3303   (1)| 00:00:40 |
|  51 |      VIEW                                  |                              |  1920 | 34560 |       |  3302   (1)| 00:00:40 |
|  52 |       SORT UNIQUE                          |                              |  1920 |   468K|       |  3302   (1)| 00:00:40 |
|  53 |        UNION-ALL                           |                              |       |       |       |            |          |
|  54 |         CONNECT BY WITH FILTERING (UNIQUE) |                              |       |       |       |            |          |
|  55 |          TABLE ACCESS FULL                 | ORGANIZATION                 |  1909 |   128K|       |   551   (2)| 00:00:07 |
|  56 |          HASH JOIN                         |                              |     5 |   675 |       |  1099   (1)| 00:00:14 |
|  57 |           CONNECT BY PUMP                  |                              |       |       |       |            |          |
|  58 |           TABLE ACCESS FULL                | ORGANIZATION                 | 76836 |  5927K|       |   547   (1)| 00:00:07 |
|  59 |         FILTER                             |                              |       |       |       |            |          |
|  60 |          CONNECT BY WITH FILTERING (UNIQUE)|                              |       |       |       |            |          |
|  61 |           TABLE ACCESS FULL                | ORGANIZATION                 |     4 |   272 |       |   548   (1)| 00:00:07 |
|  62 |           HASH JOIN                        |                              |     1 |   124 |       |  1096   (1)| 00:00:14 |
|  63 |            CONNECT BY PUMP                 |                              |       |       |       |            |          |
|  64 |            TABLE ACCESS FULL               | ORGANIZATION                 | 76836 |  5102K|       |   548   (1)| 00:00:07 |
|  65 |         INLIST ITERATOR                    |                              |       |       |       |            |          |
|  66 |          TABLE ACCESS BY INDEX ROWID       | ORGANIZATION                 |     1 |    37 |       |     5   (0)| 00:00:01 |
|  67 |           INDEX RANGE SCAN                 | UQ_ORGANIZATION_NATURAL      |     1 |       |       |     4   (0)| 00:00:01 |
|  68 |    HASH JOIN                               |                              |   300K|    74M|       |   541K  (2)| 01:48:18 |
|  69 |     TABLE ACCESS FULL                      | CURRENCY                     |    40 |  2560 |       |     3   (0)| 00:00:01 |
|  70 |     HASH JOIN RIGHT OUTER                  |                              |   300K|    56M|       |   541K  (2)| 01:48:18 |
|  71 |      VIEW                                  | --- VIEW_1                   |    19 |   247 |       |    18  (12)| 00:00:01 |
|  80 |      HASH JOIN                             |                              |   300K|    52M|  3072K|   541K  (2)| 01:48:18 |
|  81 |       TABLE ACCESS FULL                    | ACCOUNT                      | 45564 |  2536K|       |   274   (1)| 00:00:04 |
|  82 |       HASH JOIN                            |                              |   300K|    36M|  2576K|   539K  (2)| 01:47:50 |
|  83 |        TABLE ACCESS FULL                   | ORGANIZATION                 | 58577 |  1887K|       |   550   (1)| 00:00:07 |
|  84 |        HASH JOIN                           |                              |  6984K|   619M|       |   503K  (2)| 01:40:44 |
|  85 |         TABLE ACCESS FULL                  | COMPANY                      |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  86 |         HASH JOIN RIGHT OUTER              |                              |  6984K|   559M|       |   503K  (2)| 01:40:44 |
|  87 |          VIEW                              | --- VIEW_2                   |     2 |    26 |       |    29   (7)| 00:00:01 |
| 104 |          HASH JOIN                         |                              |  6984K|   472M|       |   503K  (2)| 01:40:43 |
| 105 |           NESTED LOOPS                     |                              |     9 |   171 |       |     5   (0)| 00:00:01 |
| 106 |            FAST DUAL                       |                              |     1 |       |       |     2   (0)| 00:00:01 |
| 107 |            TABLE ACCESS FULL               | TIME                         |     9 |   171 |       |     3   (0)| 00:00:01 |
| 108 |           TABLE ACCESS FULL                | FACT_PLAN_SUPP               |    84M|  4207M|       |   503K  (2)| 01:40:37 |
-----------------------------------------------------------------------------------------------------------------------------------

At this point I go into “astronomer” mode with a blink comparator. I’ll open two text files, one for each plan, in separate windows, position the windows one behind the other, align the texts and then “alt-tab” between the windows watching for the “blink” that highlights where the texts differ.

In the case of these two plans the numeric parts slip sideways by one character on the blink – fortunately I find that a small enough step that I don’t worry about doing a manual edit to re-align them.  In the first stage I’m only looking for changes in the operations and objects, with a secondary check on the numbers. For these two plans I can see very quickly that they match up to operation 69 (highlighted in both plans above).

I’ve highlighted a few other lines in the first 69 operations of the plans:

  • Operation 17 has significantly different rows/costs in the two plans 93,600/244K vs. 539K/545K
  • Operation 48 also has significant differences: 52,000/244K vs, 300K/545K – and as the second child of the hash join at operation 17 explains the previous differences
  • Operations 49 and 68 are the two child operations of the hash join at operation 48, with operation 68 carrying the differences
  • Operation 70 (where our plans shapes start to differ) is the second child of the hash join at operation 68 and introduces the differences

Although there are a few small differences in cardinality (row) and cost estimates in other lines in the first 70 lines of the plan they are small and (probably) ignorable by comparison.

The upshot of this is that we can assume (reasonably confidently) that the critical differences occur in the section of the plan that is the hash join [right outer] from operation 70 and its descendents, so our plans reduce to  the following (which emulates in text the type of appearance you would get from OEM, or TOAD, or SQL*Developer by collapsing parts of plans):

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                               |       |       |       |   244K(100)|          |
...
|  17 |  HASH JOIN RIGHT OUTER                     |                               | 93634 |    28M|       |   244K  (1)| 00:49:00 |
|  18 |   VIEW                                     | X_SECURITY_ACCOUNTS_V         |   434 | 12152 |       |   368   (2)| 00:00:05 |
...
|  48 |   HASH JOIN RIGHT OUTER                    |                               | 52211 |    14M|       |   244K  (1)| 00:48:55 |
|  49 |    VIEW                                    | X_SECURITY_OBJECTS_V          |  1976 | 55328 |       |  3303   (1)| 00:00:40 |
...
|  68 |    HASH JOIN                               |                               | 52211 |    12M|       |   241K  (1)| 00:48:16 |
|  69 |     TABLE ACCESS FULL                      | CURRENCY                      |    40 |  2560 |       |     3   (0)| 00:00:01 |
|  70 |     HASH JOIN                              |                               | 52211 |  9993K|  3072K|   241K  (1)| 00:48:16 |
|  71 |      TABLE ACCESS FULL                     | ACCOUNT                       | 45570 |  2536K|       |   274   (1)| 00:00:04 |
|  72 |      HASH JOIN                             |                               | 52211 |  7087K|       |   240K  (1)| 00:48:06 |
|  73 |       TABLE ACCESS FULL                    | COMPANY                       |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  74 |       HASH JOIN RIGHT OUTER                |                               | 52211 |  6628K|       |   240K  (1)| 00:48:06 |
|  75 |        VIEW                                | --- VIEW_1                    |    19 |   247 |       |    18  (12)| 00:00:01 |
|  84 |        HASH JOIN RIGHT OUTER               |                               | 52211 |  5965K|       |   240K  (1)| 00:48:06 |
|  85 |         VIEW                               | --- VIEW_2                    |     2 |    26 |       |    30   (7)| 00:00:01 |
| 102 |         HASH JOIN                          |                               | 52211 |  5302K|       |   240K  (1)| 00:48:06 |
| 103 |          TABLE ACCESS FULL                 | TIME                          |     9 |   171 |       |     3   (0)| 00:00:01 |
| 104 |          NESTED LOOPS                      |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 105 |           NESTED LOOPS                     |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 106 |            NESTED LOOPS                    |                               |  5756 |   185K|       |   552   (1)| 00:00:07 |
| 107 |             FAST DUAL                      |                               |     1 |       |       |     2   (0)| 00:00:01 |
| 108 |             TABLE ACCESS FULL              | ORGANIZATION                  |  5756 |   185K|       |   550   (1)| 00:00:07 |
| 109 |            INDEX RANGE SCAN                | IDX_FACT_PLAN_SUPP_K_COMP_ORG |    65 |       |       |    19   (0)| 00:00:01 |
| 110 |           TABLE ACCESS BY INDEX ROWID      | FACT_PLAN_SUPP                |   110 |  5720 |       |    82   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------------------------
-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                              |       |       |       |   545K(100)|          |
...
|  17 |  HASH JOIN RIGHT OUTER                     |                              |   539K|   162M|       |   545K  (2)| 01:49:03 |
|  18 |   VIEW                                     | X_SECURITY_ACCOUNTS_V        |   434 | 12152 |       |   368   (2)| 00:00:05 |
...
|  48 |   HASH JOIN RIGHT OUTER                    |                              |   300K|    82M|       |   544K  (2)| 01:48:58 |
|  49 |    VIEW                                    | X_SECURITY_OBJECTS_V         |  1920 | 53760 |       |  3303   (1)| 00:00:40 |
...
|  68 |    HASH JOIN                               |                              |   300K|    74M|       |   541K  (2)| 01:48:18 |
|  69 |     TABLE ACCESS FULL                      | CURRENCY                     |    40 |  2560 |       |     3   (0)| 00:00:01 |
|  70 |     HASH JOIN RIGHT OUTER                  |                              |   300K|    56M|       |   541K  (2)| 01:48:18 |
|  71 |      VIEW                                  | --- VIEW_1                   |    19 |   247 |       |    18  (12)| 00:00:01 |
|  80 |      HASH JOIN                             |                              |   300K|    52M|  3072K|   541K  (2)| 01:48:18 |
|  81 |       TABLE ACCESS FULL                    | ACCOUNT                      | 45564 |  2536K|       |   274   (1)| 00:00:04 |
|  82 |       HASH JOIN                            |                              |   300K|    36M|  2576K|   539K  (2)| 01:47:50 |
|  83 |        TABLE ACCESS FULL                   | ORGANIZATION                 | 58577 |  1887K|       |   550   (1)| 00:00:07 |
|  84 |        HASH JOIN                           |                              |  6984K|   619M|       |   503K  (2)| 01:40:44 |
|  85 |         TABLE ACCESS FULL                  | COMPANY                      |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  86 |         HASH JOIN RIGHT OUTER              |                              |  6984K|   559M|       |   503K  (2)| 01:40:44 |
|  87 |          VIEW                              | --- VIEW_2                   |     2 |    26 |       |    29   (7)| 00:00:01 |
| 104 |          HASH JOIN                         |                              |  6984K|   472M|       |   503K  (2)| 01:40:43 |
| 105 |           NESTED LOOPS                     |                              |     9 |   171 |       |     5   (0)| 00:00:01 |
| 106 |            FAST DUAL                       |                              |     1 |       |       |     2   (0)| 00:00:01 |
| 107 |            TABLE ACCESS FULL               | TIME                         |     9 |   171 |       |     3   (0)| 00:00:01 |
| 108 |           TABLE ACCESS FULL                | FACT_PLAN_SUPP               |    84M|  4207M|       |   503K  (2)| 01:40:37 |
-----------------------------------------------------------------------------------------------------------------------------------

The image we get by stripping out (or collapsing) all the bits which looks as if they aren’t significant is so much simpler to grasp than the original, and gives us a couple of extra ideas to follow if we were simply doing a generic “optimise this query” exercise starting from a position of ignorance. In fact all we’re after in this particular exercise is a pointer to the most likely place where “something changed” as this may tall us why the plan changed and what we can do to get back the old plan and stabilise it for the future.

Now that we’ve seen the condensed plans I’m going to reduce them one more time, and take out the collapse option, to hide everything above operation 70 because that’s a good focal point for the investigating the change:

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------------------------
|  70 |     HASH JOIN                              |                               | 52211 |  9993K|  3072K|   241K  (1)| 00:48:16 |
|  71 |      TABLE ACCESS FULL                     | ACCOUNT                       | 45570 |  2536K|       |   274   (1)| 00:00:04 |
|  72 |      HASH JOIN                             |                               | 52211 |  7087K|       |   240K  (1)| 00:48:06 |
|  73 |       TABLE ACCESS FULL                    | COMPANY                       |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  74 |       HASH JOIN RIGHT OUTER                |                               | 52211 |  6628K|       |   240K  (1)| 00:48:06 |
|  75 |        VIEW                                | --- VIEW_1                    |    19 |   247 |       |    18  (12)| 00:00:01 |
|  84 |        HASH JOIN RIGHT OUTER               |                               | 52211 |  5965K|       |   240K  (1)| 00:48:06 |
|  85 |         VIEW                               | --- VIEW_2                    |     2 |    26 |       |    30   (7)| 00:00:01 |
| 102 |         HASH JOIN                          |                               | 52211 |  5302K|       |   240K  (1)| 00:48:06 |
| 103 |          TABLE ACCESS FULL                 | TIME                          |     9 |   171 |       |     3   (0)| 00:00:01 |
| 104 |          NESTED LOOPS                      |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 105 |           NESTED LOOPS                     |                               |   634K|    51M|       |   240K  (1)| 00:48:06 |
| 106 |            NESTED LOOPS                    |                               |  5756 |   185K|       |   552   (1)| 00:00:07 |
| 107 |             FAST DUAL                      |                               |     1 |       |       |     2   (0)| 00:00:01 |
| 108 |             TABLE ACCESS FULL              | ORGANIZATION                  |  5756 |   185K|       |   550   (1)| 00:00:07 |
| 109 |            INDEX RANGE SCAN                | IDX_FACT_PLAN_SUPP_K_COMP_ORG |    65 |       |       |    19   (0)| 00:00:01 |
| 110 |           TABLE ACCESS BY INDEX ROWID      | FACT_PLAN_SUPP                |   110 |  5720 |       |    82   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------------------------
-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name                         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------------------------------
|  70 |     HASH JOIN RIGHT OUTER                  |                              |   300K|    56M|       |   541K  (2)| 01:48:18 |
|  71 |      VIEW                                  | --- VIEW_1                   |    19 |   247 |       |    18  (12)| 00:00:01 |
|  80 |      HASH JOIN                             |                              |   300K|    52M|  3072K|   541K  (2)| 01:48:18 |
|  81 |       TABLE ACCESS FULL                    | ACCOUNT                      | 45564 |  2536K|       |   274   (1)| 00:00:04 |
|  82 |       HASH JOIN                            |                              |   300K|    36M|  2576K|   539K  (2)| 01:47:50 |
|  83 |        TABLE ACCESS FULL                   | ORGANIZATION                 | 58577 |  1887K|       |   550   (1)| 00:00:07 |
|  84 |        HASH JOIN                           |                              |  6984K|   619M|       |   503K  (2)| 01:40:44 |
|  85 |         TABLE ACCESS FULL                  | COMPANY                      |   112 |  1008 |       |     3   (0)| 00:00:01 |
|  86 |         HASH JOIN RIGHT OUTER              |                              |  6984K|   559M|       |   503K  (2)| 01:40:44 |
|  87 |          VIEW                              | --- VIEW_2                   |     2 |    26 |       |    29   (7)| 00:00:01 |
| 104 |          HASH JOIN                         |                              |  6984K|   472M|       |   503K  (2)| 01:40:43 |
| 105 |           NESTED LOOPS                     |                              |     9 |   171 |       |     5   (0)| 00:00:01 |
| 106 |            FAST DUAL                       |                              |     1 |       |       |     2   (0)| 00:00:01 |
| 107 |            TABLE ACCESS FULL               | TIME                         |     9 |   171 |       |     3   (0)| 00:00:01 |
| 108 |           TABLE ACCESS FULL                | FACT_PLAN_SUPP               |    84M|  4207M|       |   503K  (2)| 01:40:37 |
-----------------------------------------------------------------------------------------------------------------------------------

Comparing the two fragments we can see that they both have a funny little nested loop driven by a select from dual: perhaps that’s just there to inject a value like sysdate-N, or a single value from a PL/SQL function, or a call to sys_context() that can act as a “variable constant”. It probably doesn’t matter where that tablescan of dual goes, really, so long as it happens early enough; it’s guaranteed to be only one row so the fact that it drives a nested loop is only a formality. (I’d guess that it’s probably the leading table in the join order, but appears very late in the plan because of “swap_join_inputs” introduced for all the hash joins.)

Apart from that one common nested loop (with different tables as the inner table) almost everything in both plans is a hash join with full tablescans – with one exception: in the bad plan the join to fact_plan_supp is an index-access nested loop driven by a tablescan of organization (technically it’s driven by the result of the join between dual and the result of the tablescan of organization, of course); in the good plan we see a full tablescan of fact_plan_supp – which is millions of rows at a huge fraction (503K/541K) of the total cost of the query.

It seems slightly surprising that such a massive and expensive tablescan should produce the good plan, but it does, and we have to ask why. Since the bad plan has the nested loop, and the nested loop is driven by table organization we need to look at that table in both plans. In the bad plan the prediction is 5,756 rows; in the good plan the prediction is 58,577 rows. The dramatic change in that prediction is probably the cause of the change in plan. Imagine scaling up the number of rows in the bad plan by the factor of 10 implied by those figures and the cost of the nested loop (operations 104 and 105) would go up to 240K – vastly more than the cost of the tablescan chosen for the good plan. If the prediction for the good plan is in the right ball park then the error in the cardinality estimate the optimizer has made for the organization table is almost certain to be the cause of the performance problem seen in the bad plan.

The next task, of course, is to find out why the prediction changed – which means looking at the statistics on the organization table and finding out the values used for any predicates against that one table. (Unfortunately these plans report no predicate section – and the absence of any asterisks (“*”) against the operation lines suggests the plans came from the AWR, which doesn’t capture the predicate information.) There are a couple of common possibilities suggested by the scale of the difference:

  • A column that should have a histogram has lost its histogram
  • A column that didn’t have a histogram has acquired one
  • Some column data is skewed and has a histogram, and an unlucky choice of bind variable on the first call produced a very low estimate of cardinality
  • Stats collection for histograms is sampled in 11g-  and still sampled for hybrid histograms in 12c – an unlucky sample produced a very misleading histogram
  • A bind variable has gone out of range of the low/high values with a significant pro-rated scale-down on the row estimate

After doing the analysis above, I highlighted the organization table to the originator of the question – who came back with the information that a column had recently been added to the table by the process of dropping and recreating the table then gathering stats. If you do that, and have the stats collection method_opt left at its default, you won’t get any histograms initially: the default method_opt is “for all columns size auto” – which lets Oracle decide which columns should be tested for histograms based on historic use and data skew. If it’s a “new” table there will be no historic use, so no attempt to generate histograms. The first option on my list may be the right one.

Footnote:

It took about 15 minutes to copy the plans and do the analysis – it’s taken about 3 hours (plus a few more minutes this morning for a last spelling and grammar check) to explain what I did … and even then the explanation could do with more work.

 

February 28, 2018

255 Columns

Filed under: Infrastructure,Oracle,Troubleshooting,undo — Jonathan Lewis @ 12:27 pm BST Feb 28,2018

It’s the gift that keeps on giving – no matter how many problems you find there are always more waiting to be found. It’s been some time since I last wrote about tables with more than 255 columns, and I said then that there was more to come. In the last article I described how adding a few columns to a table, or updating a trailing column in a way that made the table’s used column count exceed 255, could result in some strange row-splitting behaviour – in this article I’m going to look at a critical side effect of that behaviour.

We’ll start with a simple model and a question – I’ll create a table with a thousand rows of data, then I’ll add a few columns to that table and update the last column in every row and check the undo and redo generated by the update.  Eventually I’m going to need a table with more than 255 columns so the script to create the table is rather long and I’ve posted it at the end of the article in case you want to experiment – in the following text I’ve omitted a few hundred lines of column declarations and values.


rem
rem     Script:         wide_table_5.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Feb 2018
rem

create table t1(
        col000,
        col001,
        col002,
        col003,
...
        col199,
/*
        col200,
        col201,
        col202,
        col203,
        col204,
        col205,
        col206,
        col207,
        col208,
        col209,
*/
        col210,
        col220,
...
        col247,
        col248,
        col249
)
as
with generator as (
        select 
                rownum id
        from dual
        connect by
                level <= 1e3 -- > comment to avoid WordPress format issue
)
select
        lpad(000,10,'0'),
        lpad(001,10,'0'),
        lpad(002,10,'0'),
        lpad(003,10,'0'),
...
        lpad(247,10,'0'),
        lpad(248,10,'0'),
        lpad(249,10,'0')
from
        generator       v2
where
        rownum <= 1e4 -- > comment to avoid WordPress format issue
;

begin
        dbms_stats.gather_table_stats(
                ownname     => user,
                tabname     => 'T1',
                method_opt  => 'for all columns size 1'
        );
end;
/

alter table t1 add(
        col250 varchar2(10),
        col251 varchar2(10),
        col252 varchar2(10),
        col253 varchar2(10),
        col254 varchar2(10),
        col255 varchar2(10),
        col256 varchar2(10),
        col257 varchar2(10),
        col258 varchar2(10),
        col259 varchar2(10)
)
;

update t1 set col259 = lpad('259',10,'0');
commit;


The table I’ve created has columns named from col000 to col249 populated with a text matching the column’s numeric id – a total of 250 columns, except that for the first part of the test I’ve commented out the creation and population of 10 of those columns, giving me a total of 240 columns. Then I’ve added 10 more columns and updated the last of those 10. So, for the first part of the test, I’ve grown my table from 240 used columns to 250 used columns. Here are a few critical stats for that update from the session statistics view (v$sesstat joined to v$statname):

 

Name                                                 Value
----                                                 -----
db block gets                                        1,023
consistent gets                                        555
db block changes                                     2,012
redo entries                                           907
redo size                                          262,692
undo change vector size                             76,052
table scan rows gotten                               1,002
table scan blocks gotten                               501
HSC Heap Segment Block Changes                       1,000

That’s pretty much the sort of thing we might expect. For a small update to a row it’s reasonable to see 250 – 300 bytes of redo of which about half is the redo for the undo. We can see that we’ve scanned 1,000 rows and made 2,000 block changes (one to the table block and one to an undo block for each row in the table). The table was 500 blocks of data (the avg_row_len is about 2640 bytes from 240 columns at 10 bytes + a length byte, which makes two rows per block with lots of spare space at the default 10 pctfree). You might been expecting the number of redo entries to be a close match to the number of rows but it’s a little short because the redo records for the first few updates would have been stored in private redo and turned into a single large redo entry.

So what do the stats look like when we start with 250 columns and grow to 260 columns, breaking through the dreaded 255 barrier ?


Name                                                 Value
----                                                 -----
db block gets                                        9,503
consistent gets                                      1,894
db block changes                                     9,384
redo size                                        8,110,584
redo entries                                         5,778
undo change vector size                          3,780,260
table scan rows gotten                               1,002
table scan blocks gotten                               501
HSC Heap Segment Block Changes                       3,000

Such a simple change – with such a large impact.

The average undo is now nearly 3.5KB per row (and the rows were only about 2,860 bytes each anyway), the number of redo entries is up to 6 times the original, we’re averaging 3 “HSC Heap Segment Block Changes” per row instead of 1 and in total we’ve managed to do an extra 7,000 db block changes overall.

To get an idea of what was going on behind the scenes I dumped the redo log file. For the first part of the test most of the redo entries consisted of a pair of redo change vectors with OP codes 5.1 (modify undo block) and 11.5 (update row piece). The 5.1 corresponded to the undo needed to reverse out the effect of its paired 11.5 and both change vectors were pretty small.

For the second part of the test I found a frequently repeated sequence of three consecutive redo records of paired redo vectors: (5.1, 11.4), (5.1, 11.2) and (5.1, 11.6). Again each 5.1 corresponds to the undo needed to reverse out the effect of its associated 11.x, and in this case the three “table” (level 11) OP codes are, in order: “lock row piece”, “insert row piece”, “overwrite row piece”. These 3 pairs occured 1,000 times each, accounting for roughly 3,000 of the redo entries reported.

On top of this there were 2,500 redo records holding redo change vectors with op code 13.22 (“State change on level 1 bitmap block”), and a few hundred , with op code 13.21 (“Format page table block”) with just a few others bringing the total up to the 5,800 redo entries reported. (You might note that the last OP code is a clue that we added quite a lot of new blocks to the table as we executed the update – in fact the number of used table blocks grew by about 50%.)

We also had 500 redo change vectors of type 5.2 (“get undo header”). This number was significantly more than in the first part of the test because we had a lot more undo block changes (with bigger undo change vectors) which means we used a lot more undo blocks, and each time we move to a new undo block we update our transaction slot in the undo header with the current undo block address. I mentioned the pairing of 5.1 and 11.6 above – in fact 50% of those records recorded just two changes (5.1, 11.6) the other 50% recorded three changes (5.2, 5.1, 11.6) – in effect every other row update resulted in Oracle demanding a new undo block.

I’ll explain in a moment why we have a very large number of “State change on level 1 bitmap block”; first let’s examine the key steps of how Oracle is processing a single row update – the sequence of 11.4, 11.2, 11.6:

  • 11.4: lock the head row piece – this seems to happen when the row is in (or going to turn into) multiple pieces; presumably because the piece that is going to change might not be the head piece. This is a tiny operation that generates undo and redo in the order of tens of bytes.
  • 11.2: our code extends the row to 260 columns, which means Oracle has to split it into two pieces of 5 columns and 255 columns respectively – so one of those row-pieces has to cause an insert to take place. Inserting a row may require a lot of redo, of course, but the undo for a (table-only) insert is, again, tiny.
  • 11.6: When Oracle has to split a wide row (>255 columns) it counts columns from the end, so the first row piece of our row is 5 columns and the second row piece (which is the one inserted by the 11.2 operation) is 255 columns. This means we have to overwrite the original row piece with a much shorter row piece. So we’re replacing 2,750 bytes (250 columns) with 55 bytes (5 columns), which means we have to write the contents of the “deleted” 250 columns to the undo tablespace – and that’s where most of the huge volume of undo comes from.

There are two extra points to note about the way Oracle handles the insert/overwrite steps. The length of our row exaggerates the effect, of course, but when we insert the ending 255 columns the block they go to is probably going to change from nearly empty to half full, or half full to full – which means its bitmap entry has to be updated; similarly when the initial 250 columns is overwritten with just 5 columns a huge amount of free space will appear in the block which, again, means that the block’s bitmap entry has to be updated. This gives us a good idea of why we see so many 13.22 (“L1 bitmap state change”)redo change vectors.

The second point is that the numbers still don’t add up. Allowing a couple of hundred bytes of undo per row for the lock row and insert row, then 2,750 plus a few more for the overwrite, I’ve accounted for about 3,000 bytes per row updated – which leaves me short by about 800 bytes per row.  If I dump undo blocks I can see that the undo change vector for the overwrite is actually 3,628 bytes long rather than being “slightly over” the 2,750 for the before image of the overwritten row. Strangely I can see a couple of hundred bytes of what looks like damage in the row image, and there’s also a couple of hundred bytes of what looks like garbage (but probably isn’t) after the row image, but I’ve got no idea why there’s so much excess data in the record.

One day I (or someone else) may get around to looking very closely at why that particular undo record is a lot bigger than an observer might expect – but at least we can see that the space is there, and even if some of that volume could be made to disappear the problem of the massive undo relating to the overwrite and Oracle’s odd strategy of counting columns from the end is still going to be present, and there are probably some occasions when you need to know about this.

tl;dr

Once the number of columns in a table goes over 255 then a simple update to a “trailing” null column (i.e. one past the current end of the row) is likely to generate a much larger volume of undo and redo than you might expect. In particular the size of the undo record is likely to be equivalent to the volume of the last 255 columns of the table – and then a large fraction more.

The reason why this particular anomaly came to my attention is because a client had a problem upgrading an application that required them to add a few columns to a table and then update a couple of them. The size of the undo tablespace was 300 GB, the update (the only thing running at the time) should have added about 30 bytes to the length of each row, the update should have affected 250 million rows. The process crashed after a few hours “ORA-30036: unable to extend segment by %s in undo tablespace ‘%s'”. Even allowing for a “reasonable” overhead it seemed rather surprising that Oracle needed more than 1,200 bytes of undo space per row – but then I found the table was defined with 350 columns.

Solutions for this user:  it’s an upgrade that’s allowed to take quite a long time, and the nature of the update is such that it would be possible to update in batches, committing after each batch.  It would also be nice to review how the table was used to see if it could be rebuilt with a different column order to move all the unused columns to the end of the row – with a little luck the result table might find almost all the rows fitting into a single row piece, even after the upgrade.

Footnote

If you want to experiment, here’s the whole script to create the table, insert some rows, then add a few more columns and update one of them. It’s very long, and not in the least bit exciting, but it may save you a little typing time if you want to use it.


create table t1(
        col000,
        col001,
        col002,
        col003,
        col004,
        col005,
        col006,
        col007,
        col008,
        col009,
        col010,
        col011,
        col012,
        col013,
        col014,
        col015,
        col016,
        col017,
        col018,
        col019,
        col020,
        col021,
        col022,
        col023,
        col024,
        col025,
        col026,
        col027,
        col028,
        col029,
        col030,
        col031,
        col032,
        col033,
        col034,
        col035,
        col036,
        col037,
        col038,
        col039,
        col040,
        col041,
        col042,
        col043,
        col044,
        col045,
        col046,
        col047,
        col048,
        col049,
        col050,
        col051,
        col052,
        col053,
        col054,
        col055,
        col056,
        col057,
        col058,
        col059,
        col060,
        col061,
        col062,
        col063,
        col064,
        col065,
        col066,
        col067,
        col068,
        col069,
        col070,
        col071,
        col072,
        col073,
        col074,
        col075,
        col076,
        col077,
        col078,
        col079,
        col080,
        col081,
        col082,
        col083,
        col084,
        col085,
        col086,
        col087,
        col088,
        col089,
        col090,
        col091,
        col092,
        col093,
        col094,
        col095,
        col096,
        col097,
        col098,
        col099,
        col100,
        col101,
        col102,
        col103,
        col104,
        col105,
        col106,
        col107,
        col108,
        col109,
        col110,
        col111,
        col112,
        col113,
        col114,
        col115,
        col116,
        col117,
        col118,
        col119,
        col120,
        col121,
        col122,
        col123,
        col124,
        col125,
        col126,
        col127,
        col128,
        col129,
        col130,
        col131,
        col132,
        col133,
        col134,
        col135,
        col136,
        col137,
        col138,
        col139,
        col140,
        col141,
        col142,
        col143,
        col144,
        col145,
        col146,
        col147,
        col148,
        col149,
        col150,
        col151,
        col152,
        col153,
        col154,
        col155,
        col156,
        col157,
        col158,
        col159,
        col160,
        col161,
        col162,
        col163,
        col164,
        col165,
        col166,
        col167,
        col168,
        col169,
        col170,
        col171,
        col172,
        col173,
        col174,
        col175,
        col176,
        col177,
        col178,
        col179,
        col180,
        col181,
        col182,
        col183,
        col184,
        col185,
        col186,
        col187,
        col188,
        col189,
        col190,
        col191,
        col192,
        col193,
        col194,
        col195,
        col196,
        col197,
        col198,
        col199,
        col200,
        col201,
        col202,
        col203,
        col204,
        col205,
        col206,
        col207,
        col208,
        col209,
        col210,
        col211,
        col212,
        col213,
        col214,
        col215,
        col216,
        col217,
        col218,
        col219,
        col220,
        col221,
        col222,
        col223,
        col224,
        col225,
        col226,
        col227,
        col228,
        col229,
        col230,
        col231,
        col232,
        col233,
        col234,
        col235,
        col236,
        col237,
        col238,
        col239,
        col240,
        col241,
        col242,
        col243,
        col244,
        col245,
        col246,
        col247,
        col248,
        col249
)
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e3 -- > comment to avoid WordPress format issue
)
select
        lpad(000,10,'0'),
        lpad(001,10,'0'),
        lpad(002,10,'0'),
        lpad(003,10,'0'),
        lpad(004,10,'0'),
        lpad(005,10,'0'),
        lpad(006,10,'0'),
        lpad(007,10,'0'),
        lpad(008,10,'0'),
        lpad(009,10,'0'),
        lpad(010,10,'0'),
        lpad(011,10,'0'),
        lpad(012,10,'0'),
        lpad(013,10,'0'),
        lpad(014,10,'0'),
        lpad(015,10,'0'),
        lpad(016,10,'0'),
        lpad(017,10,'0'),
        lpad(018,10,'0'),
        lpad(019,10,'0'),
        lpad(020,10,'0'),
        lpad(021,10,'0'),
        lpad(022,10,'0'),
        lpad(023,10,'0'),
        lpad(024,10,'0'),
        lpad(025,10,'0'),
        lpad(026,10,'0'),
        lpad(027,10,'0'),
        lpad(028,10,'0'),
        lpad(029,10,'0'),
        lpad(030,10,'0'),
        lpad(031,10,'0'),
        lpad(032,10,'0'),
        lpad(033,10,'0'),
        lpad(034,10,'0'),
        lpad(035,10,'0'),
        lpad(036,10,'0'),
        lpad(037,10,'0'),
        lpad(038,10,'0'),
        lpad(039,10,'0'),
        lpad(040,10,'0'),
        lpad(041,10,'0'),
        lpad(042,10,'0'),
        lpad(043,10,'0'),
        lpad(044,10,'0'),
        lpad(045,10,'0'),
        lpad(046,10,'0'),
        lpad(047,10,'0'),
        lpad(048,10,'0'),
        lpad(049,10,'0'),
        lpad(050,10,'0'),
        lpad(051,10,'0'),
        lpad(052,10,'0'),
        lpad(053,10,'0'),
        lpad(054,10,'0'),
        lpad(055,10,'0'),
        lpad(056,10,'0'),
        lpad(057,10,'0'),
        lpad(058,10,'0'),
        lpad(059,10,'0'),
        lpad(060,10,'0'),
        lpad(061,10,'0'),
        lpad(062,10,'0'),
        lpad(063,10,'0'),
        lpad(064,10,'0'),
        lpad(065,10,'0'),
        lpad(066,10,'0'),
        lpad(067,10,'0'),
        lpad(068,10,'0'),
        lpad(069,10,'0'),
        lpad(070,10,'0'),
        lpad(071,10,'0'),
        lpad(072,10,'0'),
        lpad(073,10,'0'),
        lpad(074,10,'0'),
        lpad(075,10,'0'),
        lpad(076,10,'0'),
        lpad(077,10,'0'),
        lpad(078,10,'0'),
        lpad(079,10,'0'),
        lpad(080,10,'0'),
        lpad(081,10,'0'),
        lpad(082,10,'0'),
        lpad(083,10,'0'),
        lpad(084,10,'0'),
        lpad(085,10,'0'),
        lpad(086,10,'0'),
        lpad(087,10,'0'),
        lpad(088,10,'0'),
        lpad(089,10,'0'),
        lpad(090,10,'0'),
        lpad(091,10,'0'),
        lpad(092,10,'0'),
        lpad(093,10,'0'),
        lpad(094,10,'0'),
        lpad(095,10,'0'),
        lpad(096,10,'0'),
        lpad(097,10,'0'),
        lpad(098,10,'0'),
        lpad(099,10,'0'),
        lpad(100,10,'0'),
        lpad(101,10,'0'),
        lpad(102,10,'0'),
        lpad(103,10,'0'),
        lpad(104,10,'0'),
        lpad(105,10,'0'),
        lpad(106,10,'0'),
        lpad(107,10,'0'),
        lpad(108,10,'0'),
        lpad(109,10,'0'),
        lpad(110,10,'0'),
        lpad(111,10,'0'),
        lpad(112,10,'0'),
        lpad(113,10,'0'),
        lpad(114,10,'0'),
        lpad(115,10,'0'),
        lpad(116,10,'0'),
        lpad(117,10,'0'),
        lpad(118,10,'0'),
        lpad(119,10,'0'),
        lpad(120,10,'0'),
        lpad(121,10,'0'),
        lpad(122,10,'0'),
        lpad(123,10,'0'),
        lpad(124,10,'0'),
        lpad(125,10,'0'),
        lpad(126,10,'0'),
        lpad(127,10,'0'),
        lpad(128,10,'0'),
        lpad(129,10,'0'),
        lpad(130,10,'0'),
        lpad(131,10,'0'),
        lpad(132,10,'0'),
        lpad(133,10,'0'),
        lpad(134,10,'0'),
        lpad(135,10,'0'),
        lpad(136,10,'0'),
        lpad(137,10,'0'),
        lpad(138,10,'0'),
        lpad(139,10,'0'),
        lpad(140,10,'0'),
        lpad(141,10,'0'),
        lpad(142,10,'0'),
        lpad(143,10,'0'),
        lpad(144,10,'0'),
        lpad(145,10,'0'),
        lpad(146,10,'0'),
        lpad(147,10,'0'),
        lpad(148,10,'0'),
        lpad(149,10,'0'),
        lpad(150,10,'0'),
        lpad(151,10,'0'),
        lpad(152,10,'0'),
        lpad(153,10,'0'),
        lpad(154,10,'0'),
        lpad(155,10,'0'),
        lpad(156,10,'0'),
        lpad(157,10,'0'),
        lpad(158,10,'0'),
        lpad(159,10,'0'),
        lpad(160,10,'0'),
        lpad(161,10,'0'),
        lpad(162,10,'0'),
        lpad(163,10,'0'),
        lpad(164,10,'0'),
        lpad(165,10,'0'),
        lpad(166,10,'0'),
        lpad(167,10,'0'),
        lpad(168,10,'0'),
        lpad(169,10,'0'),
        lpad(170,10,'0'),
        lpad(171,10,'0'),
        lpad(172,10,'0'),
        lpad(173,10,'0'),
        lpad(174,10,'0'),
        lpad(175,10,'0'),
        lpad(176,10,'0'),
        lpad(177,10,'0'),
        lpad(178,10,'0'),
        lpad(179,10,'0'),
        lpad(180,10,'0'),
        lpad(181,10,'0'),
        lpad(182,10,'0'),
        lpad(183,10,'0'),
        lpad(184,10,'0'),
        lpad(185,10,'0'),
        lpad(186,10,'0'),
        lpad(187,10,'0'),
        lpad(188,10,'0'),
        lpad(189,10,'0'),
        lpad(190,10,'0'),
        lpad(191,10,'0'),
        lpad(192,10,'0'),
        lpad(193,10,'0'),
        lpad(194,10,'0'),
        lpad(195,10,'0'),
        lpad(196,10,'0'),
        lpad(197,10,'0'),
        lpad(198,10,'0'),
        lpad(199,10,'0'),
        lpad(200,10,'0'),
        lpad(201,10,'0'),
        lpad(202,10,'0'),
        lpad(203,10,'0'),
        lpad(204,10,'0'),
        lpad(205,10,'0'),
        lpad(206,10,'0'),
        lpad(207,10,'0'),
        lpad(208,10,'0'),
        lpad(209,10,'0'),
        lpad(210,10,'0'),
        lpad(211,10,'0'),
        lpad(212,10,'0'),
        lpad(213,10,'0'),
        lpad(214,10,'0'),
        lpad(215,10,'0'),
        lpad(216,10,'0'),
        lpad(217,10,'0'),
        lpad(218,10,'0'),
        lpad(219,10,'0'),
        lpad(220,10,'0'),
        lpad(221,10,'0'),
        lpad(222,10,'0'),
        lpad(223,10,'0'),
        lpad(224,10,'0'),
        lpad(225,10,'0'),
        lpad(226,10,'0'),
        lpad(227,10,'0'),
        lpad(228,10,'0'),
        lpad(229,10,'0'),
        lpad(230,10,'0'),
        lpad(231,10,'0'),
        lpad(232,10,'0'),
        lpad(233,10,'0'),
        lpad(234,10,'0'),
        lpad(235,10,'0'),
        lpad(236,10,'0'),
        lpad(237,10,'0'),
        lpad(238,10,'0'),
        lpad(239,10,'0'),
        lpad(240,10,'0'),
        lpad(241,10,'0'),
        lpad(242,10,'0'),
        lpad(243,10,'0'),
        lpad(244,10,'0'),
        lpad(245,10,'0'),
        lpad(246,10,'0'),
        lpad(247,10,'0'),
        lpad(248,10,'0'),
        lpad(249,10,'0')
from
        generator       v2
where
        rownum <= 1e4 -- > comment to avoid WordPress format issue
;

begin
        dbms_stats.gather_table_stats(
                ownname     => user,
                tabname     => 'T1',
                method_opt  => 'for all columns size 1'
        );
end;
/

select
        avg_row_len, num_rows,  blocks,
        num_rows / trunc(8000/avg_row_len) estimated_blocks
from
        user_tables
where
        table_name = 'T1'
;

prompt  =================
prompt  Add a few columns
prompt  =================

alter table t1 add(
        col250 varchar2(10),
        col251 varchar2(10),
        col252 varchar2(10),
        col253 varchar2(10),
        col254 varchar2(10),
        col255 varchar2(10),
        col256 varchar2(10),
        col257 varchar2(10),
        col258 varchar2(10),
        col259 varchar2(10)
)
;

-- alter system switch logfile;

update t1 set col259 = lpad('259',10,'0');
commit;

-- execute dump_log

P.S. if you do investigate and solve the question of the excess space in the undo record, and the odd content in the row “before image” then do let me know. (Hint: part of the excess may be a “null columns” map – but that still leaves plenty to account for.)

February 22, 2018

Huge Pages

Filed under: Oracle,RAC,Troubleshooting,Tuning — Jonathan Lewis @ 9:03 am BST Feb 22,2018

A useful quick summary from Neil Chandler replying to a thread on Oracle-L:

Topic: RAC install on Linux

You should always be using Hugepages.

They give a minor performance improvement and a significant memory saving in terms of the amount of memory needed to handle the pages – less Transaction Lookaside Buffers, which also means less TLB misses (which are expensive).

You are handling the memory chopped up into 2MB pieces instead of 4K. But you also have a single shared memory TLB for Hugepages.

The kernel has less work to do, bookkeeping fewer pointers in the TLB.

You also have contiguous memory allocation and it can’t be swapped.

If you are having problems with Hugepages, you have probably overallocated them (I’ve seen this several times at clients so it’s not uncommon). Hugepages can *only* be used for your SGA’s. All of your SGA’s should fit into the Hugepages and that should generally be no more than about 60% of the total server memory (but there are exceptions), leaving plenty of “normal” memory (small pages) for PGA , O/S and other stuff like monitoring agendas.

As an added bonus, AMM can’t use Hugepages, so your are forced to use ASMM. AMM doesn’t work well and has been kind-of deprecated by oracle anyway – dbca won’t let you setup AMM if the server has more than 4GB of memory.

There are a few follow-up emails after Neil’s; particularly helpful are two from Stefan Koehler, here and here.

 

 

February 21, 2018

Interval Partition Problem

Filed under: Bugs,Oracle,Partitioning,Troubleshooting — Jonathan Lewis @ 8:40 am BST Feb 21,2018

Assume you’ve got a huge temporary tablespace, there’s plenty of space in your favourite tablespace, you’ve got a very boring, simple table you want to copy and partition, and no-one and nothing is using the system. Would you really expect a (fairly) ordinary “create table t2 as select * from t1” to end with an Oracle error “ORA-1652: unable to extend temp segment by 128 in tablespace TEMP” . That’s the temporary tablespace that’s out of space, not the target tablespace for the copy.

Here’s a sample data set (tested on 11.2.0.4 and 12.1.0.2) to demonstrate the surprise – you’ll need about 900MB of space by the time the entire model has run to completion:

rem
rem     Script:         pt_interval_threat_2.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Feb 2018
rem

column today new_value m_today
select to_char(sysdate,'dd-mon-yyyy') today from dual;

create table t1
as
with g as (
        select rownum id
        from dual
        connect by level <= 2e3
)
select
        rownum id,
        trunc(sysdate) + g2.id  created,
        rpad('x',50)            padding
from
        g g1,
        g g2
where
        rownum <= 4e6 --> comment to avoid WordPress format issue
;

execute dbms_stats.gather_table_stats(user,'t1',method_opt=>'for all columns size 1')

I’ve created a table of 4 million rows, covering 2,000 dates out into the future starting from sysdate+1 (tomorrow). As you can see there’s nothing in the slightest bit interesting, unusual, or exciting about the data types and content of the table.

I said my “create table as select” was fairly ordinary – but it’s actually a little bit out of the way because it’s going to create a partitioned copy of this table.


execute snap_my_stats.start_snap

create table t2
partition by range(created)
interval(numtodsinterval(7, 'day'))
(
        partition p_start       values less than (to_date('&m_today','dd-mon-yyyy'))
)
storage(initial 1M)
nologging
as
select
        *
from
        t1
;

set serveroutput on
execute snap_my_stats.end_snap

I’ve created the table as a range-partitioned table with an interval() declared. Conveniently I need only mention the partitioning column by name in the declaration, rather than listing all the columns with their types, and I’ve only specified a single starting partition. Since the interval is 7 days and the data spans 2,000 days I’m going to end up with nearly 290 partitions added.

There’s no guarantee that you will see the ORA-01652 error when you run this test – the data size is rather small and your machine may have sufficient other resources to hide the problem even when you’re looking for it – but the person who reported the problem on the OTN/ODC database forum was copying a table of 2.5 Billion rows using about 200 GB of storage, so size is probably important, hence the 4 million rows as a starting point on my small system.

Of course, hitting an ORA-01652 on TEMP when doing a simple “create as select” is such an unlikely sounding error that you don’t necessarily have to see it actually happen; all you need to see (at least as a starting point in a small model) is TEMP being used unexpectedly so, for my first test (on 11.2.0.4), I’ve included some code to calculate and report changes in the session stats – that’s the calls to the package snap_my_stats. Here are some of the more interesting results:


---------------------------------
Session stats - 20-Feb 16:58:24
Interval:-  14 seconds
---------------------------------
Name                                                                     Value
----                                                                     -----
table scan rows gotten                                               4,000,004
table scan blocks gotten                                                38,741

session pga memory max                                             181,338,112

sorts (rows)                                                         2,238,833

physical reads direct temporary tablespace                              23,313
physical writes direct temporary tablespace                             23,313

The first couple of numbers show the 4,000,000 rows being scanned from 38,741 table blocks – and that’s not a surprise. But for a simple copy the 181MB of PGA memory we’ve acquired is a little surprising, though less so when we see that we’ve sorted 2.2M rows, and then ended up spilling 23,313 blocks to the temporary tablespace. But why are we sorting anything – what are those rows ?

My first thought was that there was a bug in some recursive SQL that was trying to define or identify dynamically created partitions, or maybe something in the space management code trying to find free space, so the obvious step was to enable extended tracing and look for any recursive statements that were running a large number of times or doing a lot of work. There weren’t any – and the trace file (particularly the detailed wait events) suggested the problem really was purely to do with the CTAS itself; so I ran the code again enabling events 10032 and 10033 (the sort traces) and found the following:


---- Sort Statistics ------------------------------
Initial runs                              1
Input records                             2140000
Output records                            2140000
Disk blocks 1st pass                      22292
Total disk blocks used                    22294
Total number of comparisons performed     0
Temp segments allocated                   1
Extents allocated                         175
Uses version 1 sort
Uses asynchronous IO

One single operation had resulted in Oracle sorting 2.14 million rows (but not making any comparisons!) – and the only table in the entire system with enough rows to do that was my source table! Oracle seems to be sorting a large fraction of the data for no obvious reason before inserting it.

  • Why, and why only 2.14M out of 4M ?
  • Does it do the same on 12.1.0.2 (yes), what about 12.2.0.1 (no – hurrah: unless it just needs a larger data set!).
  • Is there any clue about this on MoS (yes Bug 17655392 – though that one is erroneously, I think, flagged as “closed not a bug”)
  • Is there a workaround ? (Yes – I think so).

Playing around and trying to work out what’s happening the obvious pointers are the large memory allocation and the “incomplete” spill to disc – what would happen if I fiddled around with workarea sizing – switching it to manual, say, or setting the pga_aggregate_target to a low value. At one point I got results showing 19M rows (that’s not a typo, it really was close to 5 times the number of rows in the table) sorted with a couple of hundred thousand blocks of TEMP used – the 10033 trace showed 9 consecutive passes (that I can’t explain) as the code executed from which I’ve extract the row counts, temp blocks used, and number of comparisons made:


Input records                             3988000
Total disk blocks used                    41544
Total number of comparisons performed     0

Input records                             3554000
Total disk blocks used                    37023
Total number of comparisons performed     0

Input records                             3120000
Total disk blocks used                    32502
Total number of comparisons performed     0

Input records                             2672000
Total disk blocks used                    27836
Total number of comparisons performed     0

Input records                             2224000
Total disk blocks used                    23169
Total number of comparisons performed     0

Input records                             1762000
Total disk blocks used                    18357
Total number of comparisons performed     0

Input records                             1300000
Total disk blocks used                    13544
Total number of comparisons performed     0

Input records                             838000
Total disk blocks used                    8732
Total number of comparisons performed     0

Input records                             376000
Total disk blocks used                    3919
Total number of comparisons performed     0

There really doesn’t seem to be any good reason why Oracle should do any sorting of the data (and maybe it wasn’t given the total number of comparisons performed in this case) – except, perhaps, to allow it to do bulk inserts into each partition in turn or, possibly, to avoid creating an entire new partition at exactly the moment it finds just the first row that needs to go into a new partition. Thinking along these lines I decided to pre-create all the necessary partitions just in case this made any difference – the code is at the end of the blog note. Another idea was to create the table empty (with, and without, pre-created partitions), then do an “insert /*+ append */” of the data.

Nothing changed (much – though the number of rows sorted kept varying).

And then — it all started working perfectly with virtually no rows reported sorted and no I/O to the temporary tablespace !

Fortunately I thought of looking at v$memory_resize_ops and found that the automatic memory management had switched a lot of memory to the PGA, allowing Oracle to do whatever it needed to do completely in memory without reporting any sorting (and a couple of checks on v$process_memory showed that the amount of memory assigned to category “Other” – rather and “SQL”, interestingly – had exceeded the current value of the pga_aggregate_target). A quick re-start of the instance fixed that “internal workaround”.

Still struggling with finding a reasonable workaround I decided to see if the same anomaly would appear if the table were range partitioned but didn’t have an interval clause. This meant I had to precreate all the necessary partitions, of course – which I did by starting with an interval partitioned table, letting Oracle figure out which partitions to create, then disabling the interval feature – again, see the code at the end of this note.

The results: no rows sorted on the insert, no writes to temp. Unless it’s just a question of needing even more data to reproduce the problem with simple range partitioned tables, it looks as if there’s a problem somewhere in the code for interval partitioned tables and all you have to do to work around it is precreate loads of partitions, disable intervals, load, then re-enable the intervals.

Footnote:

Here’s the “quick and dirty” code I used to generate the t2 table with precreated partitions:


create table t2
partition by range(created)
interval(numtodsinterval(7, 'day'))
(
        partition p_start values less than (to_date('&m_today','dd-mon-yyyy'))
)
storage(initial 1M)
nologging
monitoring
as
select
        *
from
        t1
where
        rownum <= 0
;


<<expand>>
declare
        m_max_date      date;
begin
        select  max(created)
        into    expand.m_max_date
        from    t1
        ;

        <<loop>>
        for i in 1..expand.m_max_date - trunc(sysdate) loop
                dbms_output.put(
                        to_char(trunc(sysdate) + loop.i,'dd-mon-yyyy') || chr(9)
                );
                execute immediate
                        'lock table t2 partition for ('''  ||
                        to_char(trunc(sysdate) + loop.i,'dd-mon-yyyy') ||
                        ''') in exclusive mode'
                ;
        end loop;
        dbms_output.new_line();
end;
/

prompt  ========================
prompt  How to disable intervals
prompt  ========================

alter table t2 set interval();

The code causes partitions to be created by locking the relevant partition for each date between the minimum and maximum dates in the t1 table – locking the partition is enough to create it if it doesn’t already exists. The code is a little wasteful since it locks each partition 7 times as we walk through the dates, but it’s only a quick demo for a model and for copying a very large table wastage would probably be very small compared to the work of doing the actual data copy. Obviously one could be more sophisticated and limit the code to locking and creating only the partitions needed, and only locking them once each.

Update 28th Feb 2018

In comment #2 below Alexander Chervinskiy supplies another workaround. If your load is going to go to one partition and you know which one it is then SQL that specifies the target partition does not result in a massive sort – e.g. if you know you data is for 10th March 2018 then the following SQL would behave nicely:


insert
         /*+ append */
 into
        t2 partition for ('10-Mar-2018')
select
        *
from
        t1
/

Note, particularly, the use of the “for ({value})” clause that makes it possible to identify the correct partition without knowing its name.

January 30, 2018

Histogram Threat

Filed under: Histograms,Oracle,Statistics,Troubleshooting — Jonathan Lewis @ 8:07 am BST Jan 30,2018

Have you ever seen a result like this:


SQL> select sql_id, count(*) from V$sql group by sql_id having count(*) > 1000;

SQL_ID		COUNT(*)
------------- ----------
1dbzmt8gpg8x7	   30516

A client of mine who had recently upgraded to 12.2.0.1 RAC, using DRCP (database resident connection pooling) for an application using PHP was seeing exactly this type of behaviour for a small number of very simple SQL statements and wanted to find out what was going on because they were also seeing an undesirable level of contention in the library cache when the system load increased.

In this note I just want to highlight a particular detail of their problem – with an example – showing how easily histograms can introduce problems if you don’t keep an eye out for the dangers.

One of their queries really was as simple as this:

select count(*), sum(skew2) from t1 where skew = :b1;

And I’m going to use this query to model the problem. All I have to do is arrange for a data set that results in a hybrid (or height-balanced) histogram being created on the skew column, and then run the query lots of times with different input bind values. In the case of the client there were around 18,000 possible values for the column, and the number of rows per value varied from 1 to about 20,000 – but whatever the number of rows selected the optimum execution plan was always going to be an indexed access.


rem
rem     Script:         acs_child_cursors.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jan 2018
rem

create table t1 (
        id, skew, skew2, padding
)
as
with generator as (
        select
                rownum id
        from dual
        connect by
                level <= 3e3
)
select
        rownum  id,
        g1.id   id1,
        g2.id   id2,
        rpad('x',100)
from
        generator       g1,
        generator       g2
where
        g2.id <= g1.id     -- > comment to avoid WordPress format issue
order by
        g2.id, g1.id
;

alter table t1 modify skew not null;
alter table t1 modify skew2 not null;

create index t1_skew on t1(skew);

begin
        dbms_stats.gather_table_stats(
                ownname          => user,
                tabname          =>'T1',
                method_opt       => 'for all columns size 1 for columns skew size 254'
--              method_opt       => 'for all columns size 1'
        );
end;
/

variable b1 number
exec :b1 := 0;

set termout off
@start_1000
@start_1000
@start_1000
set termout on

set linesize 120
set trimspool on

column sql_text format a55

select
        child_number, plan_hash_value, executions,
        is_bind_sensitive,
        is_bind_aware,
        is_shareable,
        sql_text
from
        v$sql
where   sql_id = 'b82my582cnvut'
;

The data set contains 3,000 distinct values for skew and the way I’ve generated the rows means that the value N will appear N times – so there’s one row with the value 1 and 3,000 rows with the value 3,000 and so on for a total of 4,501,500 rows. If you want to run the tes the code is likely to take a couple of minutes to complete, requiring roughly 700 MB of disk space.

The mechanism of the script start_1000 is something I published a few years ago, and essentially it executes a script called start_1.sql 1,000 times which, for this test, contains the following two lines:


exec :b1 := :b1 + 1

select count(*), sum(skew2) from t1 where skew = :b1;

The net effect of the 3 calls to start_1000.sql is that my simple SQL statement is called once in turn for each value of skew from 1 to 3,000. The SQL_ID of the statement is ‘b82my582cnvut’ which I’ve used to query v$sql when the run is complete, with the following result:


CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS I I I SQL_TEXT
------------ --------------- ---------- - - - -------------------------------------------------------
	   0	  1041516234	    498 Y N N select count(*), sum(skew2) from t1 where skew = :b1
	   1	  1041516234	     25 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   2	  1041516234	    104 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   3	  1041516234	    308 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   4	  1041516234	    429 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   5	  1041516234	    640 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   6	  1041516234	     31 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   7	  1041516234	    305 Y Y N select count(*), sum(skew2) from t1 where skew = :b1
	   8	  1041516234	    660 Y Y Y select count(*), sum(skew2) from t1 where skew = :b1

9 rows selected.

I’ve got 9 child cursors, all with the same execution plan, all except the last labelled as not shareable (you may find that you don’t get exactly the same result, on repeated tests I got between 5 and 9 cursors). Given enough time all these cursors except the last (shareable) one would be aged out of the library cache. In the case of the client, who had a shared pool that was probably quite a bit larger than needed, the number of non-shareable cursors could get very large and they were hanging around for ages. Typically most of the cursors would report an execution count less than 30, with many showing just one or two executions and a handful showing execution counts in the region of several hundred (and that hanful were the ones that were still marked as shareable).

After eliminating the critical histogram (using dbms_stats.delete_column_stats()) and eliminating the redundant child cursors (using dbms_pool.purge()) the massive proliferation stopped happening and the performance threat disappeared. The only issue then was to change the table preferences for stats collection on this table to add the clause “for columns size 1 skew” so that the histogram would not be recreated on the next gather.

Further Observations.

I suspect that part of the client’s probem – something that exaggerated the count rather than causing it – could be attributed to using DRCP (database resident connection pool) which probably still has some quirky bits of behaviour. It was also true that the client’s connection pool was probably much bigger than it needed to be so if there were any funny little bits of emergent behaviour at scale the client would probably have hit them.

The problem of escalating child cursors is one that Oracle has been working on for quite a long time, and there’s a (hidden) parameter that was introduced late in 11gR2 (though I think that the 11g mechanism first appeared through a fix control) to allow Oracle to mark a parent cursor obsolete if it acquired too many child cursors.  There’s a note on MoS that the client had read on this topic: Doc ID: 2298504.1: Cursor Mutex X Wait Events: After Upgrading To 12.2″ which looked as if it was describing their symptoms so they had set this parameter (_cursor_obsolete_threshold) from 8192 (the 12.2 default) down to 1024 (the default for 12.1 and earlier versions). This had been of some help with the library cache problem.  When the sql_id at the top of this article reported 30,516 child cursors that would be 29 “obsolete” parent cursors with 1,024 childs cursor and one “live” parent cursor with 820 child cursors.

You can appreciate that if Oracle has to find a parent cursor and pin it while walking a chain of 30,516 child cursors that’s likely to take a lot more time than walking a chain of 30 parent cursors (while holding a library cache mutex, perhaps) to find the one non-obsolete parent, then acquiring the parent mutex to walk a chain of 820 child cursor.

I don’t know the exact details of the mechanisms involved with manipulating the various chains – but there are likely to be times when one process needs exclusive mutexes/latches to change a chain while other processes are holding shared mutexes/latches to search the chain. When you’ve got 30,000 child cursors in total the important questions become: “where’s the trade-off between making the child chains shorter and making the parent search longer ?” (I’d expect – or hope – that the Oracle developers had actually found a way to code the obsolence so that the new parent was first in the search, and the rest were never visited, of course.)

One of the suggestions I made to try to alleviate the problem – which I had assumed was due in part to the degree of concurrent execution of the statement – was to mark the cursor as “hot” This resulted in 36 differet sql_ids for the same statement (the client machine had 72 CPUs). This had some effect but ultimately meant that there were 36 chains of parents that would eventually end up with lots of child cursors – the only difference was the rate at which the total cursor count was growing (a lot slower), balanced against the threat that they might all manage to get to 30,000+ child cursors! Instead, as a quick and dirty workaround, I supplied the client with a script that could be run at quieter moments during the day to call dbms_shared_pool.purge() for the sql_id to flush all its cursors from the library cache.

One final oddity – which isn’t from the client site. When I changed my test above to avoid generating the histogram (using the commented out method_opt “for all columns size 1”) I found that I still got two child cursors; the first ended up marked as bind-aware but insensitive and non-shareable, the second appeared (time and time again) when my bind value got to 499 and was marked bind-sensitive, bind-aware and shareable.  I still have no idea why this happened.

Footnote:

When repeating the test I started with a “flush shared_pool” – but I’ve removed this line from the code above in case anyone ran it without considering the possible side effects. You do need to clear previous copies of the key statement from the library cache, though, if you want to avoid confusing the issue on repeated runs of the test.

 

January 29, 2018

Case Study – 1

Filed under: Oracle,Statspack,Troubleshooting — Jonathan Lewis @ 10:45 am BST Jan 29,2018

It has been some time since I wrote an article walking through the analysis of information on an AWR report, but a nice example appeared a few weeks ago on Twitter that broke a big AWR picture into a sequence of bite-sized chunks that made a little story. So here it is, replayed in sync with my ongoing thoughts. The problem started with the (highly paraphrased) question – “How could I get these headline figures when all the ‘SQL ordered by’ sections of the report show captured SQL account for 0.0% of Total?”. The report was a 30 minute snapshot from 11.2.0.3, and here’s the Load Profile:As you can see, the database was doing quite a lot of work as measured by the physical reads and writes, the number of block changes and size of redo, and the fact that the average CPU usage by the foreground sessions in this instance accounts for 9.5 CPUs. Generally speaking the 49 seconds per second of DB time is also a fairly good hint,when combined with the other numbers, that the instance is busy but, in the absence of any other information, that could be one session holding a blocking lock with 48 other sessions waiting for the lock to be released.

There are a couple of unusual (though not impossible) features to this profile. Given the amount of work the figures for user calls and executes look very small – again not technically impossible, just unlikely in “normal” database processing given the apparent workload – and bear in mind that the “SQL ordered by ..” figures seem to account for none of the workload. Similarly the figures for logical reads and block changes are a little unusual (for “normal” processing) – on average this instance seems to have modified every block it visited (without any work showing up in the captured SQL).

Next in the set of images was the Time Model:As you can see, the foreground time (DB time) is 85,944 seconds or which foreground CPU usage (DB CPU) is 16,735 seconds – with about 69,000 seconds unaccounted ! THere’s virtually no time spend on PL/SQL or SQL, and rman doesn’t even make an appearance  (I mention rman specifically because there was at least one version of Oracle where the rman time was accidentally lost from this summary).

So what does the Top Timed Events look like:

It’s nice to see that this is consistent with the Load Profile: the DB CPU matches, and there’s a lot of physical reads (and a quick check says that 6,560,642/1,800 = 3,644 … which is pretty close to the 3,746 physical reads per second in the Load Profile).  There’s one major anomaly here, though: the huge number of (and time spent on) latch: row cache objects. and even though it’s not the single largest component of time it’s the most obvious one to pursue so the next bit of the report to check is the Dictionary Cache Statistics, with the Tablespace IO Stats and Segments by Physical Reads to follow. I don’t have an image for the dictionary cache stats, but the answer to the question “What were all the rowcache object gets for?” was: “dc_tablespaces (214,796,434)” – which (probably) told me everything I needed to know.

I could show you the specific Instance Activity statistic that I wanted to see next, but I’ll postpone that for a moment and jump to the Tablespace IO Stats – which we were planning to do and might have done anyway if we hadn’t known the rocket science behind massive number of gets on dc_tablespaces.

That’s a horrendous number of (single block) reads of the undo tablespace – and why would they be happening ? The instance is engaged in some massive rollback activity (and the transactions being rolled back are on objects in the GIRO tablespace – which is why it is also suffering a lot of single block reads) and this is the point where we jump to the relevant Instance Activity statistic to confirm the claim:

There are two other “undo records applied” statistics, but we don’t need to think about them – the match between the count of undo records applied and the gets on the dc_tablespaces latch is close to perfect. Almost everything that this instance is doing is rolling back – there must have been some enormous data changes (possibly only one, possibly parallel-enabled) that failed in the previous half hour and now the entire mess is being cleaned up.

One little detail to note – the “undo records applied” per second is 122,355, but the Load Profile reported 247,885 “Block changes” per second. The two figures are consistent with each other. Each application of an undo record is two block changes – the first when you modify the source data block, the second when you update the undo record itself to flag it as “applied”:  122,355 * 2  = 244,710, which is a good match for 247,855.

Final Thoughts

There is a second reason why you could see lots of gets on dc_tablespaces – but I think it was a bug in 9i relating to temporary tablespace groups. The phenomenon as a side effect of rolling back was something I discovered in the 8i timeline and I’ve not actually checked what an AWR report really would look like if I forced a massive rollback to take place as the only workload across the interval – so here’s a quick test I constructed and ran to finish the thread off:


set timing on

create table t1 as
with g as (select rownum id from dual connect by level <= 1000)
select rownum id, rownum n1, rpad ('x',150) padding from g,g
;

create index t1_i1 on t1(id);

begin
        for i in 1..1000000 loop
                update t1 set n1 = n1 where id = i;
        end loop;
end;
/

alter system flush buffer_cache;

pause take AWR snapshot from another session

rollback;

prompt take AWR snapshot from another session

On the small VM I used to run the test it took a little over 60 seconds to run the update and the same again to complete the rollback. The “DB time” shown in the Time Model section of the AWR report was 62.0 seconds, while the “sql execute elapsed time” was 3.9 seconds (which was the SQL executed while capturing the AWR data).

Conclusion

This was a problem where the database seemed to have done a lot of work that couldn’t be attributed to SQL. While I had a little knowledge of the rocket science up my sleeve that may have allowed me to identify the source more quickly and with more confidence than the average DBA all I’ve done in this note is highlight a couple of oddities and big numbers that anyone could have spotted, and followed a couple of simple guesses:

  1. DB time was large, but sql (and pl/sql) time was non-existent
  2. Top timed events were I/O and latches – so identify the latch
  3. The specific latch pointed towards tablespaces – so check the Tablespace I/O and note the UNDO tablespace
  4. Look at any Instance Activity statistics about “undo”.
  5. Job done – but a quick test case is the icing on the cake.

 

January 25, 2018

gc buffer busy

Filed under: Oracle,RAC,Troubleshooting — Jonathan Lewis @ 2:12 pm BST Jan 25,2018

I had to write this post because I can never remember which way round Oracle named the two versions of gc buffer busy when it started identifying them separately. There are two scenarios to cover when my session wants my instance to acquire a global cache lock on a block and some other session is already trying to acquire that lock or is holding it in an incompatible fashion:

  • The other session is in my instance
  • The other session is in a remote instance

One of these cases is reported as “gc buffer busy acquire”, the other as a “gc buffer busy release” and I always have to check which is which. I think I usually get it right first time when I see it but I always manage to convince myself that I might have got it wrong and end up searching the internet for Riyaj Shamsudeen’s blog posting about it.

The “release” is waiting for another instance to surrender the lock to my instance; the “acquire” is waiting for another session in my instance to finish acquiring the lock from the other  instance.

I decided to jot down this note so I didn’t have to keep searching for Riyaj’s and also because a little problem on OTN at the moment showed a couple of AWR reports with an unlikely combination of waits for acquire (180,000,000) and release (2,000) waits.

If you’re wondering why this looks odd – if I’m waiting for an acquire someone else in my instance must be waiting for a release.  Obviously many sessions could be waiting for one release, and if acquirers time out very rapidly (though they’re not reported as doing so) then the ratio could get very high – but 90,000 acquires per release doesn’t look right.

 

January 15, 2018

Histogram Hassle

Filed under: Histograms,Oracle,Statistics,Troubleshooting — Jonathan Lewis @ 1:01 pm BST Jan 15,2018

I came across a simple performance problem recently that ended up highlighting a problem with the 12c hybrid histogram algorithm. It was a problem that I had mentioned in passing a few years ago, but only in the context of Top-N histograms and without paying attention to the consequences. In fact I should have noticed the same threat in a recent article by Maria Colgan that mentioned the problems introduced in 12c by the option “for all columns size repeat”.

So here’s the context (note – all numbers used in this example are approximations to make the arithmetic obvious).  The client had a query with a predicate like the follwing:

    t4.columnA = :b1
and t6.columnB = :b2

The optimizer was choosing to drive the query through an indexed access path into t6, which returned ca. 1,000,000 rows before joining (two tables later) to t4 at which point all but a couple of rows remained – typical execution time was in the order of tens of minutes. A /*+ leading(t4) */ hint to start on t4 with an index that returned two rows reduced the response time to the classic “sub-second”.

The problem had arisen because the optimizer had estimated a cardinality of 2 rows for the index on t6 and the reason for this was that, on average, that was the correct number. There were 2,000,000 rows in the table with 1,000,000 distinct values. It was just very unlucky that one of the values appeared 1,000,000 times and that was the value the users always wanted to query – and there was no histogram on the column to tell the optimizer that there was a massive skew in the data distribution.

Problem solved – all I had to do was set a table preference for this table to add a histogram to this column and gather stats. Since there were so many distinct values and so much “non-popular” data in the table the optimizer should end up with a hybrid histogram that would highlight this value. I left instructions for the required test and waited for the email telling me that my suggestion was brilliant and the results were fantastic… I got an email telling me it hadn’t worked.

Here’s a model of the situation – I’ve created a table with 2 million rows and a column where every other row contains the same value but otherwise contains the rownum. Because the client code was using a varchar2() column I’ve done the same here, converting the numbers to character strings left-padded with zeros. There are a few rows (about 20) where the column value is higher than the very popular value.


rem
rem     Script:         histogram_problem_12c.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jan 2018
rem
rem     Last tested
rem             12.2.0.1
rem             12.1.0.2
rem

create table t1
segment creation immediate
nologging
as
with generator as (
        select
                rownum id
        from dual
        connect by
                level <= 2e4
)
select
        rownum  as id,
        case
                when mod(rownum,2) = 0
                        then '999960'
                        else lpad(rownum,6,'0')
        end     as bad_col
from
        generator       v1,
        generator       v2
where
        rownum <= 2e6    -- typing error, ends up with 2 rows per non-popular value.
;

Having created the data I’m going to create a histogram on the bad_col – specifying 254 columns – then query user_tab_histograms for the resulting histogram (from which I’ll delete a huge chunk of boring rows in the middle):


begin

        dbms_stats.gather_table_stats(
                ownname         => 'TEST_USER',
                tabname         => 'T1',
                method_opt      => 'for columns bad_col size 254'
        );

end;
/

select
        column_name, histogram, sample_size
from
        user_tab_columns
where
        table_name = 'T1'
;

column end_av format a12

select
        endpoint_number         end_pt,
        to_char(endpoint_value,'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') end_val,
        endpoint_actual_value   end_av,
        endpoint_repeat_count   end_rpt
from
        user_tab_histograms
where
        table_name = 'T1'
and     column_name = 'BAD_COL'
order by
        endpoint_number
;

COLUMN_NAME          HISTOGRAM             Sample
-------------------- --------------- ------------
BAD_COL              HYBRID                 5,513
ID                   NONE               2,000,000

    END_PT END_VAL                         END_AV          END_RPT
---------- ------------------------------- ------------ ----------
         1  303030303031001f0fe211e0800000 000001                1
        12  3030383938311550648a5e3d200000 008981                1
        23  303135323034f8f5cbccd2b4a00000 015205                1
        33  3032333035311c91ae91eb54000000 023051                1
        44  303239373236f60586ef3a0ae00000 029727                1
...
      2685  3938343731391ba0f38234fde00000 984719                1
      2695  39393235303309023378c0a1400000 992503                1
      2704  3939373537370c2db4ae83e2000000 997577                1
      5513  393939393938f86f9b35437a800000 999999                1

254 rows selected.

So we have a hybrid histogram, we’ve sampled 5,513 rows to build the histogram, we have 254 buckets in the histogram report, and the final row in the histogram is end point 5513 (matching the sample size). The first row of the histogram shows us the (real) low value in the column and the last row of the histogram reports the (real) high value. But there’s something very odd about the histogram – we know that ‘999960’ is the one popular value, occurring 50% of the time in the data, but it doesn’t appear in the histogram at all.

Looking more closely we see that every bucket covers a range of about 11 (sometimes 9 or 10) rows from the sample, and the highest value in each bucket appears just once; but the last bucket covers 2,809 rows from the sample with the highest value in the bucket appearing just once. We expect a hybrid histogram to have buckets which (at least initially) are all roughly the same size – i.e. “sample size”/”number of buckets” – with some buckets being larger by something like the amount that appears in their repeat count, so it doesn’t seem right that we have an enormous bucket with a repeat count of just 1. Something is broken.

The problem is that the sample didn’t find the low and high values for the column – although the initial full tablescan did, of course – so Oracle has “injected” the low and high values into the histogram fiddling with the contents of the first and last buckets. At the bottom end of the histogram this hasn’t really caused any problems (in our case), but at the top end it has taken the big bucket for our very popular ‘999960’ and apparently simply replaced the value with the high value of ‘999999’ and a repeat count of 1.

As an indication of the truth of this claim, here are the last few rows of the histogram if I repeat the experiment but, before gathering the histogram, delete the rows where bad_col is greater than ‘999960’. (Oracle’s sample is random, of course, and has changed slightly for this run.)

    END_PT END_VAL                         END_AV          END_RPT
---------- ------------------------------- ------------ ----------
...
      2641  3938373731371650183cf7a0a00000 987717                1
      2652  3939353032310e65c1acf984a00000 995021                1
      2661  393938393433125319cc9f5ba00000 998943                1
      5426  393939393630078c23b063cf600000 999960             2764

Similarly, if I inserted a few hundred rows with a higher value than my popular value (in this case I thought 500 rows would be a fairly safe bet as the sample was about one in 360 rows) I got a histogram which started with a bucket about the popular bucket, so the problem of that bucket being hacked to the high value was less significant:


    END_PT END_VAL                         END_AV          END_RPT
---------- ------------------------------- ------------ ----------
...
      2718  393736313130fe68d8cfd6e4000000 976111                1
      2729  393836373630ebfe9c2b7b94c00000 986761                1
      2740  39393330323515efa3c99771600000 993025                1
      5495  393939393630078c23b063cf600000 999960             2747
      5497  393939393938f86f9b35437a800000 999999                1

Bottom line, then: if you have an important popular value in a column and there aren’t very many rows with a higher value, you may find that Oracle loses sight of the popular value as it fudges the column’s high value into the final bucket.

Workaround

I did consider writing a bit of PL/SQL for the client to fake a realistic frequency histogram, but decided that that wouldn’t be particularly friendly to future DBAs who might have to cope with changes. Luckily the site doesn’t gather stats using the automatic scheduler job and only rarely updates stats anyway, so I suggested we create a histogram on the column using an estimate_percent of 100. This took about 8 minutes to run – for reasons that I will go into in a moment – after which I suggested we lock stats on the table and document the fact that when stats are collected on this table it’s got to be a two-pass job – the normal gather with its auto_sample_size to start with, then a 100% sample for this column to gather the histogram:


begin
        dbms_stats.gather_table_stats(
                user,
                't1',
                method_opt       => 'for columns bad_col size 254',
                estimate_percent => 100,
                cascade          => false
        );
end;
/

    END_PT END_VAL                         END_AV          END_RPT
---------- ------------------------------- ------------ ----------
...
       125  39363839393911e01d15b75c600000 968999                0
       126  393834373530e98510b6f19a000000 984751                0
       253  393939393630078c23b063cf600000 999960                0
       254  393939393938f86f9b35437a800000 999999                0

129 rows selected.

This took a lot longer, of course, and produced an old-style height-balanced histogram. Part of the time came from the increased volume of data that had to be processed, part of it came from a suprise (which also appeared, in a different guise, in the code that created the original hybrid histogram).

I had specifically chosen the method_opt to gather for nothing but the single column. In fact whether I forced the “legacy” (height-balanced) code or the modern (hybrid) code, I got a full tablescan that did some processing of EVERY column in the table and then threw most of the results away. Here are fragments of the SQL – old version first:


select /*+
            no_parallel(t) no_parallel_index(t) dbms_stats
            cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring
            xmlindex_sel_idx_tbl no_substrb_pad
       */
       count(*),
       count("ID"), sum(sys_op_opnsize("ID")),
       count("BAD_COL"), sum(sys_op_opnsize("BAD_COL"))
       ...
from
       "TEST_USER"."T1" t

select /*+
           full(t)    no_parallel(t) no_parallel_index(t) dbms_stats
           cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring
           xmlindex_sel_idx_tbl no_substrb_pad
       */
       to_char(count("ID")),
       to_char(count("BAD_COL")),
       substrb(dump(min("BAD_COL"),16,0,64),1,240),
       substrb(dump(max("BAD_COL"),16,0,64),1,240),
       ...
       count(rowidtochar(rowid))
from
       "TEST_USER"."T1" t  /* ACL,TOPN,NIL,NIL,RWID,U,U254U*/

The new code only used the substrb() functions on the bad_col, but all other columns in the table were subject to the to_char(count()).
The old code applied the count() and sys_op_opnsize() to every column in the table.

This initial scan was a bit expensive – and disappointing – for the client since their table had 290 columns (which means intra-block chaining as a minimum) and had been updated so much that 45% of the rows in the table had to be “continued fetches”. I can’t think why every column had to be processed like this, but if they hadn’t been that would have saved a lot of CPU and I/O since the client’s critical column was very near the start of the table.

Finally

This problem with the popular value going missing is a known issue, for which there is a bug number, but there is further work going on in the same area which means this particular detail is being rolled into another bug fix. More news when it becomes available.

Bear in mind that this problem also appears for Top-N (aka Top-Frequency) histograms – where both the lowest and highest buckets may be replaced with a bucket that reports the low-value and high-value for the column with a repeat-count of 1.

Update (Jan 2018)

This is now fixed under bug number “25994960: CARDINALITY MISESTIMATE FROM HYBRID HISTOGRAM” with a patch (of the same number) for 12.1.0.2

January 11, 2018

ASSM tangle

Filed under: ASSM,Infrastructure,Oracle,Troubleshooting — Jonathan Lewis @ 5:35 pm BST Jan 11,2018

Here’s a follow-on from Tuesday’s (serious) note about a bug in 12.1.0.2 that introduces random slowdown on large-scale inserts. This threat in this note, while truthful and potentially a nuisance, is much less likely to become visible because it depends on you doing something that you probably shouldn’t be doing.

There have always been problems with ASSM and large-scale deletes – when should Oracle mark a block as having free space on deletion: if your session does it immediately then other sessions will start trying to use the free space that isn’t really there until you commit; if your session doesn’t do it immediately when can it happen, since you won’t want it done on commit – but that means the segment could “lose” a lot of free space if something doesn’t come along in a timely fashion and tidy up.

But here’s a quirky problem that takes things one step further. What happens if you try to delete a load of data and fail and your session rolls back? If we start with yesterday’s script (running on 11.2.0.4 or 12.2.0.1) we can create a table with 1M rows in it and the following space usage:


Unformatted		      : 	   0 /		      0
Freespace 1 (  0 -  25% free) : 	   0 /		      0
Freespace 2 ( 25 -  50% free) : 	   1 /		  8,192
Freespace 3 ( 50 -  75% free) : 	   0 /		      0
Freespace 4 ( 75 - 100% free) : 	  67 /		548,864
Full			      :       41,666 /	    341,327,872

You will recall that each “Full” block actually had the basic 10% free space, plus a couple of hundred extra bytes which Oracle had to “forget about” because the incoming rows were always 290 bytes long. Let’s take this table and delete the first 100,000 rows, then emulate a session error and roll back, and then check the space usage:


delete from t1 where rownum <= 100000;
rollback;

-- generate space usage report

Unformatted		      : 	   0 /		      0
Freespace 1 (  0 -  25% free) :        4,167 /	     34,136,064
Freespace 2 ( 25 -  50% free) : 	   1 /		  8,192
Freespace 3 ( 50 -  75% free) : 	   0 /		      0
Freespace 4 ( 75 - 100% free) : 	  67 /		548,864
Full			      :       37,499 /	    307,191,808

We have 4,167 blocks which were full, and we know they are effectively full for the purposes of our data, but they’re now declared as having some free space. When Oracle rolled back the delete it wasn’t running code that would attempt to discover that the block was going to go over the limit, it simply calculated the byte change from re-inserting the row, added it to the total free space (tosp) and produced a number that hadn’t reached the limit set by pctfree – so flagged the block accordingly. (Remember my comment in the earlier article that Oracle doesn’t generate undo for the state changes on the Level 1 bitmap blocks – this is, at least in part – a consequence of that strategy).

Guideline

If you’re going to do large-scale deletes in an ASSM environment, make sure they don’t fail or subsequent inserts may take a long time.

 

January 9, 2018

ASSM argh!

Filed under: 12c,ASSM,Bugs,Infrastructure,Oracle,Troubleshooting — Jonathan Lewis @ 5:53 pm BST Jan 9,2018

Here’s a problem with ASSM that used to exist in older versions of Oracle had disappeared by 11.2.0.4 and then re-appeared in 12.1.0.2 – disappearing again by 12.2.0.1. It showed up on MoS a few days ago under the heading: “Insert is running long with more waits on db file sequential read”.

The obvious response to this heading is to question the number of indexes on the table – because big tables with lots of indexes tend to give you lots of random I/O as Oracle maintains the indexes – but this table had no indexes. The owner of the problem supplied several of bits of information in the initial post, with further material in response to follow-up questions, including the tkprof summary of the 10046/level 12 trace of the insert and two extracts from the trace file to show us some of the “db file sequential read” waits – the first extract made me wonder if there might be some issue involving 16KB blocks but the second one dispelled that illusion.

There are several buggy things that can appear with ASSM and large-scale DML operations, and sometimes the problems can appear long after the original had done the dirty deed, so I thought I’d create a simple model based on the information supplied to date – and discovered what the problem (probably) was. Here’s how it starts – I’ve created a tablespace using ASSM, and in this tablespace I’ve created a table which has 48 columns with a row length of 290 bytes (roughly matching the OP’s table), and I’ve hacked out a simple PL/SQL block that loops around inserting arrays of 100 rows at a time into the table for a total of 1M rows before committing.


rem
rem     Script:         assm_cleanout.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jan 2018
rem     Purpose:
rem
rem     Last tested
rem             12.2.0.1
rem             12.1.0.2        Lots of blocks left "not full"
rem             11.2.0.4
rem

rem
rem     using OMF, so no file-name needed
rem     Ran this bit as SYS, and altered test user to have unlimited quota
rem

/*
create
        tablespace test_8k_assm
        datafile size 1G
        extent management local
        autoallocate
        segment space management auto
;
*/

rem
rem     Create the table, pre-allocate some space.
rem     This means we should get consistent 8M extents and not initial little ones
rem

create table t1 (
        v001 varchar2(5), v002 varchar2(5), v003 varchar2(5), v004 varchar2(5), v005 varchar2(5),
        v006 varchar2(5), v007 varchar2(5), v008 varchar2(5), v009 varchar2(5), v010 varchar2(5),
        v011 varchar2(5), v012 varchar2(5), v013 varchar2(5), v014 varchar2(5), v015 varchar2(5),
        v016 varchar2(5), v017 varchar2(5), v018 varchar2(5), v019 varchar2(5), v020 varchar2(5),
        v021 varchar2(5), v022 varchar2(5), v023 varchar2(5), v024 varchar2(5), v025 varchar2(5),
        v026 varchar2(5), v027 varchar2(5), v028 varchar2(5), v029 varchar2(5), v030 varchar2(5),
        v031 varchar2(5), v032 varchar2(5), v033 varchar2(5), v034 varchar2(5), v035 varchar2(5),
        v036 varchar2(5), v037 varchar2(5), v038 varchar2(5), v039 varchar2(5), v040 varchar2(5),
        v041 varchar2(5), v042 varchar2(5), v043 varchar2(5), v044 varchar2(5), v045 varchar2(5),
        v046 varchar2(5), v047 varchar2(5), v048 varchar2(5)
)
segment creation immediate
tablespace test_8k_assm
storage(initial 8M)
;

alter table t1 allocate extent (size 8M);
alter table t1 allocate extent (size 8M);

rem
rem     Simple anonymous pl/sql block
rem     Large insert, handled with array inserts
rem     Can modify loop count and array size very easily
rem

declare
        type tab_array is table of t1%rowtype;
        junk_array tab_array;
begin

        select
                'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx',
                'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx',
                'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx',
                'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx',
                'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx', 'xxxxx'
        bulk collect into
                junk_array
        from
                all_objects
        where
                rownum  <= 100 -- > comment to avoid WordPress format issue
        ;

        for i in 1..10000 loop
                forall j in 1..junk_array.count
                        insert into t1 values junk_array(j) ;
        end loop;

end;

commit;

The number of rows per block after this insert is 24, with 1038 bytes free space left (808 due to the pctfree = 10, then the bit that was too small to take a 25th row before breaching the pctfree barrier). This means we should report 1M/24 = 41,666 full blocks and one block with some free space. So we query the table using the dbms_space package:


declare
        m_unformatted_blocks    number;
        m_unformatted_bytes     number;
        m_fs1_blocks            number;
        m_fs1_bytes             number;
        m_fs2_blocks            number;
        m_fs2_bytes             number;

        m_fs3_blocks            number;
        m_fs3_bytes             number;
        m_fs4_blocks            number;
        m_fs4_bytes             number;
        m_full_blocks           number;
        m_full_bytes            number;

begin
        dbms_space.SPACE_USAGE(
                segment_owner           => 'TEST_USER',
                segment_name            => 'T1',
                segment_type            => 'TABLE',
                unformatted_blocks      => m_unformatted_blocks,
                unformatted_bytes       => m_unformatted_bytes,
                fs1_blocks              => m_fs1_blocks ,
                fs1_bytes               => m_fs1_bytes,
                fs2_blocks              => m_fs2_blocks,
                fs2_bytes               => m_fs2_bytes,
                fs3_blocks              => m_fs3_blocks,
                fs3_bytes               => m_fs3_bytes,
                fs4_blocks              => m_fs4_blocks,
                fs4_bytes               => m_fs4_bytes,
                full_blocks             => m_full_blocks,
                full_bytes              => m_full_bytes
        );

        dbms_output.new_line;
        dbms_output.put_line('Unformatted                   : ' || to_char(m_unformatted_blocks,'999,999,990') || ' / ' || to_char(m_unformatted_bytes,'999,999,999,990'));
        dbms_output.put_line('Freespace 1 (  0 -  25% free) : ' || to_char(m_fs1_blocks,'999,999,990') || ' / ' || to_char(m_fs1_bytes,'999,999,999,990'));
        dbms_output.put_line('Freespace 2 ( 25 -  50% free) : ' || to_char(m_fs2_blocks,'999,999,990') || ' / ' || to_char(m_fs2_bytes,'999,999,999,990'));
        dbms_output.put_line('Freespace 3 ( 50 -  75% free) : ' || to_char(m_fs3_blocks,'999,999,990') || ' / ' || to_char(m_fs3_bytes,'999,999,999,990'));
        dbms_output.put_line('Freespace 4 ( 75 - 100% free) : ' || to_char(m_fs4_blocks,'999,999,990') || ' / ' || to_char(m_fs4_bytes,'999,999,999,990'));
        dbms_output.put_line('Full                          : ' || to_char(m_full_blocks,'999,999,990') || ' / ' || to_char(m_full_bytes,'999,999,999,990'));

end;
/

The results aren’t what we expect:


Unformatted                   :            0 /                0
Freespace 1 (  0 -  25% free) :       35,001 /      286,728,192
Freespace 2 ( 25 -  50% free) :            1 /            8,192
Freespace 3 ( 50 -  75% free) :            0 /                0
Freespace 4 ( 75 - 100% free) :           67 /          548,864
Full                          :        6,665 /       54,599,680

We have one block marked as 25 – 50% free (that’s the one block with 16 rows in it, which means about 40% space currently free) but our 41,666 full blocks are actually reported as 6,665 full blocks and 35,001 blocks with some space available. That’s going to hurt eventually if some process wants to insert more rows and finds that it has to fail its way through 35,001 blocks before finding a block which has enough free space.

So what happens when I repeat the PL/SQL block (and commit)? Here are the results from calls to dbms_space after the next two cycles:


Unformatted                   :            0 /                0
Freespace 1 (  0 -  25% free) :       70,002 /      573,456,384
Freespace 2 ( 25 -  50% free) :            2 /           16,384
Freespace 3 ( 50 -  75% free) :            0 /                0
Freespace 4 ( 75 - 100% free) :          220 /        1,802,240
Full                          :       13,330 /      109,199,360

Unformatted                   :          256 /        2,097,152
Freespace 1 (  0 -  25% free) :      105,003 /      860,184,576
Freespace 2 ( 25 -  50% free) :            3 /           24,576
Freespace 3 ( 50 -  75% free) :            0 /                0
Freespace 4 ( 75 - 100% free) :          117 /          958,464
Full                          :       19,995 /      163,799,040

Every time we execute the PL/SQL block we leave a trail of 35,001 more blocks which are flagged as “not quite full”.

Looking at the session stats while running the insert loop I can tell that Oracle isn’t checking to see whether or not it should be using those blocks. (A quick way of proving this is to flush the buffer cache before each execution of the PL/SQL and note that Oracle doesn’t read back the 105,000 blocks before inserting any data). So somehow, sometime, someone might get a nasty surprise – and here’s one way that it might happen:

Since I know I my data fits 24 rows per block I’m going to modify my PL/SQL block to select one row into the array then loop round the insert 25 times – so I know I’m inserting a little bit more than one block’s worth of data. Starting from the state with 105,003 blocks marked as “Freespace 1” this is what I saw – first, the free space report after inserting 25 rows:


Unformatted                   :          240 /        1,966,080
Freespace 1 (  0 -  25% free) :        1,074 /        8,798,208
Freespace 2 ( 25 -  50% free) :            0 /                0
Freespace 3 ( 50 -  75% free) :            0 /                0
Freespace 4 ( 75 - 100% free) :          133 /        1,089,536
Full                          :      123,927 /    1,015,209,984

Then a few wait events and session statistics for the insert:


---------------------------------------------------------
SID:    39:TEST_USER - jonathan
Session Events - 09-Jan 16:57:18
Interval:-      6 seconds
---------------------------------------------------------
Event                                             Waits   Time_outs        Csec    Avg Csec    Max Csec
-----                                             -----   ---------        ----    --------    --------
db file sequential read                          15,308           0         128        .008           3
db file scattered read                           20,086           0         271        .014           4

---------------------------------
Session stats - 09-Jan 16:57:18
Interval:-  6 seconds
---------------------------------
Name                                                                     Value
----                                                                     -----
session logical reads                                                  269,537
physical read total IO requests                                         35,401
db block gets                                                          229,522
consistent gets                                                         40,015
physical reads                                                         124,687
physical reads cache                                                   124,687
db block changes                                                       208,489
physical reads cache prefetch                                           89,293
redo entries                                                           207,892
redo size                                                           16,262,724
undo change vector size                                                  1,720
deferred (CURRENT) block cleanout applications                         103,932
table scan blocks gotten                                                20,797
HSC Heap Segment Block Changes                                              25

The session has read and updated almost all of the level 1 bitmap blocks. I don’t know exactly what triggered this re-read, but seems to be related to the number of rows inserted (or, perhaps, the amount of space used rather than the row count) as an insert crosses the pctfree boundary and fails over to the next block. I’ve only done a couple of little tests to try and get a better idea of why an insert sometimes sweeps through the bitmap blocks – so I know that inserting 2 or 3 rows at a time will also trigger the cleanout – but there are probably several little details involved that need to be identified.

You might note a couple of details in the stats:

  • Because I had flushed the buffer cache before the insert Oracle did its “cache warmup” tablescanning trick – if this had not happened I would probably have done a single block read for every single bitmap block I touched.
  • There are 103,932 block cleanout applications – but 208,000 db block changes and redo entries. Roughly half the latter are for data block cleanouts (OP code 4.1) and half are the state changes on the level 1 bitmap blocks (OP code 13.22). You’ll notice that neither change produces any undo.
  • I’ve also included the HSC Heap Segment Block Changes statistics to show you that not all changes to Heap Segment Blocks show up where you might expect them.

And finally:

If you re-run the tests on 11.2.0.4 and 12.2.0.1 you get the following results after the intial script run – the problem doesn’t exist:


11.2.0.4
========
Unformatted                   :            0 /                0
Freespace 1 (  0 -  25% free) :            0 /                0
Freespace 2 ( 25 -  50% free) :            1 /            8,192
Freespace 3 ( 50 -  75% free) :            0 /                0
Freespace 4 ( 75 - 100% free) :           67 /          548,864
Full                          :       41,666 /      341,327,872

12.2.0.1
========
Unformatted                   :            0 /                0
Freespace 1 (  0 -  25% free) :            0 /                0
Freespace 2 ( 25 -  50% free) :            1 /            8,192
Freespace 3 ( 50 -  75% free) :            0 /                0
Freespace 4 ( 75 - 100% free) :           67 /          548,864
Full                          :       41,666 /      341,327,872

So how does this help the OP.

  • First, there may be a huge mess still waiting to be cleaned in the table – but at 34M blocks I’m not too keen to suggest running the dbms_space routine to find out what it looks like – but maybe that’s necessary.
  • Secondly – an upgrade to 12.2 will probably avoid the problem in future.
  • Thirdly – if the number of rows per block is very close to uniform, write a little code to do a loop that inserts (say) 2 * expected number of rows per block as single row inserts and rolls back; the inserts will probably trigger a massive though perhaps not complete cleanout, so rinse and repeat until the cleanout is complete. Try to find a time when you don’t mind the extra load to get this job done.
  • Finally – on the big job that does the bulk insert – repeat the dummy insert/rollback at the end of the job to clean up the mess made by the job.

Addenda

Prompted by comment #2 below, I should add that if the problem has been fixed in 12.2 then possibly there’s a bug report and patch for it already. If there isn’t then the OP could raise an SR (referencing this blog note), and request a bug fix or back-port from 12.2.

And with 24 hours of publication, comment #4 (from Yury Pudovchenko) tells us that the bug is fixed by the Oct 2017 Bundle Patch.

 

 

January 2, 2018

Defaults

Filed under: Oracle,Troubleshooting — Jonathan Lewis @ 8:43 am BST Jan 2,2018

Following on from a Twitter reference and an update to an old posting about a side effect of  constraints on the work done inserting data, I decided to have a closer look at the more general picture of default values and inserts. Here’s a script that I’ve tested against 11.2.0.4, 12.1.0.2, and 12.2.0.1 (original install, no patches applied in all cases):


rem
rem     Script:         defaults_cost.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2017
rem

create table t1 (
        column1  varchar2(10),
        column2  varchar2(10),
        column3  varchar2(10),
        column4  varchar2(10),
        column32 varchar2(32)   default 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx',
        column33 varchar2(33)   default 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx',
        virtual1      generated always as (
                column4 || column3 || column2 || column1
        ) virtual
)
segment creation immediate
;

execute dbms_output.put_line(dbms_stats.create_extended_stats(user,'t1','(column1 || column2 || column3 || column4)'))
execute dbms_output.put_line(dbms_stats.create_extended_stats(user,'t1','(column1,column2,column3)'))

create or replace function plsqlfunction_with_30char_name(
        i_in varchar2
)
return varchar
deterministic
is
begin
        return initcap(i_in);
end;
/

create index t1_i1 on t1(substr(plsqlfunction_with_30char_name(column1),1,10));

When you create a function-based index you get a hidden, virtual column supporting the index expression; when you create extended stats (of either type) you get a hidden virtual column holding the extension definition, when you create any type of virtual column, including a “real” virtual column you get a data dictionary entry holding the column name and the expression definition: all these options use the “data_default” column from user_tab_cols to display the defining information – as we can see when we the following query:


select  column_name, data_default
from    user_tab_cols
where   table_name = 'T1'
order by
         column_id
;

COLUMN_NAME                      DATA_DEFAULT
-------------------------------- --------------------------------------------------------------------------------
COLUMN1
COLUMN2
COLUMN3
COLUMN4
COLUMN32                         'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
COLUMN33                         'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
VIRTUAL1                         "COLUMN4"||"COLUMN3"||"COLUMN2"||"COLUMN1"
SYS_STUDAN97VB_XDKRTR_NPFAB80P   "COLUMN1"||"COLUMN2"||"COLUMN3"||"COLUMN4"
SYS_STUTCBJ8OFFSY1D9ZXRYZ0W3W#   SYS_OP_COMBINED_HASH("COLUMN1","COLUMN2","COLUMN3")
SYS_NC00010$                     SUBSTR("TEST_USER"."PLSQLFUNCTION_WITH_30CHAR_NAME"("COLUMN1"),1,10)

Apart from the special cases I’ve just listed, you’ll also see the “default values” I specified for column32 and column33 – you’ll notice that I’ve supplied a 30 character string as the default for column32, and a 31 character string as the default for column33 – this is a convenience that means the used space in the data_default (which is a long column) corresponds to the name of the column once you include the single quotes in the their character count.

Having set my data up I’m going to emulate a bad application that uses lots of literal string SQL and leaves Oracle to fill in the default values (and, of course, derive the various virtual values it might need).


alter session set events '10046 trace name context forever, level 4';

begin
        for i in 1..10 loop
                execute immediate '
                        insert into t1 (column1, column2, column3, column4)
                        values( ' || i || ', ' || i || ', ' || i || ', ' || i || ')'
                ;
                commit;
        end loop;
end;
/

alter session set events '10046 trace name context off';

This code generates 10 strings that populate column1 through to column4 only. But you’ll notice the call to enable SQL tracing – and here’s the interesting bit of the output from applying tkprof to the trace file:


  SQL ID: 47r1y8yn34jmj Plan Hash: 2191121161

select default$
from
 col$ where rowid=:1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       50      0.00       0.00          0          0          0           0
Execute     50      0.00       0.00          0          0          0           0
Fetch       50      0.00       0.00          0        100          0          50
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      150      0.00       0.00          0        100          0          50

The summary is the same for all three versions of Oracle I tested*** – we’ve queried for a default value from col$ 5 times for each row we insert! (Technically that’s 5 times for each insert statement we’ve had to (hard-)parse; this anomaly wouldn’t appear if we have been using a bind-variable method and reusing the insert statement.) *** There is one difference in 12.2 – the number of parse calls reported for this statement was 1 rather than 50 but, judging by the various cursor cache hit stats, that may be due to a change in accounting rather than a change in workload.

Check the table definition: there are two “real defaults” and 4 expressions due to the various virtual columns – so why 5 calls per insert and not 6 ? The answer lies in the length of the actual value involved – if the text that appears in the (long) data_default column is 32 characters or shorter it will be stored in the the dictionary cache (rowcache), but only one of our 6 values is that short, so Oracle looks up the other five on each insert (hard parse).

This is a little strange on two counts: first, given the enormous memories that have been available for years and the extreme usefulness of virtual columns and extended stats it seems something of an oversight to limit the memory available to the cache that holds such critical definitions; secondly, we don’t need to evaluate the virtual columns (unless they are indexed) or extended stats on inserts so why is Oracle querying the definitions anyway ? [Possible answer: perhaps Oracle is using generic code that allows for column check constraints – which might exist on users’ virtual columns – and hasn’t catered for bypassing system-generated virtual columns.]

A key point to remember before you start worrying too much about the impact of the execution count for this query against col$ is that it’s only relevant to “hard” parses – so you’re only likely to notice it if you have a large number of different “literal string” inserts that should be using bind variables; and that means you’ve probably got an important coding defect to address before you worry too much about the extra impact caused by this particular call. Nevertheless there are a couple of bug reports on MoS that have been raised against this query and, after writing this note, I did a quick Google search for the critical SQL_ID and found (among others) this production example from Franck Pachot.

 

Next Page »

Powered by WordPress.com.