ITPub博客

首页 > 数据库 > Oracle > 跟踪session 与 trace文件分析

跟踪session 与 trace文件分析

原创 Oracle 作者:lovehewenyu 时间:2013-10-11 11:43:22 0 删除 编辑

跟踪SESSION  trace 文件解析

 

我这里是通过学习EygleBLOG中使用DBMS_SUPPORT包跟踪SESSION来生成跟踪文件,然后分析问题。怎么用利用DBMS_SUPPORT跟踪session,这里有Eygle的连接,很详细了。http://www.eygle.com/archives/2004/06/dbms_support.html

我们这里主要学习一下分析生成的跟踪文件。

 

[ora@dg-pp udump]$ tkprof research_ora_3418.trc b.txt sys=no

 

上面这条命令:sys=no 只是为了咱们分析session更方便罢了,把所有sys用户执行的SQL不显示出来,如果这个文件research_ora_3418.trc 不用tkprof  格式化输出的话,我们是很难分析的。tkprof工具为我们分析trace文件起到了很大的作用。 

TKPROF: Release 10.2.0.1.0 - Production on Mon Apr 2 01:11:52 2012

 

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

 

 

[ora@dg-pp udump]$ cat b.txt

 

TKPROF: Release 10.2.0.1.0 - Production on Mon Apr 2 01:11:52 2012

 

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

 

Trace file: research_ora_3418.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

********************************************************************************

 

 

The following statement encountered a error during parse:

 

select tname,tabtype from tab where tabtype='TABLE' rownum<2

 

Error encountered: ORA-00933 (这里记录的是执行的SQL和报错,我们这里是执行的语法错误,很智能哦,ORACLE先告诉你什么错误,然后写出SQL,再描述报错信息)

********************************************************************************

 

select count(*)

from

 tab

 

这里记录我们执行的SQL,并记录了一些消耗信息。便于我们分析。

 

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.01       0.00          0          0          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch        2      0.05       0.01          1        812          0           1

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total        4      0.06       0.01          1        812          0           1

 

Misses in library cache during parse: 1 #shared pool 中没有命令,说明做了1次硬解析,软解析此处为0

Optimizer mode: ALL_ROWS (优化器采用的模式)

Parsing user id: 56 

 

Rows     Row Source Operation

-------  ---------------------------------------------------

      1  SORT AGGREGATE (cr=812 pr=1 pw=0 time=10130 us)

    183   NESTED LOOPS OUTER (cr=812 pr=1 pw=0 time=8125 us)

    183    TABLE ACCESS FULL OBJ$ (cr=610 pr=0 pw=0 time=6574 us)

     13    TABLE ACCESS CLUSTER TAB$ (cr=202 pr=1 pw=0 time=3512 us)

     16     INDEX UNIQUE SCAN I_OBJ# (cr=185 pr=1 pw=0 time=1819 us)(object id 3)

 

cr是一致性模式下逻辑读出的数据块数。
pr是从磁盘物理读出的数据块数。
pw是物理写入磁盘的数据块数。
time是以微秒表示的总的消逝时间。要注意根据统计得到的值不总是精确的。实际上,为了减少开销,可能用了采样。
cost是操作的评估开销。这个值只有在Oracle 11g才提供。
size是操作返回的预估数据量(字节数)。这个值只有在Oracle 11g才提供。
card是操作返回的预估行数。这个值只有在Oracle 11g才提供。

 

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

  db file sequential read                         1        0.00          0.00

  SQL*Net message from client                     3        0.00          0.00

  SQL*Net break/reset to client                   2        0.00          0.00

********************************************************************************

 

select tname,tabtype

from

 tab where tabtype='TABLE'  and rownum<2

 

 

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.01       0.00          0          2          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch        2      0.00       0.00          0        611          0           1

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total        4      0.01       0.00          0        613          0           1

 

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 56 

 

Rows     Row Source Operation

-------  ---------------------------------------------------

      1  COUNT STOPKEY (cr=611 pr=0 pw=0 time=580 us)

      1   NESTED LOOPS OUTER (cr=611 pr=0 pw=0 time=564 us)

      1    TABLE ACCESS FULL OBJ$ (cr=608 pr=0 pw=0 time=511 us)

      1    TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=32 us)

      1     INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=13 us)(object id 3)

 

 

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

