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

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


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