link:
http://www.eygle.com/case/sql_trace_1.htm
问题描述:
这是帮助一个公司的诊断案例.
应用是一个后台新闻发布系统.
症状是,通过连接访问新闻页是极其缓慢
通常需要十数秒才能返回.
这种性能是用户不能忍受的.
操作系统:SunOS 5.8
数据库版本:8.1.7
1.检查并跟踪数据库进程
诊断时是晚上,无用户访问
在前台点击相关页面,同时进行进程跟踪
查询v$session视图,获取进程信息
>
> SQL> select sid,serial#,username from v$session;
>
> SID SERIAL# USERNAME
> ---------- ---------- ------------------------------
> 1 1
> 2 1
> 3 1
> 4 1
> 5 1
> 6 1
> 7 284 IFLOW
> 11 214 IFLOW
> 12 164 SYS
> 16 1042 IFLOW
>
> 10 rows selected.
>
启用相关进程sql_trace
>
> SQL> exec dbms_system.set_sql_trace_in_session(7,284,true)
>
> PL/SQL procedure successfully completed.
>
> SQL> exec dbms_system.set_sql_trace_in_session(11,214,true)
>
> PL/SQL procedure successfully completed.
>
> SQL> exec dbms_system.set_sql_trace_in_session(16,1042,true)
>
> PL/SQL procedure successfully completed.
>
> SQL> select sid,serial#,username from v$session;
>
> SID SERIAL# USERNAME
> ---------- ---------- ------------------------------
> 1 1
> 2 1
> 3 1
> 4 1
> 5 1
> 6 1
> 7 284 IFLOW
> 11 214 IFLOW
> 12 164 SYS
> 16 1042 IFLOW
>
> 10 rows selected.
>
等候一段时间,关闭sql_trace
>
> SQL> exec dbms_system.set_sql_trace_in_session(7,284,false)
>
> PL/SQL procedure successfully completed.
>
> SQL> exec dbms_system.set_sql_trace_in_session(11,214,false)
>
> PL/SQL procedure successfully completed.
>
>
> SQL> exec dbms_system.set_sql_trace_in_session(16,1042,false)
>
> PL/SQL procedure successfully completed.
>
2.检查trace文件
检查发现以下语句是可疑的
>
> ********************************************************************************
>
> 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进行新闻读取的.
很可疑的是query读取有3892
这个内容引起了我的注意.
如果遇到过类似的问题，大家在这里就应该知道是怎么回事情了.
如果没有遇到过的朋友，可以在这里思考一下再往下看.
>
> Misses in library cache during parse: 1
> Optimizer goal: CHOOSE
> Parsing user id: 41
>
> Rows Row Source Operation
> ------- ---------------------------------------------------
> 1 NESTED LOOPS
> 2 INDEX RANGE SCAN (object id 25062)
> 1 TABLE ACCESS BY INDEX ROWID CATEGORY
> 2 INDEX UNIQUE SCAN (object id 25057)
>
> ********************************************************************************
>
> select auditstatus,categoryid
> from
> categoryarticleassign where articleId=20030700400138 and categoryId in ('63',
> '138','139','140','141','142','143','144','168','213','292','341','346',
> '347','348','349','350','351','352','353','354','355','356','357','358',
> '359','360','361','362','363','364','365','366','367','368','369','370',
> '371','372','383','460','461','462','463','621','622','626','629','631',
> '634','636','643','802','837','838','849','850','851','852','853','854',
> '858','859','860','861','862','863','-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
>
> Misses in library cache during parse: 1
> Optimizer goal: CHOOSE
> Parsing user id: 41
>
> Rows Row Source Operation
> ------- ---------------------------------------------------
> 1 ' TABLE ACCESS FULL CATEGORYARTICLEASSIGN'
>
> 我们注意到，这里有一个全表扫描存在
>
>
> ********************************************************************************
>
>
> ---
3.登陆数据库,检查相应表结构
>
>
> >
> 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
> IDX_CAT_ARTICLE CATEGORYARTICLEASSIGN AUDITSTATUS
> IDX_CAT_ARTICLE CATEGORYARTICLEASSIGN ARTICLEID
> IDX_CAT_ARTICLE CATEGORYARTICLEASSIGN CATEGORYID
> IDX_CAT_ARTICLE CATEGORYARTICLEASSIGN ASSIGNTYPE
>
> 11 rows selected.
>
> >
>
我们注意到,IDX_ARTICLEID索引在以上查询中都没有被用到.
检查表结构:
> > 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
>
> Elapsed: 00:00:02.62
>
> 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)
>
>
>
4.解决方法
简单的在参数两侧各增加一个',既可解决这个问题.
对于类似的查询,我们发现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)
>
> ********************************************************************************
>
至此,这个问题得到了完满的解决.