Oracle的SQL_TRACE使用

DBA小记 2020-10-27

1489

SQL_TRACE是Oracle提供的一个非常实用的跟踪工具，当用户想了解一条SQL的运行情况时，特别是数据库性能非常差的时候。SQL_TRACE主要是用来检查数据库的异常情况，通过跟踪数据库的活动，查看SQL的执行情况，用户就能够比较容易的知道当前正在执行的SQL究竟在做什么。

一、概述

打开SQL_TRACE就可以逐步捕获任何一个会话的数据库活动，或者捕获整个数据库的活动，并将数据库活动记录成跟踪文件（每次使用完之后需要关闭跟踪，否则会降低系统的性能），通过读取trace文件了解SQL执行过程中Oracle做了哪些事。

二、用法

1、全局启用

在参数文件(pfile/spfile)中指定:

sql_trace =true

或者：

alter system set sql_trace=true;

在全局启用SQL_TRACE会导致所有进程的活动被跟踪，包括后台进程及所有用户进程，这通常会导致比较严重的性能问题，所以在生产环境中要谨慎使用，这个参数在10g之后是动态参数，可以随时调整，在某些诊断中非常有效。

2、当前SESSION启用

使用SQL_TRACE跟踪当前会话，通过跟踪当前会话可以发现当前操作的后台数据库递归活动，研究SQL执行过程，发现执行错误等。

在SESSION级启用和停止SQL_TRACE方式如下:

启用当前session的跟踪:

#设置SQL_TRACE生成的文件标识，便于查找
SQL> alter session set tracefile_identifier='my_sql_trace';
Session altered
SQL> alter session set sql_trace=true;
Session altered.
此时的SQL操作将被跟踪:
SQL> select count(*) from dba_objects;
  COUNT(*)
----------
        74449
结束跟踪:
SQL> alter session set sql_trace=false;
Session altered.
SQL>  host ls -ltr oracle/app/oracle/diag/rdbms/xddb/xddb/trace|tail -2
-rw-r----- 1 oracle oinstall      157 Aug 21 13:53 xddb_ora_19384_my_sql_trace.trm
-rw-r----- 1 oracle oinstall     5476 Aug 21 13:53 xddb_ora_19384_my_sql_trace.trc

3、跟踪指定会话

很多时候需要跟踪其他会话的进程，而不是当前会话，这可以通过Oracle提供的系统包DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION来获取。

SET_SQL_TRACE_IN_SESSION程序要提供三个参数

SQL> desc dbms_system 
PROCEDURE SET_SQL_TRACE_IN_SESSION
 Argument Name                  Type                  In/Out Default?
 ------------------------------ ----------------------- ------ --------
 SID                        NUMBER                  IN
 SERIAL#                  NUMBER                  IN
 SQL_TRACE                  BOOLEAN             IN

如果需要跟踪一个指定的会话，首先需要获取会话的SID和Serial#，这些信息可以在视图V$SESSION中获得。

SQL> select sid,serial#,username from v$session;
       SID    SERIAL# USERNAME
---------- ---------- ------------------------------
      493       11023 SYS
      10      10387 TEST

获取了这两个参数，就可以运行以下命令：

设置跟踪:
SQL>  exec dbms_system.set_sql_trace_in_session(10,10387,true);
PL/SQL procedure successfully completed.
等候片刻，跟踪session执行任务,捕获sql操作后的TRACE文件。
停止跟踪:
SQL>  exec dbms_system.set_sql_trace_in_session(10,10387,false);
PL/SQL procedure successfully completed.
SQL> host ls -ltr oracle/app/oracle/diag/rdbms/xddb/xddb/trace|tail -2
-rw-r----- 1 oracle oinstall      967 Aug 21 13:43 xddb_ora_19400.trm
-rw-r----- 1 oracle oinstall    45595 Aug 21 13:43 xddb_ora_19400.trc

注：11g中新增的trm文件

.trc文件称为Sql Trace Collection file，它是系统的跟踪文件(trace),当系统启动时或运行过程中出现错误时,系统会自动记录跟踪文件到指定的目录,以便于检查,这些文件需定期维护删除。

.trm file 全称是trace map file. 被称为跟踪元数据文件，.trm文件中的元数据描述了存储在.trc文件中的跟踪记录。

.trm文件是伴随着.trc文件产生，一个.trm对应一个.trc文件。.trm文件包含.trc文件的结构化信息。

The files located in the TRACE directory, with the “.trm” extensions, are called Trace Metadata files. The metadata in .trm files describe the trace records stored inside of .trc trace files.

三、跟踪文件的位置

会话激活了SQL_TRACE，ORACLE就会在udump管理区创建跟踪文件，文件的目标位置由参数user_dump_dest来确定。

SQL> show parameter user_dump_dest
NAME                             TYPE       VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest                       string       oracle/app/oracle/diag/rdbms/xddb/xddb/trace

也可以通过SQL来查找TRACE文件名。

SQL>  select s.SID,
       s.SERVER,
       lower(case
               when s.SERVER in ('DEDICATED', 'SHARED') then
                i.INSTANCE_NAME || '_' || nvl(pp.SERVER_NAME, nvl(ss.NAME, 'ora')) || '_' ||
                p.SPID || '.trc'
               else
                null
             end) as trace_file_name
  from v$instance      i,
       v$session       s,
       v$process       p,
       v$px_process    pp,
       v$shared_server ss
 where s.PADDR = p.ADDR
   and s.SID = pp.SID(+)
   and s.PADDR = ss.PADDR(+)
   and s.TYPE = 'USER'
   and s.SID = '10'      --上边指定会话的SID
 order by s.SID ;
       SID SERVER    TRACE_FILE_NAME
