Home -> Mailing Lists -> Oracle-L -> Re: Is hash join slower in 12.2 compared to 11.2.0.3 or am i hitting a bug?

Re: Is hash join slower in 12.2 compared to 11.2.0.3 or am i hitting a bug?

From: kunwar singh <krishsingh.111_at_gmail.com>
Date: Sat, 25 Jan 2020 23:30:32 -0500
Message-ID: <CAJSrDUo5jR3y3-4hO0UqU=Ss2E6epTPW55-uQb5JVB1Zo4G22w_at_mail.gmail.com> 








One interesting finding. When i use the parallel degree of 2 , response
time is very fast .



SQL Text




select /*+ gather_plan_statistics monitor leading(a,b) use_hash(a,b)
full(a) full(b) parallel(b,2) */ *from TMP_emp a, tmp_dba_objects b where
a.empno=b.object_id



Global Information



 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  KUNWAR (33:1022)
 SQL ID              :  9mth9sd3amuy2
 SQL Execution ID    :  16777217
 Execution Started   :  01/26/2020 05:01:06
 First Refresh Time  :  01/26/2020 05:01:06
 Last Refresh Time   :  01/26/2020 05:01:07
 Duration            :  1s




 <<<<<<< finishes within a second after usingthe parallel degree. maybe due
to blooom filter

 Module/Action       :  SQL*Plus/-
 Service             :  SYS$USERS
 Fetch Calls         :  4





Global Stats




| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  |


| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |






|    0.15 |    0.01 |     0.03 |     0.10 |     4 |   8764 |  110 |  68MB |







Parallel Execution Details (DOP=2 , Servers Allocated=4)




|      Name      | Type  | Server# | Elapsed |   Cpu   |    IO    |  Other


  | Buffer | Read | Read  | Wait Events |


|                |       |         | Time(s) | Time(s) | Waits(s) |


