Mohamed Houri’s Oracle Notes

June 23, 2015

Real Time SQL Monitoring oddity

Filed under: Oracle,Sql Plan Managment — hourim @ 1:45 pm

This is a small note about a situation I have encountered and which I thought it is worth sharing with you. There was an insert/select executing in parallel DOP 16 on a 11.2.0.3 Oracle database for which the end user was complaining about the exceptional time it was taking without completing. Since the job was still running I tried getting its Real Time SQL monitoring report:


Global Information
------------------------------
 Status              :  DONE (ERROR)        
 Instance ID         :  1                   
 Session             :  XXXXX (392:229)    
 SQL ID              :  bbccngk0nn2z2       
 SQL Execution ID    :  16777216            
 Execution Started   :  06/22/2015 11:57:06 
 First Refresh Time  :  06/22/2015 11:57:06 
 Last Refresh Time   :  06/22/2015 11:57:46 
 Duration            :  40s                 

Global Stats
=================================================================================================
| Elapsed |   Cpu   |    IO    | Concurrency |  Other   | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) |  Gets  | Reqs | Bytes | Reqs  | Bytes |
=================================================================================================
|   15315 |   15220 |       54 |        0.38 |       40 |     2G | 8601 |   2GB |  5485 |   1GB |

The insert/select according to the above report summary is DONE with (ERROR).
So why the end user is still complaining about the not ending batch job? And why he didn’t receive an error?

After having ruled out the resumable time out hypothesis I came back to the v$sql_monitor and issued the following two selects:

SQL> SELECT
  2    sql_id,
  3    process_name,
  4    status
  5  FROM v$sql_monitor
  6  WHERE sql_id = 'bbccngk0nn2z2'
  7  AND status   ='EXECUTING'
  8  ORDER BY process_name ;

SQL_ID        PROCE STATUS
------------- ----- ------------
bbccngk0nn2z2 p000  EXECUTING
bbccngk0nn2z2 p001  EXECUTING
bbccngk0nn2z2 p002  EXECUTING
bbccngk0nn2z2 p003  EXECUTING
bbccngk0nn2z2 p004  EXECUTING
bbccngk0nn2z2 p005  EXECUTING
bbccngk0nn2z2 p006  EXECUTING
bbccngk0nn2z2 p007  EXECUTING
bbccngk0nn2z2 p008  EXECUTING
bbccngk0nn2z2 p009  EXECUTING
bbccngk0nn2z2 p010  EXECUTING
bbccngk0nn2z2 p011  EXECUTING
bbccngk0nn2z2 p012  EXECUTING
bbccngk0nn2z2 p013  EXECUTING
bbccngk0nn2z2 p014  EXECUTING
bbccngk0nn2z2 p015  EXECUTING
bbccngk0nn2z2 p019  EXECUTING
bbccngk0nn2z2 p031  EXECUTING

SQL> SELECT
  2    sql_id,
  3    process_name,
  4    status
  5  FROM v$sql_monitor
  6  WHERE sql_id = 'bbccngk0nn2z2'
  7  AND status   ='DONE (ERROR)'
  8  ORDER BY process_name ;

SQL_ID        PROCE STATUS
------------- ----- -------------------
bbccngk0nn2z2 ora   DONE (ERROR)
bbccngk0nn2z2 p016  DONE (ERROR)
bbccngk0nn2z2 p017  DONE (ERROR)
bbccngk0nn2z2 p018  DONE (ERROR)
bbccngk0nn2z2 p020  DONE (ERROR)
bbccngk0nn2z2 p021  DONE (ERROR)
bccngk0nn2z2  p022  DONE (ERROR)
bbccngk0nn2z2 p023  DONE (ERROR)
bbccngk0nn2z2 p024  DONE (ERROR)
bbccngk0nn2z2 p025  DONE (ERROR)
bbccngk0nn2z2 p026  DONE (ERROR)
bbccngk0nn2z2 p027  DONE (ERROR)
bbccngk0nn2z2 p028  DONE (ERROR)
bbccngk0nn2z2 p029  DONE (ERROR)
bbccngk0nn2z2 p030  DONE (ERROR)

Among the 32 parallel servers half are executing and half are in error! How could this be possible? I have already been confronted to a parallel process that ends in its entirety when a single parallel server is in error. For example I have encountered several times the following error which is due to a parallel broadcast distribution of a high data row source exploding henceforth the TEMP tablespace:

ERROR at line 1:
ORA-12801: error signaled in parallel query server P013
ORA-01652: unable to extend temp segment by 128 in tablespace TEMP

A simple select against v$active_session_history confirmed that the insert/select is still running and it is consuming CPU

