home *** CD-ROM | disk | FTP | other *** search
/ Liren Large Software Subsidy 5 / 05.iso / a / a524 / 28.ddi / doc / tkprof.doc < prev   
Encoding:
Text File  |  1991-03-04  |  9.5 KB  |  235 lines
  1. ...
  2. ... $Header: tkprof.doc,v 6002701.1 89/06/15 23:01:35 rcs Exp $ tkprof.doc Copyr (c) 1989 Oracle
  3. ...
  4.  
  5. This document describes the SQL level profiling facility.
  6.  
  7. SQL level profiling consists of two parts: generating raw statistics,
  8. and processing the statistics into a useable forms.
  9.  
  10.  
  11. 1. Generating Statistics
  12.  
  13. To generate the statistics you must run a session against the kernel
  14. with sql tracing enabled.  Sql tracing causes a record to be written
  15. to the trace file every time a SQL statement is parsed or executed or
  16. a row is fetched.
  17.  
  18. You can enable sql tracing either on a per session basis or globally.
  19. To enable it on a per session basis, execute the following 'alter
  20. session' SQL statement within the session:
  21.  
  22. alter session set sql_trace true;
  23.  
  24. To enable it globally (for all sessions) include the following line
  25. in your init.ora file and restart the instance:
  26.  
  27. sql_trace = true
  28.  
  29. If you would like to profile execution times for SQL statments, you
  30. must also enable the gathering of timing statistics in your database.
  31. This is done by putting the following line in your init.ora file:
  32.  
  33. timed_statistics = true
  34.  
  35.  
  36. 2. Processing Statistics
  37.  
  38. Once you have produced a trace file containing execution time
  39. statistics, you can format it into a human readable form using the
  40. tkprof program.  The program is invoked as follows:
  41.  
  42. TKPROF TRACEFILE OUTPUTFILE [SORT] [PRINT] [EXPLAIN]
  43.  
  44. Where:
  45.  Tracefile - name of trace file to which statistics were dumped. Trace
  46.    files are written to the directory specified by the init.ora parameter
  47.    user_dump_dest or to a default directory if this parameter is not
  48.    specified.
  49.  
  50.  Outputfile - file to which human readable statistics should be written.
  51.  
  52.  Sort - optional argument that causes the statistics in the
  53.    outputfile to be written in a sorted order.  For example, you can sort
  54.    by cpu time spent executing a statement, or you can sort by the number
  55.    of physical reads that occured while fetching rows.  Invoking the
  56.    tkprof program with no arguments will cause a list of sortoptions to
  57.    be printed.  You can also give more than one sortoption in which case
  58.    the output will be sorted by the sum of the values specified by the
  59.    sortoptions.
  60.  
  61.  Print - this optional argument causes only the top NUM statements to be 
  62.       printed to the outputfile
  63.  
  64.  Explain - this optional argument instructs tkprof to run EXPLAIN PLAN on all 
  65.       the SQL statements it prints out.  To do so it will login to the database
  66.       using the username/password given on the command line.  Username
  67.       must have resource privilege in order for tkprof to create the plan
  68.       table that EXPLAIN PLAN uses.  DDL and recursive SQL statements will
  69.       not be explained.
  70.  
  71.  
  72. Example:  
  73.  
  74. tkprof sqldba_jrl_005.trc run1.prf sort=(execpu,fchcpu) print=20 
  75.        explain=scott/tiger
  76.  
  77. This command runs the tkprof program on the statistics in the file
  78. 'sqldba_jrl_005.trc'.  Tkprof will generate summary statistics for
  79. each sql statement and sort the statistics by the sum of cpu time
  80. spent executing (execpu) and the cpu time spent fetching rows
  81. (fchcpu).  Only the top 20 statements will be printed out, and an
  82. execution plan will be printed for each statement.  The output of
  83. tkprof will be written to the file 'run1.prf'.
  84.  
  85. If you enable the trace globally (in the init.ora file), you can obtain
  86. global summary statistics by appending the trace files produced by all
  87. sessions into a new file, and running tkprof on the new file.
  88.  
  89.  
  90. 3. Output of Tkprof
  91.  
  92. This section gives a short description of the statistics that are output
  93. by tkprof.  Be warned that some of these statistics are hard to interpret
  94. without an intimate knowledge of the internals of the database kernel.
  95. A sample of the output of tkprof is included at the end of this file.
  96.  
  97. COUNT - the number of times that the OCI operation (parse, execute, or
  98. fetch) was called.
  99.  
  100. CPU - total cpu time for the operation measured in hundreths of seconds.
  101.  
  102. Note that because the granularity of our clock is a hundreth of a
  103. second, any operation on a cursor that takes on the order of a
  104. hundreth of a second or less will not be timed accurately.
  105. Unfortunately, this applies to a large number of SQL statements,
  106. especially simple queries.  Therefore, you must be very careful when
  107. interpreting these numbers. Be especially wary of queries that are
  108. executed frequently, but have low cpu and elapsed times.
  109.  
  110. ELAP - total elapsed time for the operation measured in hundreths of
  111. seconds.
  112.  
  113. PHYS - total number of physical reads of buffers (from disk).
  114.  
  115. CR - number of buffers gotten for consistent read. A buffer is gotten
  116. for consistent read when a read consistent version of the data in the
  117. buffer is needed.  
  118.  
  119. In order to select a row out of a table, the buffer containing that row
  120. must be gotten for consistent read.  In order to update a row in a
  121. table, the buffer containing the row must be gotten for consistent
  122. read to verify the 'where' clause of the update. In order to read a
  123. value out of an index, the leaf block containing the value and all the
  124. branch blocks above the leaf block must be gotten for consistent read.
  125. A table scan requires getting all the buffers in the table for
  126. consistent read.
  127.  
  128. CUR - number of buffers gotten in current mode.  A buffer is gotten in
  129. current mode when the most recent version of the buffer is needed.
  130.  
  131. In order to insert a row into a buffer, the buffer must be gotten in
  132. current mode.  In order to update a row in a buffer, the buffer must be
  133. gotten in current mode. In order to insert or delete a value in an
  134. index, the leaf block containing the value and all the branch blocks
  135. above the leaf block must be gotten in current mode. (values in an
  136. index are updated by deleting the old value and inserting  the new
  137. one).  In order to perform a table scan, the segment header block for
  138. the table must be gotten in current mode.  Any time a change is made
  139. to either an index block or a table block, the appropriate transaction
  140. table must be gotten in current mode, and an undo block must be gotten
  141. in current mode. 
  142.  
  143. ROWS - total number of rows processed by the SQL statement. This
  144. number does not include the number of  rows processed by subqueries of
  145. the SQL statement.
  146.  
  147.  
  148. 4. Caveats
  149.  
  150. You should also be careful when adding up the statistics for several
  151. sql statements by hand to not double count statistics for recursive
  152. sql statements.  The cpu time, elapsed time, physical, consistent, and
  153. current reads for recursive sql statements are included in the
  154. statistics of the sql statement that caused the recursive execution.
  155. The rest of the statistics are not.
  156.  
  157. Another init.ora parameter that you should be aware of is
  158. max_dump_file_size.  It controls the maximum size that the trace files
  159. can grow to.  If your runs are long and you find that your trace
  160. files are overflowing, you should increase this value.
  161.  
  162. You should probably not look at the first few trace files that are
  163. created after starting a database.  They will contain disproportionate
  164. values until the various caches in the database get filled.
  165.  
  166. If you set the trace globally (in the init.ora file) you should make
  167. sure that the directory to which the trace files are being written has
  168. a high version limit on files.
  169.  
  170.  
  171. The current implementation of the profiling facility should be
  172. considered a prototype.  At some point in the future it will be
  173. reworked to dump statistics into the database rather than to trace
  174. files.  It is also possible that the tkprof program will be merged
  175. into SQL*DBA at some point in the future.
  176.  
  177.  
  178. 5. Sample Output of Tkprof
  179.  
  180.  
  181. This sample output is taken from oracle mail.
  182.  
  183. ============================================================================
  184. SELECT MSG_ID,MSG_NODE FROM M_HEADER MINUS(SELECT MSG_ID,MSG_NODE FROM M_INS
  185. TANCE UNION SELECT INCLUSION_ID,INCLUSION_NODE FROM M_HEADER UNION SELECT I
  186. NTR_ID,INTR_NODE FROM M_USER)
  187.  
  188.             count     cpu    elap    phys      cr     cur    rows
  189. Parse:          1      27      38       0      12       0
  190. Execute:        4    7842   13222    5961    6732    1112       0
  191. Fetch:         36    2306    2894     224     201     394     682
  192.  
  193. Execution plan:
  194. PROJECTION
  195.   MINUS
  196.     SORT (UNIQUE)
  197.       TABLE ACCESS (FULL) OF 'M_HEADER'
  198.     UNION
  199.       UNION
  200.         SORT (UNIQUE)
  201.           TABLE ACCESS (FULL) OF 'M_INSTANCE'
  202.         SORT (UNIQUE)
  203.           TABLE ACCESS (FULL) OF 'M_HEADER'
  204.       SORT (UNIQUE)
  205.         TABLE ACCESS (FULL) OF 'M_USER'
  206. ============================================================================
  207. DELETE FROM M_BODY WHERE MSG_ID=:b1 AND MSG_NODE=:b2 AND ROWNUM<:b3
  208.  
  209.             count     cpu    elap    phys      cr     cur    rows
  210. Parse:          1       1       0       0       0       0
  211. Execute:      662    6760   12988     998    5354   21142    2504
  212. Fetch:          0       0       0       0       0       0       0
  213.  
  214. Execution plan:
  215. COUNT
  216.   FILTER
  217.     INDEX (RANGE SCAN) OF 'M_BODY_KEY' (NON-UNIQUE)
  218. ============================================================================
  219. SELECT DISTINCT TYPE,MTA_NODE,FOR_DOMAIN FROM M_RECIPIENT M WHERE MSG_ID=:b1
  220.  AND MSG_NODE=:b2 AND TYPE BETWEEN 50 AND 99 AND NOT EXISTS(SELECT MSG_ID,M
  221. SG_NODE FROM T_INSTANCE T WHERE T.MSG_ID=:b3 AND T.MSG_NODE=:b4 AND M.MTA_N
  222. ODE=T.NODE_ID AND T.FOLDER_ID=1)
  223.  
  224.             count     cpu    elap    phys      cr     cur    rows
  225. Parse:        488    1823    2138       0       0       0
  226. Execute:      488    1623    1634       6    2041       0       0
  227. Fetch:        488      57      64       0       0       0      72
  228.  
  229. Execution plan:
  230. SORT (UNIQUE)
  231.   FILTER
  232.     TABLE ACCESS (BY ROWID) OF 'M_RECIPIENT'
  233.       INDEX (RANGE SCAN) OF 'M_RECP_KEY' (NON-UNIQUE)
  234.       INDEX (RANGE SCAN) OF 'T_INST_KEY' (NON-UNIQUE)
  235.