Re: Increased runtime and 4 xids for one insert

Lothar,

Snapper samples from another session, generally over a short period. The suggestion I made was relevant for a job which is known to be a long-running task. In particular it's appropriate as a framework to put around any regular batch-like job where you might want better explanatory information after the event than would otherwise be available.

I wrote a note some years ago about using the strategy to explain the variation in performance of a "constant" job: https://jonathanlewis.wordpress.com/2007/08/09/volatility/

Regards
Jonathan Lewis

.

On Wed, 10 Apr 2024 at 17:42, Lothar Flatz <l.flatz_at_bluewin.ch> wrote:

> Hi Jonathan,
>
> would snapper work for that purpose?
> I have very little experience with snapper . I have a case where such
> option would be helpfull.
>
> Thanks
>
> Lothar
>
> Am 10.04.2024 um 18:32 schrieb Jonathan Lewis:
>
>
> 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