使用TKPROF

3.6.5 使用TKPROF(1)

TKPROF是个命令行工具,其主要作用是把原始跟踪文件作为输入,输出格式化的文本文件。另外,也能够生成SQL脚本来载入数据到数据库中,当然这个特性很少使用。

最简单的分析就是指定输入与输出文件并运行。在如下例子中,输入文件是 DBM11106_ ora_6334.trc,输出文件是DBM11106_ora_6334.txt,默认的输出文件扩展名为prf,不过我个人还是喜欢用txt。就我个人观点,最好使用有意义的扩展名,这样任何人任何操作系统都能正确识别。

不指定更多参数的分析只对分析很小的跟踪文件有帮助。多数情况下,要得到更好的输出,必须指定多个参数。

1. TKPROF参数

如果不带任何参数运行TKPROF,将得到完整的参数列表并带有简单的描

的功能如下。

explain指示TKPROF要为在跟踪文件中找到的每个SQL语句提供一个执行计划。这是通过执行SQL语句EXPLAIN PLAN(参见第6章以获取更多关于此语句的信息)来做到的。很明显,为了执行SQL语句,实际上需要连接到数据库。因而,该参数用来指定用户、密码,如果需要的话,还要指定数据库连接串。可接受的格式为explain=user/password@connect_string与explain=user/password。要注意为了尽可能地获取正确的执行计划,应该指定一个能访问同样对象的用户并且确保所有查询优化器初始化参数要和生成跟踪文件的数据是一样的。还要当心在运行时通过应用程序或者登录触发器改变的初始化参数。不是说你一定要用同样的用户,当然使用更好。任何情况下,即使前面的条件都符合了,EXPLAIN PLAN生成的执行计划也不一定和真实的一样(原因将在第6章解释),指定explain参数并不可取。如果指定了无效的用户名、密码、连接串,跟踪文件处理不会报告交互的错误信息,而是在输出文件头部会发现如下错误信

e只和explain参数一起使用。实际上,它的目的是用来指定哪个表被EXPLAIN PLAN语句使用来生成执行计划。通常需要避免指定它,因为TKPROF自动创建并删除用于分析的模式的prof$plan_table计划表,无论如何,如果用户不能创建表(例如,因为缺少CREATE TABLE权限),就必须指定table参数。例如,要指定必须使用system用户的plan_table表,参数必须设定为table=system.plan_table。执行分析的用户必须具有该表的SELECT、INSERT与DELETE权限,而且,在这个情况下,错误只出现在输出文件中。

警告 在Oracle 10gR1中,因为Bug 3451410的问题,TKPROF不能自动创建计划表,因而,将在输出文件的头部发现ORA-00922错误信息。这个问题在MetaLink文章"Tkprof Fails With Error In Create Table Of Explain Plan: Ora-922"(293481.1)中加以描述。

print用于限制输出文件生成的SQL语句的数量。默认是无限制的,只有在和参数sort(过一会儿会介绍)一起使用的时候才有意义。例如,只得到10个SQL语句,参数必须指定为print=10。

aggregate指定TKPROF是否单独处理同样内容的SQL语句。默认情况下,不单独处理。换句话说,属于某个特定SQL语句的信息是聚合在一起的。要注意在跟踪文件中每个SQL语句是独立处理的。任何聚合都会丢失信息。比如这样的案例,一个具有多个子游标的游标可能有不同的执行计划,但会当成一个SQL语句来处理。即使很多时候都采用默认值都不会有问题,但在有些时候最好是指定aggregate=no,以便能够看一下单独的每个SQL语句。

insert告诉TKPROF生成SQL脚本,SQL脚本可以用来存储信息到数据库中。SQL 脚本的名字由参数本身指定,如这里的:insert=load.sql。

sys指定sys用户运行的SQL语句(例如,解析操作阶段对数据字典的递归查询)是否也写入到输出文件中。默认值为yes,不过多数情况下我倾向于设为no,以避免不必要的输出信息。不必要是因为通常没办法控制sys用户递归执行的SQL语句。

record让TKPROF生成SQL脚本,里面包含在跟踪文件中找到的所有非递归语句,脚本名通过参数本身来指定(比如record=replay.sql)。根据文档,这个特性可以用来重演SQL语句。不过既然绑定变量不能处理,这通常是不可能的。

