Home » RDBMS Server » Performance Tuning » Query takes long time to execute first time
| Query takes long time to execute first time [message #308027] |
Thu, 20 March 2008 16:19  |
emilSverige
Messages: 21
Registered: October 2006
|
Junior Member |
|
|
I have a query that sometimes takes very long time to execute.
When I just tried it it took 14 seconds to execute the first time, and after that around 0.015 seconds. It doesn't matter if I change the parameters after the first execution, it still takes about 0.015.
I have tried to trace statistics (my first time) see result below.
According to the tkrof file there are no full table scans.
Any idea what the reason could be? Will it only be the first time, or could it occur anytime?
Regards
Emil
TKROF file:
-------------------------------------------------------
TKPROF: Release 9.2.0.1.0 - Production on Tor Mar 20 22:02:17 2008
Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
Trace file: C:\oracle\admin\poker\udump\poker_ora_5592_robotnikperformance.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
alter session set events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.02 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.02 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 61
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 9.41 9.42
SQL*Net more data from client 1 0.00 0.00
********************************************************************************
SELECT HANDVALUE as id, handValue, sum(NUMOFCALLS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFCALLS, sum(NUMOFCHECKS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFCHECKS, sum(NUMOFFOLDS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFFOLDS, sum(NUMOFRAISES * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFRAISES
from
ProbPerDecision_Player, PLAYERENTITY, PLAYERTYPEENTITY where
ProbPerDecision_Player.PLAYERENTITY_NICKNAME = PLAYERENTITY.NICKNAME and
PLAYERENTITY.POSTFLOPPLAYERTYPE_ID = PLAYERTYPEENTITY.ID and
ProbPerDecision_Player.RAISEDPOT = 0 and ProbPerDecision_Player.STREET
= 2 and ProbPerDecision_Player.LASTDECISION = 3 and
ProbPerDecision_Player.numOfPlayers = 2 and
ProbPerDecision_Player.POSITION = 5 and
ProbPerDecision_Player.numOfRaisersToAct = 2 group by HANDVALUE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.04 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.14 0.14 0 860 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.15 0.19 0 860 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 61
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY NOSORT
0 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID PROBPERDECISION_PLAYER
0 INDEX RANGE SCAN PROBPERDECISION_PLAYER_PK (object id 30199)
0 TABLE ACCESS BY INDEX ROWID PLAYERENTITY
0 INDEX UNIQUE SCAN SYS_C003109 (object id 30187)
0 TABLE ACCESS BY INDEX ROWID PLAYERTYPEENTITY
0 INDEX UNIQUE SCAN SYS_C003140 (object id 30193)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
SQL*Net message from client 4 0.00 0.01
********************************************************************************
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,
o.dataobj#,o.flags
from
obj$ o where o.obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 6 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 6 0 2
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.04 0 0 0 0
Execute 2 0.00 0.02 0 0 0 0
Fetch 1 0.14 0.14 0 860 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.15 0.21 0 860 0 0
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 7 9.41 9.44
SQL*Net more data from client 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 6 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 6 0 2
Misses in library cache during parse: 1
2 user SQL statements in session.
1 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: C:\oracle\admin\poker\udump\poker_ora_5592_robotnikperformance.trc
Trace file compatibility: 9.00.01
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
1 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
111 lines in trace file.
|
|
|
|
| Re: Query takes long time to execute first time [message #308038 is a reply to message #308027] |
Thu, 20 March 2008 17:12  |
scottwmackey
Messages: 515
Registered: March 2005
|
Senior Member |
|
|
What do you mean by "first time"? And what do you mean when you say it took 14 seconds? Is that what Oracle says, as inSQL> set timing on
SQL> select * from dual;
DUMMY
-----
X
Executed in 0.015 seconds <------------- |
|
|
|
| Re: Query takes long time to execute first time [message #308115 is a reply to message #308038] |
Fri, 21 March 2008 04:30 |
emilSverige
Messages: 21
Registered: October 2006
|
Junior Member |
|
|
Sorry for not being totally clear in my question.
I ran the query in squirrel sql, a program similar to toad.
The first time I executed it I got the response time from oracle:
Executed in 14.500 seconds <-------------
I started tracing after this, that is probably the reason why the trace file doesn't show it.
Regards
Emil
|
|
|
|
| Re: Query takes long time to execute first time [message #308130 is a reply to message #308115] |
Fri, 21 March 2008 06:53 |
rleishman
Messages: 3728
Registered: October 2005
Location: Melbourne, Australia
|
Senior Member |
|
|
So you posted the fast trace and asked if we could make it fast? Hmmmm.
Try tracing it when its slow.
I don't see any bind variables in this SQL. Does the original have variables and you replaced them with constants for this run?
Ross Leishman
|
|
|
|
| Re: Query takes long time to execute first time [message #308149 is a reply to message #308130] |
Fri, 21 March 2008 10:50 |
emilSverige
Messages: 21
Registered: October 2006
|
Junior Member |
|
|
Yes,
I don't know why, but I didn't start tracing until the problem no longer occurred.
Stupid.
Sorry.
I am also sorry to say that I left my computer at home, and went away over easter.
I will try to post a better tkprof file on Monday night when I'm back home again.
You're right about the bind variables.
The original query had them, but I replaced them when running the query. I will use bind variables when I trace next time.
Regards
Emil
|
|
|
|
| Re: Query takes long time to execute first time [message #308882 is a reply to message #308149] |
Tue, 25 March 2008 16:25 |
emilSverige
Messages: 21
Registered: October 2006
|
Junior Member |
|
|
Hi, I traced again. I didn't use bind variables this time either, not sure how I should do it...
But this time it shows that it takes 14 seconds to complete:
TKPROF: Release 9.2.0.1.0 - Production on Tis Mar 25 22:17:22 2008
Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
Trace file: C:\oracle\admin\poker\udump\poker_ora_5028_robotnikperformance.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
alter session set events '10046 trace name context forever, level 12'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.01 0.01 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.01 0.01 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 61
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 5.57 5.59
SQL*Net more data from client 1 0.00 0.00
********************************************************************************
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
spare2
from
obj$ where owner#=:1 and name=:2 and namespace=:3 and(remoteowner=:4 or
remoteowner is null and :4 is null)and(linkname=:5 or linkname is null and
:5 is null)and(subname=:6 or subname is null and :6 is null)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 3 0.03 0.04 0 0 0 0
Fetch 3 0.00 0.00 0 9 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.04 0.05 0 9 0 3
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
3 TABLE ACCESS BY INDEX ROWID OBJ$
3 INDEX RANGE SCAN I_OBJ2 (object id 37)
********************************************************************************
select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clucols,0),
audit$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,blkcnt,empcnt,
avgspc,chncnt,avgrln,analyzetime, samplesize,cols,property,nvl(degree,1),
nvl(instances,1),avgspc_flb,flbcnt,kernelcols,nvl(trigflag, 0),nvl(spare1,0)
,nvl(spare2,0),spare4,spare6
from
tab$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.01 0.00 0 12 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.01 0.01 0 12 0 3
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
3 TABLE ACCESS CLUSTER TAB$
3 INDEX UNIQUE SCAN I_OBJ# (object id 3)
********************************************************************************
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags, i.property,
i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey, i.lblkkey,
i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
nvl(i.spare1,i.intcols),i.spare4,spare2,spare6, decode(i.pctthres$,null,
null, mod(trunc(i.pctthres$/256),256))
from
ind$ i, (select enabled, min(cols) unicols, min(to_number(bitand(defer,1)))
deferrable#, min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=
:1 and enabled > 1 group by enabled) c where i.obj#=c.enabled(+) and i.bo#=
:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 13 0.00 0.03 3 23 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 17 0.00 0.04 3 23 0 10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 3 0.02 0.03
********************************************************************************
select pos#,intcol#,col#,spare1,bo#,spare2
from
icol$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 65 0.00 0.00 0 130 0 55
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 76 0.00 0.00 0 130 0 55
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
nvl(spare3,0)
from
col$ where obj#=:1 order by intcol#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 35 0.01 0.00 0 12 0 32
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 39 0.01 0.00 0 12 0 32
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
select type#,blocks,extents,minexts,maxexts,extsize,extpct,user#,iniexts,
NVL(lists,65535),NVL(groups,65535),cachehint,hwmincr, NVL(spare1,0)
from
seg$ where ts#=:1 and file#=:2 and block#=:3
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 13 0.00 0.00 0 0 0 0
Execute 13 0.00 0.00 0 0 0 0
Fetch 13 0.00 0.00 0 39 0 13
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 39 0.00 0.00 0 39 0 13
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS CLUSTER SEG$
1 INDEX UNIQUE SCAN I_FILE#_BLOCK# (object id 9)
********************************************************************************
select con#,obj#,rcon#,enabled,nvl(defer,0)
from
cdef$ where robj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.01 0.00 0 0 0 0
Fetch 10 0.00 0.00 0 17 0 7
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.01 0.00 0 17 0 7
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),
rowid,cols,nvl(defer,0),mtime,nvl(spare1,0)
from
cdef$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 29 0.00 0.00 0 37 0 26
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 33 0.00 0.00 0 37 0 26
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
select intcol#,nvl(pos#,0),col#
from
ccol$ where con#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 26 0.00 0.00 0 0 0 0
Fetch 65 0.00 0.01 2 130 0 39
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 92 0.00 0.01 2 130 0 39
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.01 0.01
********************************************************************************
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 and col# is not null group by privilege#, col#,
grantee# order by col#, grantee#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 6 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.00 0.00 0 6 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by
grantee#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 6 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.00 0.00 0 6 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 23 0.00 0.00 0 0 0 0
Fetch 23 0.00 0.02 2 69 0 23
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 47 0.00 0.03 2 69 0 23
Misses in library cache during parse: 1
Optimizer goal: RULE
Parsing user id: SYS (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.02 0.02
********************************************************************************
select name,online$,contents$,undofile#,undoblock#,blocksize,dflmaxext,
dflinit,dflincr,dflextpct,dflminext, dflminlen, owner#,scnwrp,scnbas,
NVL(pitrscnwrp, 0), NVL(pitrscnbas, 0), dflogging, bitmapped, inc#, flags,
plugged, NVL(spare1,0), NVL(spare2,0)
from
ts$ where ts#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS CLUSTER TS$
1 INDEX UNIQUE SCAN I_TS# (object id 7)
********************************************************************************
SELECT HANDVALUE as id, handValue, sum(NUMOFCALLS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFCALLS, sum(NUMOFCHECKS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFCHECKS, sum(NUMOFFOLDS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFFOLDS, sum(NUMOFRAISES * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFRAISES
from
ProbPerDecision_Player, PLAYERENTITY, PLAYERTYPEENTITY where
ProbPerDecision_Player.PLAYERENTITY_NICKNAME = PLAYERENTITY.NICKNAME and
PLAYERENTITY.POSTFLOPPLAYERTYPE_ID = PLAYERTYPEENTITY.ID and
ProbPerDecision_Player.RAISEDPOT = 0 and ProbPerDecision_Player.STREET
= 2 and ProbPerDecision_Player.LASTDECISION = 3 and
ProbPerDecision_Player.numOfPlayers = 2 and
ProbPerDecision_Player.POSITION = 5 and
ProbPerDecision_Player.numOfRaisersToAct = 2 group by HANDVALUE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.20 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.32 13.78 860 860 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.40 13.98 860 860 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 61
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY NOSORT
0 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID PROBPERDECISION_PLAYER
0 INDEX RANGE SCAN PROBPERDECISION_PLAYER_PK (object id 30199)
0 TABLE ACCESS BY INDEX ROWID PLAYERENTITY
0 INDEX UNIQUE SCAN SYS_C003109 (object id 30187)
0 TABLE ACCESS BY INDEX ROWID PLAYERTYPEENTITY
0 INDEX UNIQUE SCAN SYS_C003140 (object id 30193)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
SQL*Net message from client 4 0.16 0.17
db file sequential read 860 0.12 13.55
********************************************************************************
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,
o.dataobj#,o.flags
from
obj$ o where o.obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 13 0.00 0.00 0 0 0 0
Fetch 13 0.00 0.00 0 39 0 13
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 28 0.00 0.00 0 39 0 13
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.20 0 0 0 0
Execute 2 0.01 0.01 0 0 0 0
Fetch 1 0.32 13.78 860 860 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.42 14.00 860 860 0 0
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 7 5.57 5.76
SQL*Net more data from client 1 0.00 0.00
db file sequential read 860 0.12 13.55
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 27 0.01 0.03 0 0 0 0
Execute 110 0.04 0.07 0 0 0 0
Fetch 279 0.03 0.08 7 531 0 225
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 416 0.09 0.19 7 531 0 225
Misses in library cache during parse: 14
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 7 0.02 0.07
2 user SQL statements in session.
27 internal SQL statements in session.
29 SQL statements in session.
********************************************************************************
Trace file: C:\oracle\admin\poker\udump\poker_ora_5028_robotnikperformance.trc
Trace file compatibility: 9.00.01
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
27 internal SQL statements in trace file.
29 SQL statements in trace file.
16 unique SQL statements in trace file.
2152 lines in trace file.
[formatted by moderator]
[Updated on: Tue, 25 March 2008 21:21] by Moderator Report message to a moderator |
|
|
|
| Re: Query takes long time to execute first time [message #308900 is a reply to message #308882] |
Tue, 25 March 2008 21:50 |
rleishman
Messages: 3728
Registered: October 2005
Location: Melbourne, Australia
|
Senior Member |
|
|
So this is the statement where the problem lies:
SELECT HANDVALUE as id, handValue, sum(NUMOFCALLS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFCALLS, sum(NUMOFCHECKS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFCHECKS, sum(NUMOFFOLDS * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFFOLDS, sum(NUMOFRAISES * ( DECODE(
flopRaised, 1, 1, 0 ) + DECODE( aggressiveness, 2, 1, 0 ) +
DECODE( preFlopRaised, 1, 1, 0 ) + DECODE( playerRaised1, 0, 1, 0 )
+ DECODE( numOfRaisersToAct, 1, 1, 0 ) + DECODE(
playerRaised4, 0, 1, 0 ) + DECODE( playerRaised3, 0, 1, 0 ) +
DECODE( turnRaised, 5, 1, 0 ) + DECODE( tightness, 2, 1, 0 ) +
0 )) AS NUMOFRAISES
from
ProbPerDecision_Player, PLAYERENTITY, PLAYERTYPEENTITY where
ProbPerDecision_Player.PLAYERENTITY_NICKNAME = PLAYERENTITY.NICKNAME and
PLAYERENTITY.POSTFLOPPLAYERTYPE_ID = PLAYERTYPEENTITY.ID and
ProbPerDecision_Player.RAISEDPOT = 0 and ProbPerDecision_Player.STREET
= 2 and ProbPerDecision_Player.LASTDECISION = 3 and
ProbPerDecision_Player.numOfPlayers = 2 and
ProbPerDecision_Player.POSITION = 5 and
ProbPerDecision_Player.numOfRaisersToAct = 2 group by HANDVALUE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.20 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.32 13.78 860 860 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.40 13.98 860 860 0 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 61
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY NOSORT
0 NESTED LOOPS
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID PROBPERDECISION_PLAYER
0 INDEX RANGE SCAN PROBPERDECISION_PLAYER_PK (object id 30199)
0 TABLE ACCESS BY INDEX ROWID PLAYERENTITY
0 INDEX UNIQUE SCAN SYS_C003109 (object id 30187)
0 TABLE ACCESS BY INDEX ROWID PLAYERTYPEENTITY
0 INDEX UNIQUE SCAN SYS_C003140 (object id 30193)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
SQL*Net message from client 4 0.16 0.17
db file sequential read 860 0.12 13.55
What can we see from this:- The plan involves 2 nested-loops joins; one nested insode the other
- Rows from PROBPERDECISION_PLAYER will then use an index to lookup PLAYERENTITY, and then another index to lookup PLAYERTYPEENTITY
- There were no rows selected from PROBPERDECISION_PLAYER, so therefore there was no reason to lookup the other 2 tables.
- This leads us to think that all of the time is spent looking for rows in PROBPERDECISION_PLAYER.
- The scan on PROBPERDECISION_PLAYER_PK is a RANGE scan. It could potentially scan millions of rows based on the first column(s) of the index and then filter on later columns returning no rows.
- Good theory, but TKPROF says that only 860 blocks were read from disk and 860 buffers from the buffer cache. This seems an inordinately small number of blocks to read in 14 seconds.
- The wait events suggest that time was spent on DB File Sequential Read. That usually means an index read.
My hypothesis:- When the query runs fast, the index is cached and does not need to go to disk (DB File Sequential Read). When it is slow, the index is not cached and needs to be read from disk.
- For reasons unknown to me, access to that index on disk is slow. Inordinately slow. 860 blocks in 14 seconds kind of slow.
I suspect you will need to take this to the next level; invovling the DBA and system administrator.
As a test, cut down your query so that it does not perform the join, and uses only colums from PROBPERDECISION_PLAYER_PK. Such a query would have an Explain Plan like this:
Rows Row Source Operation
------- ---------------------------------------------------
0 SELECT STATEMENT
0 INDEX RANGE SCAN PROBPERDECISION_PLAYER_PK (object id 30199)
If that is slow as well (when the index is not cached) then you have removed joins and tables from the equation and isolated the problem to the index.
Then you check the tablespace of this index, find the data files and work out which disk it is located on. Then when you run the query, you get the system administrator to monitor that disk and work out what's happening.
Ross Leishman
|
|
|
|
| Re: Query takes long time to execute first time [message #309113 is a reply to message #308027] |
Wed, 26 March 2008 08:08 |
emilSverige
Messages: 21
Registered: October 2006
|
Junior Member |
|
|
Thank you so much for your informative answer!
Cutting down the query seems like a very good idea.
An observation I did, don't know if it's relevant:
My db_cache_size and every db_x_cache_size are set to 0 (zero).
I understand that this is crazy and will try to fix it. Could that have anything to do with my problem?
Regards
Emil
|
|
|
|
|
|
| Re: Query takes long time to execute first time [message #309543 is a reply to message #308900] |
Thu, 27 March 2008 17:11 |
emilSverige
Messages: 21
Registered: October 2006
|
Junior Member |
|
|
I followed your suggestion, breaking down the query to include one table only.
Still 14 seconds, so the problem probably lies at PROBPERDECISION_PLAYER.
I tried a long shot, rebuilding the index PROBPERDECISION_PLAYER_PK.
This actually seems to have solved the problem, it now seems to execute in no more than 0,3 seconds which is perfectly acceptable.
Thank you so much for your help!
Regards
Emil
[Updated on: Thu, 27 March 2008 17:13] Report message to a moderator |
|
|
|
Goto Forum:
Current Time: Fri Jun 28 10:22:17 CDT 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
