RE: MERGE statement - where time goes ?

Hello Albeto, 
Thank you for your prompt reply .
OK, after selecting/filterung  which rows should be inserted und which rows 
should be updated (VIEW step),
The rows should be physically written to the table. This operation takes
52349971- 11221649 microseconds =  41128322 microseconds
VIEW step filtered 1378 rows.  Time to update/insert a row would be:

41128322 microseconds/1378 rows = 29846 microseconds ~ 29 ms, just for  writing 
one row ?!
At the time of issuing the statement there were no locks (or other 
serialization mechanism) on the table
T_F_MESSUNG_DLZ_2.
GlancePlus showed me at that time maximum ~ 400 I/Os per second (Max is ~ 3000 
I/Os per second). So, there was no I/O
subsystem botthelneck
Furthermore, the sum of sizes of all T_F_MESSUNG_DLZ_2 columns is ~ 1k (9xx 
bytes). 
How is it possible to take 29 ms to update/insert 1k ? 
That is what I can not explain (to me).

Best Regards. Milen 


-----Original Message-----
From: Alberto Dell'Era [mailto:alberto.dellera@xxxxxxxxx] 
Sent: Monday, July 23, 2007 6:03 PM
To: makulev@xxxxxxx
Subject: Re: MERGE statement - where time goes ?


Hi Milen,

