LINK:
http://www.eygle.com/case/sql_trace_1.htm
Problem Description:
This is a diagnostic case that helped a company. Application is a background press release system.
Symptom is that the access news page is extremely slow to return to ten seconds to return.
This performance is the user's unbearable.
Operating system: SunOS 5.8 Database Version: 8.1.7
1. Check and track database processes
Diagnostics is night, no user access in the front desk, click on the related page, while processes tracking
Query V $ SESSION view to get process information
SQL> SELECT SID, Serial #, UserName from V $ Session;
Sid Serial # UserName
---------- ----------------------------------------------------------------------------------------------------------------
1 1
twenty one
3 1
4 1
5 1
6 1
7 284 iflow
11 214 iflow
12 164 SYS
16 1042 iflow
10 rows selected.
Enable related process 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
twenty one
3 1
4 1
5 1
6 1
7 284 iflow
11 214 iflow
12 164 SYS
16 1042 iflow
10 rows selected.
Waiting for a while, close 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. Check the trace file check to find that the following statement is suspicious.
*********************************************************** *****************************
Select Auditstatus, CategoryId, Auditlevel
From
CategoryArticleAssign A, Category B Where B.Id = a.categoryid and articleid = 20030700400141 and auditatus> 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
*********************************************************** *****************************
It is obviously based on ArticleID. Very suspicious is that Query reads 3892 This content has attracted my attention. If you have encountered a similar problem, everyone should know what is going on here. If not Friends encountered, you can think about it here again.
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', '357,' 356 ',' 357, '358', '359 ',' 360 ',' 361 ',' 362 ',' 365 ',' 366 ',' 367 ',' 368 ',' 369 ',' 370 ',
'371', '372', '383', '460', '461', '462', '463', '621', '622', '626', '629', '631',
'634', '636', '643', '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'
We noticed that there is a full meter scan existence.
*********************************************************** *****************************
3. Log in to the database and check the corresponding table structure
SQL> SELECT INDEX_NAME, TABLE_NAME, Column_name from user_ind_columns2 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_CATEGORYATICLECLEASSIGN CATEGORYATICLEASSIGN ARTICLEID
PK_CATEGORYATicleAssign CategoryArticleAssign CategoryId
PK_CATEGORYATICLEASSIGN CATEGORYATICLECLEASSIGNASSIGNTYPE
IDX_CAT_Article CategoryArticleAssign Auditstatus
IDX_CAT_Article CategoryArticleAssiGN ArticleId
IDX_CAT_Article CategoryArticleAssign CategoryID
IDX_CAT_Article CategoryArticleAssign AssignType
11 rows selected.
We noticed that the IDX_ArticleID index is not used in the above queries. Check the table structure:
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) The problem found: because ArticleID is a characteristic data, ArticleID = 20030700400141, which is given in the query is a potential data type conversion, resulting in index failure.
SQL> SELECT AUDITSTATUS, CATEGORYID
2 from
3 categoryArticleAssign where article management = 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. Solution to add one of the parameters on both sides of the parameter, can solve this problem. For similar queries, we found that Query mode read reduction is almost no cost CPU time.
*********************************************************** *****************************
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) *************************************************** ***********************************************
At this point, this problem has been completed.
