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 .105.04 20:00 1
22 .005.04 20:15 1 35 .005.04 20:30
1 82 .105.04 20:45 1 40
.005.04 21:00 1 16 .005.04 21:15 1
15 .005.04 21:30 1 28 .005.04 21:45 1
6 .005.04 22:00 1 14 .005.04 22:15
1 16 .005.04 22:30 1 24
.005.04 22:45 1 4 .005.04 23:00 1
11 .005.04 23:15 1 22 .005.04 23:30 1
9 .005.04 23:45 1 17 .006.04 00:00
1 7 .006.04 00:15 1 8
.006.04 00:30 1 4 .006.04 00:45 1
10 .006.04 01:00 1 6 .006.04 01:15 1
9 .006.04 01:30 1 7 .006.04 01:45
1 8 .006.04 02:00 1 7
.006.04 02:15 1 9 .006.04 02:30 1
6 .006.04 02:45 1 8 .006.04 03:00 1
7 .006.04 03:15 1 8 .006.04 03:30
1 6 .006.04 03:45 1 8
.006.04 04:00 1 10 .006.04 04:15 1
6 .006.04 04:30 1 2 .006.04 04:45 1
2,218,406 2,625.306.04 05:00 1 6,958,902 7,689.406.04 05:15
1 6,990,704 7,716.006.04 05:30 1 7,338,606
8,109.006.04 05:45 1 7,150,708 7,901.306.04 06:00 1
7,024,902 7,762.306.04 06:15 1 7,185,502 7,939.806.04 06:30
1 7,414,104 8,192.406.04 06:45 1 7,438,808
8,228.806.04 07:00 1 7,415,404 8,193.806.04 07:15 1
7,344,408 8,106.406.04 07:31 1 6,400,908 7,072.806.04 07:45
1 6,573,408 7,788.406.04 08:00 1 7,015,812
7,752.306.04 08:15 1 6,907,406 7,624.106.04 08:30 1
6,963,906 7,694.906.04 08:45 1 6,705,704 7,409.606.04 09:00
1 5,471,208 6,045.506.04 09:15 1 5,359,306
5,921.906.04 09:30 1 5,129,406 5,667.906.04 09:45 1
5,036,006 5,564.606.04 10:00 1 5,120,408 5,657.906.04 10:15
1 5,117,269 5,654.406.04 10:30 1 4,607,351
5,452.506.04 10:45 1 5,268,032 5,821.006.04 11:00 1
4,866,578 5,377.406.04 11:15 1 5,075,904 5,608.706.04 11:30
1 4,983,209 5,506.306.04 11:45 1 4,924,707
5,441.706.04 12:00 1 4,512,007 4,985.606.04 12:15 1
4,541,708 5,018.506.04 12:30 1 4,876,410 5,388.306.04 12:45
1 4,697,808 5,190.906.04 13:00 1 4,511,124
4,984.706.04 13:15 1 4,725,896 5,222.006.04 13:31 1
4,944,108 5,463.106.04 13:45 1 4,708,510 5,578.806.04 14:00
1 4,945,790 5,465.006.04 14:15 1 1,257,286
1,389.306.04 14:30 1 8 .006.04 14:45 1
8 .006.04 15:00 1 4 .006.04 15:15 1
8 .006.04 15:30 1 20 .006.04
15:45 1 2 .006.04 16:00 1 6
.006.04 16:15 1 13 .006.04 16:31 1
8 .006.04 16:45 1 8 .006.04 17:00 1
2 .006.04 17:15 1 10 .006.04
17:30 1 10 .006.04 17:45 1 6
.006.04 18:00 1 9 .006.04 18:15 1
10 .006.04 18:30 1 9 .006.04 18:45 1
7 .006.04 19:00 1 7 .006.04
19:15 1 8 .006.04 19:31 1 7
.006.04 19:45 1 8 .006.04 20:04 1
4 .006.04 20:15 1 4 .006.04 20:30 1
2 .006.04 20:45 1 2 .006.04
21:15 1 1 .006.04 22:45 1 2
.006.04 23:00 1 11 .006.04 23:30 1
1 .007.04 00:00 1 2 .007.04 00:15 1
4 .007.04 01:15 1 6 .007.04
02:00 1 3 .007.04 02:15 1 421
.507.04 02:30 1 8 .007.04 03:00 1
4 .007.04 03:15 1 4 .007.04 04:00 1
195,214 202.307.04 04:15 1 3,670,600 4,349.107.04
04:30 1 4,332,100 4,792.107.04 04:45 1 4,607,200
5,090.807.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.407.04 05:30 1
4,410,600 4,879.007.04 05:45 1 4,271,900 4,720.307.04 06:00
1 4,502,200 4,980.307.04 06:15 1 3,921,002
4,332.607.04 06:30 1 4,330,000 4,789.807.04 06:45 1
4,507,100 4,980.207.04 07:00 1 4,390,702 4,857.007.04 07:15
1 4,338,400 4,793.807.04 07:30 1 4,034,000
4,779.607.04 07:45 1 4,381,100 4,846.307.04 08:00 1
3,822,102 4,223.307.04 08:15 1 3,503,801 3,875.907.04 08:30
1 3,724,600 4,115.607.04 08:45 1 3,871,502
4,277.907.04 09:00 1 3,611,702 3,995.207.04 09:15 1
3,579,505 3,959.607.04 09:30 1 3,262,200 3,604.607.04 09:45
1 3,654,500 4,038.107.04 10:00 1 3,863,200
4,273.507.04 10:15 1 3,378,601 3,733.307.04 10:30 1
3,868,202 4,279.007.04 10:46 1 3,337,000 3,687.307.04 11:00
1 3,684,800 4,365.907.04 11:15 1 3,975,043
4,397.207.04 11:30 1 3,829,559 4,231.607.04 11:45 1
3,924,800 4,341.607.04 12:00 1 3,885,900 4,293.807.04 12:15
1 3,411,900 3,774.207.04 12:30 1 3,114,585
3,441.507.04 12:45 1 3,616,816 4,000.907.04 13:00 1
3,393,306 3,749.507.04 13:15 1 3,344,603 3,699.807.04 13:30
1 3,174,900 3,508.207.04 13:45 1 3,297,500
3,647.707.04 14:00 1 3,192,600 3,527.707.04 14:15 1
3,021,300 3,579.707.04 14:30 1 3,182,804 3,516.907.04 14:45
1 3,102,301 3,431.707.04 15:00 1 3,111,403
3,438.007.04 15:15 1 3,029,205 3,350.907.04 15:30 1
3,087,301 3,411.407.04 15:45 1 2,922,001 3,232.307.04 16:00
1 3,048,900 3,369.007.04 16:15 1 3,062,402
3,387.607.04 16:30 1 3,070,102 3,392.407.04 16:45 1
3,142,200 3,475.907.04 17:00 1 3,121,998 3,449.707.04 17:15
1 2,896,721 3,204.307.04 17:30 1 2,862,600
3,391.707.04 17:45 1 3,074,000 3,396.707.04 18:00 1
3,132,500 3,465.207.04 18:15 1 2,916,100 3,222.207.04 18:30
1 2,953,200 3,266.807.04 18:45 1 3,110,201
3,436.707.04 19:00 1 3,065,113 3,390.607.04 19:15 1
2,971,300 3,283.207.04 19:30 1 3,020,000 3,340.707.04 19:45
1 2,991,802 3,305.907.04 20:00 1 3,062,200
3,387.407.04 20:15 1 2,895,200 3,199.107.04 20:30 1
3,001,501 3,320.207.04 20:45 1 2,962,104 3,273.007.04 21:00
1 2,864,900 3,394.407.04 21:15 1 2,989,400
3,306.907.04 21:30 1 3,008,602 3,324.407.04 21:45 1
3,004,242 3,323.307.04 22:00 1 3,051,260 3,371.607.04 22:15
1 2,986,002 3,303.107.04 22:30 1 2,964,167
3,275.307.04 22:45 1 3,034,537 3,356.807.04 23:00 1
2,989,110 3,302.907.04 23:15 1 2,981,100 3,297.707.04 23:30
1 2,986,900 3,300.407.04 23:45 1 3,049,202
3,373.008.04 00:00 1 3,091,102 3,415.608.04 00:15 1
2,878,600 3,410.708.04 00:30 1 3,184,900 3,523.108.04 00:45
1 3,002,000 3,317.108.04 01:00 1 1,949,320
2,156.308.04 01:15 1 9 .008.04 01:30 1
6 .008.04 01:45 1 8 .008.04 02:00 1
11 .008.04 02:15 1 153 .208.04
03:00 1 3 .008.04 03:15 1 7
.008.04 03:30 1 17 .008.04 03:45 1
3 .008.04 04:00 1 7 .008.04 04:15 1
5,928,863 6,551.208.04 04:30 1 6,721,439 7,435.208.04
04:45 1 7,076,334 7,819.208.04 05:00 1 7,006,866
7,751.008.04 05:15 1 7,002,000 7,737.008.04 05:30 1
6,470,800 7,158.008.04 05:45 1 6,389,800 7,060.608.04 06:00
1 6,692,740 7,403.508.04 06:15 1 6,656,860
7,355.608.04 06:30 1 6,723,509 7,437.508.04 06:45 1
6,712,105 7,416.708.04 07:00 1 6,206,500 7,353.708.04 07:15
1 6,573,718 7,271.808.04 07:30 1 6,558,991
7,247.508.04 07:45 1 6,854,249 7,582.108.04 08:00 1
6,671,014 7,371.308.04 08:15 1 6,734,710 7,441.708.04 08:30
1 6,563,427 7,260.408.04 08:45 1 6,725,297
7,439.508.04 09:00 1 6,231,328 6,885.408.04 09:15 1
6,341,922 7,015.408.04 09:30 1 6,341,311 7,007.008.04 09:45
1 6,394,913 7,074.008.04 10:00 1 6,250,222
6,906.308.04 10:15 1 5,895,417 6,985.108.04 10:30 1
6,189,414 6,839.108.04 10:45 1 5,183,212 5,733.608.04 11:00
1 6,169,718 6,817.408.04 11:15 1 6,294,760
6,963.208.04 11:30 1 6,024,993 6,657.508.04 11:45 1
6,132,519 6,783.808.04 12:00 1 6,074,324 6,712.008.04 12:15
1 6,275,015 6,941.408.04 12:30 1 6,227,816
6,889.208.04 12:45 1 5,948,016 6,572.408.04 13:00 1
5,556,545 6,146.608.04 13:15 1 3,945,117 4,359.208.04 13:30
1 3,241,614 3,581.908.04 13:45 1 2,693,770
3,191.708.04 14:00 1 23 .008.04 14:15 1
21 .008.04 14:30 1 17 .008.04 14:45 1
15 .008.04 15:00 1 19 .008.04
15:15 1 16 .008.04 15:30 1 27
.008.04 15:45 1 25 .008.04 16:00 1
19 .008.04 16:15 1 17 .008.04 16:30 1
21 .008.04 16:45 1 21 .008.04
17:00 1 20 .008.04 17:15 1 21
.008.04 17:30 1 17 .008.04 17:45 1
21 .008.04 18:00 1 16 .008.04 18:15 1
14 .008.04 18:30 1 13 .008.04
18:45 1 14 .008.04 19:00 1 27
.008.04 19:15 1 15 .008.04 19:30 1
12 .008.04 19:45 1 18 .008.04 20:00 1
12 .008.04 20:16 1 13 .008.04
20:30 1 12 .008.04 20:45 1 18
.008.04 21:00 1 18 .0
Best Regards,Petr
Am Mittwoch, 10. April 2024 um 18:33:54 MESZ hat Jonathan Lewis
<jlewisoracle@xxxxxxxxx> 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 applieddata blocks
consistent reads - undo records appliedrollback 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.
RegardsJonathan Lewis
On Wed, 10 Apr 2024 at 13:35, Petr Novak <dmarc-noreply@xxxxxxxxxxxxx> 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: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
