Hallo Dominic,
col coser format 99999 heading "Co(Ser)"col cosid format 9999 heading
"Co(Sid)"col diin format 9999 heading "Di(In)"col disi format 9999 heading
"Di(Sid)"
select xid, sql_exec_id,SQL_EXEC_START,
coalesce(qc_session_id, session_id) cosid, coalesce(qc_session_serial#,
session_serial#) coser, count(distinct instance_number) diin ,
count(distinct(session_id)) disi,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')and sql_exec_id is not null and
sql_exec_start is not nullgroup by
xid,sql_exec_id,SQL_EXEC_START,coalesce(qc_session_id, session_id),
coalesce(qc_session_serial#, session_serial#)order by
SQL_EXEC_START,min(sample_time);
XID SQL_EXEC_ID SQL_EXEC_START Co(Sid) Co(Ser) Di(In)
Di(Sid) COUNT(*) Min(Sample_Time) Max(Sample_Time)----------------
-------------- ------------------- ------- ------- ------ -------
-------------- -------------------- --------------------
16777216 05.04.2024 20:13:40 1141 11657 1 5 50
05.04 20:13:44 06.04 04:26:032E00180051D62200 16777216 05.04.2024
20:13:40 1141 11657 1 1 12532 05.04 20:14:25
06.04 14:04:0320001C0008633B00 16777217 06.04.2024 14:04:10 1141
11657 1 1 24486 06.04 14:04:13 08.04 00:55:20
16777217 06.04.2024 14:04:10 1141 11657 1 3
30 06.04 14:08:29 07.04 01:10:2915001100CD95C100 16777218
08.04.2024 00:55:22 1141 11657 1 1 8986 08.04
00:55:31 08.04 13:42:29 16777218 08.04.2024
00:55:22 1141 11657 1 4 28 08.04 00:59:06
08.04 03:59:5203001200F4F1B600 16777219 08.04.2024 13:42:30 1141
11657 1 1 4178 08.04 13:42:39 08.04 19:39:05
16777219 08.04.2024 13:42:30 1141 11657 1 4
24 08.04 13:48:48 08.04 18:20:44
So there were different SQL_EXEC_IDs.Most samples have XID filled and only 1
Session. There 24-50 samples for every SQL_EXEC_ID without XID, 3-5 different
Sessions, about 0.26 percent of all samples.For me it looks like serial
execution.I dont understand different SQL_EXEC_IDs - should this mean, there
was some app error and statement was restarted ?But there were no errors in
alert.log , no snapshot too old error in dba_hist_undostat
Active Extents in dba_hist_undostat start on 5th April 8PM from 4GB, reach 87
GB on 6th April 5 AM,remain constant till 6th April 2 PM (9 hours) , then
abruptly go back to 9 GB, reach 98GB on 6th April 10 PM, remain constant till
8th April 3 AM (29 hours), then abruptly to 77 GB, reach 89GB on 8th April
4AM,remain constant till 8th April 1 PM (9 hours), then abruptly to 1G, reach
111 GB on 8th April at 8 PM, then goes to 0.Dissmiss of active extents is
related to start of new XID.Could these long hours with constant number of
active extents be related to work on compression ?
Best Regards,Petr
Am Mittwoch, 10. April 2024 um 17:12:52 MESZ hat Dominic Brooks
<dombrooks@xxxxxxxxxxx> Folgendes geschrieben:
#yiv3921392174 P {margin-top:0;margin-bottom:0;}The formatting of the ASH data
is hard to digest.
A couple of points of order on ASH queries here -
- I would always include sql_exec_id as
sql_id + sql_exec_id + sql_exec_start should be unique to an instance.
- if it's a parallel insert then you should be able to tell from
QC_SESSION_ID
- I nearly always end up deliberately omitting rows where sql_id and
sql_exec_id are null unless I'm looking for a parsing issue.
So my initial aggregation query would be something like this:
select xid, sql_exec_id, sql_exec_start, coalesce(qc_session_id, session_id),
coalesce(qc_session_serial#, session serial#), count(distinct instance_number),
count(session_id),count(*), to_char(min(sample_time),'dd.mm hh24:mi:ss') mint,
to_char(max(sample_time),'dd.mm hh24:mi:ss') maxtfrom
dba_hist_active_sess_historywhere sql_id='fdq9c3q9jfavc'and sql_exec_id is not
null and sql_exec_start is not null...which also tells me whether it's parallel
or not and if parallel how many sessions were sampled participating.
if it's a parallel execution then DBMS_XPLAN should be able to tell you why
it's parallel if the code is not explicitly requesting parallel.
If it is parallel then perhaps you want the insert to be parallelised as well?
At least part of the answers might be visible in your own (unaggregated) ASH
data. If there was blocking, etc and anything which would account for timing
discrepancies etc.
11 million rows taking 3.5 hours sound way too long in the first place.
An ever increasing execution time indicates an ever increasing amount of work.
Either a symptom/consequence of what was done before (or not done or failed)
Leaving behind consequences for the next.
UNDO can be a strong indicator here of either something like delayed block
cleanout or concurrent executions of this (or something else) against the same
objects.
However please also note that ASH data columns can be cleared out lazily.So
it's highly likely that CURRENT_FILE# is only set/reset when you're waiting on
an IO event.
So if you join across all ASH data but the event is not an IO event, you might
well end up with a large mispresentation of what was going on.
Other things - perhaps some suboptimal implementation elsewhere - e.g. an ETL
process which just does a DELETE from T_SOURCE rather than a TRUNCATE leaving
more and more empty blocks to be scanned the next time.
What ASH can often not be able to tell you is WHY something is being done.
Some samples of session stats can be useful here - particularly in the case of
why something is reading UNDO significantly, if that's what was happening.
Try picking an execution out of sql monitoring (preferably in memory from
gv$sql_monitor or else from dba_hist_reports) . At least you should get a
holistic summary of where the time went.
Hope this helps.
Cheers,
Dominic
From: oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on behalf
of Petr Novak <dmarc-noreply@xxxxxxxxxxxxx>
Sent: 10 April 2024 13:34
To: Oracle List <oracle-l@xxxxxxxxxxxxx>
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: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