waits决定关于等待事件的信息是否添加到输出文件中。默认是添加的。我个人认为没必要指定waits=no,那样重要等待事件将不出现在输出文件中。

sort指定写入输出文件里的SQL语句的顺序。默认是跟踪文件中发现的SQL顺序。基本上,通过指定想要的选项,可以根据资源使用(比如,调用次数、CPU时间、物理读的数量等)或是响应时间(也就是,流逝的时间)进行排序。如你所见多数选项(比如流逝时间),对于每个类型的数据库调用都有可用的对应值。例如,prsela对一个游标解析耗费的时间,exeela针对游标执行花费的时间,以及fchela针对游标获取数据行所花费的时间。即使有多个选择与组合,只有一个排序方式真的对调查性能问题有用,即响应时间。因此,应该指定 sort=prsela, exeela,fchela。当指定逗号分隔的值的时候,TKPROF汇总这些作为参数传递进来的选项的值,即使彼此不兼容也是如此。要注意当跟踪文件包含若干个会话且指定aggregate=no的时候,SQL语句根据每个会话单独排序。

基于刚才提供的信息,我个人通常使用如下例子中的参数运行TKPR

白如何用TKPROF分析跟踪文件,让我们看一下生成的输出文件。
 

3.6.5 使用TKPROF(2)

2. 解释TKPROF 输出

分析是通过指定如下参数来做的。要注意这不是刚才建议的方式,只是为了演示一下输出内容。跟踪文件和输出文件都将随本章的其他文件一起提

头部内容开始。多数信息是固定的。不过,仍然存在有用的信息:跟踪文件的名字,sort参数值(用于生成输出文件),以及标记所跟踪会话的标记。最后一条信息的存在是因为指定了aggregate=no的缘故。注意当跟踪文件包含多个会话并且指定了aggregate=no的话,头部信息将在不同的会话间重复出现用以分隔

据库时发生的任何错误以及生成的执行计划紧随在头部信息后面出现。

头部内容之后,针对每个SQL语句提供如下信息:SQL 语句文本、执行统计、关于解析的信息、执行计划以及等待事件。执行计划以及等待事件是可选的,只有存储在跟踪文件中才会出现。记住,执行计划只有在游标关闭后才会被存储,等待事件只有在等待事件激活后才会被存储。

有些情况下SQL语句文本是格式化好的,遗憾的是,执行该操作的代码并不是在所有情形下都好用。例如,在这里的例子中,函数EXTRACT的关键词FROM与SQL语句的FROM子句相混淆。要注意,SQL语句的ID只有从Oracle 11g以

序的统计以表格的形式提供数据,这些数据根据数据库调用类型来聚合,提供的性能数字如下。

count表示执行的数据库调用数量。

cpu表示处理数据调用花去的CPU时间,以秒为单位。

elapsed是处理数据库调用花费的总的时间,以秒为单位,如果这个值比CPU时间高,下一节关于执行统计中的等待事件会提供在等待的资源或同步点。

disk表示物理读的数据块数量。要当心,这不是物理I/O操作的数量,物理I/O操作数在关于等待事件一节给出。如果这个值大于逻辑读的数量(disk > query +current),这意味着数据块填充进了临时表空间。在本例中,可以看到至少读取870个块(2590 1720 0)。这在后面关于行来源与等待事件会得到确认。

query是在一致性模式(consistent mode)下从高速缓存逻辑读取的块数量。通常,这类型的逻辑读用作查询。

current代表在当前模式下从高速缓存逻辑读取的块数量。通常,这类逻辑读被INSERT、DELETE、MERGE以及UPDATE等语句所使用。

