Re: Increased runtime and 4 xids for one insert

Petr,

There are some circumstances when a DML statement will rollback and restart automatically.

One of the reasons for for something that Tom Kyte referred to as "write consistency" but I think that was only likely to be relevant for updates or deletes where session A doing a long running DML would find that session B had modified a row that session A was supposed to update; this would result in session A rolling back its statement and restarting it at a new SCN so that it could do the right thing with the new version of the row that session B has modified. Since you're doing an insert this may be irrelevant.

Another reason is an odd feature of undo segment extension, I've got an article talking about this, with links in the first comment from Mikhail Velikikh going into the problem in more detail. It's ion the context of updates again, but I think it applies to all DML. https://jonathanlewis.wordpress.com/2019/09/10/update-restarts/

In some older version of Oracle I've seen this behaviour manage to restart an operation more than once - which may be why you see 4 transaction IDs and a lot of Undo activity.

Regards
Jonathan Lewis

On Wed, 10 Apr 2024 at 13:35, Petr Novak <dmarc-noreply_at_freelists.org> wrote:

> 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:15
> 2E00180051D62200 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:03
> 20001C0008633B00 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:23
> 15001100CD95C100 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:00
> 03001200F4F1B600 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:44
> 03001200F4F1B600 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 since
> last_call_et. TX start was one of these SQL_EXEC_STARTs
> In 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_id
> and 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 32746
> RB_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
>
>

--
http://www.freelists.org/webpage/oracle-l