Mohamed Houri’s Oracle Notes

May 24, 2020

Why my hint has not been used?

Filed under: Hint,Oracle — hourim @ 12:20 pm

While waiting for Tanel Poder hacking session about sql hint invalidity which I encourage everyone to subscribe and to follow, here’re few particular cases where hints are not obeyed by the Oracle Cost Based Optimizer. It happens when the hint asks the CBO to do something which is either impossible or not yet implemented in its algorithm. When two hints are contradictory one of them will be ignored by the CBO to the detriment of the other one. We will see that the victim hint seems not to be cost based dependent but rather rule based. Let’s see this via a reproducible example

JPPD and HASH JOIN

To allow data filtering as early as possible, Oracle can use a JPPD transformation in order to apply a predicate from the outer query block (or main query block) into the contained non-mergeable query block. As such, a precise index range scan can be used and data are filtered much earlier.

Here’s a simple model with which I will illustrate this transformation:

SQL> select banner from v$version;

BANNER
----------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 – Production

create table t1 as 
  select
      rownum n1
	 ,mod(rownum,5) n2
	 ,trunc( (rownum - 1 / 3) ) n3
  from
     dual
connect by level <= 1e2;

create table t2 as
  select
     rownum n1
    ,mod(rownum,3) n2
	,trunc( (rownum - 1 / 5) ) n3
from
    dual
 connect by level <= 1e3;

create table t3 as 
   select 
     rownum n1
	,lpad('x',4000,'x') vc
from dual
connect by level <= 100;

alter table t2 add constraint t2_pk primary key (n1);
alter table t3 add constraint t3_pk primary key (n1);

begin
  dbms_stats.gather_table_stats(user, 't1' );
  dbms_stats.gather_table_stats(user, 't2' );
  dbms_stats.gather_table_stats(user, 't3' );
end;
/

Let’s now execute the following query and get its corresponding execution plan

select 
   t1.n1, t1.n3
from 
   t1
  left join
   (select t2.n1 from t2, t3
    where t2.n1 = t3.n1
	) vw_1
on t1.n1 = vw_1.n1; 

Plan hash value: 3070139659
--------------------------------------------------------------
| Id  | Operation               | Name  | Rows  | Cost (%CPU)|
--------------------------------------------------------------
|   0 | SELECT STATEMENT        |       |       |     3 (100)|
|   1 |  NESTED LOOPS OUTER     |       |   100 |     3   (0)|
|   2 |   TABLE ACCESS FULL     | T1    |   100 |     3   (0)|
|   3 |   VIEW PUSHED PREDICATE |       |     1 |     0   (0)|  --> JPPD used
|   4 |    NESTED LOOPS         |       |     1 |     0   (0)|
|*  5 |     INDEX UNIQUE SCAN   | T3_PK |     1 |     0   (0)|
|*  6 |     INDEX UNIQUE SCAN   | T2_PK |     1 |     0   (0)|
--------------------------------------------------------------
Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('19.1.0')
      DB_VERSION('19.1.0')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$639F1A6F")
      PUSH_PRED(@"SEL$776AA54E" "VW_1"@"SEL$1" 1)
      OUTLINE_LEAF(@"SEL$776AA54E")
      MERGE(@"SEL$8812AA4E" &gt;"SEL$E8571221")
      OUTLINE(@"SEL$2")
      OUTLINE(@"SEL$E8571221")
      ANSI_REARCH(@"SEL$3")
      OUTLINE(@"SEL$8812AA4E")
      ANSI_REARCH(@"SEL$1")
      OUTLINE(@"SEL$3")
      OUTLINE(@"SEL$1")
      FULL(@"SEL$776AA54E" "T1"@"SEL$1")
      NO_ACCESS(@"SEL$776AA54E" "VW_1"@"SEL$1")
      LEADING(@"SEL$776AA54E" "T1"@"SEL$1" "VW_1"@"SEL$1")
      USE_NL(@"SEL$776AA54E" "VW_1"@"SEL$1")
      INDEX(@"SEL$639F1A6F" "T3"@"SEL$2" ("T3"."N1"))
      INDEX(@"SEL$639F1A6F" "T2"@"SEL$2" ("T2"."N1"))
      LEADING(@"SEL$639F1A6F" "T3"@"SEL$2" "T2"@"SEL$2")
      USE_NL(@"SEL$639F1A6F" "T2"@"SEL$2")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - access("T3"."N1"="T1"."N1")
   6 - access("T2"."N1"="T1"."N1")