SQL> select sql_id, count(1)
  2  from gv$active_session_history
  3  where sample_time between to_date('22062015 12:30:00', 'ddmmyyyy hh24:mi:ss')
  4                    and     to_date('22062015 13:00:00', 'ddmmyyyy hh24:mi:ss')
  5  group by  sql_id
  6  order by 2 desc;

SQL_ID          COUNT(1)
------------- ----------
bbccngk0nn2z2       2545
                       4
0uuczutvk6jqj          1
8f1sjvfxuup9w          1

SQL> select decode(event,null, 'on cpu', event), count(1)
  2  from gv$active_session_history
  3  where sample_time between to_date('22062015 12:30:00', 'ddmmyyyy hh24:mi:ss')
  4                    and     to_date('22062015 13:00:00', 'ddmmyyyy hh24:mi:ss')
  5  and sql_id = 'bbccngk0nn2z2'
  6  group by  event
  7  order by 2 desc;

DECODE(EVENT,NULL,'ONCPU',EVENT)  COUNT(1)
--------------------------------  ---------
on cpu                            5439
db file sequential read           3

SQL> /

DECODE(EVENT,NULL,'ONCPU',EVENT)  COUNT(1)
--------------------------------- ---------
on cpu                            5460
db file sequential read           3

SQL> /

DECODE(EVENT,NULL,'ONCPU',EVENT)  COUNT(1)
--------------------------------  ---------
on cpu                            5470
db file sequential read           3

And after a while


SQL> /

DECODE(EVENT,NULL,'ONCPU',EVENT)   COUNT(1)
---------------------------------- ---------
on cpu                             15152
db file sequential read            9

While the parallel insert is still running I took several SQL monitoring reports of which the two followings ones:

