Re: Increased runtime and 4 xids for one insert

  • From: Lothar Flatz <l.flatz@xxxxxxxxxx>
  • To: jlewisoracle@xxxxxxxxx, novak_petr@xxxxxxxx
  • Date: Wed, 10 Apr 2024 18:42:02 +0200

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@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 <http://dd.mm> hh24:mi:ss') mint,
    to_char(max(sample_time),'dd.mm <http://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

Other related posts: