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: @OracleSK
kunwar singh <krishsingh.111@xxxxxxxxx> 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@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@xxxxxxxxxxxxxxxxxxxxxxxx (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
