如何追踪其他SESSION会话信息

 

今天测试说在加载条目数据、校验数据和质检数据的时候很慢，但是又不知道这些操作的具体SQL是什么，很难分析，应用程序用的是weblogic中间件，session很难跟踪，只好追踪整个库的会话情况，由于整库跟踪需要前台只有一个人操作，跟踪结果才准确，如果多人操作，对跟踪结果会有影响，需要和测试人员约好时间，目前还未开始正式测试性能，所以以下操作都是在本人电脑上实验。

利用dbms_monitor追踪SESSION，如果在程序里指定CLIENT_ID，追踪起来相对简单些，可以使用CLIENT_ID_STAT_ENABLE来追踪，但是程序别没有指定，那么追踪单个SESSION的信息，就需要用SESSION_TRACE_ENABLE来追踪，但是WEBLOGIC连接池很可能连接数据库的不是同一个SESSION，没法确定SID和SERIAL#,也没法使用，只好使用DATABASE_TRACE_ENABLE进行整个数据库的跟踪，下面分别对SESSION_TRACE_ENABLE和DATABASE_TRACE_ENABLE进行演示。

首先演示利用SESSION_TRACE_ENABLE追踪SESSION的用法，首先需要查到要追踪会话的SID和SERIAL#。

SQL> select sid, serial# from v$session where sid in (select sid from

  2  v$mystat where rownum = 1);

       SID    SERIAL#

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

       144          5

         启动会话跟踪。

SQL> exec dbms_monitor.session_trace_enable(144, 5, true, true);

PL/SQL 过程已成功完成。

         做一些操作，让dbms_monitor追踪到。

SQL> select count(*) from user_objects;

  COUNT(*)

----------

        52

SQL> select count(*) from tab;

  COUNT(*)

----------

        34

         停止追踪。

SQL> exec dbms_monitor.session_trace_disable(144,5);

PL/SQL 过程已成功完成。

         找到SID=144,SERIAL#=5的SESSION对应的操作系统进程号，通过操作系统进程号，找到生成的TRACE文件。

SQL> select spid from v$process p, v$session s where

s.paddr = p.addr and sid =144;

SPID

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

5360

    我的数据库是11gR2版本，需要到$ORACLE_BASE/diag/rdbms/$ORACLE_SID/$ORACLE_SID/trace目录下查找TRACE文件，10G默认是在UDUMP目录下。

 

D:\oracle\diag\rdbms\stream\stream\trace>dir stream_ora_5360*

2011-12-22  15:41            73,459 stream_ora_5360.trc

2011-12-22  15:41               366 stream_ora_5360.trm

    直接打开TRACE文件，内容很多，而且格式很乱，像我这个水平很难看得懂，使用ORACLE的tkprof工具格式化之后，就很容易阅读了。

D:\oracle\diag\rdbms\stream\stream\trace>tkprof stream_ora_5360.trc

stream_5306.txt sys=no

TKPROF: Release 11.2.0.1.0 - Development on 星期四 12月 22 15:56:47 2011

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

    这样TKPROF工具会把格式化后的内容保存到stream_5306.txt文件内，指定sys=no表示由sys用户执行的SQL不统计，下面贴部分格式化后的文件内容。

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

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

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

    此部分是对下面的列标识的解释。

SQL ID: c30rfcmq0b6s0

Plan Hash: 0

BEGIN dbms_monitor.session_trace_enable(144, 5, true, true); END;

call    count  cpu   elapsed  disk   query   current  rows

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

Parse      0   0.00     0.00     0       0         0     0

Execute    1   0.01     0.03     1      51         0     1

Fetch      0   0.00     0.00     0       0         0     0

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

total      1   0.01     0.03     1      51         0     1

Misses in library cache during parse: 0

Misses in library cache during execute: 1

Optimizer mode: ALL_ROWS

Parsing user id: 95 

Elapsed times include waiting on following events:

  Event waited on                 Times   Max. Wait  Total Waited

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

  SQL*Net message to client            1        0.00          0.00

  SQL*Net message from client          1       85.75         85.75

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

    此部分记录的是打开SESSION跟踪命令的信息，主要是SQL解析多少次，SQL执行多少此，占用的资源和哪些等待信息。

SQL ID: 8x615vyks733p

Plan Hash: 1218565518

select count(*) from user_objects

call    count  cpu  elapsed  disk  query  current  rows

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

Parse       1  0.03    0.06     0      0        0     0

Execute     1  0.00    0.00     0      0        0     0

Fetch       2  0.04    0.05     1    978        0     1

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

total       4  0.07    0.11     1    978        0     1

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 95 

    此部分和上面一样，列出了SQL的一些执行信息，下面是该SQL的执行计划。

