您的位置:首页 > 数据库 > Oracle

Oracle诊断案例-Sql_trace[转]

2008-11-11 13:46 691 查看
这是帮助一个公司的诊断案例.

应用是一个后台新闻发布系统.

症状是,通过连接访问新闻页是极其缓慢

通常需要十数秒才能返回.

这种性能是用户不能忍受的.

操作系统: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)
********************************************************************************


至此,这个问题得到了完满的解决.
内容来自用户分享和网络整理,不保证内容的准确性,如有侵权内容,可联系管理员处理 点击这里给我发消息
标签: