Oracle具有打开一个相当底层的跟踪能力的工具,就是TKPROF。一旦启用跟踪,Oracle将所有的SQL和应用程序使用的顶层PL/SQL调用记录到服务器上的跟踪文件中。
启用TKPROF
在开始运行TFPROF之前需要开启一些设置,可以将其编辑称为一个脚本程序:starttfprof.sql,其中包含的内容:alter session set timed_statistics=true; alter session set events '10046 trace name context forever,level 12'; |
l 1启用了标准SQL_TRACE工具
l 4启用了SQL_TRACE并捕捉跟踪文件中的绑定变量的值
l 8启用了SQL_TRACE并捕捉跟踪文件的等待事件
l 12启用标准的SQL_TRACE并捕捉绑定变量和等待事件
运行TKPROF
启用了TKPROF以后,就可以执行你需要执行的SQL语句了。例如,我设计了一张大表,在OE用户下进行如下操作:Create table seagal_orders As Select * from orders Insert into seagal_orders Select * from seagal_orders 这样重复不断执行,直到seagal_orders表中有超过150万行记录为止,设计了一个大表,有百万条记录。但是其中包含非常多的重复的记录。(没关系) |
执行如下的操作:
SQL> select count(*) from oe.seagal_orders where customer_id=118; COUNT(*) ---------- 32768 |
然后,获得系统追踪文件:
SQL> select rtrim(c.value,'\') ||'\'||d.instance_name|| 2 '_ora_' ||ltrim(to_char(a.spid))||'.trc' 3 from v$process a,v$session b,v$parameter c,v$instance d 4 where a.addr=b.paddr 5 and b.audsid =sys_context('userenv','sessionid') 6 and c.name='user_dump_dest'; RTRIM(C.VALUE,'\')||'\'||D.INSTANCE_NAME||'_ORA_'||LTRIM(TO_CHAR(A.SPID))||'.TRC' ---------------------------------------------------------------------------------- E:\ORACLE\PRODUCT\10.2.0\ADMIN\MYORACLE\UDUMP\myoracle_ora_3708.trc |
追踪文件的名字为myoracle_ora_3708.trc。
生成TKPROF报告
在命令行提示符下,执行:C:\>tkprof E:\ORACLE\PRODUCT\10.2.0\ADMIN\MYORACLE\UDUMP\myoracle_ora_3708.trc c:\tk.prof TKPROF: Release 10.2.0.1.0 - Production on 星期一 3月 19 22:44:44 2007 Copyright (c) 1982, 2005, Oracle. All rights reserved. C:\> |
生成的报告文件存储在C盘,文件名称为:tk.prof
阅读TKPROF报告
这是一个文本文件,可以通过记事本或者EditPlus工具打开,阅读.报告的内容很长,需要自己阅读,下面截取一部分:select count(*) from oe. seagal _orders where customer_id=118 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 74 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.10 0.11 0 10360 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.10 0.11 0 10434 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Rows Row Source Operation ------- --------------------------------------------------- 1 SORT AGGREGATE (cr=10360 pr=0 pw=0 time=114189 us) 32768 TABLE ACCESS FULL MYORDERS (cr=10360 pr=0 pw=0 time=131132 us) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.00 ******************************************************************************** |
这部分就是刚才执行的查询语句的执行分析报告,理解这个报告需要首先了解一些基本的设置:
查询的三个主要阶段为:
1. 分析(Parse):此阶段是Oracle在共享池中找到该查询(软分析)或创建该查询的新计划(硬分析)的所在。
2. 执行(Execute):此阶段是由Oracle在该查询的OPEN或者EXECUTE语句中做的工作。对于SELECT语句,在许多情况下此阶段为空。对于UPDATE语句,此阶段将是执行所有工作的所在。
3. 提取(Fetch):对于SELECT语句,大多数工作将在此阶段进行。对于UPDATE语句,将不显示任何工作(因为不从更新操作中提取)。
在报告的顶部可以看到的一些信息说明:
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
解释如下:
l 计数(Count)――查询在此阶段执行的次数。
l CPU(cpu)――该查询在此阶段花费的CPU时间量,以毫秒为单位。
l 占用时间(Elapsed)――花费在此阶段的挂钟时间。当花费的时间大于CPU时间时,就意味着为某些事件耗费了等待时间。
l 磁盘(Disk)――查询在此阶段中执行物理IO的次数。
l 查询(Query)――检索一致方式时执行逻辑IO的次数。那些块是从回滚段中重构的块。如果在查询开始时它们存在就可以看到。
l 当前(current)――到目前为止检索块时所执行的逻辑IO的次数。
l 行(Row)――此阶段中被处理或者受影响的行数。在更改操作中,将看到Exceute阶段的Rows值。在SELECT查询中,该值出现在Fetch阶段。
在报告中还可以看到一些信息:
Cr――表示为一致方式读取,显示一致读取数(逻辑IO)
R――物理读取
W――物理写
Time――以百万分之一秒计数的时间占用,即us秒(微秒)