Hi,
We have an insert statement that started to run very slowly during the last days (several hours instead of less than 1 hour)
The analysis of the ASH says that the problem is on the LOAD TABLE CONVENTIONAL operation, so that let me guess that the problem is located inthe INSERT part.
The SQL_ID is running several times during the night for different execution (use of bind variables) but it is always the same execution that is facing the issue.
The statement inserts about 300k of rows in several hours (last night it took 6h) but we have other inserts (same sql_id) inserting 900K rows which complete in a few minutes every night.
The problem is not repoducible during the day.
I'm triying to understand:
- Where is spending the CPU time during the LOAD TABLE CONVENTIONAL operation?
- Why other executions for the same SQl_ID are completing in a few minutes ?
The database is running on Exadata (X3 db node) and on a 11.2.0.4 database.
Here is the query:
INSERT
/*+ ignore_row_on_dupkey_index(tgt OTC_DAT_TV_PROC_STATUS_UK) */
INTO OTC_DAT_TV_PROC_STATUS TGT
(
SK_TRADE_STATUS ,
SK_TRADE_VERSION ,
SK_STATUS_TYPO ,
SK_STATUS_DURATION ,
STATUS_START_TIMESTAMP ,
STATUS_END_TIMESTAMP ,
STATUS_MEDIA_TYPE ,
STATUS_SENDER_PARTY_ID ,
STATUS_SENDER_PARTY_ID_SC ,
STATUS_RECEIVER_PARTY_ID ,
STATUS_RECEIVER_PARTY_ID_SCH ,
STATUS_TIMESTAMP ,
CLEARING_PARTY_ID ,
CLEARING_PARTY_ID_SCH ,
CLEARING_SYSTEM_TYPE ,
CHECKSUM_PROC_STATUS ,
DT_LOAD ,
DT_LOAD_TRADE_VERSION ,
SEQ_PROC_STATUS
)
SELECT
/*+ parallel(8) */
OTC_DAT_TV_PROC_STATUS_SEQ.NEXTVAL ,
TV.SK_TRADE_VERSION ,
PST.SK_STATUS_TYPO ,
PSD.SK_STATUS_DURATION ,
PS.STATUS_START_TIMESTAMP ,
PS.STATUS_END_TIMESTAMP ,
PS.STATUS_MEDIA_TYPE ,
PS.STATUS_SENDER_PARTY_ID ,
PS.STATUS_SENDER_PARTY_ID_SC ,
PS.STATUS_RECEIVER_PARTY_ID ,
PS.STATUS_RECEIVER_PARTY_ID_SCH ,
PS.STATUS_TIMESTAMP ,
PS.CLEARING_PARTY_ID ,
PS.CLEARING_PARTY_ID_SCH ,
PS.CLEARING_SYSTEM_TYPE ,
PS.CHECKSUM_PROC_STATUS ,
:B3 ,
TV.DT_LOAD ,
SEQ_AND_CHECKSUM.SEQ_PROC_STATUS
FROM TPS_STG$OWNER.OTC_DAT_TV_PROC_STATUS PS
JOIN
(SELECT PS.CHECKSUM_PROC_STATUS,
PS.SEQ_TRADE,
MAX (PS.SEQ_PROC_STATUS) SEQ_PROC_STATUS
FROM TPS_STG$OWNER.OTC_DAT_TV_PROC_STATUS PS
WHERE PS.PARTITION_ID = :B2
AND PS.TRADESET_ID = :B1
GROUP BY CHECKSUM_PROC_STATUS,
PS.SEQ_TRADE
) SEQ_AND_CHECKSUM
ON SEQ_AND_CHECKSUM.SEQ_PROC_STATUS = PS.SEQ_PROC_STATUS
JOIN REF_DAT_STATUS_TYPOLOGY PST
ON PST.STATUS_TYPE = PS.STATUS_TYPE
AND PST.STATUS_SUB_TYPE = PS.STATUS_SUB_TYPE
AND PST.STATUS_SUB_TYPE_CODING_SCHEME = 'NA'
JOIN REF_DAT_STATUS_DURATION PSD
ON PSD.DURATION_CODE = PS.STATUS_DURATION_CODE
AND PSD.DURATION_COD_SCHEME = PS.STATUS_DURATION_COD_SCH
JOIN TPS_STG$OWNER.OTC_DAT_TRADE_VERSION STG
ON STG.PARTITION_ID = PS.PARTITION_ID
AND STG.TRADESET_ID = PS.TRADESET_ID
AND STG.SEQ_TRADE = PS.SEQ_TRADE
JOIN OTC_DAT_TRADE_VERSION TV
ON TV.ID = STG.ID
AND TV.CHECKSUM_TRADE_VERSION = STG.CHECKSUM_TRADE_VERSION
WHERE PS.PARTITION_ID = :B2
AND PS.TRADESET_ID = :B1 ;
-- ASH analysis
select sql_plan_line_id,sql_plan_operation, count(*) from DBA_HIST_active_sess_history ash
where sample_time > to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')
AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')
and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425
group by sql_plan_line_id,sql_plan_operation
order by 3 desc;
SQL_PLAN_LINE_ID SQL_PLAN_OPERATION COUNT(*)
---------------- ---------------------------------------------------------------- ----------
1 LOAD TABLE CONVENTIONAL 2277 => PB is due to the INSERT part
5 HASH JOIN 272
39 TABLE ACCESS 62
2 SEQUENCE 60
15 HASH JOIN 52
29
INSERT STATEMENT 27
7 PX SEND 21
21 TABLE ACCESS 20
3 PX COORDINATOR 18
6 PX RECEIVE 15
4 PX SEND 14
10 PX SEND 12
8 HASH JOIN 9
37 TABLE ACCESS 8
12 PX RECEIVE 7
13 PX SEND 7
14 HASH JOIN 3
19 SORT 2
38 PX BLOCK 2
17 PX SEND 2
14 PX SEND 1
26 TABLE ACCESS 1
9 PX RECEIVE 1
12 HASH JOIN 1
16 PX RECEIVE 1
The same query ran in less than a hour the night before and this time the ASH analysis shows that the time has been spent in the SELECT part:
SQL_PLAN_LINE_ID SQL_PLAN_OPERATION COUNT(*)
---------------- ---------------------------------------------------------------- ----------
15 HASH JOIN 1281
21 TABLE ACCESS 500
1 LOAD TABLE CONVENTIONAL 328
2 SEQUENCE 4
2
3 PX COORDINATOR 1
When the problem occurs I have noticed that the CURRENT_OBJ# = 0 or -1:
select current_obj#, count(*) from DBA_HIST_active_sess_history ash
where sample_time > to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')
AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')
and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425
group by current_obj#
order by 2 desc;
CURRENT_OBJ# COUNT(*)
------------ ----------
0 659
-1 625
5309346 46
5309335 46
I have also noticed that the p1TEXT is mainly on "cache id" and "cellhash" when sql_plan_operation='LOAD TABLE CONVENTIONAL' and CURRENT_OBJ#<1:
SQL> select p1text,count(*) from DBA_HIST_active_sess_history ash
2 where sample_time > to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')
3 AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')
4 and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425 and sql_plan_operation='LOAD TABLE CONVENTIONAL' and CURRENT_OBJ#<1
5 group by p1text
6 order by 2 desc;
P1TEXT COUNT(*)
---------------------------------------------------------------- ----------
cache id 526
cellhash# 340
sleeptime/senderid 159
address 52
handle address 30
file# 28
name|mode 23
idn 2
SQL> select p1,p2,p3,count(*) from DBA_HIST_active_sess_history ash
2 where sample_time > to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')
3 AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')
4 and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425 and sql_plan_operation='LOAD TABLE CONVENTIONAL'
5 group by p1,p2,p3
6 order by 4 desc;
P1 P2 P3 COUNT(*)
---------- ---------- ---------- ----------
13 0 5 723
0 0 0 228
4215650800 1532286858 8192 31
1397817350 5308686 0 31
2973322368 5435300368 2.2801E+16 21
1610823616 299 0 21
1 1295744 33554433 19
3391883262 1935226483 8192 18
3701283688 3717488454 8192 18
2480893931 247570295 8192 17
3391883262 1702723751 8192 17
3391883262 1723529083 8192 17
2480893931 1427725789 8192 17
2106104525 3532961050 8192 17
6.4459E+10 115 0 16
4215650800 3591178946 8192 16
1 1295744 1 16
2774995862 2268391603 8192 16
2774995862 1767183701 8192 16
2973322368 6.5671E+10 2.2801E+16 15
2774995862 2333714537 8192 15
The table is partitioned by MONTH (DT_LOAD column) and there is 3 indexes on it. There is no TRIGGER.
===================================================================================================================================
TABLE STATISTICS
===================================================================================================================================
Owner : tps_dwh$owner
Table name : otc_dat_tv_proc_status
Tablespace :
Cluster name :
Partitioned : yes
Last analyzed : 02/01/2017 13:59:28
Sample size : 849474791
Degree : 1
IOT Type :
IOT name :
# Rows : 849474791
# Blocks : 1243278
Empty Blocks : 0
Avg Space : 0
Avg Row Length: 66
Monitoring? : yes
Elapsed: 00:00:00.04
===================================================================================================================================
PARTITION INFORMATION
===================================================================================================================================
Elapsed: 00:00:00.02
Part# Partition Name Sample Size # Rows # Blocks Partition Bound Last Analyzed
------ ------------------------------ --------------- --------------- --------------- ------------------------------------------------------------------------------------------------------------------------ -------------------
1 PMINI . 0 0 TIMESTAMP' 1900-01-01 00:00:00' 09/22/2016 19:31:39
2 SYS_P778163 1504467 1504467 1704 TIMESTAMP' 2015-04-01 00:00:00' 09/22/2016 19:34:25
3 SYS_P787248 7018114 7018114 7448 TIMESTAMP' 2015-05-01 00:00:00' 09/22/2016 19:34:27
4 SYS_P843336 22057768 22057768 22144 TIMESTAMP' 2015-06-01 00:00:00' 09/22/2016 19:34:33
5 SYS_P910767 31032596 31032596 28608 TIMESTAMP' 2015-07-01 00:00:00' 09/22/2016 19:34:40
6 SYS_P987062 38605939 38605939 35120 TIMESTAMP' 2015-08-01 00:00:00' 09/22/2016 19:34:49
7 SYS_P1055366 36682048 36682048 35312 TIMESTAMP' 2015-09-01 00:00:00' 09/22/2016 19:31:49
8 SYS_P1120003 34947472 34947472 35392 TIMESTAMP' 2015-10-01 00:00:00' 09/22/2016 19:31:59
9 SYS_P1186673 39591670 39591670 39208 TIMESTAMP' 2015-11-01 00:00:00' 09/22/2016 19:32:10
10 SYS_P1265684 32391927 32391927 29456 TIMESTAMP' 2015-12-01 00:00:00' 09/22/2016 19:32:19
11 SYS_P1340470 34716827 34716827 32608 TIMESTAMP' 2016-01-01 00:00:00' 09/22/2016 19:32:31
12 SYS_P1388682 39997458 39997458 40056 TIMESTAMP' 2016-02-01 00:00:00' 09/22/2016 19:32:42
13 SYS_P1433080 40138343 40138343 39488 TIMESTAMP' 2016-03-01 00:00:00' 09/22/2016 19:32:53
14 SYS_P1480473 42412720 42412720 41248 TIMESTAMP' 2016-04-01 00:00:00' 09/22/2016 19:33:05
15 SYS_P1531264 41607977 41607977 40736 TIMESTAMP' 2016-05-01 00:00:00' 09/22/2016 19:33:16
16 SYS_P1574276 40811459 40811459 40080 TIMESTAMP' 2016-06-01 00:00:00' 09/22/2016 19:33:27
17 SYS_P1619633 42935485 42935485 42408 TIMESTAMP' 2016-07-01 00:00:00' 09/22/2016 19:33:39
18 SYS_P1665727 41300996 41300996 41128 TIMESTAMP' 2016-08-01 00:00:00' 09/22/2016 19:33:58
19 SYS_P1715065 46290708 46290708 45616 TIMESTAMP' 2016-09-01 00:00:00' 09/22/2016 19:34:12
20 SYS_P1765027 44209306 44209306 44864 TIMESTAMP' 2016-10-01 00:00:00' 10/16/2016 08:37:33
21 SYS_P1814453 46319442 46319442 49400 TIMESTAMP' 2016-11-01 00:00:00' 11/06/2016 06:09:20
22 SYS_P1884838 46782453 46782453 48160 TIMESTAMP' 2016-12-01 00:00:00' 12/04/2016 07:08:23
23 SYS_P1941375 49778327 49778327 50208 TIMESTAMP' 2017-01-01 00:00:00' 01/01/2017 05:40:21
24 SYS_P1987976 47734893 47734893 447344 TIMESTAMP' 2017-02-01 00:00:00' 02/01/2017 14:00:53
25 SYS_P2033672 41766799 41766799 388521 TIMESTAMP' 2017-03-01 00:00:00' 02/28/2017 14:03:32
26 SYS_P2073160 . . . TIMESTAMP' 2017-04-01 00:00:00' .
Elapsed: 00:00:00.16
===================================================================================================================================
COLUMN STATISTICS
===================================================================================================================================
Name Analyzed Null? NDV Density # Nulls # Buckets Sample AvgLen Lo-Hi Values
===================================================================================================================================
checksum_proc_status 02/01/2017 13:56:09 N 166166528 .000000 0 1 849474791 7 3 | 4294967230
clearing_party_id 02/01/2017 13:56:09 Y 0 .000000 849474791 0 0 |
clearing_party_id_sch 02/01/2017 13:56:09 Y 0 .000000 849474791 0 0 |
clearing_system_type 02/01/2017 13:56:09 Y 2 .000003 849317707 2 6920 2 CCILMUM | MKS
dt_load 02/01/2017 13:56:09 N 719744 .000001 0 1 849474791 11 UNKNOWN DATATYPE
dt_load_trade_version 02/01/2017 13:56:09 N 719744 .000001 0 1 849474791 11 UNKNOWN DATATYPE
seq_proc_status 02/01/2017 13:56:09 N 325681152 .000001 0 254 20984 6 -1 | 1418836207
sk_status_duration 02/01/2017 13:56:09 N 1 .000000 0 1 20984 3 1 | 1
sk_status_typo 02/01/2017 13:56:09 N 79 .000000 0 36 20985 4 1 | 1221
sk_trade_status 02/01/2017 13:56:09 N 849474791 .000000 0 1 849474791 7 1 | 1675688151
sk_trade_version 02/01/2017 13:56:09 N 805240832 .000000 0 1 849474791 7 1 | 1556212297
status_end_timestamp 02/01/2017 13:56:09 Y 0 .000000 849474791 0 1 UNKNOWN DATATYPE
status_media_type 02/01/2017 13:56:09 Y 19780 .000226 849349200 254 5467 2 00000101 | 00713502
status_receiver_party_id 02/01/2017 13:56:09 Y 1 .000004 849349200 1 5467 2 Party | Party
status_receiver_party_id_sch 02/01/2017 13:56:09 Y 2 .000004 849349200 2 5468 2 0.000000000000000 | 0.959500000000000
status_sender_party_id 02/01/2017 13:56:09 Y 1 .000004 849349200 1 5467 2 PTS | PTS
status_sender_party_id_sc 02/01/2017 13:56:09 Y 1 .000004 849349200 1 5467 2 Other | Other
status_start_timestamp 02/01/2017 13:56:09 Y 478 .002208 849447077 254 5542 2 UNKNOWN DATATYPE
status_timestamp 02/01/2017 13:56:09 Y 8451072 .000002 723473206 254 8833 3 UNKNOWN DATATYPE
Index Name BLevel Leaf Blks # Rows Distinct Keys Avg Lf/Blks/Key Avg Dt/Blks/Key Clustering Factor Sample Size Uniq? Type Status Deg Part? Vis? Last Analyzed
------------------------------ ------- --------------- --------------- --------------- --------------- --------------- ----------------- --------------- ----- -------- -------- --- ----- ---- -------------------
OTC_DAT_TV_PROC_STATUS_IX1 2 23018 726577 719744 1 1 726577 36459 NO BITM N/A 1 YES . 02/01/2017 14:00:38
OTC_DAT_TV_PROC_STATUS_PK 2 2532878 845757696 845757696 1 1 187638614 374315 YES NORM N/A 1 YES . 02/01/2017 14:00:04
OTC_DAT_TV_PROC_STATUS_UK 2 3580793 853618729 853618729 1 1 275078004 270809 YES NORM N/A 1 YES . 02/01/2017 14:00:32
Elapsed: 00:00:00.04
Index Name Pos# Order Column Name
------------------------------ ---------- ----- ------------------------------
otc_dat_tv_proc_status_ix1 1 ASC dt_load
OTC_DAT_TV_PROC_STATUS_PK 1 ASC sk_trade_status
otc_dat_tv_proc_status_uk 1 ASC sk_trade_version
2 ASC checksum_proc_status