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

From: Noveljic Nenad <nenad.noveljic_at_vontobel.com>
Date: Mon, 27 Jan 2020 08:27:07 +0000
Message-ID: <38751_1580113691_5E2E9F1B_38751_16358_1_d6a7443ff1784ed2a6209d352905940d_at_vontobel.com>

Hi Stefan,

> As already mentioned the stacks are driven by top function clock_gettime() - however the calling functions are not particularly related to the HJ/FTS (e.g. kdstf111010100001000km().

kdstf111010100001000km is a dynamically generated function doing full table scan.

> What are these functions (e.g. 000000002D93D64B, 0000000014D30516, etc.) without any symbols about?

This is probably dynamically ("just-in-time") generated code presumably sitting in the private memory. A longer stack would provide more context.

Best regards,

Nenad

https://nenadnoveljic.com/blog/

-----Original Message-----
From: oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> On Behalf Of Stefan Koehler Sent: Montag, 27. Januar 2020 09:08
To: krishsingh.111_at_gmail.com; ORACLE-L <oracle-l_at_freelists.org> Subject: Re: Is hash join slower in 12.2 compared to 11.2.0.3 or am i hitting a bug?

Hello Kunwar,
a few things that I have noticed and a few more questions of course ;-)

1. Are the two databases running on the same OS/host?
2. Is the response time / resource contribution the same if you create an extended SQL trace (because of the mentioned glitch in ASH) for the query?
3. As already mentioned the stacks are driven by top function clock_gettime() - however the calling functions are not particularly related to the HJ/FTS (e.g. kdstf111010100001000km(). What are these functions (e.g. 000000002D93D64B, 0000000014D30516, etc.) without any symbols about?
4. Do you see clock_gettime() as a syscall or not? Normally this syscall is vDSO nowadays but there are cases where this one gets slower too :-)

Best Regards
Stefan Koehler

Independent Oracle performance consultant and researcher Website: http://www.soocs.de
Twitter: _at_OracleSK

> kunwar singh <krishsingh.111_at_gmail.com> hat am 26. Januar 2020 um 03:24 geschrieben:
>
>
> 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<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-00000000392A8918<-6D7072
> 6B00796669
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-kpusattr()+58060<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-kzftfpc()+108<-6B6D70726
> B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-dmsglLRPersist()+1480<-6
> B6D70726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000016646A58<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000001CD11420<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000002305FE48<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000002928CA8A<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000002F6031FE<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-00000000359BB229<-6B6D70
> 726B007966
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-00000000003FAF84<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-kfclUnlinkBh()+1586<-736
> B6D70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-kdstf111010100001000km()
> +14<-736B6D70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000012BCB837<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000018D8C1B8<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000001EFA8E9F<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-00000000252DCF2E<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000002B574A8C<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-00000000317E01AF<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000037C374DF<-736B6D
> 70726B0079
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-kdiss_fetch()+4710<-7673
> 6B6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-qmxxtiAdjMKXTIArgs()+384
> <-76736B6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-qesgvslice_0_MIN_MO_DA_F
> ()+6004<-76736B6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000014D30516<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000001B002C0A<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000002125D372<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-00000000276006C7<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-000000002D93D64B<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000033C3E57D<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-0000000039EC64C6<-76736B
> 6D70726B00
> ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandle
> r()<-clock_gettime()+331<-clock_gettime()+54<-xsspfc_Comp504()+575<-5F
> 76736B6D70726B
>
> 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
--
http://www.freelists.org/webpage/oracle-l

---

Please consider the environment before printing this e-mail. Bitte denken Sie an die Umwelt, bevor Sie dieses E-Mail drucken.

Important Notice  

 This message is intended only for the individual named. It may contain confidential or privileged information. If you are not the named addressee you should in particular not disseminate, distribute, modify or copy this e-mail. Please notify the sender immediately by e-mail, if you have received this message by mistake and delete it from your system.  Without prejudice to any contractual agreements between you and us which shall prevail in any case, we take it as your authorization to correspond with you by e-mail if you send us messages by e-mail. However, we reserve the right not to execute orders and instructions transmitted by e-mail at any time and without further explanation.  E-mail transmission may not be secure or error-free as information could be intercepted, corrupted, lost, destroyed, arrive late or incomplete. Also processing of incoming e-mails cannot be guaranteed. All liability of Vontobel Holding Ltd. and any of its affiliates (hereinafter collectively referred to as "Vontobel Group") for any damages resulting from e-mail use is excluded. You are advised that urgent and time sensitive messages should not be sent by e-mail and if verification is required please request a printed version.  Please note that all e-mail communications to and from the Vontobel Group are subject to electronic storage and review by Vontobel Group. Unless stated to the contrary and without prejudice to any contractual agreements between you and Vontobel Group which shall prevail in any case, e-mail-communication is for informational purposes only and is not intended as an offer or solicitation for the purchase or sale of any financial instrument or as an official confirmation of any transaction.  The legal basis for the processing of your personal data is the legitimate interest to develop a commercial relationship with you, as well as your consent to forward you commercial communications. You can exercise, at any time and under the terms established under current regulation, your rights. If you prefer not to receive any further communications, please contact your client relationship manager if you are a client of Vontobel Group or notify the sender.  Please note for an exact reference to the affected group entity the corporate e-mail signature.  For further information about data privacy at Vontobel Group please consult www.vontobel.com.

†Ûiÿü0ÁúÞzX¬¶Ê+ƒün– {ú+iÉ^ Received on Mon Jan 27 2020 - 09:27:07 CET