*correction , not another OS , but another machine on Linux OS only.
On Tue, Jan 28, 2020 at 1:28 PM kunwar singh <krishsingh.111@xxxxxxxxx>
wrote:
Hi Jonathan,Tanel,Stefan,Noveljic,
Sorry for the delay as i was away from my laptop the whole day yday.
Thanks for all the great pointers. I am reviewing them all. So it is
pointing to something at the OS end which causing the problem as i tested
the same query on another OS which had both version databases and it ran
fine. So i thought of comparing this "FAST" system with the "SLOW" one
which hosts the 12c test environment.
Here are the checks so far :
1. All are virtual machines .
2. LSCPU output :
Parameter |SLOW SYSTEM |FAST SYSTEM
----------------------|--------------------|------------
Architecture: x86_64 x86_64
CPU op-mode(s): 32-bit, 64-bit 32-bit, 64-bit
Byte Order: Little Endian Little Endian
CPU(s): 2 24
<< <<<<<Even though it is 2 vs 24 CPU , should it really make that
much difference to the hash join , no one else is using these VMs than me.
On-line CPU(s) list: 0,1 0-23
Thread(s) per core: 1 1
Core(s) per socket: 2 24
Socket(s): 1 1
NUMA node(s): 1 1
Vendor ID: GenuineIntel GenuineIntel
CPU family: 6 6
Model: 79 85
Stepping: 1 4
CPU MHz: 2194.171 2095.855
BogoMIPS: 4388.34 4191.71
L1d cache: 32K 32K
L1d cache: 32K 32K
L2d cache: 6144K 6144K
NUMA node0 CPU(s): 0,1 0-23
3. Few other details.
Parameter |SLOW SYSTEM |FAST SYSTEM
----------------------|-----------------------------|------------
uname -r |4.1.12-124.16.4.el6uek.x86_64|2.6.32-431.el6.x86_64
/sys/devices/system/clocksource/clocksource0/current_clocksource |acpi_pm
|acpi_pm
4. _rowsource_statistics_sampfreq is set to default 128
On Mon, Jan 27, 2020 at 4:53 AM Jonathan Lewis <
jonathan@xxxxxxxxxxxxxxxxxx> wrote:
Since Tanel has join in with a couple of points, this seems to be a good
moment to suggest that you try running the query and capturing the instance
activity stats (v$sesstat) and detailed wait events (v$session_wait) to
see if the session stats (in particular) tell you about some activity that
we're not expecting to see, or suggest a source for the excess CPU time.
And what better way to capture the information that Tanel's Snapper.
Regards
Jonathan Lewis
________________________________________
From: kunwar singh <krishsingh.111@xxxxxxxxx>
Sent: 26 January 2020 14:59
To: Jonathan Lewis
Cc: ORACLE-L
Subject: Re: Is hash join slower in 12.2 compared to 11.2.0.3 or am i
hitting a bug?
Thanks Jonathan.
yes i do see good performance with px_join_filter as well.
SQL Monitoring Report
SQL Text
------------------------------
select /*+ gather_plan_statistics monitor leading(a,b) use_hash(a,b)
full(a) full(b) px_join_filter(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 (32:40079)
SQL ID : f88k408dc9qn4
SQL Execution ID : 16777216
Execution Started : 01/26/2020 15:37:23
First Refresh Time : 01/26/2020 15:37:23
Last Refresh Time : 01/26/2020 15:37:23
Duration : .31806s
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.32 | 0.16 | 0.14 | 0.02 | 4 | 8735 | 92 | 68MB
|
===========================================================================
SQL Plan Monitoring Details (Plan Hash Value=1496359809)
=============================================================================================================================================================
| 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 | | | |
1 | +0 | 1 | 32 | | | . | |
|
| 1 | HASH JOIN | | 32 | 2482 |
1 | +0 | 1 | 32 | | | 297KB | |
|
| 2 | JOIN FILTER CREATE | :BF0000 | 1 | 3 |
1 | +0 | 1 | 1 | | | . | |
|
| 3 | TABLE ACCESS FULL | TMP_EMP | 1 | 3 |
1 | +0 | 1 | 1 | 2 | 16384 | . | |
|
| 4 | JOIN FILTER USE | :BF0000 | 640K | 2477 |
1 | +0 | 1 | 32 | | | . | |
|
| 5 | TABLE ACCESS FULL | TMP_DBA_OBJECTS | 640K | 2477 |
1 | +0 | 1 | 32 | 81 | 68MB | . | |
|
=============================================================================================================================================================
I will check into the OS & h/w difference. Is there a reference blog or
step by step checks that you can suggest?
Yes removing gather_plan_statistics didnt make a difference to the
performance.
On Sun, Jan 26, 2020 at 5:03 AM Jonathan Lewis <
jonathan@xxxxxxxxxxxxxxxxxx<mailto:jonathan@xxxxxxxxxxxxxxxxxx>> wrote:
I've run up your test on 11.2.0.4 and 12.2.0.1 - there is basically no
difference between the two (though 12.2.0.1 is slightly faster, but the
variation by each version is similar to the difference between versions, so
not significant). CPU time is ca. 0.32 - 0.35 seconds.
Tested with and without direct path reads, with and without
gather_plan_statistics.
I would have expected the impact of gathering rowsource execution
statistics to be minimal in all your test cases because I believe the
counters and timers are checked at the start and end of each call to a
child operation - and a hash join calls it's child operations just once
each.
I suspect any problem may relate to O/S or hardware differences, that's
resulting in a difference with memory access as rows are moved up from
child to parent. (This might explain why the parallel query with Bloom
filter is faster - very few rows get moved from child to parent - you could
test this by adding the hint px_join_filter(b) to the SQL to force the
Bloom filter to appear in the (12.2) serial query.)
Regards
Jonathan Lewis
________________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx<mailto:oracle-l-bounce@xxxxxxxxxxxxx>
<oracle-l-bounce@xxxxxxxxxxxxx<mailto:oracle-l-bounce@xxxxxxxxxxxxx>> on
behalf of kunwar singh <krishsingh.111@xxxxxxxxx<mailto:
krishsingh.111@xxxxxxxxx>>
Sent: 26 January 2020 02:24
To: ORACLE-L
Subject: Is hash join slower in 12.2 compared to 11.2.0.3 or am i hitting
a bug?
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<mailto:
sqlplus@xxxxxxxxxxxxxxxxxxxxxxxx><mailto:sqlplus@xxxxxxxxxxxxxxxxxxxxxxxx
<mailto: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
--
Cheers,
Kunwar
--
//www.freelists.org/webpage/oracle-l
--
Cheers,
Kunwar
