Increased runtime and 4 xids for one insert

  • From: "Petr Novak" <dmarc-noreply@xxxxxxxxxxxxx> ("novak_petr")
  • To: Oracle List <oracle-l@xxxxxxxxxxxxx>
  • Date: Wed, 10 Apr 2024 12:34:39 +0000 (UTC)

Hallo,
there is problem with increasing execution time of simple Insert 
statement.(insert into T_TARGET select * from T_SOURCE)Execution time increased 
overproportionally to increased number of rows.11 millions rows  took 3,5 hours 
 , 38 million rows 3 days.T_TARGET is 1,5 TB range partitioned table , 1469 
partitions and 5 local indexes (same partitioned key as the table).
for shorter execution time there was one XID, but for long execution time 4 
XIDs  ??
select xid, SQL_EXEC_START,SESSION_ID,SESSION_SERIAL#,count(*) 
,to_char(min(sample_time),'dd.mm hh24:mi:ss') 
mint,to_char(max(sample_time),'dd.mm hh24:mi:ss') maxt from  
dba_hist_active_sess_history where sql_id='fdq9c3q9jfavc' and 
sample_time>to_date('2404052000','yymmddhh24mi') and sample_time< 
to_date('2404082100','yymmddhh24mi')group by 
xid,SQL_EXEC_START,SESSION_ID,SESSION_SERIAL# order by 
SQL_EXEC_START,min(sample_time);
XID              SQL_EXEC_START          SESSION_ID SESSION_SERIAL#       
COUNT(*) Min(IntervalEnd)     Max(IntervalEnd)---------------- 
------------------- -------------- --------------- -------------- 
-------------------- --------------------                 05.04.2024 20:13:40   
        1141           11657              8 05.04 20:13:44       05.04 
20:14:152E00180051D62200 05.04.2024 20:13:40           1141           11657     
     12532 05.04 20:14:25       06.04 14:04:03                 05.04.2024 
20:13:40           1064           35873             12 05.04 20:39:31       
06.04 01:42:10                 05.04.2024 20:13:40           1016           
54350              8 05.04 20:49:35       05.04 22:16:08                 
05.04.2024 20:13:40           1103            5986             16 05.04 
21:00:10       06.04 02:49:36                 05.04.2024 20:13:40            
986           61332              6 05.04 21:34:39       06.04 
04:26:0320001C0008633B00 06.04.2024 14:04:10           1141           11657     
     24486 06.04 14:04:13       08.04 00:55:20                 06.04.2024 
14:04:10           1057           63794              6 06.04 14:08:29       
07.04 01:10:29                 06.04.2024 14:04:10           1026           
41466              8 06.04 14:21:17       06.04 23:58:37                 
06.04.2024 14:04:10           1103           51053             16 06.04 
14:36:49       06.04 22:38:2315001100CD95C100 08.04.2024 00:55:22           
1141           11657           8986 08.04 00:55:31       08.04 13:42:29         
        08.04.2024 00:55:22           1026            1396              8 08.04 
00:59:06       08.04 03:59:52                 08.04.2024 00:55:22           
1104           28322              8 08.04 01:05:14       08.04 02:51:25         
        08.04.2024 00:55:22           1005           29042              8 08.04 
01:21:07       08.04 03:53:02                 08.04.2024 00:55:22           
1075           54721              4 08.04 02:05:30       08.04 
02:20:0003001200F4F1B600 08.04.2024 13:42:30           1141           11657     
      4178 08.04 13:42:39       08.04 19:39:05                 08.04.2024 
13:42:30            325           35023             10 08.04 13:48:48       
08.04 16:16:38                 08.04.2024 13:42:30            296            
7915              2 08.04 14:30:27       08.04 14:30:27                 
08.04.2024 13:42:30            369           46540              4 08.04 
14:55:12       08.04 16:05:22                 08.04.2024 13:42:30            
395           14967              8 08.04 15:38:13       08.04 
18:20:4403001200F4F1B600                               1141           11657     
        16 08.04 19:39:15       08.04 19:40:27

In dba_hist_undostat are same 4 execution start times for this query 
(maxquerylen,maxquerysqlid). During the execution I checked the 
transaction_start and last_call_et in the session 1141 and it loooked like TX 
started hours later sincelast_call_et. TX start was one of these 
SQL_EXEC_STARTsIn dba_hist_sqlstat only one execution is shown, most time was 
spend with CPU.
most ASH samples are related to UNDO TS.
select tablespace_name,count(*) from  dba_hist_active_sess_history 
,dba_data_files where sql_id='fdq9c3q9jfavc' and CURRENT_FILE#=file_idand 
sample_time>to_date('2404052000','yymmddhh24mi') and sample_time< 
to_date('2404082100','yymmddhh24mi')group by tablespace_name order by count(*) 
desc;
TABLESPACE_NAME                      COUNT(*)------------------------------ 
--------------UNDOTBS1                                32746RB_STAGING_TAB       
                   17576
There are also some intervals with increased commit times (2->100ms) , but for 
me it looks like another issue.
I have two main questions :- how it is possible to have for one execution 4 
XIDs ?- where the statements spends the time ?
Any ideas ?
Best Regards,Petr

Other related posts: