Re: Strange behaviour of Cramer query
From: joel garry <joel-garry_at_home.com>
Date: Wed, 24 Jun 2009 09:35:40 -0700 (PDT)
Message-ID: <a1576461-8aa3-4e94-8ff1-a8c11384c190_at_n7g2000prc.googlegroups.com>
On Jun 24, 5:41 am, HansP <hans-peter.sl..._at_atosorigin.com> wrote:
> OS: Solaris 5.10
> Oracle: 10.2.0.2
> Application: Cramer see http://en.wikipedia.org/wiki/Cramer_Systems
>
> I was ask to look at a performance issue on a database used for
> Cramer.
>
> A stored procedure is executed which executes a couple of queries and
> returns some data.
>
> Like :
> PL/SQL procedure successfully completed.
>
> Elapsed: 00:00:01.33
>
> After a couple of tries the Elapsed time goes up to 20 minutes. So no
> caching issues. Because
> After cancelling the next execution is quick again.
>
> I did traced both cases.
> The strange thing is that execution plan is in both cases the same
> except for the numer of rows returned by the steps.
> The explain plan is 228 lines long so I will not copy in the complete
> plan but just the last lines.
>
> Fast execution:
> 0 BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
> 0 INDEX FAST FULL SCAN CC_UK (cr=0 pr=0 pw=0 time=0 us)(object id
> 191358)
> 0 TABLE ACCESS BY INDEX ROWID CIRCUIT (cr=0 pr=0 pw=0 time=0 us)
> 0 INDEX UNIQUE SCAN CCT_PK (cr=0 pr=0 pw=0 time=0 us)(object id
> 191354)
> 3 TABLE ACCESS BY INDEX ROWID SERVICEOBJECT (cr=12 pr=0 pw=0 time=116
> us)
> 3 INDEX RANGE SCAN SEROBJ_OBJ_I (cr=9 pr=0 pw=0 time=69 us)(object id
> 192668)
> 3 TABLE ACCESS BY INDEX ROWID SERVICE (cr=9 pr=0 pw=0 time=60 us)
> 3 INDEX UNIQUE SCAN SERV_PK (cr=6 pr=0 pw=0 time=38 us)(object id
> 192658
>
> Slow execution:
> 9112536 BUFFER SORT (cr=149 pr=18090 pw=90 time=1151263 us)
> 45336 INDEX FAST FULL SCAN CC_UK (cr=149 pr=0 pw=0 time=70 us)(object
> id 191358)
> 9112536 TABLE ACCESS BY INDEX ROWID CIRCUIT (cr=18225074 pr=0 pw=0
> time=68090494 us)
> 9112536 INDEX UNIQUE SCAN CCT_PK (cr=9112538 pr=0 pw=0 time=31488868
> us)(object id 191354)
> 3 TABLE ACCESS BY INDEX ROWID SERVICEOBJECT (cr=12 pr=0 pw=0 time=269
> us)
> 3 INDEX RANGE SCAN SEROBJ_OBJ_I (cr=9 pr=0 pw=0 time=110 us)(object id
> 192668)
> 3 TABLE ACCESS BY INDEX ROWID SERVICE (cr=9 pr=0 pw=0 time=87 us)
> 3 INDEX UNIQUE SCAN SERV_PK (cr=6 pr=0 pw=0 time=56 us)(object id
> 192658)
>
> v$sql_plan shows only 1 plan.
>
> Does anyone have clue?
> Statistics cannot be the issue because the remain the same between
> executions.
>
> regards HansP
Date: Wed, 24 Jun 2009 09:35:40 -0700 (PDT)
Message-ID: <a1576461-8aa3-4e94-8ff1-a8c11384c190_at_n7g2000prc.googlegroups.com>
On Jun 24, 5:41 am, HansP <hans-peter.sl..._at_atosorigin.com> wrote:
> OS: Solaris 5.10
> Oracle: 10.2.0.2
> Application: Cramer see http://en.wikipedia.org/wiki/Cramer_Systems
>
> I was ask to look at a performance issue on a database used for
> Cramer.
>
> A stored procedure is executed which executes a couple of queries and
> returns some data.
>
> Like :
> PL/SQL procedure successfully completed.
>
> Elapsed: 00:00:01.33
>
> After a couple of tries the Elapsed time goes up to 20 minutes. So no
> caching issues. Because
> After cancelling the next execution is quick again.
>
> I did traced both cases.
> The strange thing is that execution plan is in both cases the same
> except for the numer of rows returned by the steps.
> The explain plan is 228 lines long so I will not copy in the complete
> plan but just the last lines.
>
> Fast execution:
> 0 BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
> 0 INDEX FAST FULL SCAN CC_UK (cr=0 pr=0 pw=0 time=0 us)(object id
> 191358)
> 0 TABLE ACCESS BY INDEX ROWID CIRCUIT (cr=0 pr=0 pw=0 time=0 us)
> 0 INDEX UNIQUE SCAN CCT_PK (cr=0 pr=0 pw=0 time=0 us)(object id
> 191354)
> 3 TABLE ACCESS BY INDEX ROWID SERVICEOBJECT (cr=12 pr=0 pw=0 time=116
> us)
> 3 INDEX RANGE SCAN SEROBJ_OBJ_I (cr=9 pr=0 pw=0 time=69 us)(object id
> 192668)
> 3 TABLE ACCESS BY INDEX ROWID SERVICE (cr=9 pr=0 pw=0 time=60 us)
> 3 INDEX UNIQUE SCAN SERV_PK (cr=6 pr=0 pw=0 time=38 us)(object id
> 192658
>
> Slow execution:
> 9112536 BUFFER SORT (cr=149 pr=18090 pw=90 time=1151263 us)
> 45336 INDEX FAST FULL SCAN CC_UK (cr=149 pr=0 pw=0 time=70 us)(object
> id 191358)
> 9112536 TABLE ACCESS BY INDEX ROWID CIRCUIT (cr=18225074 pr=0 pw=0
> time=68090494 us)
> 9112536 INDEX UNIQUE SCAN CCT_PK (cr=9112538 pr=0 pw=0 time=31488868
> us)(object id 191354)
> 3 TABLE ACCESS BY INDEX ROWID SERVICEOBJECT (cr=12 pr=0 pw=0 time=269
> us)
> 3 INDEX RANGE SCAN SEROBJ_OBJ_I (cr=9 pr=0 pw=0 time=110 us)(object id
> 192668)
> 3 TABLE ACCESS BY INDEX ROWID SERVICE (cr=9 pr=0 pw=0 time=87 us)
> 3 INDEX UNIQUE SCAN SERV_PK (cr=6 pr=0 pw=0 time=56 us)(object id
> 192658)
>
> v$sql_plan shows only 1 plan.
>
> Does anyone have clue?
> Statistics cannot be the issue because the remain the same between
> executions.
>
> regards HansP
See http://jonathanlewis.wordpress.com/2006/12/17/buffer-sorts/
My crystal ball tells me it must be something like housekeeping in the area where it keeps the temp results of the buffer-sorta-sort, perhaps a bug. Do you see lots of memory usage increase from the OS side every time you run this repeatedly? Or maybe since it is in the same session, Oracle thinks (correctly or not) it will be needing the previously buffered data again, and so hangs onto it or even cartesian joins it. What was it exactly the stored procedure did?
jg
-- _at_home.com is bogus. Apple text-to-speech pronounces Gizmodo with a soft g.Received on Wed Jun 24 2009 - 11:35:40 CDT