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 Go to next message
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 Go to previous messageGo to next message
scottwmackey
Messages: 505
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 in
SQL> set timing on
SQL> select * from dual;

DUMMY
-----
X

Executed in 0.015 seconds <-------------
or is that 14 seconds in wall clock time? If the later, your 14 seconds could be the time your client takes to initialize the session -- something you will often experience when using clients like Toad and it is set to multi-session. You trace file certainly isn't indicating that executing the SQL took 14 seconds.
Re: Query takes long time to execute first time [message #308115 is a reply to message #308038] Fri, 21 March 2008 04:30 Go to previous messageGo to next message
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 Go to previous messageGo to next message
rleishman
Messages: 3724
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 Go to previous messageGo to next message
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 Go to previous messageGo to next message
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 Go to previous messageGo to next message
rleishman
Messages: 3724
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 Go to previous messageGo to next message
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 #309374 is a reply to message #309113] Thu, 27 March 2008 04:42 Go to previous messageGo to next message
hristo
Messages: 258
Registered: May 2007
Senior Member
Have you set SGA_taget? If yes, then db_cache_size will/should be 0 (internally determined by the Oracle Database).

Regards
H

[Updated on: Thu, 27 March 2008 04:44]

Report message to a moderator

Re: Query takes long time to execute first time [message #309543 is a reply to message #308900] Thu, 27 March 2008 17:11 Go to previous message
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

Previous Topic: How to do update statistics on oracle 10g database
Next Topic: bulkloading
Goto Forum:
  


Current Time: Wed Dec 07 09:08:43 CST 2016

Total time taken to generate the page: 0.20555 seconds