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_at_gmail.com] Sent: Monday, July 23, 2007 6:03 PM
To: makulev_at_gmx.net
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_at_gmx.net> 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