Rows     Row Source Operation

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

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

     52   VIEW  USER_OBJECTS (cr=978 pr=1 pw=0 time=1938 us cost=263 size=0 card=2360)

     52    UNION-ALL  (cr=978 pr=1 pw=0 time=1683 us)

     52     FILTER  (cr=977 pr=0 pw=0 time=1122 us)

     61      HASH JOIN  (cr=946 pr=0 pw=0 time=840 us cost=262 size=268922 card=2537)

     96       INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=285 us cost=1 size=2112 card=96)(object id 47)

     61       TABLE ACCESS FULL OBJ$ (cr=945 pr=0 pw=0 time=0 us cost=261 size=213108 card=2537)

      7      TABLE ACCESS BY INDEX ROWID IND$ (cr=31 pr=0 pw=0 time=0 us cost=2 size=8 card=1)

     16       INDEX UNIQUE SCAN I_IND1 (cr=18 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 41)

      0      NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=29 card=1)

      0       INDEX FULL SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)(object id 47)

      0       INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=1 size=9 card=1)(object              id 39)

      0     INDEX RANGE SCAN I_LINK1 (cr=1 pr=1 pw=0 time=0 us cost=1 size=12 card=3)(object id 137)

    这个SQL执行计划可够详细的，连递归调用的都列出来了，在下面就是一些等待信息。

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               1   0.01          0.01

  SQL*Net message from client           2  11.97         11.97

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

    此TRACE文件的其他内容都和这个差不多，不在列举，下面说下利用DATABASE_TRACE_ENABLE进行整库级的追踪，和用SESSION_TRACE_ENABLE的用法一样，首先打开追踪。

SESSION 1>exec dbms_monitor.database_trace_enable(true,true);

PL/SQL 过程已成功完成。

    然后在查看这个SESSION的进程号，方便查找TRACE文件。

可以看到SESSION 2，进程号为1004的会话并没有被追踪到，SESSION 1和SESSION 3的会话信息被追踪到，下面用tkprof格式化SESSION 1生成的TRACE文件。

D:\oracle\diag\rdbms\stream\stream\trace>tkprof stream_ora_1544.trc stream_1544.txt sys=no

TKPROF: Release 11.2.0.1.0 - Development on 星期一 12月 26 10:46:56 2011

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

    格式化后，查看SESSION 1格式化后的信息,限于篇幅，只列举追踪到的SQL语句。

1：SQL ID: 3p2jjjccp3rsd

Plan Hash: 0

BEGIN dbms_monitor.database_trace_enable(true,true); END;

2：SQL ID: c4v426hbuhmt2

Plan Hash: 1985757361

select spid

from

 v$process p, v$session s where s.paddr = p.addr and sid =(select sid from

  v$mystat where rownum = :"SYS_B_0")

3：SQL ID: a026j4p77v02a

Plan Hash: 0

BEGIN dbms_monitor.database_trace_disable; END;

    在看下SESSION 3格式化后的信息。

1：SQL ID: c4v426hbuhmt2

Plan Hash: 1985757361

select spid from v$process p, v$session s where s.paddr = p.addr and sid =(select sid from v$mystat where rownum = :"SYS_B_0")

2：SQL ID: f6kwymknrt7z1

Plan Hash: 1067070269

select count(*) from tab

    还有写SQLPLUS自动执行的SQL也会被追踪到，还有些递归调用的SQL，这些SQL这里没有列举，可以在未被tkprof格式化的TRACE文件里通过dep不等于0查到，dep=0表示未递归的SQL。

    在格式化后的TRACE文件里，可以看到USER_ID，这表示这个SQL是被哪个USER执行的，例如：

SESSION 1的TRACE文件的USER_ID信息。

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 95 

SESSION 3的TRACE文件USER_ID信息。

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 104 

    查看这两个USER_ID对应的是哪个用户。

SQL>select username,user_id from dba_users where user_id in(104,95);

USERNAME                          USER_ID

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

STREAM                                 95

META                                  104

    SESSION 1我是用STREAM用户登录的，SESSION 2我是用THAMS用户登录的，SESSION 3我是用META用户登录的，SESSION 2的信息没有被追踪到，在TRACE文件的最下面ORACLE还对这个SESSION的信息做了总结，描述的非常详细。

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call       count   cpu  elapsed  disk  query  current   rows

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

Parse          41  0.00     0.00     0      0       0      0

Execute        45  0.01     0.03     0     22       2      2

Fetch          97  0.00     0.04     5    144       0     66

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

total      183     0.01     0.07     5    166       2     68

Misses in library cache during parse: 0

Elapsed times include waiting on following events:

  Event waited on                 Times   Max. Wait  Total Waited

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

  Disk file operations I/O             1        0.00          0.00

  db file sequential read              5        0.01          0.04

   16  user  SQL statements in session.

   37  internal SQL statements in session.

   53  SQL statements in session.

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

Trace file: stream_ora_2460.trc

Trace file compatibility: 11.1.0.7

Sort options: default

       1  session in tracefile.

      16  user  SQL statements in trace file.

      37  internal SQL statements in trace file.

      53  SQL statements in trace file.

      42  unique SQL statements in trace file.

    1209  lines in trace file.

      40  elapsed seconds in trace file.

    很多时候，比如我的这个项目，测试的就说数据库慢，可是又不清楚客户操作调用的是哪些SQL，就可以对测试人员的操作做下追踪，更直接更准确的定位问题SQL，ORACLE提供的工具有些还是很好用的。