DBA手记:SQL_TRACE跟踪与诊断案例

2004年，笔者曾经帮客户处理过一则案例，其中涉及SQL_TRACE的使用，我们首先来回顾一下这个案例。

客户的应用是一个后台新闻发布系统，主要性能问题是通过连接访问新闻页极其缓慢，通常需要十数秒才能返回，这是用户不能忍受的。客户操作系统是SunOS 5.8，数据库版本为8.1.7。

面对这个问题，首先想到的是SQL问题，但如何定位具体的问题SQL成为我们考虑的主要目标，通过Statspack采样是一个全局手段，而通过sql_trace则可以实时对会话进行跟踪。诊断时是晚上，在无集中用户访问情况下，让用户在前台进行相关页面的访问，同时进行进程跟踪。

查询v$session视图，获取进程信息：

SQL> select sid,serial#,username from v$session where username is not null;

       SID    SERIAL# USERNAME

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

         7        284 IFLOW

        11        214 IFLOW

        12        164 SYS

        16       1042 IFLOW

然后对相应的应用会话启用sql_trace跟踪如下：

SQL> exec dbms_system.set_sql_trace_in_session(7,284,true)

SQL> exec dbms_system.set_sql_trace_in_session(11,214,true)

SQL> exec dbms_system.set_sql_trace_in_session(16,1042,true)

应用执行一段时间后，关闭sql_trace：

SQL> exec dbms_system.set_sql_trace_in_session(7,284,false)

SQL> exec dbms_system.set_sql_trace_in_session(11,214,false)

SQL> exec dbms_system.set_sql_trace_in_session(16,1042,false)

检查trace文件，可以找到跟踪过程中前台执行的SQL调用，检查发现以下语句是可疑的性能瓶颈点：

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

select auditstatus,categoryid,auditlevel from

 categoryarticleassign a,category b where b.id=a.categoryid and articleId=

  20030700400141 and auditstatus>0

 

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        1      0.81       0.81          0       3892          0           1

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

total        3      0.81       0.81          0        3892           0         1

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

这里的查询显然是根据articleId进行新闻读取的，但是注意到逻辑读有3892，这是较高的一个数字，这个内容引起了我的注意。

接下来的类似查询跟踪得到的执行计划显示，全表访问被执行：

select auditstatus,categoryid from

 categoryarticleassign where articleId=20030700400138 and categoryId in ('63',

  '138','139','140','141','142','143','144','168','213','292','341''-1')

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        1      4.91       4.91          0       2835          7           1

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

total        3      4.91       4.91          0       2835          7           1

 

Rows     Row Source Operation

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

      1 TABLE ACCESS FULL CATEGORYARTICLEASSIGN

登录数据库，检查相应表结构，看是否存在有效的索引，以下输出中的IDX_ARTICLEID基于ARTICLEID创建，但是在以上查询中都没有被用到：

SQL> select index_name,table_name,column_name from user_ind_columns

  2  where table_name=upper('categoryarticleassign');

INDEX_NAME                     TABLE_NAME                     COLUMN_NAME                   

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

IDX_ARTICLEID                  CATEGORYARTICLEASSIGN          ARTICLEID

IND_ARTICLEID_CATEG            CATEGORYARTICLEASSIGN          ARTICLEID                    

IND_ARTICLEID_CATEG            CATEGORYARTICLEASSIGN          CATEGORYID                   

IDX_SORTID                     CATEGORYARTICLEASSIGN          SORTID                       

PK_CATEGORYARTICLEASSIGN       CATEGORYARTICLEASSIGN          ARTICLEID                    

PK_CATEGORYARTICLEASSIGN       CATEGORYARTICLEASSIGN          CATEGORYID                   

PK_CATEGORYARTICLEASSIGN       CATEGORYARTICLEASSIGN          ASSIGNTYPE                   

检查如下表结构:

SQL> desc categoryarticleassign

 Name                                      Null?    Type

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

 CATEGORYID                                NOT NULL NUMBER

 ARTICLEID                                 NOT NULL VARCHAR2(14)

 ASSIGNTYPE                                NOT NULL VARCHAR2(1)

 AUDITSTATUS                               NOT NULL NUMBER

 SORTID                                    NOT NULL NUMBER

 UNPASS                                             VARCHAR2(255)

我们发现了问题所在，因为ARTICLEID是个字符型数据,查询中给入的articleId= 20030700400141 是一个数字值，Oracle发生潜在的数据类型转换，从而导致了索引失效：

SQL>  select auditstatus,categoryid

  2   from

  3    categoryarticleassign where articleId=20030700400132;

AUDITSTATUS CATEGORYID                                    

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

          9         94                                    

          0        383                                    

          0        695                                     

Execution Plan

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

   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=110 Card=2 Bytes=38)   

   1    0   TABLE ACCESS (FULL) OF 'CATEGORYARTICLEASSIGN' (Cost=110 Card=2 Bytes=38)  

解决方法很简单，只须在参数两侧各增加一个单引号，即可解决这个问题，对于类似的查询，我们发现Query模式读取降低为2，占用CPU时间也大大减少：

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

select unpass from

 categoryarticleassign where articleid='20030320000682' and categoryid='113'

 

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        1      0.00       0.00          0          2          0           0

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

total        3      0.00       0.00          0          2          0           0

 

Misses in library cache during parse: 1

Optimizer goal: CHOOSE

Parsing user id: 20 

 

Rows     Row Source Operation

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

      0  TABLE ACCESS BY INDEX ROWID CATEGORYARTICLEASSIGN

      1   INDEX RANGE SCAN (object id 3080)

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

至此，这个问题得到了完满的解决。