Oracle Diagnostic Case - One of Sql_trace

Keywords: SQL Database Session Oracle

Problem Description:

This is a diagnostic case to help a company.
Application is a background news release system.

Symptoms are that access to news pages via links is extremely slow
It usually takes ten seconds to return.

This performance is intolerable to users.

Operating System: SunOS 5.8
Database Version: 8.1.7

 

1. Check and track database processes

Diagnosis at night, no user access
Click on the relevant pages in the foreground and track the process at the same time

Query the v$session view for 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
        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
         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. 

Wait for a while to 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 trace files

Check to find that the following statement is suspect

********************************************************************************

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
********************************************************************************

This is apparently based on articleId for news reading.
It's doubtful that query reads are 3892

This content attracted my attention.
If you have encountered similar problems, you should know what's going on here.
If you haven't met any friends, you can think about it here and look down.

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'
We noticed that there is a full table scan.
********************************************************************************

3. Log on to the database and 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          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.

We note that the IDX_ARTICLEID index is not used in the above queries.

Checklist 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) 

Problem finding:
Because ARTICLEID is a character data, the articleId= 20030700400141 entered in the query is a numeric value.
Potential data type conversion in Oracle leads to index failure
 

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. Solutions

Simply adding a''on each side of the parameter can solve this problem.

For similar queries, we found that Query mode reads were reduced to 2
It hardly takes 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)

********************************************************************************

So far, the problem has been solved satisfactorily.

Posted by incarnate on Sat, 20 Apr 2019 00:09:35 -0700