Waits(s) |  Gets  | Reqs | Bytes | (sample #)  |




| PX Coordinator | QC    |         |    0.02 |    0.01 |          |



0.00 |      5 |      |     . |             |


| p000           | Set 1 |       1 |    0.06 |         |     0.02 |


0.05 |   4722 |   65 |  37MB |             |


| p001           | Set 1 |       2 |    0.07 |         |     0.02 |


0.05 |   4035 |   45 |  31MB |             |


| p002           | Set 2 |       1 |    0.00 |         |          |


0.00 |        |      |     . |             |


| p003           | Set 2 |       2 |    0.00 |         |          |


0.00 |      2 |      |     . |             |
====================================================================================================================





SQL Plan Monitoring Details (Plan Hash Value=4190125912)




| 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           |                 |         |      |




    2 |     +0 |     5 |       32 |      |       |     . |          |
          |


|  1 |   PX COORDINATOR           |                 |         |      |


    2 |     +0 |     5 |       32 |      |       |     . |          |
          |


|  2 |    PX SEND QC (RANDOM)     | :TQ10001        |      32 | 1379 |


    1 |     +0 |     2 |       32 |      |       |     . |          |
          |


|  3 |     HASH JOIN              |                 |      32 | 1379 |


    1 |     +0 |     2 |       32 |      |       | 594KB |          |
          |


|  4 |      JOIN FILTER CREATE    | :BF0000         |       1 |    3 |


    1 |     +0 |     2 |        2 |      |       |     . |          |
          |


|  5 |       PX RECEIVE           |                 |       1 |    3 |


    1 |     +0 |     2 |        2 |      |       |     . |          |
          |


|  6 |        PX SEND BROADCAST   | :TQ10000        |       1 |    3 |


    1 |     +0 |     2 |        2 |      |       |     . |          |
          |


|  7 |         PX SELECTOR        |                 |         |      |


    1 |     +0 |     2 |        1 |      |       |     . |          |
          |


|  8 |          TABLE ACCESS FULL | TMP_EMP         |       1 |    3 |


    1 |     +0 |     1 |        1 |      |       |     . |          |
          |


|  9 |      JOIN FILTER USE       | :BF0000         |    640K | 1375 |


    1 |     +0 |     2 |       32 |      |       |     . |          |
          |


| 10 |       PX BLOCK ITERATOR    |                 |    640K | 1375 |


    1 |     +0 |     2 |       32 |      |       |     . |          |
          |


| 11 |        TABLE ACCESS FULL   | TMP_DBA_OBJECTS |    640K | 1375 |


    1 |     +0 |    35 |       32 |  110 |  68MB |     . |          |
          |                <<<<<<< due to bloom filter?
==================================================================================================================================================================


Query Block Name / Object Alias (identified by operation id):




   1 - SEL$1
   8 - SEL$1 / A_at_SEL$1
  11 - SEL$1 / B_at_SEL$1





Outline Data





  /*+

      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.2.0.1')
      DB_VERSION('12.2.0.1')
      OPT_PARAM('_b_tree_bitmap_plans' 'false')
      OPT_PARAM('optimizer_dynamic_sampling' 0)
      OPT_PARAM('_optimizer_use_feedback' 'false')
      OPT_PARAM('_optimizer_cbqt_or_expansion' 'off')
      OPT_PARAM('_fix_control' '22143411:0')
      ALL_ROWS
      OUTLINE_LEAF(_at_"SEL$1")
      FULL(_at_"SEL$1" "A"_at_"SEL$1")
      FULL(_at_"SEL$1" "B"_at_"SEL$1")
      LEADING(_at_"SEL$1" "A"_at_"SEL$1" "B"@"SEL$1")
      USE_HASH(_at_"SEL$1" "B"_at_"SEL$1")
      PQ_DISTRIBUTE(_at_"SEL$1" "B"_at_"SEL$1" BROADCAST NONE)
      PX_JOIN_FILTER(_at_"SEL$1" "B"_at_"SEL$1")
      END_OUTLINE_DATA




  */



Predicate Information (identified by operation id):




   3 - access("A"."EMPNO"="B"."OBJECT_ID")
  11 - access(:Z>=:Z AND :Z<=:Z)
       filter(SYS_OP_BLOOM_FILTER(:BF0000,"B"."OBJECT_ID"))





On Sat, Jan 25, 2020 at 11:10 PM kunwar singh <krishsingh.111_at_gmail.com>
wrote:


> Also i tinkered with _small_table_threshold. No improvements in hash join
> timings as such.
>
> On Sat, Jan 25, 2020 at 11:09 PM kunwar singh <krishsingh.111_at_gmail.com>
> wrote:
>
>> i forced using _serial_direct_read=true, it is doing direct path reads ,
>> but time spent on CPU it still high. and the time is spent on hash
>> joining the rows returned from second table (TMP_DBA_OBJECTS)
>>
>> On Sat, Jan 25, 2020 at 9:48 PM Mladen Gogala <gogala.mladen_at_gmail.com>
>> wrote:
>>
>>> Plans are not the same. Oracle 11.2 is doing direct reads, Oracle 12.2
>>> is not.  Do you have big table caching turned on? If you do have big table
>>> caching turned on, turn it off and see if you're getting direct reads.
>>> Also, check PGA_AGGREGATE_TARGET and make it the same on both versions.
>>> Oracle 12.2 changed the method for deciding when to do direct reads:
>>>
>>>
>>> https://fritshoogland.wordpress.com/2017/09/08/the-full-table-scan-direct-path-read-decision-for-version-12-2/
>>>
>>> For the record, I am not advising you to change _small_table_threshold.
>>> You shouldn't be messing with the "underscore" parameters, unless advised
>>> by Oracle Support.
>>>
>>> Regards
>>> On 1/25/20 9:24 PM, kunwar singh wrote:
>>>
>>> Hi Listers,
>>>
>>> I am doing a testing of migrating app for a customer from 11.2.0.3 to
>>> 12.2 and find the queries doing hash join are taking upto 4x more time.
>>> Hash join step is the one taking the time , more cpu and more elapsed time.
>>> *Is this a known issue or any bug?  I searched in MOS , no hits or maybe
>>> i am not using correct keywords to match. *
>>>
>>> Note that i am doing testing on base releases of 11.2.0.3 & 12.2 for
>>> simplifying my testcase.
>>>
>>> 1. *Testcase *
>>> create table tmp_dba_objects AS SELECT *from  dba_objects where rownum
>>> <20001;
>>> insert into tmp_dba_objects select *from tmp_dba_objects;
>>> insert into tmp_dba_objects select *from tmp_dba_objects;
>>> insert into tmp_dba_objects select *from tmp_dba_objects;
>>> insert into tmp_dba_objects select *from tmp_dba_objects;
>>> insert into tmp_dba_objects select *from tmp_dba_objects;
>>>
>>> create table TMP_EMP ( EMPNO NUMBER);
>>> insert into TMP_EMP select min(object_id) from tmp_dba_objects;
>>> commit;
>>>
>>> alter system flush shared_pool;
>>> alter system flush buffer_cache;
>>>
>>> select /*+ gather_plan_statistics monitor leading(a,b) use_hash(a,b)
>>> full(a) full(b) */ *from TMP_emp a, tmp_dba_objects b where
>>> a.empno=b.object_id;
>>> set lin 300 pages 9999
>>> select *from table(dbms_xplan.display_cursor(NULL,NULL,'IOSTATS LAST'));
>>>
>>>
>>> 2.
>>>
>>> *SQL monitor report outputs *SQL Monitoring Report -
>>>
>>> *12.2.0.1 *SQL Text
>>> ------------------------------
>>> select /*+ gather_plan_statistics monitor leading(a,b) use_hash(a,b)
>>> full(a) full(b) */ *from TMP_emp a, tmp_dba_objects b where
>>> a.empno=b.object_id
>>>
>>> Global Information
>>> ------------------------------
>>>  Status              :  DONE (ALL ROWS)
>>>  Instance ID         :  1
>>>  Session             :  KUNWAR (40:7639)
>>>  SQL ID              :  0257vnkax6zak
>>>  SQL Execution ID    :  16777216
>>>  Execution Started   :  01/26/2020 02:52:50
>>>  First Refresh Time  :  01/26/2020 02:52:50
>>>  Last Refresh Time   :  01/26/2020 02:52:58
>>>  Duration            :  8s                                       <<<<<<<
>>> 8 seconds
>>>  Module/Action       :  SQL*Plus/-
>>>  Service             :  SYS$USERS
>>>  Program             :  sqlplus_at_devserver1 (TNS V1-V3)
>>>  Fetch Calls         :  4
>>>
>>> Global Stats
>>>
>>> =========================================================================================
>>> | Elapsed |   Cpu   |    IO    | Application |  Other   | Fetch | Buffer
>>> | Read | Read  |
>>> | Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) | Calls |  Gets
>>>  | Reqs | Bytes |
>>>
>>> =========================================================================================
>>> |    7.83 |    5.18 |     2.46 |        0.01 |     0.18 |     4 |   8742
>>> |   91 |  68MB |
>>>
>>> =========================================================================================
>>>
>>> SQL Plan Monitoring Details (Plan Hash Value=1398591261)
>>>
>>> ============================================================================================================================================================
>>> | 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     |                 |         |      |
>>> 8 |     +1 |     1 |       32 |      |       |     . |          |
>>>       |
>>> |  1 |   HASH JOIN          |                 |      32 | 2482 |
>>> 8 |     +1 |     1 |       32 |      |       | 708KB |          |
>>>       |                 -- Just as a side note that ASH is not getting
>>> populated, due to some other reason
>>> |  2 |    TABLE ACCESS FULL | TMP_EMP         |       1 |    3 |
>>> 1 |     +1 |     1 |        1 |    2 | 16384 |     . |          |
>>>       |
>>> |  3 |    TABLE ACCESS FULL | TMP_DBA_OBJECTS |    640K | 2477 |
>>> 8 |     +1 |     1 |     640K |   80 |  68MB |     . |          |
>>>       |
>>>
>>> ============================================================================================================================================================
>>>
>>>
>>> ---
>>> SQL Monitoring Report -*11.2.0.3*
>>> SQL Text
>>> ------------------------------
>>> select /*+ gather_plan_statistics monitor leading(a,b) use_hash(a,b)
>>> full(a) full(b) */ *from TMP_emp a, tmp_dba_objects b where
>>> a.empno=b.object_id
>>>
>>> Global Information
>>> ------------------------------
>>>  Status              :  DONE (ALL ROWS)
>>>  Instance ID         :  1
>>>  Session             :  KUNWAR (147:18275)
>>>  SQL ID              :  0257vnkax6zak
>>>  SQL Execution ID    :  16777216
>>>  Execution Started   :  01/26/2020 03:12:22
>>>  First Refresh Time  :  01/26/2020 03:12:22
>>>  Last Refresh Time   :  01/26/2020 03:12:24
>>>  Duration            :  2s
>>>  <<<<<<< 2 seconds
>>>  Module/Action       :  SQL*Plus/-
>>>  Service             :  SYS$USERS
>>>  Program             :  sqlplus_at_devserver2.us.oracle.com (TNS V1-V3)
>>>  Fetch Calls         :  4
>>>
>>> Global Stats
>>> ================================================================
>>> | Elapsed |   Cpu   |    IO    | Fetch | Buffer | Read | Read  |
>>> | Time(s) | Time(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
>>> ================================================================
>>> |    1.96 |    0.53 |     1.43 |     4 |   8844 |   83 |  69MB |
>>> ================================================================
>>>
>>> SQL Plan Monitoring Details (Plan Hash Value=1398591261)
>>>
>>> =================================================================================================================================================================
>>> | 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     |                 |         |      |
>>> 3 |     +0 |     1 |       32 |      |       |       |          |
>>>            |
>>> |  1 |   HASH JOIN          |                 |      32 | 2494 |
>>> 3 |     +0 |     1 |       32 |      |       |  734K |          |
>>>            |
>>> |  2 |    TABLE ACCESS FULL | TMP_EMP         |       1 |    3 |
>>> 1 |     +0 |     1 |        1 |    2 | 49152 |       |          |
>>>            |
>>> |  3 |    TABLE ACCESS FULL | TMP_DBA_OBJECTS |    640K | 2487 |
>>> 3 |     +0 |     1 |     640K |   81 |  69MB |       |    50.00 | direct
>>> path read (1) |
>>>
>>> =================================================================================================================================================================
>>>
>>> Not sure what diagnostic to dig deeper, strace/perf?  i am not  much
>>> familiar with these.
>>> oradebug oradebug short_stack in 12.2 shows lots of rows like below :
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-00000000392A8918<-6D70726B00796669
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-kpusattr()+58060<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-kzftfpc()+108<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-dmsglLRPersist()+1480<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000016646A58<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000001CD11420<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000002305FE48<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000002928CA8A<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000002F6031FE<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-00000000359BB229<-6B6D70726B007966
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-00000000003FAF84<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-kfclUnlinkBh()+1586<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-kdstf111010100001000km()+14<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000012BCB837<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000018D8C1B8<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000001EFA8E9F<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-00000000252DCF2E<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000002B574A8C<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-00000000317E01AF<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000037C374DF<-736B6D70726B0079
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-kdiss_fetch()+4710<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-qmxxtiAdjMKXTIArgs()+384<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-qesgvslice_0_MIN_MO_DA_F()+6004<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000014D30516<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000001B002C0A<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000002125D372<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-00000000276006C7<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-000000002D93D64B<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000033C3E57D<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-0000000039EC64C6<-76736B6D70726B00
>>>
>>> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-clock_gettime()+331<-clock_gettime()+54<-xsspfc_Comp504()+575<-5F76736B6D70726B
>>>
>>> I dont see these in 11.2
>>>
>>> While researching i am saw some twitter conversation of Frank Pachot and
>>> thought this link could help , but i am not familar with tmux/gdb , so
>>> still reading :) :
>>> https://github.com/FranckPachot/demo/blob/master/TVD-JoinMethods.sql
>>>
>>> Maybe i will have to go to one of conferences like POUG for such
>>> advanced techniques :D
>>>
>>> --
>>> Cheers,
>>> Kunwar
>>>
>>> --
>>> Mladen Gogala
>>> Database Consultant
>>> Tel: (347) 321-1217
>>>
>>>
>>
>> --
>> Cheers,
>> Kunwar
>>
>
>
> --
> Cheers,
> Kunwar
>





-- 
Cheers,
Kunwar

--
http://www.freelists.org/webpage/oracle-l


Received on Sun Jan 26 2020 - 05:30:32 CET












Original text of this message