********************************************************************************

 

select count(*)

from

 HB_EMAIL_TEST20120405

 

 

call     count       cpu    elapsed       disk      query   current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.01       0.00          0          0          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch        2      0.79       0.20       3840       7591          1           1

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total        4      0.80       0.20       3840       7591          1           1

 

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 56 

 

Rows     Row Source Operation

-------  ---------------------------------------------------

      1  SORT AGGREGATE (cr=7591 pr=3840 pw=0 time=201751 us)

 597354   TABLE ACCESS FULL HB_EMAIL_TEST20120405 (cr=7591 pr=3840 pw=0 time=4816013 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

  db file sequential read                         3        0.00          0.00

  db file parallel read                           1        0.03          0.03

  db file scattered read                        480        0.00          0.05

  SQL*Net message from client                     2        0.00          0.00

 

 

 

********************************************************************************

 

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

 

(统计全部不递归声明,这个可以综合等待事件和解析语法来观察。)

 

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        3      0.04       0.00          0          2          0           0

Execute      3      0.00       0.00          0          0          0           0

Fetch        6      0.84       0.21       3841       9014          1           3

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total       12      0.88       0.22       3841       9016          1           3

 

Misses in library cache during parse: 3

 

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited

  ----------------------------------------   Waited  ----------  ------------

  db file sequential read                         4        0.00          0.00

  SQL*Net message to client                      13        0.00          0.00

  SQL*Net message from client                    13        7.07         21.11

  SQL*Net break/reset to client                   2        0.00          0.00

  db file parallel read                           1        0.03          0.03

  db file scattered read                        480        0.00          0.05

 

 

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

(统计全部递归声明,这个可以综合等待事件和解析语法来观察。)

 

 

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse       36      0.04       0.00          0          0          0           0

Execute    206      0.21       0.04          0          0          0           0

Fetch      226      0.11       0.01         43        615          0         428

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total      468      0.37       0.07         43        615          0         428

 

Misses in library cache during parse: 25

Misses in library cache during execute: 25

 

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited

  ----------------------------------------   Waited  ----------  ------------

  db file sequential read                        43        0.00          0.00

 

    3  user  SQL statements in session.

  206  internal SQL statements in session.

  209  SQL statements in session.

********************************************************************************

Trace file: research_ora_3418.trc

Trace file compatibility: 10.01.00

Sort options: default

 

1         session in tracefile.

一个会话

       3  user  SQL statements in trace file.

用户3SQL

     206  internal SQL statements in trace file.

内部206 SQL

     209  SQL statements in trace file.

209 SQL语句

      28  unique SQL statements in trace file.

28唯一SQL

    2368  lines in trace file.

      14  elapsed seconds in trace file.

总事件14

 

输出文件的结尾给出了所有关于跟踪文件的信息。首先可以看到跟踪文件名称、版本号、用于这个分析所使用的参数sort的值。然后,给出了所有会话数量与SQL语句数量。

总结:使用包dbms_support跟踪session (也可以用来跟踪SQL):

1、可以记录session执行每一条SQL 3个动作(语法分析,执行,取出)消耗的CPU时间,总时间,物理读,一致性读缓存区统计,current,所有执行和取出进程数。

2、没有软解析的次数,优化器选择模式,用户ID

3、Row来源和消耗:逻辑读出的数据块数,物理读出的数据块数,写入的数据库块数。

4、等待事件,递归或不递归查询,最后统计会话的SQL语句多少条,内部执行多少条(这里让我对一个SQL执行有了更深的了解,一条SQL执行,要先进行这么多内部SQL,真的很神奇)

感谢以下3位老师

本文参考:http://czmmiao.iteye.com/blog/1493765  (czmmiao)

http://www.eygle.com/archives/2004/06/dbms_support.html(eygle)

http://blog.csdn.net/tianlesoftware/article/details/5857023 (tianlesoftware)

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/26442936/viewspace-774138/,如需转载,请注明出处,否则将追究法律责任。

下一篇: 手工创建数据库
请登录后发表评论 登录
全部评论
10年老鸟,Oracle,Mysql,EMC 存储,NBU备份

注册时间:2012-02-03

  • 博文量
    268
  • 访问量
    1296460