rows代表处理的数据行数量。对于查询来说,这就是获取的行数量。对于INSERT、DELETE、MERGE以及UPDATE 等语句来说,这是所影响的行数量。在这个示例中,值得注意的是164 次调用获取(fetch)了16348行数据,这意味着平均每次调用处理100行,注意100是Oracle 10g在PL/SQL中的行预取(prefetch)的大小(第11章提供了关于预获取

行总结了关于解析的基本信息。开始两行(Misses in library cache)提供了发生在解析和执行调用阶段的硬解析数量。如果在执行调用时没有硬解析发生,这一行将不存在。接下来是优化器模式以及用于解析SQL语句的用户。要注意,用户名在本例中是ops$cha,只有在参数explain指定的时候才会提供。否则,只显示用户ID(本例中是33)。最后的信息是递归深度。只针对递归SQL语句提供。直接由应用程序执行的SQL语句深度为0。深度为n (本例为1)仅仅表示另一个深度为n 1(本例为0)的SQL语句执行了这条语句。在我们的例子中,深度为0的SQL语句是被SQL *Plus执行的

3.6.5 使用TKPROF(3)

在关于解析的常规信息之后,可以看到执行计划。事实上,如果指定了explain参数的话可能会看到两部分,第一部分被不够准确地称为行源操作(Row Source Operation ),是游标关闭且开启跟踪情况下写到跟踪文件中的执行计划。这意味着如果应用程序不关闭游标而重用它们的话,不会有新的针对重用游标的执行计划写入到跟踪文件中。第二部分,叫做执行计划 (Execution Plan),是由指定了explain参数的TKPROF生成的。既然这是随后生成的,所以和第一部分不一定完全匹配。万一你看到不一致,前者是正确的。

第6章讲述如何阅读执行计划。这里我只针对TKPROF的特性说明一下,两个执行计划都通过Rows列提供执行计划中每个操作返回的行数(不是处理的--要注意)。在本例中,表sales有918843行而根据跟踪文件仅返回540318行,这表示WHERE条件过滤了大约41%的行。此后的GROUP BY进一步减少结果到16348行。

对于每个行源操作来说,可能还会提供如下的运行时统计:

cr是一致性模式下逻辑读出的数据块数。

pr是从磁盘物理读出的数据块数。

pw是物理写入磁盘的数据块数。

time是以微秒表示的总的消逝时间。要注意根据统计得到的值不总是精确的。实际上,为了减少开销,可能用了采样。

cost是操作的评估开销。这个值只有在Oracle 11g才提供。

size是操作返回的预估数据量(字节数)。这个值只有在Oracle 11g才提供。

card是操作返回的预估行数。这个值只有在Oracle 11g才提供。

注意这些值,除了card,都是累计的,即,包括子行源操作的值。例如,在HASH GROUP BY操作中进入临时表空间的块数量为941(2590 1649)。从前面的执行统计看(参见关于disk列的讨论,可以预估只有870,这样多了71(941 870),这意味着71个进入临时表空间的块,在高速缓存不可以找到。这个数值也和TABLE ACCESS FULL操作提供的运行时统计相匹配。实际上,逻辑读和物理读的差值为71(17

下一节总结了SQL语句的等待事件,对每种类型的等待事件提供了如下值。

Times Waited是等待事件占用时间。

Max. Wait是单个等待事件最大等待时间,单位为秒。

Total Waited是针对一个等待事件总的等待秒数。理想情况下,所有等待事件的等待时间总量应该等于执行统计提供的流逝时间与CPU时间的差值。该差值,如果存在,叫做未说明的时间(unaccounted for time)。

未说明时间

SQL跟踪提供数据库在执行操作时消耗的时间。理想情况下,计算应该非常精确。不过,罕有发现跟踪文件给出秒级以下的精准信息。只要实际消耗时间与可说明时间有差异,就会存在未说明时间。

未说明时间=实际消耗时间 可说明时间

(unaccounted-for time = real elapsed time - accounted for time)

针对未说明时间最常见的原因如下。

最显而易见的原因是跟踪文件中缺少计时信息或是缺少等待事件。前者在初始化参数timed_ statistics设定为FALSE时候产生,后者当SQL跟踪在1或者4级激活的时候会遇到。两种情况下,未说明时间的值总是正的,自然,正确地激活SQL跟踪能够有助于避免这样的问题。

一般来说,一个进程可能有三种状态:在CPU上运行、等待对设备的请求完成,或是在运行队列中等待CPU。性能测量代码能够计算前面两种状态所费时间,但对于在运行队列中的等待时间却束手无策。因此,一旦CPU能力不够,就会产生未说明时间,它总是一个正的数值,且可能会比较长。基本上,可以通过两种方式避免该问题:增加可用CPU时间数量或是降低CPU使用率。

性能测量代码运行的时间度量是精确的。不过,因为计算机系统的计时器的实现问题使得每次度量存在很小的量化误差。尤其是当所度量的事件都很短暂的时候,量化误差就会导致比较明显的未说明时间。鉴于此,量化误差可能导致正的也可能是负的未说明时间。不幸的是,你对此无能为力。在实践中,既然正负可能抵消,这个问题很少导致更大的未说明时间。

如果能够忽略这里列出的三种原因,则可能是因为性能测量代码没有覆盖到全部代码。例如,写入到跟踪文件本身的没有纳入统计。这通常不是问题。如果跟踪文件写入到性能较差的设备或者跟踪信息产生得非常多,可能真的导致开销。在这样的情况下,未说明时间总是正的值。要避免这样的问题,应该简单地把跟踪文件写入能提供必要能力的设备上。有些极端情况下,可能必须要把跟踪文件写入RAM磁盘。

既然这些值是高度聚合的,能够有助于你了解在等待什么样的资源。例如,根据如下的信息,实际上所有的等待时间都消耗在执行物理读取上。事实上,db file sequential read是和单块读取相关的等待事件,db file scattered read是和多块读取相关的等待事件(关于多块读取的额外信息在第5章给出)。此外,direct path write temp与direct path read temp等待和临时表空间数据读写有关。注意等待数941和前面提供的行源操作的HASH GROUP BY物理写的数量相符。

<IMG class=fit-image onmousewheel="javascript:return big(this)" style="WIDTH: 498px" height=133 alt="" src="http://images.51cto.com/files/uploadimg/20091015/160407149.jpg" width=567 onload="javascript:if(this.width>498)this.style.width=498;" border=0> 

要分析等待事件,关键是要知道哪些操作是相关的。幸运的是,尽管有数百个等待事件类型,重复发生的大多都是常见的几种。可以在Oracle Database Reference手册的附录中找到关于多数常见等待事件的简短描述。

继续分析下一个SQL语句。信息结构和上一个是一样的,我将描述输出

 
3.6.5 使用TKPROF(4)

PL/SQL调用的执行统计是有限的。没有关于物理读与逻辑读的信息,这是因为被递归SQL语句(比如,前面分析的查询)消耗的资源与父SQL语句是不相关的,只能看到SQ
既然PL/SQL块没有被数据库递归执行,递归深度就没有显示(递归深度为0
 
数据库等待SQL*Net message to client表明网络层在发送数据给客户端(注意,实际通过网络发送数据的时间没包括在内),并且,在等待客户端数据的时候数据库在等待SQL*Net message from client的消息。因而,对于SQL*Net层带来每一个往返,应该能看到一对如此的等待事件。要注意低层带来的往返数可能是不同的。例如,网络层(如IP层)因为小尺寸数据包的缘故进
 
下一个SQL语句是数据库引擎递归执行的,用于获取对象使用情况信息(例如,对象统计)。查询优化器用这样的信息以及其他因素确定最有效的执行计划。可以确认这个SQL语句是数据库引擎执行的,因为它是SYS用户解析的。递归深度为2,可以设想一个深度为1的SQL语句的解析需要使用它,换句话说,第一个
 
既然用户SH对该SQL语句中涉及的对象没有权限,这里只显示了行源操作。关于执行EXPLAIN PLAN所需要的
 
在报告完所有的SQL语句之后,可以看总的执行统计以及解析与等待事件。唯一需
> 
接下来这几行汇总了属于当前会话的SQL语句数量,被数据库引擎递归调用了多少次,E
 
输出文件的结尾给出了所有关于跟踪文件的信息。首先可以看到跟踪文件名称、版本号、用于这个分析所使用的参数sort的值。然后,给出了所有会话数量与SQL语句数量。在这个特定案例中,既然指定了print=3参数,我们减少了979(928 3)条SQL语句的输出。关于执行EXPLAIN PLAN语句的表的信息也给出了。在最后,显示组成跟踪文件的行数,对于Oracle 10g,可以看到所有SQL语句用去的时间。我个人宁愿把这部分最后的信息当作输出文件的开头而不是在结尾。因为每次我打开一个TKPROF输出文件,都先浏览最后的行。知道整个跟踪文件消耗了多少时间是很关键的,没有这个,你无
 
posted @ 2011-06-08 23:03  大卫.宋  阅读(5000)  评论(0编辑  收藏  举报