Re: Increased runtime and 4 xids for one insert

From: Lothar Flatz <l.flatz_at_bluewin.ch>
Date: Wed, 10 Apr 2024 18:38:38 +0200
Message-ID: <0441afe2-7a51-4a84-a4f5-f85dc56c2bd9_at_bluewin.ch>



Hi Petr,

we would need some measurements here.
Ideally we would see a sql Monitor Report. I assume you do not have diagnostics and tuning pack licensed. Can you please provide us with runtime statistics (https://savvinov.com/2012/05/14/dbms_xplan-display_cursor/) And also the Result of this Query:

select inner.*,
ROUND (RATIO_TO_REPORT (seconds ) OVER () * 100) AS "% seconds"

             from (
   SELECT NVL(event,'CPU')
          sql_plan_operation,
          sql_plan_options,
          sql_plan_line_id,
          COUNT (*) *10  seconds
     FROM DBA_HIST_active_sess_history
    WHERE     SQL_ID = '&sql_id'
    -- AND sample_time between TO_DATE('07.08.2020 13:30:00','DD.MM.YYYY 
HH24:MI:SS') and TO_DATE('08.08.2020 02:30:00','DD.MM.YYYY HH24:MI:SS') GROUP BY event, sql_plan_operation, sql_plan_options, sql_plan_line_id order by seconds desc ) inner
;

Thanks

Lothar
Am 10.04.2024 um 17:17 schrieb Petr Novak (novak_petr):
> Hallo Mark,
>
> no RAC, single instance.  The XIDs were not running paralell, but
> after one was finished, the next was started (?). I hope, it can be
> seen in the query (min/max (sample_time)).
> T_TARGET has daily partitions (something like transaction time),
> advanced compression is used on the table and indexes. Last week 4 new
> partitions were created, this week 2.
>
> Best Regards,
> Petr
>
> Am Mittwoch, 10. April 2024 um 16:28:04 MESZ hat Mark W. Farnham
> <mwf_at_rsiz.com> Folgendes geschrieben:
>
>
> Non-local RAC parallel executions of the select part?
>
> Tell us more about the partitioning, and whether partitions are being
> dynamically added or increased in size during the insert.
>
> Tell us whether previous deletions have made long convoluted insert
> eligible contestant freespace bit maps or freelists/freelist groups.
>
> If there is a reasonable way to partition the select into chunks
> exactly corresponding to the range partition destinations, it is
> likely you can run 4 (say) copies of the insert each inserting into
> the requisite destination partition by name and each at parallel 1,
> and if this is 4 node rac, each using a different insert node.
>
> Or it could be something completely different.
>
> mwf
>
> *From:*oracle-l-bounce_at_freelists.org
> [mailto:oracle-l-bounce_at_freelists.org] *On Behalf Of *Petr Novak
> ("novak_petr")
> *Sent:* Wednesday, April 10, 2024 8:35 AM
> *To:* Oracle List
> *Subject:* Increased runtime and 4 xids for one insert
>
> 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
Received on Wed Apr 10 2024 - 18:38:38 CEST

Original text of this message