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)
********************************************************************************
至此,这个问题得到了完满的解决。
扫一扫订阅我的微信号:IT技术博客大学习
- 作者:eygle 来源: Oracle Life
- 标签: SQL_TRACE
- 发布时间:2011-03-02 22:54:34
- [55] IOS安全–浅谈关于IOS加固的几种方法
- [55] Oracle MTS模式下 进程地址与会话信
- [54] 如何拿下简短的域名
- [53] android 开发入门
- [52] Go Reflect 性能
- [52] 图书馆的世界纪录
- [49] 读书笔记-壹百度:百度十年千倍的29条法则
- [48] 【社会化设计】自我(self)部分――欢迎区
- [38] 程序员技术练级攻略
- [32] 视觉调整-设计师 vs. 逻辑