Parallel Execution Details (DOP=16 , Servers Allocated=32)
============================================================================================
|      Name      | Type  | Server# | Elapsed |Buffer | Read  |         Wait Events         |
|                |       |         | Time(s) | Gets  | Bytes |         (sample #)          |
============================================================================================
| PX Coordinator | QC    |         |    0.48 |  2531 | 16384 |                             |
| p000           | Set 1 |       1 |    1049 |  128M |  63MB | direct path read (1)        |
| p001           | Set 1 |       2 |    1518 |  222M |  61MB |                             |
| p002           | Set 1 |       3 |     893 |  109M |  59MB |                             |
| p003           | Set 1 |       4 |    1411 |  194M |  62MB | direct path read (1)        |
| p004           | Set 1 |       5 |     460 |   64M |  62MB | direct path read (1)        |
| p005           | Set 1 |       6 |     771 |   87M | 322MB | direct path read (1)        |
|                |       |         |         |       |       | direct path read temp (5)   |
| p006           | Set 1 |       7 |     654 |   67M |  62MB | direct path read (1)        |
| p007           | Set 1 |       8 |     179 |   24M |  55MB | direct path read (1)        |
| p008           | Set 1 |       9 |    1638 |  235M |  70MB |                             |
| p009           | Set 1 |      10 |     360 |   46M |  54MB | direct path read (1)        |
| p010           | Set 1 |      11 |    1920 |  294M | 337MB | direct path read temp (6)   | --> 1920s
| p011           | Set 1 |      12 |     289 |   30M |  69MB |                             |
| p012           | Set 1 |      13 |     839 |   98M |  66MB | direct path read (1)        |
| p013           | Set 1 |      14 |     524 |   63M |  55MB |                             |
| p014           | Set 1 |      15 |    1776 |  263M |  69MB |                             |
| p015           | Set 1 |      16 |    1016 |  130M |  61MB | direct path read (1)        |
| p016           | Set 2 |       1 |    0.22 |  1166 |   3MB |                             |
| p017           | Set 2 |       2 |    1.36 |  6867 |  51MB |                             |
| p018           | Set 2 |       3 |    1.02 |  1298 |  36MB |                             |
| p019           | Set 2 |       4 |    6.71 |  2313 | 129MB | direct path read temp (2)   |
| p020           | Set 2 |       5 |    0.40 |   978 |  16MB |                             |
| p021           | Set 2 |       6 |    1.32 |  8639 |  41MB | direct path read temp (1)   |
| p022           | Set 2 |       7 |    0.18 |   896 |   2MB |                             |
| p023           | Set 2 |       8 |    0.23 |   469 |   9MB |                             | --> 0.23s
| p024           | Set 2 |       9 |    0.52 |  3635 |  19MB |                             | --> 0.52s
| p025           | Set 2 |      10 |    0.33 |  1163 |   3MB |                             |
| p026           | Set 2 |      11 |    0.65 |   260 |  31MB | db file sequential read (1) |
| p027           | Set 2 |      12 |    0.21 |  1099 |   6MB |                             |
| p028           | Set 2 |      13 |    0.58 |   497 |  20MB |                             |
| p029           | Set 2 |      14 |    1.43 |  4278 |  54MB |                             |
| p030           | Set 2 |      15 |    0.30 |  3481 |   8MB |                             |
| p031           | Set 2 |      16 |    2.86 |   517 |  91MB |                             |
============================================================================================


Parallel Execution Details (DOP=16 , Servers Allocated=32)
=============================================================================================
|      Name      | Type  | Server# | Elapsed | Buffer | Read  |         Wait Events         |
|                |       |         | Time(s) |  Gets  | Bytes |         (sample #)          |
=============================================================================================
| PX Coordinator | QC    |         |    0.48 |   2531 | 16384 |                             |
| p000           | Set 1 |       1 |    1730 |   202M |  63MB | direct path read (1)        |
| p001           | Set 1 |       2 |    2416 |   351M |  61MB |                             |
| p002           | Set 1 |       3 |    1094 |   133M |  59MB |                             |
| p003           | Set 1 |       4 |    2528 |   348M |  64MB | direct path read (1)        |
| p004           | Set 1 |       5 |     965 |   129M |  63MB | direct path read (1)        |
| p005           | Set 1 |       6 |    1089 |   129M | 322MB | direct path read (1)        |
|                |       |         |         |        |       | direct path read temp (5)   |
| p006           | Set 1 |       7 |    1459 |   165M |  62MB | direct path read (1)        |
| p007           | Set 1 |       8 |     221 |    30M |  55MB | direct path read (1)        |
| p008           | Set 1 |       9 |    2640 |   357M |  70MB |                             |
| p009           | Set 1 |      10 |     952 |   115M |  54MB | direct path read (1)        |
| p010           | Set 1 |      11 |    3117 |   471M | 337MB | direct path read temp (6)   | --> 3117s
| p011           | Set 1 |      12 |     400 |    42M |  69MB |                             |
| p012           | Set 1 |      13 |    1621 |   195M |  66MB | direct path read (1)        |
| p013           | Set 1 |      14 |    1126 |   132M |  55MB |                             |
| p014           | Set 1 |      15 |    2662 |   370M |  72MB |                             |
| p015           | Set 1 |      16 |    1194 |   147M |  61MB | direct path read (1)        |
| p016           | Set 2 |       1 |    0.22 |   1166 |   3MB |                             |
| p017           | Set 2 |       2 |    1.36 |   6867 |  51MB |                             |
| p018           | Set 2 |       3 |    1.02 |   1298 |  36MB |                             |
| p019           | Set 2 |       4 |    6.72 |   2313 | 131MB | direct path read temp (2)   |
| p020           | Set 2 |       5 |    0.40 |    978 |  16MB |                             |
| p021           | Set 2 |       6 |    1.32 |   8639 |  41MB | direct path read temp (1)   |
| p022           | Set 2 |       7 |    0.18 |    896 |   2MB |                             |
| p023           | Set 2 |       8 |    0.23 |    469 |   9MB |                             | --> 0.23s
| p024           | Set 2 |       9 |    0.52 |   3635 |  19MB |                             | --> 0.52s
| p025           | Set 2 |      10 |    0.33 |   1163 |   3MB |                             |
| p026           | Set 2 |      11 |    0.65 |    260 |  31MB | db file sequential read (1) |
| p027           | Set 2 |      12 |    0.21 |   1099 |   6MB |                             |
| p028           | Set 2 |      13 |    0.58 |    497 |  20MB |                             |
| p029           | Set 2 |      14 |    1.43 |   4278 |  54MB |                             |
| p030           | Set 2 |      15 |    0.30 |   3481 |   8MB |                             |
| p031           | Set 2 |      16 |    2.89 |    517 |  92MB |                             |
=============================================================================================

If you look carefully to the above reports you will notice that the elapsed time of the parallel servers mentioned being in ERROR (p16-p30) is not increasing in contrast to the elapsed time of the parallel servers mentioned being in EXECUTION (p0-p15) which is continuously increasing.

Thanks to Randolf Geist (again) I knew that there is a bug in Real time SQL monitoring report which occurs when a parallel server is not working for more than 30 minutes. In such a case the Real time SQL monitoring will starts showing those parallel severs in in ERROR confusing the situation.

As far as I was able to reproduce the issue I started the process again at 16h03 and I kept executing the following select from time to time having no rows for each execution

SELECT 
  sql_id,
  process_name,
  status
FROM v$sql_monitor
WHERE sql_id = '5np4u0m0h69jx' –- changed a little bit the sql_id
AND status   ='DONE (ERROR)'
ORDER BY process_name ;

no rows selected

Until at around 16h37 i.e. after 30 minutes (and a little bit more) of execution the above select started showing processes in error:

SQL> SELECT
  2    sql_id,
  3    process_name,
  4    status
  5  FROM v$sql_monitor
  6  WHERE sql_id = '5np4u0m0h69jx'
  7  AND status   ='DONE (ERROR)'
  8  ORDER BY process_name ;

SQL_ID        PROCE STATUS
------------- ----- ---------------
5np4u0m0h69jx ora   DONE (ERROR)
5np4u0m0h69jx p016  DONE (ERROR)
5np4u0m0h69jx p017  DONE (ERROR)
5np4u0m0h69jx p018  DONE (ERROR)
5np4u0m0h69jx p020  DONE (ERROR)
5np4u0m0h69jx p021  DONE (ERROR)
5np4u0m0h69jx p022  DONE (ERROR)
5np4u0m0h69jx p023  DONE (ERROR)
5np4u0m0h69jx p024  DONE (ERROR)
5np4u0m0h69jx p025  DONE (ERROR)
5np4u0m0h69jx p026  DONE (ERROR)
5np4u0m0h69jx p027  DONE (ERROR)
5np4u0m0h69jx p028  DONE (ERROR)
5np4u0m0h69jx p029  DONE (ERROR)
5np4u0m0h69jx p030  DONE (ERROR)

At the very beginning of the process several parallel servers was not running while several others were busy. And when the first parallel server (p10 in this case) reaches more than 1800 seconds (1861 seconds in this case) the real time Sql monitoring started showing the not working parallel servers in ERROR.

Bottom line: don’t be confused (as I have been) by that DONE (ERROR) status, your SQL statement might still be running consuming time and energy despite this wrong real time SQL monitoring reporting status

June 12, 2015

Why Dynamic Sampling has not been used?

Filed under: Oracle — hourim @ 10:15 am

Experienced tuning guys are known for their pronounced sense of looking at details others are very often ignoring. This is why I am always paying attention to their answers in otn and oracle-l list. Last week I have been asked to look at a query performing badly which has been monitored via the following execution plan:

Global Information
------------------------------
 Status              :  EXECUTING
 Instance ID         :  1
 SQL ID              :  8114dqz1k5arj
 SQL Execution ID    :  16777217            

Global Stats
=============================================================================================
| Elapsed |   Cpu   |    IO    | Concurrency | Cluster  |  Other   | Buffer | Read  | Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) | Waits(s) |  Gets  | Reqs  | Bytes |
=============================================================================================
|  141842 |  140516 |       75 |        5.82 |       69 |     1176 |    21G | 26123 | 204MB |
=============================================================================================

SQL Plan Monitoring Details (Plan Hash Value=3787402507)
===========================================================================================
| Id   |             Operation             |      Name       |  Rows   | Execs |   Rows   |
|      |                                   |                 | (Estim) |       | (Actual) |
===========================================================================================
|    0 | SELECT STATEMENT                  |                 |         |     1 |          |
|    1 |   SORT ORDER BY                   |                 |       1 |     1 |          |
|    2 |    FILTER                         |                 |         |     1 |          |
|    3 |     NESTED LOOPS                  |                 |         |     1 |        0 |
| -> 4 |      NESTED LOOPS                 |                 |       1 |     1 |       4G |
| -> 5 |       TABLE ACCESS BY INDEX ROWID | TABLEXXX        |       1 |     1 |     214K |
| -> 6 |        INDEX RANGE SCAN           | IDX_MESS_RCV_ID |      2M |     1 |     233K |
| -> 7 |       INDEX RANGE SCAN            | VGY_TEST2       |       1 |  214K |       4G |->
|    8 |      TABLE ACCESS BY INDEX ROWID  | T_TABL_YXZ      |       1 |    4G |        0 |->
|      |                                   |                 |         |       |          |
===========================================================================================

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter(TO_DATE(:SYS_B_2,:SYS_B_3)<=TO_DATE(:SYS_B_4,:SYS_B_5))
   5 - filter(("TABLEXXX"."T_NAME"=:SYS_B_6 AND
              "TABLEXXX"."M_TYPE"=:SYS_B_0 AND
              "TABLEXXX"."A_METHOD"=:SYS_B_7 AND
              "TABLEXXX"."M_STATUS"<>:SYS_B_8))
   6 - access("TABLEXXX"."R_ID"=:SYS_B_1)
   7 - access("T_TABL_YXZ"."SX_DATE">=TO_DATE(:SYS_B_2,:SYS_B_3) AND
              "T_TABL_YXZ"."SX_DATE"<=TO_DATE(:SYS_B_4,:SYS_B_5))
   8 - filter("T_TABL_YXZ"."T_ID"="TABLEXXX"."T_ID")

Those 214K and 4G executions (Execs) of operations 7 and 8 respectively are the classical wrong NESTED LOOP join the CBO has decided to go with because of the wrong cardinality estimation at operation n° 5 (the double NESTED LOOP operation is the effect of the NLJ_BATCHING optimisation).
There was no previous historical plan_hash_value for this particular sql_id in order to compare with the current execution plan. But the report has certainly been executed in the past without any complaint from the end user.
The outline_data section of the execution plan is where I usually look when trying to understand what the optimizer has done behind the scene:

Outline Data
-------------
   /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
      DB_VERSION('11.2.0.3')
      OPT_PARAM('_b_tree_bitmap_plans' 'false')
      OPT_PARAM('optimizer_dynamic_sampling' 4) ---------------------------> spot this
      OPT_PARAM('optimizer_index_cost_adj' 20)
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "TABLEXXX"@"SEL$1" ("TABLEXXX"."R_ID"))
      INDEX(@"SEL$1" "T_TABL_YXZ"@"SEL$1" ("T_TABL_YXZ"."SX_DATE"
              "T_TABL_YXZ"."GL_ACCOUNT_ID" "T_TABL_YXZ"."CASH_ACCOUNT_ID"))
      LEADING(@"SEL$1" "TABLEXXX"@"SEL$1" "T_TABL_YXZ"@"SEL$1")
      USE_NL(@"SEL$1" "T_TABL_YXZ"@"SEL$1")
      NLJ_BATCHING(@"SEL$1" "T_TABL_YXZ"@"SEL$1")
      END_OUTLINE_DATA
  */