that's the time requested to physically modify the table (insert or update 
rows); it takes 11221649 microseconds to
calculate the differences between the "INTO" table and the "USING" table 
[that's the VIEW in the plan], and 52349971-
11221649 microseconds  to inject them into the "INTO" table (as specified by 
"WHEN MATCHED" etc).

hth
Alberto

On 7/23/07, Milen Kulev <makulev@xxxxxxx> wrote:
> Hi lsiters,
> I have the following problem: a MERGE statement is runing and is 
> taling ~ 52  seconds to run. I  have traced the statement with event 
> 10046 and I have found that I am "loosing" ~ 42 seconds (> 80% of 
> response time) im  MERGE statement step (for execution statistics & 
> execution plan -> see below). The interesing lines are:
>
> Rows     Row Source Operation
> -------  ---------------------------------------------------
>       2  MERGE  T_F_MESSUNG_DLZ_2 (cr=27552 pr=7876 pw=0 time=52349971 us)
>    1378   VIEW  (cr=4752 pr=602 pw=0 time=11221649 us)
>
>
> Does someone know what actually the MERGE is doing in the background ? 
> Any Ideas, links ?
>
> OS= HPUX, Version 10.2.0.2
>
> Best Regards. Milen
>
> ------------------------------------------------------------
>        merge  into GPFRSYSTEM.t_f_messung_dlz_etl m
>         using (select * from GPFRSYSTEM.tt_messung_dlz where ARBEITSTAGE >= 0 
> or MESSSTRECKE_ID = 21) t
>         on (t.order_id = m.order_id and t.messstrecke_id = m.messstrecke_id)
>         WHEN MATCHED THEN UPDATE set m.status = t.status,
>                                                                  
> m.arbeitstage = case when t.messstrecke_id = 21 and
t.arbeitstage < 0 then 0 else t.arbeitstage end,
>                                                                  
> m.kalendertage = case when t.messstrecke_id = 21 and
t.arbeitstage < 0 then 0 else t.kalendertage end,
>                                                                  
> m.produktionswochen = t.produktionswochen,
>                                                                  
> m.kalenderwochen = t.kalenderwochen,
>                                                                  
> m.kalendermonate = t.kalendermonate,
>                                                                  
> m.messeingangsereignis = nvl(t.eingangsereignis,0) ,
>                                                                  
> m.messausgangsereignis = nvl(t.ausgangsereignis,0),
>                                                                  
> m.eingangsereignis = nvl(t.von,0),
>                                                                  
> m.ausgangsereignis = nvl(t.bis,0),
>                                                                  
> m.ereignis_zeh = t.ereignis_zeh,
>                                                                  
> m.kovp_relevant = t.kovp_relevant,
>                                                                  
> m.pak_geaendert = t.pak_geaendert,
>                                                                  m.versandart 
> = t.versandart,
>                                                                  
> m.versandart_geaendert = t.versandart_geaendert,
>                                                                  
> m.kundenbelegung_id = t.kundenbelegung_id,
>                                                                  
> m.vab_geaendert = t.vab_geaendert,
>                                                                  m.pak = 
> t.pak,
>                                                                  
> m.letzte_aenderung = sysdate,
>                                                                  
> m.migrierte_messung = t.migrierte_messung,
>                                                                  m.trend = 
> t.trend
>         WHEN NOT MATCHED THEN insert Values (t.messstrecke_id, t.order_id, 
> t.status,
>                          case when t.messstrecke_id = 21 and t.arbeitstage < 
> 0 then 0 else t.arbeitstage end,
>                          case when t.messstrecke_id = 21 and t.arbeitstage < 
> 0 then 0 else t.kalendertage end,
>                          t.produktionswochen,t.kalenderwochen, 
> t.kalendermonate, nvl(t.von,0), nvl(t.bis,0),
t.ereignis_zeh,
>                          nvl(t.eingangsereignis,0), 
> nvl(t.ausgangsereignis,0), t.pak,t.pak_geaendert, t.versandart,
>                          t.versandart_geaendert, t.kundenbelegung_id, 
> t.vab_geaendert, t.kovp_relevant, t.migrierte_messung, sysdate, 
> t.trend)
>
> call     count       cpu    elapsed       disk      query    current        
> rows
> ------- ------  -------- ---------- ---------- ---------- ----------  
> ----------
> Parse        1      0.21       0.22          0        302          8          
>  0
> Execute      1      2.43      52.35       7876      27552      22199        
> 1378
> Fetch        0      0.00       0.00          0          0          0          
>  0
> ------- ------  -------- ---------- ---------- ---------- ----------  
> ----------
> total        2      2.64      52.57       7876      27854      22207        
> 1378
>
> Misses in library cache during parse: 1
> Optimizer mode: ALL_ROWS
> Parsing user id: SYS
> call     count       cpu    elapsed       disk      query    current        
> rows
> ------- ------  -------- ---------- ---------- ---------- ----------  
> ----------
> Parse        1      0.21       0.22          0        302          8          
>  0
> Execute      1      2.43      52.35       7876      27552      22199        
> 1378
> Fetch        0      0.00       0.00          0          0          0          
>  0
> ------- ------  -------- ---------- ---------- ---------- ----------  
> ----------
> total        2      2.64      52.57       7876      27854      22207        
> 1378
>
> Misses in library cache during parse: 1
> Optimizer mode: ALL_ROWS
> Parsing user id: SYS
>
> Rows     Row Source Operation
> -------  ---------------------------------------------------
>       2  MERGE  T_F_MESSUNG_DLZ_2 (cr=27552 pr=7876 pw=0 time=52349971 us)
>    1378   VIEW  (cr=4752 pr=602 pw=0 time=11221649 us)
>    1378    NESTED LOOPS OUTER (cr=4752 pr=602 pw=0 time=11214749 us)
>    1378     TABLE ACCESS FULL TT_MESSUNG_DLZ (cr=17 pr=16 pw=0 time=65196 us)
>      49     PARTITION RANGE ITERATOR PARTITION: KEY KEY (cr=4735 pr=586 pw=0 
> time=5214707 us)
>      49      PARTITION HASH ITERATOR PARTITION: KEY KEY (cr=4735 pr=586 pw=0 
> time=5190425 us)
>      49       TABLE ACCESS BY LOCAL INDEX ROWID T_F_MESSUNG_DLZ_2 PARTITION:  
>  (cr=4735 pr=586 pw=0 time=5172029 us)
>      49        INDEX UNIQUE SCAN PK_T_F_MESSUNG_DLZ_2 PARTITION:   (cr=4684 
> pr=538 pw=0 time=4729204 us)(object id
89305)
>
>
> Elapsed times include waiting on following events:
>   Event waited on                             Times   Max. Wait  Total Waited
>   ----------------------------------------   Waited  ----------  ------------
>   db file sequential read                      7861        0.28         50.54
>   db file scattered read                          1        0.04          0.04
>   SQL*Net message to client                       1        0.00          0.00
>   SQL*Net message from client                     1        0.00          0.00
> **********************************************************************
> **********
> ------------------------------------------------------------
> --
> Der GMX SmartSurfer hilft bis zu 70% Ihrer Onlinekosten zu sparen!
> Ideal für Modem und ISDN: http://www.gmx.net/de/go/smartsurfer
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>


-- 
Alberto Dell'Era
"the more you know, the faster you go"

--
http://www.freelists.org/webpage/oracle-l

Other related posts: