Nice job compiling detailed (and relevant) info with your question!
In addition to (and somewhat overlapping with) what others have already
said:
1) Since all the stack traces showed *clock_gettime()* as the "current"
function (when the oradebug signal was received), it looks like related to
the GATHER_PLAN_STATISTICS / _rowsrc_statistics_enabled feature
- On 11g, this feature uses gettimeofday() system calls
- On 12.2 it uses clock_gettime() that is supposed to be more precise
and with the CLOCK_MONOTONIC option not jump backwards
2) Has anyone changed the *_rowsource_statistics_sampfreq* (should default
to 128)
3) Any infrastructure changes (like the old DB being on bare metal and the
new one on a VM?)
- the precise time getting functions may have performance issues on VMs,
depending on configuration (which hypervisor, which timer mechanism is the
guest using) and some other moving parts
4) What does this command show on both systems (if on different machines):
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
Thanks,
Tanel Poder
https://blog.tanelpoder.com/seminar
On Sat, Jan 25, 2020 at 11:32 PM kunwar singh <krishsingh.111@xxxxxxxxx>
wrote:
One interesting finding. When i use the parallel degree of 2 , response
time is very fast .
SQL Text
------------------------------
select /*+ gather_plan_statistics monitor leading(a,b) use_hash(a,b)
full(a) full(b) parallel(b,2) */ *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 (33:1022)
SQL ID : 9mth9sd3amuy2
SQL Execution ID : 16777217
Execution Started : 01/26/2020 05:01:06
First Refresh Time : 01/26/2020 05:01:06
Last Refresh Time : 01/26/2020 05:01:07
Duration : 1s
<<<<<<< finishes within a second after usingthe parallel degree. maybe
due to blooom filter
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.15 | 0.01 | 0.03 | 0.10 | 4 | 8764 | 110 | 68MB |
===========================================================================
Parallel Execution Details (DOP=2 , Servers Allocated=4)
====================================================================================================================
| Name | Type | Server# | Elapsed | Cpu | IO | Other
| Buffer | Read | Read | Wait Events |
| | | | Time(s) | Time(s) | Waits(s) |
Waits(s) | Gets | Reqs | Bytes | (sample #) |
====================================================================================================================
| PX Coordinator | QC | | 0.02 | 0.01 | |
0.00 | 5 | | . | |
| p000 | Set 1 | 1 | 0.06 | | 0.02 |
0.05 | 4722 | 65 | 37MB | |
| p001 | Set 1 | 2 | 0.07 | | 0.02 |
0.05 | 4035 | 45 | 31MB | |
| p002 | Set 2 | 1 | 0.00 | | |
0.00 | | | . | |
| p003 | Set 2 | 2 | 0.00 | | |
0.00 | 2 | | . | |
====================================================================================================================
SQL Plan Monitoring Details (Plan Hash Value=4190125912)
==================================================================================================================================================================
| 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 | | | |
2 | +0 | 5 | 32 | | | . | |
|
| 1 | PX COORDINATOR | | | |
2 | +0 | 5 | 32 | | | . | |
|
| 2 | PX SEND QC (RANDOM) | :TQ10001 | 32 | 1379 |
1 | +0 | 2 | 32 | | | . | |
|
| 3 | HASH JOIN | | 32 | 1379 |
1 | +0 | 2 | 32 | | | 594KB | |
|
| 4 | JOIN FILTER CREATE | :BF0000 | 1 | 3 |
1 | +0 | 2 | 2 | | | . | |
|
| 5 | PX RECEIVE | | 1 | 3 |
1 | +0 | 2 | 2 | | | . | |
|
| 6 | PX SEND BROADCAST | :TQ10000 | 1 | 3 |
1 | +0 | 2 | 2 | | | . | |
|
| 7 | PX SELECTOR | | | |
1 | +0 | 2 | 1 | | | . | |
|
| 8 | TABLE ACCESS FULL | TMP_EMP | 1 | 3 |
1 | +0 | 1 | 1 | | | . | |
|
| 9 | JOIN FILTER USE | :BF0000 | 640K | 1375 |
1 | +0 | 2 | 32 | | | . | |
|
| 10 | PX BLOCK ITERATOR | | 640K | 1375 |
1 | +0 | 2 | 32 | | | . | |
|
| 11 | TABLE ACCESS FULL | TMP_DBA_OBJECTS | 640K | 1375 |
1 | +0 | 35 | 32 | 110 | 68MB | . | |
| <<<<<<< due to bloom filter?
==================================================================================================================================================================
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
8 - SEL$1 / A@SEL$1
11 - SEL$1 / B@SEL$1
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('12.2.0.1')
DB_VERSION('12.2.0.1')
OPT_PARAM('_b_tree_bitmap_plans' 'false')
OPT_PARAM('optimizer_dynamic_sampling' 0)
OPT_PARAM('_optimizer_use_feedback' 'false')
OPT_PARAM('_optimizer_cbqt_or_expansion' 'off')
OPT_PARAM('_fix_control' '22143411:0')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "A"@"SEL$1")
FULL(@"SEL$1" "B"@"SEL$1")
LEADING(@"SEL$1" "A"@"SEL$1" "B"@"SEL$1")
USE_HASH(@"SEL$1" "B"@"SEL$1")
PQ_DISTRIBUTE(@"SEL$1" "B"@"SEL$1" BROADCAST NONE)
PX_JOIN_FILTER(@"SEL$1" "B"@"SEL$1")
END_OUTLINE_DATA
*/
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("A"."EMPNO"="B"."OBJECT_ID")
11 - access(:Z>=:Z AND :Z<=:Z)
filter(SYS_OP_BLOOM_FILTER(:BF0000,"B"."OBJECT_ID"))
On Sat, Jan 25, 2020 at 11:10 PM kunwar singh <krishsingh.111@xxxxxxxxx>
wrote:
Also i tinkered with _small_table_threshold. No improvements in hash join
timings as such.
On Sat, Jan 25, 2020 at 11:09 PM kunwar singh <krishsingh.111@xxxxxxxxx>
wrote:
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@xxxxxxxxx>
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@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
--
Mladen Gogala
Database Consultant
Tel: (347) 321-1217
--
Cheers,
Kunwar
--
Cheers,
Kunwar
--
Cheers,
Kunwar