As you can see apart from the optimizer_index_cost_adj parameter value we should never change, there is one thing that has kept my attention: optimizer_dynamic_sampling. Since the outline is showing that the optimizer has used dynamic sampling why then there is no Note about dynamic sampling at the bottom of the above corresponding execution plan?
I decided to run the same query in a CLONE data base (cloned via RMAN). Below is the corresponding execution plan for the same set of input parameters:

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 SQL ID              :  8114dqz1k5arj
 SQL Execution ID    :  16777217
 Duration            :  904s           

SQL Plan Monitoring Details (Plan Hash Value=2202725716)
========================================================================================
| Id |            Operation             |      Name       |  Rows   | Execs |   Rows   |
|    |                                  |                 | (Estim) |       | (Actual) |
========================================================================================
|  0 | SELECT STATEMENT                 |                 |         |     1 |      280 |
|  1 |   SORT ORDER BY                  |                 |    230K |     1 |      280 |
|  2 |    FILTER                        |                 |         |     1 |      280 |
|  3 |     HASH JOIN                    |                 |    230K |     1 |      280 |
|  4 |      TABLE ACCESS BY INDEX ROWID | T_TABL_YXZ      |    229K |     1 |     301K |
|  5 |       INDEX RANGE SCAN           | VGY_TEST2       |       1 |     1 |     301K |
|  6 |      TABLE ACCESS BY INDEX ROWID | TABLEXXX        |    263K |     1 |       2M |
|  7 |       INDEX RANGE SCAN           | IDX_MESS_RCV_ID |      2M |     1 |       2M |
========================================================================================

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter(TO_DATE(:SYS_B_2,:SYS_B_3)<=TO_DATE(:SYS_B_4,:SYS_B_5))
   3 - access("T_TABL_YXZ"."T_ID"="TABLEXXX"."T_ID")
   5 - access("T_TABL_YXZ"."SX_DATE">=TO_DATE(:SYS_B_2,:SYS_B_3) AND
              "T_TABL_YXZ"."SX_DATE"<=TO_DATE(:SYS_B_4,:SYS_B_5))
   6 - filter(("TABLEXXX"."T_NAME"=:SYS_B_6 AND
              "TABLEXXX"."M_TYPE"=:SYS_B_0 AND
              "TABLEXXX"."A_METHOD"=:SYS_B_7 AND
              "TABLEXXX"."M_STATUS"<>:SYS_B_8))
   7 - access("TABLEXXX"."R_ID"=:SYS_B_1)

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

