Oracle Diagnostics Case-sql

Oracle
Link

Http://www.eygle.com/case/sql_trace_1.htm

Problem Description:

This is a diagnostic case for helping a company.
Application is a backstage news release system.

The symptom is that accessing the news page through a connection is extremely slow
It usually takes a dozen seconds to return.

This performance is not tolerated by the user.

Operating system: SunOS 5.8
Database version: 8.1.7


1. Check and track the database process
Night of diagnosis, no user access
Click on the relevant page at the front desk and follow the process

Query V$session view to get process information




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 214 Iflow 164 SYS 1042 IFLOW10 rows selected.

Enable related processes Sql_trace




sql> exec dbms_system.set_sql_trace_in_session (7,284,true) pl/sql procedure successfully. sql> exec dbms_system.set_sql_trace_in_session (11,214,true) pl/sql procedure successfully. sql> exec dbms_system.set_sql_trace_in_session (16,1042,true) pl/sql procedure successfully. 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 214 Iflow 164 SYS 1042 IFLOW10 rows selected.

Wait for some time, close sql_trace




sql> exec dbms_system.set_sql_trace_in_session (7,284,false) pl/sql procedure successfully. sql> exec dbms_system.set_sql_trace_in_session (11,214,false) pl/sql procedure successfully. sql> exec dbms_system.set_sql_trace_in_session (16,1042,false) pl/sql procedure successfully.

2. Check the trace file

The check found the following statement to be suspicious




Select Auditstatus,categoryid, AuditLevel from categoryarticleassign a,category b where B.id=a.categoryid and articleid= 20030700400141 and auditstatus& Gt;0call count CPU Elapsed disk query current rows----------------------------------------------------------------- ------Parse 1 0.00 0.00 0 0 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 1 0.81 0.81 0 3892 0 1-------------------------------- ---------------------------------------Total 3 0.81 0.81 0 3892 0 1************************************************** ******************************

This is clearly based on ArticleID for news reading.
What's suspicious is that query reads 3892

This content caught my attention.
If you have a similar problem, you should know what's going on here.
If you haven't met a friend, you can think about it here and look down.

Misses in library cache during Parse:1optimizer goal:chooseparsing user id:41 Rows Row Source Operation--------------- -------------------------------------------1 NESTED LOOPS 2 INDEX RANGE SCAN (Object ID 25062) 1 TABLE ACCESS by INDEX RO WID 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 0Execute 1 0.00 0.00 0 0 0 0Fetch 1 4.91 4.91 0 2835 7 1---------------------- -------------------------------------------------Total 3 4.91 4.91 0 2835 7 1Misses in library cache during PARSE:1OP Timizer goal:chooseparsing user id:41 Rows Row Source Operation------------------------------------------------------ ----1 ' table ACCESS full categoryarticleassign ' We note that there is a whole table scan present ************************************************** ******************************







3. Log in to the database, check the corresponding table structure







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 articleidind_articleid_categ categoryarticleassign ArticleID Ind_articleid_categ categoryarticleassign CategoryID idx_sortid categoryarticleassign SORTID PK_ Categoryarticleassign categoryarticleassign ArticleID pk_categoryarticleassign CATEGORYARTICLEASSIGN CATEGORYID Categoryarticleassign categoryarticleassign assigntype idx_cat_article categoryarticleassign AUDITSTATUS ARTICLE categoryarticleassign ArticleID idx_cat_article categoryarticleassign CategoryID Categoryarticleassign assigntype rows selected.


We note that the Idx_articleid index is not used in any of the above queries.

Check table structure:




sql> desc categoryarticleassign Name Null? Type-----------------------------------------------------------------------------CategoryID not NULL number ArticleID NOT NULL VARCHAR2 (a) Assigntype NOT null VARCHAR2 (1) auditstatus NOT NULL number SortID NOT NULL number Unpass VARCHAR2 (255)



Problem Discovery:
Because ArticleID is a character-type data, the articleid= 20030700400141 given in the query is a numeric value
Oracle has potential data type conversions, resulting in index invalidation





Sql> Select Auditstatus,categoryid 2 from 3 categoryarticleassign where articleid=20030700400132; Auditstatus CategoryID---------------------9 0 383 0 695 elapsed:00:00:02.62execution Plan------------------------- ---------------------------------0 SELECT STATEMENT optimizer=choose (cost=110 card=2 bytes=38) 1 0 TABLE ACCESS (full) O F ' categoryarticleassign ' (cost=110 card=2 bytes=38)





4. How to Solve

Simply add one on each side of the parameter to solve the problem.

For similar queries, we found that query mode reads down to 2
It's hardly going to take 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 0Execute 1 0.00 0.00 0 0 0 0Fetch 1 0.00 0.00 0 2 0 0-----------------------------------------------------------------------Total 3 0.0 0 0.00 0 2 0 0Misses in library cache during Parse:1optimizer goal:chooseparsing user id:20 Rows Row Source operation-- --------------------------------------------------------0 TABLE ACCESS by index ROWID categoryarticleassign 1 index RAN GE SCAN (Object ID 3080) ********************************************************************************





At this point, the problem has been satisfactorily resolved.