Notice at operation Id n°5 that the predicate

on t1.n1 = vw_1.n1; 

Has been pushed inside the view vw_1 to become

("T3"."N1"="T1"."N1")

This is simply what a JPPD transformation is.

Let’s now take the NESTED LOOPS hint from the above execution plan outline

USE_NL(@"SEL$776AA54E" "VW_1"@"SEL$1")

change it into a HASH JOIN

USE_HASH(@"SEL$776AA54E" "VW_1"@"SEL$1")

and use it in the above query as shown below:

select /*+ 
         USE_HASH(@"SEL$776AA54E" "VW_1"@"SEL$1")
	  */
   t1.n1, t1.n3
from 
   t1
  left join
   (select t2.n1 from t2, t3
    where t2.n1 = t3.n1
	) vw_1
on t1.n1 = vw_1.n1; 

----------------------------------------------------------
| Id  | Operation            | Name  | Rows  |Cost (%CPU)|
----------------------------------------------------------
|   0 | SELECT STATEMENT     |       |       |    4 (100)|
|*  1 |  HASH JOIN OUTER     |       |   100 |    4   (0)| --> HASH JOIN used
|   2 |   TABLE ACCESS FULL  | T1    |   100 |    3   (0)|
|   3 |   VIEW               |       |   100 |    1   (0)|
|   4 |    NESTED LOOPS      |       |   100 |    1   (0)|
|   5 |     INDEX FULL SCAN  | T3_PK |   100 |    1   (0)|
|*  6 |     INDEX UNIQUE SCAN| T2_PK |     1 |    0   (0)|
----------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."N1"="VW_1"."N1")
   6 - access("T2"."N1"="T3"."N1")

Notice that, while the HASH JOIN hint has been obeyed, the JPPD transformation has, however, not been used.

Let’s then force the JPPD transformation via the PUSH_PRED hint and see what happens

select /*+ 
         USE_HASH(@"SEL$776AA54E" "VW_1"@"SEL$1")
	 PUSH_PRED(@"SEL$776AA54E" "VW_1"@"SEL$1" 1)
	*/
   t1.n1, t1.n3
from 
   t1
  left join
   (select t2.n1 from t2, t3
    where t2.n1 = t3.n1
	) vw_1
on t1.n1 = vw_1.n1; 

-------------------------------------------------------------
| Id  | Operation               | Name  | Rows  |Cost (%CPU)|
-------------------------------------------------------------
|   0 | SELECT STATEMENT        |       |       |    3 (100)|
|   1 |  NESTED LOOPS OUTER     |       |   100 |    3   (0)| --> NESTED LOOPS vs HASH JOIN
|   2 |   TABLE ACCESS FULL     | T1    |   100 |    3   (0)|
|   3 |   VIEW PUSHED PREDICATE |       |     1 |    0   (0)| --> JPPD used
|   4 |    NESTED LOOPS         |       |     1 |    0   (0)|
|*  5 |     INDEX UNIQUE SCAN   | T3_PK |     1 |    0   (0)|
|*  6 |     INDEX UNIQUE SCAN   | T2_PK |     1 |    0   (0)|
-------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - access("T3"."N1"="T1"."N1")
   6 - access("T2"."N1"="T1"."N1")

Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 1 (U - Unused (1))
---------------------------------------------------------------------------
   1 -  SEL$776AA54E / VW_1@SEL$1
         U -  USE_HASH(@"SEL$776AA54E" "VW_1"@"SEL$1")   

Bizarrely, the HASH JOIN hint has, this time, not been used. This non-utilization of the HASH JOIN hint is also confirmed by the 19c Hint Report:

Total hints for statement: 1 (U - Unused (1)

Why?

Oracle decided to ignore the HASH JOIN hint in profit of the PUSH_PRED hint simply because JPPD transformation is not possible with HASH JOIN. When Oracle decides to follow the JPPD directive it knows that this will be possible only under a NESTED LOOPS join operation. Consequently it has to ignore the HASH JOIN hint.

The 10053 trace file is not very verbose in this case. Here’s below what we can link to the non-obeyed HASH JOIN hint from this trace file:

*********************************
Number of join permutations tried: 1
*********************************
Enumerating distribution method (advanced)
--- Distribution method for 
join between T1[T1](serial) and VW_1[from$_subquery$_002](serial); jm = 1; right side access path = TableScan
---- serial Hash-Join ---> NONE     

In the Adaptive plan section of the same trace file we can read that the HASH JOIN is not legal

AP: adaptive joins bypassed for table VW_1 @ SEL$776AA54E due to Hash join is not legal

Probably through this illegality Oracle is indicating that it is impossible to obey the HASH JOIN in presence of a PUSH PREDICATE hint.

It looks like, whatever the cost of the JPPD is, it will be always prefered to the HASH JOIN as the JPPD has certainly the advantage of filtering data much earlier in the query execution path.

JPPD and ROWNUM

I think that I have already explained why one should always consider using the rownum pseudo-column with careful attention. Here’re two rownum usage side effects that I am aware of:

  • Where rownum =1 might automatically switch to the buggy FIRST_ROWS mode
  •  Using a rownum stops view merging and JPPD transformation

Let’s examine the second case via the above query

select /*+ 
	  PUSH_PRED(@"SEL$776AA54E" "VW_1"@"SEL$1" 1)
	*/
   t1.n1, t1.n3
from 
   t1
  left join
   (select t2.n1 from t2, t3
    where t2.n1 = t3.n1
	) vw_1
on t1.n1 = vw_1.n1; 

--------------------------------------------------------------
| Id  | Operation               | Name  | Rows  | Cost (%CPU)|
--------------------------------------------------------------
|   0 | SELECT STATEMENT        |       |       |    11 (100)|
|   1 |  NESTED LOOPS OUTER     |       | 10000 |    11  (19)|
|   2 |   TABLE ACCESS FULL     | T1    | 10000 |     9   (0)|
|   3 |   VIEW PUSHED PREDICATE |       |     1 |     0   (0)| --> JPPD used
|   4 |    NESTED LOOPS         |       |     1 |     0   (0)|
|*  5 |     INDEX UNIQUE SCAN   | T3_PK |     1 |     0   (0)|
|*  6 |     INDEX UNIQUE SCAN   | T2_PK |     1 |     0   (0)|
--------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   5 - access("T3"."N1"="T1"."N1")
   6 - access("T2"."N1"="T1"."N1")
select /*+ 
	  PUSH_PRED(@"SEL$776AA54E" "VW_1"@"SEL$1" 1)
	*/
   t1.n1, t1.n3
from 
   t1
  left join
   (select t2.n1 from t2, t3
    where t2.n1 = t3.n1
    and rownum >1    --------------> spot this here
	) vw_1
on t1.n1 = vw_1.n1; 

-------------------------------------------------------------
| Id  | Operation              | Name  | Rows  | Cost (%CPU)|
-------------------------------------------------------------
|   0 | SELECT STATEMENT       |       |       |    10 (100)|
|*  1 |  HASH JOIN RIGHT OUTER |       | 10000 |    10   (0)|
|   2 |   VIEW                 |       |   100 |     1   (0)|
|   3 |    COUNT               |       |       |            |
|*  4 |     FILTER             |       |       |            |
|   5 |      NESTED LOOPS      |       |   100 |     1   (0)|
|   6 |       INDEX FULL SCAN  | T3_PK |   100 |     1   (0)|
|*  7 |       INDEX UNIQUE SCAN| T2_PK |     1 |     0   (0)|
|   8 |   TABLE ACCESS FULL    | T1    | 10000 |     9   (0)|
-------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."N1"="VW_1"."N1")
   4 - filter(ROWNUM>1)
   7 - access("T2"."N1"="T3"."N1")

Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 1 (U - Unused (1))
---------------------------------------------------------------------------
   1 -  SEL$776AA54E / VW_1@SEL$1
         U -  PUSH_PRED(@"SEL$776AA54E" "VW_1"@"SEL$1" 1)