In this CLONED database, in contrast to the Production database, the optimizer has used dynamic sampling at its level 4 and has come up with a different estimation when visiting TABLEXXX (263K instead of 1) and T_TABL_YXZ (229K instead of 1) tables so that it has judiciously opted for a HASH JOIN instead of that dramatic production NESTED LOOP operation making the query completing in 904 seconds.

The fundamental question turns then from why the report is performing badly to why the optimizer has ignored using dynamic sampling at level 4?

There are several ways to answer this question (a) 10053 trace file, (b) 10046 or (c) trace file or tracing directly dynamic sampling as it has been suggested to me by Stefan Koehler

SQL> alter session set events 'trace[RDBMS.SQL_DS] disk=high';

The corresponding 10053 optimizer trace shows the following lines related to dynamic sampling:

10053 of the COPY database

*** 2015-06-03 11:05:43.701
** Executed dynamic sampling query:
    level : 4
    sample pct. : 0.000489
    actual sample size : 837
    filtered sample card. : 1
    orig. card. : 220161278
    block cnt. table stat. : 6272290
    block cnt. for sampling: 6345946
    max. sample block cnt. : 32
sample block cnt. : 31
min. sel. est. : 0.00000000
** Using single table dynamic sel. est. : 0.00119474
  Table: TABLEXXX  Alias: TABLEXXX
    Card: Original: 220161278.000000  Rounded: 263036  Computed: 263036.17  Non Adjusted: 263036.17

In the COPY data base, the optimiser has used dynamic sampling at level 4 and did come up with a cardinality estimation of TABLEXXX of be 263K which obviously has conducted the CBO to opt for a reasonable HASH JOIN operation.

10053 of the PRODUCTION database

*** 2015-06-03 13:39:03.992
** Executed dynamic sampling query:
    level : 4
    sample pct. : 0.000482
    actual sample size : 1151
    filtered sample card. : 0  ------------------>  spot this information
    orig. card. : 220161278
    block cnt. table stat. : 6272290
    block cnt. for sampling: 6435970
    max. sample block cnt. : 32
sample block cnt. : 31
min. sel. est. : 0.00000000
** Not using dynamic sampling for single table sel. or cardinality.
DS Failed for : ----- Current SQL Statement for this session (sql_id=82x3mm8jqn5ah) -----
  Table: TABLEXXX  Alias: TABLEXXX
    Card: Original: 220161278.000000  Rounded: 1  Computed: 0.72  Non Adjusted: 0.72

In the PRODUCTION database, the CBO failed to use dynamic sampling at level 4 as clearly shown by the following line taken from the above 10053 trace file:

** Not using dynamic sampling for single table sel. or cardinality.
DS Failed for : ----- Current SQL Statement for this session (sql_id=82x3mm8jqn5ah)

PS: 10053 trace file has been applied on the important part of the query this is
    why the sql_id is not the same as the one mentioned above.

Thanks to Randolf Geist I learnt that the internal code of the Dynamic Sampling algorithm is so that when the predicate part has been applied on a sample of the TABLEXXX it returned 0 rows

filtered sample card. : 0

which is the reason why the optimizer has ignored Dynamic sampling at level 4 and falls back to the available object statistics producing a 1 row cardinality estimation and henceforth a dramatic wrong NESTED LOOP operation. By the way, should I have been in 12c database release the STATISTICS COLLECTOR placed above the first operation in the NESTED LOOP join would have reached the inflexion point and would have, hopefully, switched to a HASH JOIN operation during execution time.

A quick solution to this very critical report was to up the level of the dynamic sampling to a higher value. And, as far as this query belongs to a third party software I decided to use Kerry Osborne script in order to inject a dynamic sampling hint as shown below:

SQL>@create_1_hint_sql_profile.sql
Enter value for sql_id: 8114dqz1k5arj
Enter value for profile_name (PROFILE_sqlid_MANUAL):
Enter value for category (DEFAULT):
Enter value for force_matching (false): true
Enter value for hint: dynamic_sampling(6)
Profile PROFILE_8114dqz1k5arj_MANUAL created.

Once this done, the end user re-launched the report which completed within 303 seconds instead of those not ending 141,842 seconds


Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 SQL ID              :  8114dqz1k5arj
 SQL Execution ID    :  16777216
 Execution Started   :  06/10/2015 11:40:39
 First Refresh Time  :  06/10/2015 11:40:45
 Last Refresh Time   :  06/10/2015 11:45:39
 Duration            :  300s           

SQL Plan Monitoring Details (Plan Hash Value=2202725716)
========================================================================================
| Id |            Operation             |      Name       |  Rows   | Execs |   Rows   |
|    |                                  |                 | (Estim) |       | (Actual) |
========================================================================================
|  0 | SELECT STATEMENT                 |                 |         |     1 |     2989 |
|  1 |   SORT ORDER BY                  |                 |    234K |     1 |     2989 |
|  2 |    FILTER                        |                 |         |     1 |     2989 |
|  3 |     HASH JOIN                    |                 |    234K |     1 |     2989 |
|  4 |      TABLE ACCESS BY INDEX ROWID | T_TABL_YXZ      |    232K |     1 |     501K |
|  5 |       INDEX RANGE SCAN           | VGY_TEST2       |       1 |     1 |     501K |
|  6 |      TABLE ACCESS BY INDEX ROWID | TABLEXXX        |    725K |     1 |       2M |
|  7 |       INDEX RANGE SCAN           | IDX_MESS_RCV_ID |      2M |     1 |       2M |
========================================================================================

Note
-----
   - dynamic sampling used for this statement (level=6)
   - SQL profile PROFILE_8114dqz1k5arj_MANUAL used for this statement

June 6, 2015

SUBQ INTO VIEW FOR COMPLEX UNNEST

Filed under: Oracle — hourim @ 8:42 am

If you are a regular reader of Jonathan Lewis blog you will have probably came across this article in which the author explains why an “OR subquery” pre-empts the optimizer from unnesting the subquery and merging it with its parent query for a possible optimal join path. This unnesting impossibility is so that the “OR subquery” is executed as a FILTER predicate which when applied on a huge data row set penalizes dramatically the performance of the whole query. In the same article, you will have hopefully also learned how by re-writing the query using a UNION ALL (and taking care of the always threatening NULL via the LNNVL() function) you can open a new path for the CBO allowing an unnest of the subquery.

Unfortunately, nowadays there is a massive expansion of third party software where changing SQL code is not possible so that I hoped that the optimizer was capable to automatically re-factor a disjunctive subquery and consider unnesting it using the UNION ALL workaround.

I was under that impression that this hope is never exhausted by the optimizer until last week when I have received from my friend Ahmed Aangour an e-mail showing a particular disjunctive subquery which has been unnested by the optimizer without any rewrite of the original query by the developer. I have found the case very interesting so that I decided to model it and to share it with you. Take a look to the query and the execution plan first in 11.2.0.2 (the table script is supplied at the end of the article)

SQL> alter session set statistics_level=all;

SQL> alter session set optimizer_features_enable='11.2.0.2';

SQL> select
 a.id1
 ,a.n1
 ,a.start_date
from t1 a
where (a.id1 in
 (select
 b.id
 from t2 b
 where
 b.status = 'COM'
 )
 OR
 a.id1 in
 (select
 c.id1
 from t2 c
 where
 c.status = 'ERR'
 )
 );

SQL> select * from table(dbms_xplan.display_cursor(null,null, ‘allstats last’));

-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |   9890 |00:00:02.23 |     742K|<--
|*  1 |  FILTER            |      |      1 |        |   9890 |00:00:02.23 |     742K|
|   2 |   TABLE ACCESS FULL| T1   |      1 |  10000 |  10000 |00:00:00.01 |    1686 |
|*  3 |   TABLE ACCESS FULL| T2   |  10000 |      1 |   9890 |00:00:02.16 |     725K|
|*  4 |   TABLE ACCESS FULL| T2   |    110 |      1 |      0 |00:00:00.05 |   15400 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
 1 - filter(( IS NOT NULL OR IS NOT NULL))
 3 - filter(("B"."ID"=:B1 AND "B"."STATUS"='COM'))
 4 - filter(("C"."ID1"=:B1 AND "C"."STATUS"='ERR'))

The double full access to table t2 plus the FILTER operation indicate clearly that the OR clause has not been combined with the parent query. If you want to know what is behind the filter predicate n°1 above then the “not so famous” explain plan for command will help in this case:

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |   975 | 15600 |   462   (0)| 00:00:01 |
|*  1 |  FILTER            |      |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T1   | 10000 |   156K|   462   (0)| 00:00:01 |
|*  3 |   TABLE ACCESS FULL| T2   |     1 |     8 |    42   (0)| 00:00:01 |
|*  4 |   TABLE ACCESS FULL| T2   |     1 |     7 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( EXISTS (SELECT 0 FROM "T2" "B" WHERE "B"."ID"=:B1 AND
              "B"."STATUS"='COM') OR  EXISTS (SELECT 0 FROM "T2" "C" WHERE
              "C"."ID1"=:B2 AND "C"."STATUS"='ERR'))
   3 - filter("B"."ID"=:B1 AND "B"."STATUS"='COM')
   4 - filter("C"."ID1"=:B1 AND "C"."STATUS"='ERR')

Notice how the subquery has been executed as a FILTER operation which sometimes (if not often) represents a real performance threat. 

However, when I‘ve executed the same query under optimizer 11.2.0.3 I got the following interesting execution plan

SQL> alter session set optimizer_features_enable='11.2.0.3';

--------------------------------------------------------------------------------------------
| Id  | Operation             | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |          |      1 |        |   9890 |00:00:00.03 |    1953 |<--
|*  1 |  HASH JOIN            |          |      1 |   5000 |   9890 |00:00:00.03 |    1953 |
|   2 |   VIEW                | VW_NSO_1 |      1 |   5000 |   9890 |00:00:00.01 |     282 |
|   3 |    HASH UNIQUE        |          |      1 |   5000 |   9890 |00:00:00.01 |     282 |
|   4 |     UNION-ALL         |          |      1 |        |   9900 |00:00:00.01 |     282 |
|*  5 |      TABLE ACCESS FULL| T2       |      1 |   2500 |     10 |00:00:00.01 |     141 |
|*  6 |      TABLE ACCESS FULL| T2       |      1 |   2500 |   9890 |00:00:00.01 |     141 |
|   7 |   TABLE ACCESS FULL   | T1       |      1 |  10000 |  10000 |00:00:00.01 |    1671 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("A"."ID1"="ID1")
   5 - filter("C"."STATUS"='ERR')
   6 - filter("B"."STATUS"='COM')

