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.