Notice how the use of the ROWNUM pseudo-column in the contained query block impeached the JPPD hint to be obeyed. Hopefully in this case the corresponding 10053 trace file shows clearly why the JPPD transformation (hint) has been ignored

---------------------
QUERY BLOCK SIGNATURE
---------------------
  signature (): qb_name=SEL$E8571221 nbfros=1 flg=0
    fro(0): flg=1 objn=0 hint_alias="from$_subquery$_005"@"SEL$3"

JPPD:     JPPD bypassed: View has unsupported constructs.
Check Basic Validity for Non-Union View for query block SEL$2 (#0)
JPPD:     JPPD bypassed: View contains a rownum reference.

JPPD:     JPPD bypassed: View contains a rownum reference. ------------> here
FPD: Considering simple filter push in query block SEL$2 (#0)
"T2"."N1"="T3"."N1" AND ROWNUM >1

Summary

There are many other situations like the ones exposed above out of which the SUBQUERY_PRUNING hint which forces a PARTITION RANGE SUBQUERY but only under a HASH JOIN operation or under a NESTED LOOPS but only when the partitioned table is on the right hand side of the join (inner row source). The combination of SUBQUERY_PRUNING and USE_NL hint would be impossible to be obeyed at the same time since this will force a recursive SQL ( SELECT distinct TBL$OR$IDX$PART$NUM) that would have been executed as many times as there are rows in the outer row source.

I may continue blogging about similar non-obeyed hints in a separate blog article to keep the current one about 5 minutes of read.

May 16, 2020

SQL*Net break/reset to client

Filed under: Oracle — hourim @ 6:10 pm

This is a draft I wrote in 2015. I don’t know why I have not published it by that time? probably I was looking for something to add in this context. Anyway, I decided to give it a rebirth right now  after almost 5 years of dormant time.

A SQL*Net break/reset to client wait event was popping out at a dramatic rate so that the client application ASH data was abnormally flushed out from memory. It was then vital to find what is causing this wait event to show up at this high rate. This article aims to explain the steps I have followed trying to figure out the sql_id at the origin of this wait event.

The first article, dealing with SQL*Net break/reset to client error, that pops up when you Google for it, is this one by Tanel Poder.  It explains clearly what this event represents and gives a reproducible example.  In the real life case I’ve faced  ASH was showing this:

SQL> select event, count(1)
    from gv$active_session_history
    where sample_time between to_date('10072015 11:00:00', 'ddmmyyyy hh24:mi:ss')
                      and     to_date('10072015 12:00:00', 'ddmmyyyy hh24:mi:ss')
    group by event
    order by 2 desc;

EVENT                                                              COUNT(1)
---------------------------------------------------------------- ----------
SQL*Net break/reset to client                                        164205
                                                                      10438
db file sequential read                                                2960
SQL*Net message from dblink                                            2499
direct path read                                                       1322
log file sync                                                           427
log file parallel write                                                 411
SQL*Net more data from client                                           183
control file sequential read                                             98
Backup: MML create a backup piece                                        82
…/…

Let’s try to find, naively, the sql_id behind this dramatic 164,205 SQL*Net break/reset to client recorded waits

SQL>  select sql_id, count(1)
      from gv$active_session_history
      where sample_time between to_date('10072015 11:00:00', 'ddmmyyyy hh24:mi:ss')
                        and     to_date('10072015 12:00:00', 'ddmmyyyy hh24:mi:ss')
      and event = 'SQL*Net break/reset to client'
      group by sql_id
      order by 2 desc;

SQL_ID          COUNT(1)
------------- ----------
                  164205 

Damn!! It is a NULL sql_id

What about the sessions experimenting this wait event

SQL> select session_id, count(1)
     from gv$active_session_history
     where sample_time between to_date('10072015 11:00:00', 'ddmmyyyy hh24:mi:ss')
                       and     to_date('10072015 12:00:00', 'ddmmyyyy hh24:mi:ss')
     and event = 'SQL*Net break/reset to client'
     group by session_id
     order by 2 desc;

SESSION_ID   COUNT(1)
---------- ----------
       151       3575
      2846       3575
       465       3575
      1791       3575
      2465       3575
       853       3575
      1216       3575
      1270       3575
      1397       3575
      2912       3575
        90       3575
       412       3575
      1155       3575
      1838       3575
      1957       3575
      2777       3575
      1038       3575 
      1290       3575
      1455       3575
      2648       3575
      2860       3575
      2988       3575
       344       3575
       533       3575
       337       3575
      2424       3575
      1028       3575
      1779       3575
      2047       3575
      2412       3575
       136       3575
       591       3575
       773       3575
       900       3575
       913       3575
      1335       3575
      1657       3575
      2101       3575
      2363       3575
       202       3575
      2226       3575
        16       3575
        79       3575
      1916       3575
      2362       3575
      1705       1429
       908       1181 

More than 45 sessions experimenting this wait event. Let’s then try to get the sql_id of one of those sessions:

SQL> select sql_id, count(1)
    from gv$active_session_history
    where sample_time between to_date('10072015 11:00:00', 'ddmmyyyy hh24:mi:ss')
                      and     to_date('10072015 12:00:00', 'ddmmyyyy hh24:mi:ss')
    and session_id = 151
    group by sql_id
    order by 2 desc;

SQL_ID          COUNT(1)
------------- ----------
                    3515 

Damn!! It is a NULL sql_id again.

Let’s now get the list of wait events the above session (151) was experimenting


SQL> select event, count(1)
     from gv$active_session_history
     where sample_time between to_date('10072015 11:00:00', 'ddmmyyyy hh24:mi:ss')
                       and     to_date('10072015 12:00:00', 'ddmmyyyy hh24:mi:ss')
     and session_id = 151
     group by event
     order by 2 desc;

EVENT                            COUNT(1)
-------------------------------- -------
SQL*Net break/reset to client    3453

I am going around a vicious circle! Isn’t it?

What if I try, now, to join those particular sessions with v$process view to see, at least, what their process are accomplishing

SQL> with got_my_sid
    as(
       select
            session_id
          , count(1)
       from
           v$active_session_history
       where sample_time between to_date('10072015 11:00:00', 'ddmmyyyy hh24:mi:ss')
                         and     to_date('10072015 12:00:00', 'ddmmyyyy hh24:mi:ss')
      and event = 'SQL*Net break/reset to client'
      group by session_id
      )
   select
          p.username
         ,p.tracefile
         ,p.pga_used_mem
         ,p.pga_alloc_mem
    from
         v$process p
        ,v$session s
   where
         p.addr=s.paddr
    and exists (select null
               from got_my_sid a
               where s.sid = a.session_id);

USERNAME     TRACEFILE                                                                        PGA_USED_MEM PGA_ALLOC_MEM
------------ -------------------------------------------------------------------------------- ------------ -------------
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_116986.trc               44210323      46756230
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_58127.trc                22468107      26308998
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_58151.trc                51969971      56979846
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_69733.trc                42309691      45969798
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_69747.trc               103456803     115241350
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_69759.trc                 5183995       8810886
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_58169.trc               122509563     126316934
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_94674.trc                 4810835      10711430
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_77524.trc                 4867723      10711430
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_77727.trc                48775851      57307526
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_77837.trc                 5697963       6517126
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_77962.trc                 4926947       7500166
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76614.trc               142568163     170160518
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76622.trc                10887843      12743046
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76634.trc                13751019      16675206
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76662.trc                17715523      18772358
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76670.trc                 4852883       7631238
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76676.trc                 5040315       6517126
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76734.trc                20039043      22114694
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76741.trc               110836667     127889798
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76749.trc                29546107      33255814
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76792.trc                 5336891       6975878
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11735.trc               141510371     167014790
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11741.trc                50941459      54882694
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11759.trc                13313739      15102342
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11772.trc                45210595      56390022
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11784.trc                16259099      18641286
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_58289.trc                86902963     103838086
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_76815.trc                10668723      13005190
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11808.trc                13386251      15036806
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11844.trc                64225827      68252038
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11856.trc                50413091      54620550
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117006.trc               38196715      46952838
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117012.trc               27739851      30241158
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11862.trc               114249963     120418694
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11868.trc                90697083      95973766
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117042.trc               78140859      79982982
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11892.trc               188237195     226324870
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117078.trc              141404363     171209094
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117092.trc              142334875     166883718
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117098.trc               44335187      46887302
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_117112.trc               98170435     117469574
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11898.trc                 5171715       7696774
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_11904.trc                 4970579       5534086
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_95446.trc               142625387     164524422
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_58609.trc                 5278147       7041414
oracle       /oracle/base/diag/rdbms/pwrwdp1/CLSWPROD1/trace/CLSWPROD1_ora_58689.trc                 5316451       6910342 

Finally I have something to get my teeth into.

It looks like sessions that were suffering from the SQL*Net break/reset to client wait event have generated several trace files. And, hopefully, one of those trace files shows the following error:

ORA-04030: out of process memory when trying to allocate 824504 bytes (pga heap,kco buffer)
ORA-04030: out of process memory when trying to allocate 3032 bytes (kkoutlCreatePh,kkotrb : kkoabr) 

The same trace file shows, as well, the SQL Statement which has originated this very high number of  SQL*Net break/reset to client wait event

dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=d6jgtxn25741y) -----
select * from ( select alias.cols as skey87_0_, alias.skey as skey81_1_ 

This is how I drilled down to the root cause of this wait event.

 

 

May 10, 2020

Why my execution plan has not been shared: Part 6

Filed under: Oracle — hourim @ 9:57 am

In this sixth installment of the series of articles about the non-sharing reasons that prevent Oracle from using an existing execution plan, I am going to dig into a new supplementary reason which is Session Specific Cursor Session Mismatch. For the sake of completeness here’s below the list of already investigated non-sharing reasons:

I didn’t find any definition from the official Oracle documentation for the Session Specific Cursor non-sharing reason. So let’s start immediately by building a test case with which we will provoke the apparition of this non-sharing reason

SQL> select banner from v$version;

BANNER
----------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production

SQL> select distinct sid from v$mystat;

       SID
----------
        16
		
SQL> create global temporary table t1 (owner varchar2(128), object_type varchar2(30)) on commit preserve rows;

Table created.

SQL> insert into t1 select owner, object_type from all_objects where owner ! = 'SYS';

19296 rows created.

SQL> commit;

SQL> col prefs format a20
SQL> select dbms_stats.get_prefs('GLOBAL_TEMP_TABLE_STATS') prefs from dual;

PREFS
--------------------
SESSION

SQL> exec dbms_stats.gather_table_stats(user, 't1');

Using session id n°16, I have created a simple global temporary table, inserted into it few rows and ended up by gathering statistics on this table using the default private SESSION preference. Simply put, statistics gathered under this preference are not propagated to all other sessions. This is why it is also known as PRIVATE statistic. The current session global temporary table (GTT) statistics are not shared with other sessions using the same GTT.

This is clearly shown via the following select


SQL> SELECT
        table_name,
        blocks,
        num_rows,
        scope
    FROM
        user_tab_statistics
    WHERE
        table_name = 'T1';

TABLE_NAME       BLOCKS   NUM_ROWS SCOPE
------------ ---------- ---------- -------
T1                                 SHARED
T1                   55      19296 SESSION

As you can see, the only available statistics are those that are local to the current session.

Let’s now execute a simple query and get its execution plan

SQL>select owner, count(1)
    from t1
    where object_type = 'TABLE'
    group by owner
    order by 2 desc;

OWNER                            COUNT(1)
------------------------------ ----------
MDSYS                                 151
SYSTEM                                131
ORDDATA                                90
XDB                                    56
CTXSYS                                 53
DVSYS                                  44
GSMADMIN_INTERNAL                      42
WMSYS                                  40
LBACSYS                                22
DBSNMP                                 20
OJVMSYS                                 6
C##MHOURI                               5
APPQOSSYS                               5
ORDSYS                                  4
DBSFWUSER                               3
OUTLN                                   3
OLAPSYS                                 2
AUDSYS                                  1

18 rows selected.

SQL> select * from table(dbms_xplan.display_cursor);

SQL_ID  c1j862cvqgh99, child number 0
-------------------------------------
select owner, count(1) from t1 where object_type = 'TABLE' group by
owner order by 2 desc

Plan hash value: 2808104874
----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |       |       |    19 (100)|          |
|   1 |  SORT ORDER BY      |      |    24 |   360 |    19  (11)| 00:00:01 |
|   2 |   HASH GROUP BY     |      |    24 |   360 |    19  (11)| 00:00:01 |
|*  3 |    TABLE ACCESS FULL| T1   |   772 | 11580 |    17   (0)| 00:00:01 |
----------------------------------------------------------------------------

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

   3 - filter("OBJECT_TYPE"='TABLE')

Note
-----
   - Global temporary table session private statistics used
   

The above Note at the bottom of the execution plan is clearly indicating that Oracle has used the session private statistics of the GTT.

To end up the setup I am going to run the same query but from a different session as shown below:


SQL> select distinct sid from v$mystat;

       SID
----------
       394
 
SQL> select count(1) from t1;

  COUNT(1)
----------
         0
		 
SQL> insert into t1 select owner, object_type from all_objects where owner  = 'CTXSYS';
	   		
SQL>select owner, count(1)
    from t1
    where object_type = 'TABLE'
    group by owner
    order by 2 desc;

OWNER            COUNT(1)
-------------- ----------
CTXSYS                 53

SQL> select * from table(dbms_xplan.display_cursor);

SQL_ID  c1j862cvqgh99, child number 1  --> new child cursor
-------------------------------------
select owner, count(1) from t1 where object_type = 'TABLE' group by
owner order by 2 desc

Plan hash value: 2808104874
----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |       |       |     4 (100)|          |
|   1 |  SORT ORDER BY      |      |    53 |  4399 |     4  (50)| 00:00:01 |
|   2 |   HASH GROUP BY     |      |    53 |  4399 |     4  (50)| 00:00:01 |
|*  3 |    TABLE ACCESS FULL| T1   |    53 |  4399 |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("OBJECT_TYPE"='TABLE')

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)

As you can see the same query has refused to share the previous execution plan (child cursor 0 from session 16) and has hard parsed a new child cursor n°1 (in session 394). This is simply due to the following reason:

SQL> @nonshared c1j862cvqgh99

Show why existing SQL child cursors were not reused (V$SQL_SHARED_CURSOR)...

SQL_ID                        : c1j862cvqgh99
ADDRESS                       : 00007FFCCD36B030
CHILD_ADDRESS                 : 00007FFCCD3698D8
CHILD_NUMBER                  : 0
REASON                        : <ChildNode><ChildNumber>0</ChildNumber><ID>46</ID>
                                <reason>Session Specific Cursor SessionMismatch(1)</reason>
								<size>7x4</size><session_mismatch>1</session_mismatch>
								<current_qcsesidx>394</current_qcsesidx>       --> here the current SID
								<current_qcsesser>58570</current_qcsesser><current_qcinst>1</current_qcinst>
								<stored_qcsesidx>16</stored_qcsesidx> --> the SID of the original child cursor
								<stored_qcsesser>58601</stored_qcsesser>
								<stored_qcinst>1</stored_qcinst></ChildNode>
CON_ID                        : 1
-----------------
SQL_ID                        : c1j862cvqgh99
ADDRESS                       : 00007FFCCD36B030
CHILD_ADDRESS                 : 00007FFCCD348328
CHILD_NUMBER                  : 1
REASON                        :
CON_ID                        : 1
-----------------

PL/SQL procedure successfully completed.

Conclusion

In light of what I have demonstrated above I can, finally, define this non-sharing reason as:

(Y|N) The session specific cursor environment does not match the existing child cursor

With the first session mismatch being:

  • SessionMismatch(1) –> points to GTT private statistics

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's blog

Just another blog : Databases, Linux and other stuffs

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.

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)