Re: Increased runtime and 4 xids for one insert

  • From: Lothar Flatz <l.flatz@xxxxxxxxxx>
  • To: novak_petr@xxxxxxxx, 'Oracle List' <oracle-l@xxxxxxxxxxxxx>, "Mark W. Farnham" <mwf@xxxxxxxx>
  • Date: Wed, 10 Apr 2024 18:38:38 +0200

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@xxxxxxxx> 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@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx] *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

Other related posts: