SQL Trace จับ Query Statement ที่มีปัญหา..

วันนี้แอบเอาเรื่องการใช้ SQL Trace มาช่วยในการจับปรับ SQL ที่มีปัญหา หลายๆครั้งที่ developer พัฒนา application ขึ้นมาแล้วบางครั้งทำงานช้า แต่ไม่รู้ว่าช้าที่ statment ไหน DBA อย่างเราก็สามารถที่จะช่วยเหลือได้ โดยการ เปิด Trace session app นั้นๆ ซึ่งจะเก็บ statement ที่ทำทั้งหมดใน app นั้น แต่ Function นี้จะใช้ได้ก็ต่อเมื่อ Session นั้นรันอยู่
 

วิธีการเริ่มแรกเลย

1. ต้องรู้ก่อนว่า application นั้นๆ รันด้วย SID, SERIAL# อะไร
     โดย สามารถ ใช้ SQL ประมาณนี้ได้

select a.sid, a.serial#, a.username, b.spid, a.program, a.status
from v$process b, v$session a
where a.paddr =b.addr
and a.username = 'USERNAME'
order by  logon_time;

2. log on by  SYS as sysdba

3. alter system set timed_statistics=true;
   — ถ้า DB มีการ set เป็น true อยู่แล้วก็ไม่ต้องรันค่ะ

4. exec dbms_system.set_sql_trace_in_session(SID,SERIAL#,STATUS);
     รันด้วยคำสั่งด้านบน
     – SID, SERIAL# ได้จาก Query ข้อ 1
     – STATUS  มี 2 status
               1.   true  (เปิด trace)  
               2.   false  (ปิด trace)

5. เมื่อรันเสร็จเรียบร้อย Output จะอยู่ที่ udump
    –  show parameter user_dump_dest  (เพื่อดู path)

6. ไฟล์จะ write ออกมา format ดังนี้
    – DBNAME_ora_SPID.trc         
    – ตัวอย่างชื่อไฟล์ orcl_ora_1111.trc
              1.  DBNAME คือชื่อ instance database  เช่น DBNAME = ORCL
              2.  SPID คือค่าที่ได้จาก Query ข้อ 1    เช่น SPID = 1111
 

หลังจากที่เราได้ Trace file จากการทำตาม Step 1-6 แล้ว ถ้าเราเปิดดุจะเป็นภาษาที่เราอ่านไม่เข้าใจ เราต้องทำการแปลงออกมาให้เป็นภาษาคนที่เราอ่านรู้เรื่องก่อน โดยการใช้ TKPROF เข้ามาช่วย…  โดยใช้แค่คำสั่งบรรทัดเดียวเลย

tkprof tracefile outfile [explain=user/password] [options…]

     – tracefile คือชื่อ file ที่เราเปิด sql trace ใน path user_dump_dest
             ex. orcl_ora_1111.trc

     – outfile  คือชื่อที่เราต้องการให้เป็น output หลังจากที่เราแปลงแล้ว
             ex.  tkprof orcl_ora_111.txt

     – [option..]   เราสามารถดูตาม list ด้านล่างได้เลย ว่าต้องการให้ tkprof sort ให้เราตามอะไร cpu หรือว่า show plan มั้ย และอื่นๆ

TKPROF Options
~~~~~~~~~~~~~~
   print=integer    List only the first 'integer' SQL statements.
   insert=filename  List SQL statements and data inside INSERT statements.
   sys=no           TKPROF does not list SQL statements run as user SYS.
   record=filename  Record statements found in the trace file.
   sort=option      Set of zero or more of the following sort options:

     prscnt  number of times parse was called
     prscpu  cpu time parsing
     prsela  elapsed time parsing
     prsdsk  number of disk reads during parse
     prsqry  number of buffers for consistent read during parse
     prscu   number of buffers for current read during parse
     prsmis  number of misses in library cache during parse

     execnt  number of execute was called
     execpu  cpu time spent executing
     exeela  elapsed time executing
     exedsk  number of disk reads during execute
     exeqry  number of buffers for consistent read during execute
     execu   number of buffers for current read during execute
     exerow  number of rows processed during execute
     exemis  number of library cache misses during execute

     fchcnt  number of times fetch was called
     fchcpu  cpu time spent fetching
     fchela  elapsed time fetching
     fchdsk  number of disk reads during fetch
     fchqry  number of buffers for consistent read during fetch
     fchcu   number of buffers for current read during fetch
     fchrow  number of rows fetched

     userid  userid of user that parsed the cursor

Tips ! 

tkprof orcl_ora_1111.trc tkprof orcl_ora_111.txt
explain=username/password sys=no sort=\(execpu,fchcpu,prscpu\)

       statment ด้านบนจะเป็นการใส่ option ให้ sort ตาม execpu,fchcpu,prscpu ซึ่งถ้าเปิดดูใน file tkprof orcl_ora_111.txt จะพบว่า statment ที่มีปัญหาจะอยู่บนๆ โดยจะมีค่า elapsed เยอะๆ ซึ่งอาจจะเป็นเพราะอ่าน full table scan หรือใช้ index ถูกตัว จะทำให้ developer สามารถแก้ปัญหาได้ตรงจุดและรวดเร็วยิ่งขึ้นค่ะ

 ตัวอย่าง Trace file ที่ทำการแปลงด้วย TKPROF เรียบร้อยแล้ว

KPROF: Release 10.2.0.2.0 – Production on Fri Jun 17 09:49:56 2011

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Trace file: genprod_ora_9273.trc
Sort options: execpu  fchcpu  prscpu 
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SELECT source 
FROM
    (SELECT cd.label event_source, cd.start_d, cd.ed_dat  FROM  
  CUSTPRODETAIL CD  WHERE  CD.ACC_NUM = :f1             AND   
  CD.ED_DAT IS NULL  AND CD.LABEL IS NOT NULL  AND (CD.LABEL
  like '00%'  or CD.LABEL like '01%')  ORDER BY CD.START_D  ) AA 
  where  rownum = 1

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse      520      0.00       0.06          0          0          0           0
Execute    520      0.14       0.14          0          0          0           0
Fetch     1024      1.19      33.82       2529       5836          0         504
——- ——  ——– ———- ———- ———- ———-  ———-
total     2064      1.33      34.04       2529       5836          0         504

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 567  (APP)

Rows     Row Source Operation
——-  —————————————————
      1  COUNT STOPKEY (cr=27 pr=11 pw=0 time=183731 us)
      1   VIEW  (cr=27 pr=11 pw=0 time=183725 us)
      1    SORT ORDER BY STOPKEY (cr=27 pr=11 pw=0 time=183716 us)
      1     TABLE ACCESS BY INDEX ROWID CUSTPRODETAIL (cr=27 pr=11 pw=0 time=183510 us)
     86      INDEX SKIP SCAN CUSTPRODETAIL_IND (cr=5 pr=2 pw=0 time=6237 us)(object id 21127)

Rows     Execution Plan
——-  —————————————————
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   COUNT (STOPKEY)
      1    VIEW
      1     SORT (ORDER BY STOPKEY)
      1      TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF
                 'CUSTPRODUCTDETAILS' (TABLE)
     86       INDEX   MODE: ANALYZED (SKIP SCAN) OF
                  'CUSTPRODUCTDETAILS_AK1' (INDEX)

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

Related Search:

• sqltrace