Re: Increased runtime and 4 xids for one insert

This is a good indicator that the big DML stopped (holding on to all the extents from the one it started in to the current) while it rolled back a massive transaction.

Brief approximation mental arithmetic (maybe losing my place on the scrolldown) that looks like about 180M undo records applied, on the first big one, which I would think means something in the order of 30M rows rolled back if you've got 5 indexes on the table.

Regards
Jonathan Lewis

On Wed, 10 Apr 2024 at 18:01, Petr Novak <novak_petr_at_yahoo.de> wrote:

> Hallo Jonathan,
>
> interval withs high values for 'rollback changes - undo records applied'
> match the hours with constant number of active extents in
> dba_hist_undostat, before next transaction is started.
>
>
> Interval Statistics 'rollback changes - undo records applied'
>
> End Inst Value Value/s
> ----------- ----- ---------------- ----------
> 05.04 19:45 1 73 .1
> 05.04 20:00 1 22 .0
> 05.04 20:15 1 35 .0
> 05.04 20:30 1 82 .1
> 05.04 20:45 1 40 .0
> 05.04 21:00 1 16 .0
> 05.04 21:15 1 15 .0
> 05.04 21:30 1 28 .0
> 05.04 21:45 1 6 .0
> 05.04 22:00 1 14 .0
> 05.04 22:15 1 16 .0
> 05.04 22:30 1 24 .0
> 05.04 22:45 1 4 .0
> 05.04 23:00 1 11 .0
> 05.04 23:15 1 22 .0
> 05.04 23:30 1 9 .0
> 05.04 23:45 1 17 .0
> 06.04 00:00 1 7 .0
> 06.04 00:15 1 8 .0
> 06.04 00:30 1 4 .0
> 06.04 00:45 1 10 .0
> 06.04 01:00 1 6 .0
> 06.04 01:15 1 9 .0
> 06.04 01:30 1 7 .0
> 06.04 01:45 1 8 .0
> 06.04 02:00 1 7 .0
> 06.04 02:15 1 9 .0
> 06.04 02:30 1 6 .0
> 06.04 02:45 1 8 .0
> 06.04 03:00 1 7 .0
> 06.04 03:15 1 8 .0
> 06.04 03:30 1 6 .0
> 06.04 03:45 1 8 .0
> 06.04 04:00 1 10 .0
> 06.04 04:15 1 6 .0
> 06.04 04:30 1 2 .0
> 06.04 04:45 1 2,218,406 2,625.3
> 06.04 05:00 1 6,958,902 7,689.4
> 06.04 05:15 1 6,990,704 7,716.0
> 06.04 05:30 1 7,338,606 8,109.0
> 06.04 05:45 1 7,150,708 7,901.3
> 06.04 06:00 1 7,024,902 7,762.3
> 06.04 06:15 1 7,185,502 7,939.8
> 06.04 06:30 1 7,414,104 8,192.4
> 06.04 06:45 1 7,438,808 8,228.8
> 06.04 07:00 1 7,415,404 8,193.8
> 06.04 07:15 1 7,344,408 8,106.4
> 06.04 07:31 1 6,400,908 7,072.8
> 06.04 07:45 1 6,573,408 7,788.4
> 06.04 08:00 1 7,015,812 7,752.3
> 06.04 08:15 1 6,907,406 7,624.1
> 06.04 08:30 1 6,963,906 7,694.9
> 06.04 08:45 1 6,705,704 7,409.6
> 06.04 09:00 1 5,471,208 6,045.5
> 06.04 09:15 1 5,359,306 5,921.9
> 06.04 09:30 1 5,129,406 5,667.9
> 06.04 09:45 1 5,036,006 5,564.6
> 06.04 10:00 1 5,120,408 5,657.9
> 06.04 10:15 1 5,117,269 5,654.4
> 06.04 10:30 1 4,607,351 5,452.5
> 06.04 10:45 1 5,268,032 5,821.0
> 06.04 11:00 1 4,866,578 5,377.4
> 06.04 11:15 1 5,075,904 5,608.7
> 06.04 11:30 1 4,983,209 5,506.3
> 06.04 11:45 1 4,924,707 5,441.7
> 06.04 12:00 1 4,512,007 4,985.6
> 06.04 12:15 1 4,541,708 5,018.5
> 06.04 12:30 1 4,876,410 5,388.3
> 06.04 12:45 1 4,697,808 5,190.9
> 06.04 13:00 1 4,511,124 4,984.7
> 06.04 13:15 1 4,725,896 5,222.0
> 06.04 13:31 1 4,944,108 5,463.1
> 06.04 13:45 1 4,708,510 5,578.8
> 06.04 14:00 1 4,945,790 5,465.0
> 06.04 14:15 1 1,257,286 1,389.3
> 06.04 14:30 1 8 .0
> 06.04 14:45 1 8 .0
> 06.04 15:00 1 4 .0
> 06.04 15:15 1 8 .0
> 06.04 15:30 1 20 .0
> 06.04 15:45 1 2 .0
> 06.04 16:00 1 6 .0
> 06.04 16:15 1 13 .0
> 06.04 16:31 1 8 .0
> 06.04 16:45 1 8 .0
> 06.04 17:00 1 2 .0
> 06.04 17:15 1 10 .0
> 06.04 17:30 1 10 .0
> 06.04 17:45 1 6 .0
> 06.04 18:00 1 9 .0
> 06.04 18:15 1 10 .0
> 06.04 18:30 1 9 .0
> 06.04 18:45 1 7 .0
> 06.04 19:00 1 7 .0
> 06.04 19:15 1 8 .0
> 06.04 19:31 1 7 .0
> 06.04 19:45 1 8 .0
> 06.04 20:04 1 4 .0
> 06.04 20:15 1 4 .0
> 06.04 20:30 1 2 .0
> 06.04 20:45 1 2 .0
> 06.04 21:15 1 1 .0
> 06.04 22:45 1 2 .0
> 06.04 23:00 1 11 .0
> 06.04 23:30 1 1 .0
> 07.04 00:00 1 2 .0
> 07.04 00:15 1 4 .0
> 07.04 01:15 1 6 .0
> 07.04 02:00 1 3 .0
> 07.04 02:15 1 421 .5
> 07.04 02:30 1 8 .0
> 07.04 03:00 1 4 .0
> 07.04 03:15 1 4 .0
> 07.04 04:00 1 195,214 202.3
> 07.04 04:15 1 3,670,600 4,349.1
> 07.04 04:30 1 4,332,100 4,792.1
> 07.04 04:45 1 4,607,200 5,090.8
> 07.04 05:00 1 4,568,200 5,053.3
>
> End Inst Value Value/s
> ----------- ----- ---------------- ----------
> 07.04 05:15 1 4,564,302 5,043.4
> 07.04 05:30 1 4,410,600 4,879.0
> 07.04 05:45 1 4,271,900 4,720.3
> 07.04 06:00 1 4,502,200 4,980.3
> 07.04 06:15 1 3,921,002 4,332.6
> 07.04 06:30 1 4,330,000 4,789.8
> 07.04 06:45 1 4,507,100 4,980.2
> 07.04 07:00 1 4,390,702 4,857.0
> 07.04 07:15 1 4,338,400 4,793.8
> 07.04 07:30 1 4,034,000 4,779.6
> 07.04 07:45 1 4,381,100 4,846.3
> 07.04 08:00 1 3,822,102 4,223.3
> 07.04 08:15 1 3,503,801 3,875.9
> 07.04 08:30 1 3,724,600 4,115.6
> 07.04 08:45 1 3,871,502 4,277.9
> 07.04 09:00 1 3,611,702 3,995.2
> 07.04 09:15 1 3,579,505 3,959.6
> 07.04 09:30 1 3,262,200 3,604.6
> 07.04 09:45 1 3,654,500 4,038.1
> 07.04 10:00 1 3,863,200 4,273.5
> 07.04 10:15 1 3,378,601 3,733.3
> 07.04 10:30 1 3,868,202 4,279.0
> 07.04 10:46 1 3,337,000 3,687.3
> 07.04 11:00 1 3,684,800 4,365.9
> 07.04 11:15 1 3,975,043 4,397.2
> 07.04 11:30 1 3,829,559 4,231.6
> 07.04 11:45 1 3,924,800 4,341.6
> 07.04 12:00 1 3,885,900 4,293.8
> 07.04 12:15 1 3,411,900 3,774.2
> 07.04 12:30 1 3,114,585 3,441.5
> 07.04 12:45 1 3,616,816 4,000.9
> 07.04 13:00 1 3,393,306 3,749.5
> 07.04 13:15 1 3,344,603 3,699.8
> 07.04 13:30 1 3,174,900 3,508.2
> 07.04 13:45 1 3,297,500 3,647.7
> 07.04 14:00 1 3,192,600 3,527.7
> 07.04 14:15 1 3,021,300 3,579.7
> 07.04 14:30 1 3,182,804 3,516.9
> 07.04 14:45 1 3,102,301 3,431.7
> 07.04 15:00 1 3,111,403 3,438.0
> 07.04 15:15 1 3,029,205 3,350.9
> 07.04 15:30 1 3,087,301 3,411.4
> 07.04 15:45 1 2,922,001 3,232.3
> 07.04 16:00 1 3,048,900 3,369.0
> 07.04 16:15 1 3,062,402 3,387.6
> 07.04 16:30 1 3,070,102 3,392.4
> 07.04 16:45 1 3,142,200 3,475.9
> 07.04 17:00 1 3,121,998 3,449.7
> 07.04 17:15 1 2,896,721 3,204.3
> 07.04 17:30 1 2,862,600 3,391.7
> 07.04 17:45 1 3,074,000 3,396.7
> 07.04 18:00 1 3,132,500 3,465.2
> 07.04 18:15 1 2,916,100 3,222.2
> 07.04 18:30 1 2,953,200 3,266.8
> 07.04 18:45 1 3,110,201 3,436.7
> 07.04 19:00 1 3,065,113 3,390.6
> 07.04 19:15 1 2,971,300 3,283.2
> 07.04 19:30 1 3,020,000 3,340.7
> 07.04 19:45 1 2,991,802 3,305.9
> 07.04 20:00 1 3,062,200 3,387.4
> 07.04 20:15 1 2,895,200 3,199.1
> 07.04 20:30 1 3,001,501 3,320.2
> 07.04 20:45 1 2,962,104 3,273.0
> 07.04 21:00 1 2,864,900 3,394.4
> 07.04 21:15 1 2,989,400 3,306.9
> 07.04 21:30 1 3,008,602 3,324.4
> 07.04 21:45 1 3,004,242 3,323.3
> 07.04 22:00 1 3,051,260 3,371.6
> 07.04 22:15 1 2,986,002 3,303.1
> 07.04 22:30 1 2,964,167 3,275.3
> 07.04 22:45 1 3,034,537 3,356.8
> 07.04 23:00 1 2,989,110 3,302.9
> 07.04 23:15 1 2,981,100 3,297.7
> 07.04 23:30 1 2,986,900 3,300.4
> 07.04 23:45 1 3,049,202 3,373.0
> 08.04 00:00 1 3,091,102 3,415.6
> 08.04 00:15 1 2,878,600 3,410.7
> 08.04 00:30 1 3,184,900 3,523.1
> 08.04 00:45 1 3,002,000 3,317.1
> 08.04 01:00 1 1,949,320 2,156.3
> 08.04 01:15 1 9 .0
> 08.04 01:30 1 6 .0
> 08.04 01:45 1 8 .0
> 08.04 02:00 1 11 .0
> 08.04 02:15 1 153 .2
> 08.04 03:00 1 3 .0
> 08.04 03:15 1 7 .0
> 08.04 03:30 1 17 .0
> 08.04 03:45 1 3 .0
> 08.04 04:00 1 7 .0
> 08.04 04:15 1 5,928,863 6,551.2
> 08.04 04:30 1 6,721,439 7,435.2
> 08.04 04:45 1 7,076,334 7,819.2
> 08.04 05:00 1 7,006,866 7,751.0
> 08.04 05:15 1 7,002,000 7,737.0
> 08.04 05:30 1 6,470,800 7,158.0
> 08.04 05:45 1 6,389,800 7,060.6
> 08.04 06:00 1 6,692,740 7,403.5
> 08.04 06:15 1 6,656,860 7,355.6
> 08.04 06:30 1 6,723,509 7,437.5
> 08.04 06:45 1 6,712,105 7,416.7
> 08.04 07:00 1 6,206,500 7,353.7
> 08.04 07:15 1 6,573,718 7,271.8
> 08.04 07:30 1 6,558,991 7,247.5
> 08.04 07:45 1 6,854,249 7,582.1
> 08.04 08:00 1 6,671,014 7,371.3
> 08.04 08:15 1 6,734,710 7,441.7
> 08.04 08:30 1 6,563,427 7,260.4
> 08.04 08:45 1 6,725,297 7,439.5
> 08.04 09:00 1 6,231,328 6,885.4
> 08.04 09:15 1 6,341,922 7,015.4
> 08.04 09:30 1 6,341,311 7,007.0
> 08.04 09:45 1 6,394,913 7,074.0
> 08.04 10:00 1 6,250,222 6,906.3
> 08.04 10:15 1 5,895,417 6,985.1
> 08.04 10:30 1 6,189,414 6,839.1
> 08.04 10:45 1 5,183,212 5,733.6
> 08.04 11:00 1 6,169,718 6,817.4
> 08.04 11:15 1 6,294,760 6,963.2
> 08.04 11:30 1 6,024,993 6,657.5
> 08.04 11:45 1 6,132,519 6,783.8
> 08.04 12:00 1 6,074,324 6,712.0
> 08.04 12:15 1 6,275,015 6,941.4
> 08.04 12:30 1 6,227,816 6,889.2
> 08.04 12:45 1 5,948,016 6,572.4
> 08.04 13:00 1 5,556,545 6,146.6
> 08.04 13:15 1 3,945,117 4,359.2
> 08.04 13:30 1 3,241,614 3,581.9
> 08.04 13:45 1 2,693,770 3,191.7
> 08.04 14:00 1 23 .0
> 08.04 14:15 1 21 .0
> 08.04 14:30 1 17 .0
> 08.04 14:45 1 15 .0
> 08.04 15:00 1 19 .0
> 08.04 15:15 1 16 .0
> 08.04 15:30 1 27 .0
> 08.04 15:45 1 25 .0
> 08.04 16:00 1 19 .0
> 08.04 16:15 1 17 .0
> 08.04 16:30 1 21 .0
> 08.04 16:45 1 21 .0
> 08.04 17:00 1 20 .0
> 08.04 17:15 1 21 .0
> 08.04 17:30 1 17 .0
> 08.04 17:45 1 21 .0
> 08.04 18:00 1 16 .0
> 08.04 18:15 1 14 .0
> 08.04 18:30 1 13 .0
> 08.04 18:45 1 14 .0
> 08.04 19:00 1 27 .0
> 08.04 19:15 1 15 .0
> 08.04 19:30 1 12 .0
> 08.04 19:45 1 18 .0
> 08.04 20:00 1 12 .0
> 08.04 20:16 1 13 .0
> 08.04 20:30 1 12 .0
> 08.04 20:45 1 18 .0
> 08.04 21:00 1 18 .0
>
>
>
> Best Regards,
> Petr
>
> Am Mittwoch, 10. April 2024 um 18:33:54 MESZ hat Jonathan Lewis <
> jlewisoracle_at_gmail.com> Folgendes geschrieben:
>
>
>
> One further point, since you've probably got AWR reports over the period
> you could look at the Instance Activity stats. (Ideally a special task like
> this might capture the change in v$session_event, v$sess_time_model and
> v$sesstat for the session). Check for the statistics for "% - undo records
> applied". This can give you some clues about why the UNDO was being
> accessed
>
> transaction tables consistent reads - undo records applied
> data blocks consistent reads - undo records applied
> rollback changes - undo records applied
>
> If you're restarting the the last one will show a large number. If you're
> dealing with competing transactions on the same table (or its indexes) the
> second will show large numbers, if you're trying to check whether "recent"
> changes from other session committed before or after your transaction
> started the first will show large numbers.
>
> 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