---------- --------- --------------------------------------------------
      10 DEDICATED xddb_ora_19400.trc

四、TKPROF工具

我们可以通过使用TKPROF工具来处理TRACE文件，这样可读性比编译查看效果更好。tkprof是Oracle自带的一个工具，本身就是处理TRACE文件使用，作用是合并汇总TRACE文件的一些关键项，规范化的文件输出。

[oracle@ TEST-16 ~]$ export PS1='[\u@\h `pwd`]\$'   --显示全路径
[oracle@ TEST-16 home/oracle]$cd oracle/app/oracle/diag/rdbms/xddb/xddb/trace
[oracle@TEST-16 oracle/app/oracle/diag/rdbms/xddb/xddb/trace]$tkprof xddb_ora_19400.trc test.txt
[oracle@TEST-16 oracle/app/oracle/diag/rdbms/xddb/xddb/trace]$ more test.txt

执行后，会生成test.txt文件，阅读更加方便。

tkprof工具有很多参数，一些特定参数会使用到，使可读性更全面。

[oracle@TEST-16 ~]$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  waits=yes|no     Record summary for any wait events found in the trace file.
  sort=option      Set of zero or more of the following sort options:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
userid  userid of user that parsed the cursor

几个常用参数介绍：

1）explain= user/password

Connect to ORACLE and issue EXPLAIN PLAN.

不指定参数explain输出，可以看到SQL实际的执行路径：

$ tkprof xddb_ora_19723_my_sql_trace.trc test_out.txt
********************************************************************************
SQL ID: 7b2twsn8vgfsc Plan Hash: 1950795681
select count(*)
from
 test


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.08       0.08          0       3139          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.08       0.08          0       3139          0           1


Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 128 
Number of plan statistics captured: 1


Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=3139 pr=0 pw=0 time=83741 us)
    227626     227626     227626   TABLE ACCESS FULL TEST (cr=3139 pr=0 pw=0 time=146077 us cost=855 size=0 card=227626)


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

如果使用explain参数，不但输出SQL的实际执行路径，还会生成该SQL的执行计划。

$ tkprof xddb_ora_19723_my_sql_trace.trc test_out.txt explain=test/test
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=3139 pr=0 pw=0 time=83741 us)
    227626     227626     227626   TABLE ACCESS FULL TEST (cr=3139 pr=0 pw=0 time=146077 us cost=855 size=0 card=227626)
Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   SORT (AGGREGATE)
 227626    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'TEST' (TABLE)

2）sys=(yes|no)

如果设置为yes,在trace文件中将输出所有SYS用户的操作（也包含用户SQL语句引发的递归SQL），如果为no,则不输出。默认为yes，如果设置为no,trace文件更具有可读性。在SQL的解析过程中，需要访问一些数据字典视图，通常来讲我们可能不需要用到，可以使用 tkprof sys=no的方式屏蔽掉它们。

3）aggregate=yes|no

默认情况下，tkprof工具将所有相同的sql在输入文件中做合并，如果设置aggregate=no ,则分别列出每个sql的信息。

默认yes的情况，就是合并后的SQL，这样看起来比较简洁，如果你需要每一个SQL的单独信息，可以把aggregate设置为no，可以看到每条SQL的执行清理。

五、TRACE文件解读

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
********************************************************************************

trace文件的头部信息描述了tkprof的版本，以及报告中一些列的含义。

********************************************************************************
SQL ID: 7b2twsn8vgfsc Plan Hash: 1950795681
select count(*)
from
 test


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       2      0.08       0.08          0       3139          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.08       0.08          0       3139          0           1


Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 128  (TEST)
Number of plan statistics captured: 1


Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=3139 pr=0 pw=0 time=83741 us)
    227626     227626     227626   TABLE ACCESS FULL TEST (cr=3139 pr=0 pw=0 time=146077 us cost=855 size=0 card=227626)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   SORT (AGGREGATE)
 227626    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'TEST' (TABLE)
********************************************************************************

parse（分析）：SQL的分析阶段
execute（执行）：SQL的执行阶段
fetch（数据提取）：数据的提取阶段

其他列，还包含如下信息。

Count：计数器，表示当前的操作被执行了多少次
Cpu：当前的操作消耗CPU的时间（单位秒）
Elapsed：当期的操作一共用时多少（包括CPU时间和等待时间）
Disk：当前操作的物理读（磁盘I/O次数）
Query：通常是查询的使用方式，当前操作的一致性方式读取的数据块数
Current：通常是修改数据使用的方式，当前操作的current的方式读取的数据块数
Misses in library cache during parse：是指是不是重用了执行计划,如果同一条SQL语句第二次执行,为软解析，其值为0,这里是1,表示在共享池（shared pool）里没有这一条SQL的执行计划,发生了一次硬解析。
Optimizer：优化器模式 CBO的ALL_ROWS
Parsing user id：分析的用户ID
Rows：当前操作实际处理的数据记录数
Row Source Operation：行源操作，表示当前操作的数据访问方式
cr：一致性读取的数据块,相当于query列上Fetch步骤的值
pr：物理读取的数据库, 相当于disk列上的Fetch步骤的值
pw：物理写
time：当前操作的执行时间

oracle

文章转载自DBA小记，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

Oracle的SQL_TRACE使用

评论