Re: Is hash join slower in 12.2 compared to 11.2.0.3 or am i hitting a bug?
Date: Sat, 25 Jan 2020 21:48:00 -0500
Message-ID: <c2a861ec-8ab0-711f-400d-84a16bd98503_at_gmail.com>
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:
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
> <mailto: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 -- http://www.freelists.org/webpage/oracle-lReceived on Sun Jan 26 2020 - 03:48:00 CET