Analyze the tkprof output

From: Andrey Bronfin <bronfin_at_VisualTop.com>
Date: Thu, 16 Mar 2000 11:03:16 +0200
Message-Id: <10492.105216@fatcity.com>

This is a multi-part message in MIME format.

------=_NextPart_000_008B_01BF8F37.3AC27920 Content-Type: text/plain;

charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable

  HI , ALL !
  I'm having a pretty strange tkprof output of a SQL trace .   There is a Java program that runs SQL queries , and it looks like = each statement is parsed 3 times for each execution when we're not using = bind variables ,=20
  and each statement is parsed 2 times when we're using bind variables = .
  There is also an execution for every fetch of a query .   We use Oracle 8.1.5 on Windows2000 .
  Both the Oracle8i and Windows are new for me . I previously used = Oracle8 on HP-UX and i never seen this kind of tkprof results .   Please help !
  TIA=20   Here is what i have in my *.prf file :

  Select ename,emp_id
  from
   emp where ename like 'SMITH%' order by ename

  call     count       cpu    elapsed       disk      query    current   =
     rows

------ -------- ---------- ---------- ---------- ---------- =
Parse 15 0.03 0.03 0 0 0 = 0 Execute 5 0.00 0.00 0 0 0 = 0 Fetch 5 0.00 0.00 0 5 0 = 10
------ --------------------------------- -------- ---------- = ---------- ---------- ---------- ---------- total 25 0.03 0.03 0 5 0 = 10

Misses in library cache during parse: 0

When we use bind variables in the Java program i see the following :

  SELECT emp_data=20
  from
   emp where emp_id=3D:1

  call     count       cpu    elapsed       disk      query    current   =
     rows

------ -------- ---------- ---------- ---------- ---------- =
Parse 8 0.01 0.01 0 0 0 = 0 Execute 4 0.00 0.00 0 0 0 = 0 Fetch 4 0.00 0.00 0 4 16 = 4
------ -------- ---------- ---------- ---------- ---------- =
total 16 0.01 0.01 0 4 = 16 4

Thanks a lot in advance !!

------=_NextPart_000_008B_01BF8F37.3AC27920 Content-Type: text/html;

charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 Transitional//EN">
<HTML><HEAD>
<META content=3D"text/html; charset=3Diso-8859-1" =

http-equiv=3DContent-Type>

<META content=3D"MSHTML 5.00.2920.0" name=3DGENERATOR>
<STYLE></STYLE>
</HEAD>
<BODY bgColor=3D#ffffff>
<BLOCKQUOTE=20

style=3D"BORDER-LEFT: #000000 2px solid; MARGIN-LEFT: 5px; MARGIN-RIGHT: = 0px; PADDING-LEFT: 5px; PADDING-RIGHT: 0px">

  <DIV><BR></DIV>
  <DIV><FONT face=3DArial size=3D2>HI , ALL !</FONT></DIV>
  <DIV><FONT face=3DArial size=3D2>I'm having a pretty strange tkprof =

output of a=20
SQL trace .</FONT></DIV>
<DIV><FONT face=3DArial size=3D2>There is a Java program that runs SQL =

  queries  , and it looks like each statement is parsed 3 times for = each=20
  execution when we're not using bind variables , </FONT></DIV>   <DIV><FONT face=3DArial size=3D2>and each statement is parsed 2 = times =20
  when we're  using bind variables  .</FONT></DIV>   <DIV><FONT face=3DArial size=3D2>There is also an execution for every = fetch of a=20
  query .</FONT></DIV>
  <DIV><FONT face=3DArial size=3D2>We use Oracle 8.1.5 on Windows2000 = .</FONT></DIV>
  <DIV><FONT face=3DArial size=3D2>Both the Oracle8i and Windows are new = for me . I=20
  previously used Oracle8 on HP-UX and i never seen this kind of tkprof = results=20
  .</FONT></DIV>

  <DIV><FONT face=3DArial size=3D2>Please help !</FONT></DIV>
  <DIV><FONT face=3DArial size=3D2>TIA </FONT></DIV>
  <DIV>&nbsp;</DIV>
  <DIV><FONT face=3DArial size=3D2>Here is what i have in my *.prf file=20

  :</FONT></DIV>
  <DIV> </DIV>
  <DIV><FONT face=3DArial size=3D2>Select = ename,emp_id<BR>from<BR> emp=20
  where ename like 'SMITH%' order by ename</FONT></DIV>   <DIV><FONT face=3DArial size=3D2><BR>call    =20   count       cpu   =20   elapsed       = disk     =20
  query    =
current       =20   rows<BR>------- ------  -------- ---------- ---------- ---------- =

---------- =20
=

----------------------------------------<BR>Parse&nbsp;&nbsp;&nbsp;&nbsp;=

  =20
15      =
0.03      =20 0.03         =20

  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20

0<BR>Execute     5     =20 0.00      =20 0.00         =20

  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20

0<BR>Fetch       =20 5      =
0.00      =20 0.00         =20

  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  5&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 10<BR>-------=20
  ------&nbsp;--------------------------------- -------- ---------- =
----------=20

---------- =20 ----------<BR>total      =20 25      = 0.03      =20 0.03         =20 0         =20 5         =20 0          = 10</FONT></DIV> <DIV> </DIV> <DIV><FONT face=3DArial size=3D2>Misses in library cache during parse: =

0</FONT></DIV>

  <DIV>&nbsp;</DIV>
  <DIV>&nbsp;</DIV>
  <DIV><FONT face=3DArial size=3D2>When&nbsp;we use bind variables in =

the Java=20
  program i see the following :</FONT></DIV>   <DIV> </DIV>
  <DIV><FONT face=3DArial size=3D2>SELECT  emp_data = <BR>from<BR> emp where=20
  emp_id=3D:1</FONT></DIV>
  <DIV><FONT face=3DArial size=3D2><BR>call    =20   count       cpu   =20   elapsed       = disk     =20
  query    =
current       =20   rows<BR>------- ------  -------- ---------- ---------- ---------- =

---------- =20
=

-----------------------------------------<BR>Parse&nbsp;&nbsp;&nbsp;&nbsp=

;    =20
8      =
0.01      =20 0.01         =20

  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20

0<BR>Execute      = 4     =20
0.00      =20 0.00         =20

  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20
  0&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;=20

0<BR>Fetch         =20 4      =
0.00      =20 0.00         =20 0         =20 4        =20 16           =

4<BR>-------=20
  ------&nbsp; -------- ---------- ---------- ---------- =
----------&nbsp;=20

-----------------------------------------------<BR>total&nbsp;&nbsp;&nbsp=

;      =20 16      =
0.01      =20 0.01         =20 0         =20 4        =20 16           = Received on Thu Mar 16 2000 - 03:03:16 CST