Notice now how the new plan is showing a HASH JOIN operation between an internal view( VW_NSO_1) and table t1 coming from the parent query block. Notice as well the HASH JOIN condition (access(“A”.”ID1″=”ID1″)) that appears in filter n°1. The optimizer has done a double transformation:

  • created an internal view VW_NSO_1  representing a UNION-ALL between the two subqueries present in the where clause
  • joined the newly online created view with table t1 present in the parent query block

Looking at the corresponding 10053 trace file I have found how the CBO has transformed the initial query:

select a.id1 id1,
  a.n1 n1,
  a.start_date start_date
from (
  (select c.id1 id1 from c##mhouri.t2 c where c.status='ERR')
union
  (select b.id id from c##mhouri.t2 b where b.status='COM')
     ) vw_nso_1,
  c##mhouri.t1 a
where a.id1= vw_nso_1.id1;

In fact the optimizer has first combined the two subqueries into a VIEW and finished by UNNESTING them with the parent query. This is a transformation which Oracle optimizer seems to name : SUBQ INTO VIEW FOR COMPLEX UNNEST

In the same 10053 trace file we can spot the following lines:

*****************************
Cost-Based Subquery Unnesting
*****************************
Query after disj subq unnesting:******* UNPARSED QUERY IS *******

SU:   Transform an ANY subquery to semi-join or distinct.
Registered qb: SET$7FD77EFD 0x15b5d4d0 (SUBQ INTO VIEW FOR COMPLEX UNNEST SET$E74BECDC)

SU: Will unnest subquery SEL$3 (#2)
SU: Will unnest subquery SEL$2 (#3)
SU: Reconstructing original query from best state.
SU: Considering subquery unnest on query block SEL$1 (#1).
SU:   Checking validity of unnesting subquery SEL$2 (#3)
SU:   Checking validity of unnesting subquery SEL$3 (#2)
Query after disj subq unnesting:******* UNPARSED QUERY IS *******

SU:   Checking validity of unnesting subquery SET$E74BECDC (#6)
SU:   Passed validity checks.

This is a clear enhancement made in the optimizer query transformation that will help improving performance of disjunctive subqueries automatically without any external intervention.

Unfortunately, I was going to end this article until I’ve realized that although I am testing this case under 12.1.0.1.0 database release I still have not executed the same query under optimizer feature 12.1.0.1.0

SQL> alter session set optimizer_features_enable='12.1.0.1.1';
SQL > execute query
-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |   9890 |00:00:03.84 |     716K|
|*  1 |  FILTER            |      |      1 |        |   9890 |00:00:03.84 |     716K|
|   2 |   TABLE ACCESS FULL| T1   |      1 |  10000 |  10000 |00:00:00.01 |    1686 |
|*  3 |   TABLE ACCESS FULL| T2   |  10000 |      2 |   9890 |00:00:03.81 |     715K|
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( IS NOT NULL)
   3 - filter((("B"."ID1"=:B1 AND "B"."STATUS"='ERR') OR ("B"."ID"=:B2 AND
              "B"."STATUS"='COM')))

The automatic unnesting of the disjunctive subquery has been removed in the 12.1.0.1.1 optimizer model.

If you want to reproduce and test this case here below is the model (I would be interested to see if the disjunctive subquery is unnested or not in the 12.1.0.1.2 release )

create table t1
   as select
    rownum                id1,
    trunc((rownum-1/3))   n1,
    date '2012-06-07' + mod((level-1)*2,5) start_date,
    lpad(rownum,10,'0')   small_vc,
    rpad('x',1000)        padding
from dual
connect by level <= 1e4;   

create table t2
as select
    rownum id
    ,mod(rownum,5) + mod(rownum,10)* 10  as id1
    ,case
       when mod(rownum, 1000) = 7 then 'ERR'
       when rownum <= 9900 then 'COM'
       when mod(rownum,10) between 1 and 5 then 'PRP'
     else
       'UNK'
     end status
     ,lpad(rownum,10,'0')    as small_vc
     ,rpad('x',70)           as padding
from dual
connect by level <= 1e4;

alter table t1 add constraint t1_pk primary key (id1);

Create a free website or blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud Oracle's blog

Just another Oracle blog : Database topics and techniques

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

EU Careers info

Your career in the European Union

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)