Reading TKPROF Output

Dari topik sebelumnya yaitu Activate Extended SQL Trace, kita telah memperoleh sebuah file yang berisi history tentang apa saja yang dikerjakan oleh Oracle kernel untuk memenuhi permintaan aplikasi terhadap database. Menurut pengalaman saya dalam tracing ini, file yang dihasilkan dari SQL tracing ini berukuran besar, dan tidak mudah untuk langsung dianalisa. Untuk itulah TKPROF dibuat supaya mempermudah kita melakukan analisa.

TKPROF ini akan mem-format trace file yang dihasilkan ke dalam bentuk standard dengan tujuan mudah dimengerti. Saya tidak akan menjelaskan seluruh option yang dimiliki oleh TKPROF karena Oracle telah mendokumentasikannya dengan baik, hanya yang sering saya pakai saja. Untuk lebih dimengerti, penjelasan akan saya sertai dengan contoh. Berikut saya bentuk dulu test case-nya, saya jalankan dengan menggunakan Oracle 11g, karenanya saya memakai v$diag_info untuk mencari nama trace file yang terbentuk.

spool trace;

set serveroutput off;

select value
from v$diag_info
where inst_id = (select instance_number from v$instance) and
      name = 'Default Trace File';

execute dbms_random.seed(0);

create table t
as
select rownum-1 id,
       dbms_random.string('X',50) name,
       trunc((rownum-1)/10) manager,
       to_date('19800101','yyyymmdd')+trunc((rownum-1)/100) hire_date,
       1000000-trunc(rownum/10) salary,
       'LEVEL '||decode(rownum-1,0,0,trunc((rownum-1)/10)+1) job,
       rpad('*',50,'*') description
from dual
connect by level <= 1000000;

alter table t add constraint t_pk primary key (id);

alter table t add constraint t_r01 foreign key (manager) references t(id);

alter table t modify(manager not null);

execute dbms_stats.gather_table_stats(user,'T',cascade => true);

alter session set timed_statistics = true;

alter session set max_dump_file_size = unlimited;

alter session set events '10046 trace name context forever, level 12';

begin
  for i in (select a.*
            from (select emp.*, mgr.name mgr_name
                  from t emp, t mgr
                  where mgr.id = emp.manager
                  order by emp.id) a
            where rownum <= 100000)
  loop
    null;
  end loop;
end;
/

alter session set events '10046 trace name context off';

spool off;

exit;

Selanjutnya pada command line/shell ketikkan perintah berikut.

tkprof rac3_ora_6942.trc tkrpt1.prf sys=no sort=prsela,exeela,fchela

Perintah TKPROF ini akan memproses trace file yang diinputkan yaitu rac3_ora_6942.trc dan kemudian menghasilkan report dengan nama tkrpt1.prf. Option sys=no ini memberi perintah kepada TKPROF supaya SQL statement yang dieksekusi oleh user SYS (recursive SQL) tidak disertakan ke dalam report yang terbentuk. Option sort=prsela,exeela,fchela memberi perintah pada TKPROF untuk mengurutkan SQL statement pada report yang terbentuk berdasarkan penjumlahan waktu (response time) yang dibutuhkan untuk parsing, execute dan fetching secara descending. Selanjutnya akan saya jelaskan bagian-bagian dari report tersebut yang penting untuk troubleshooting.

Bagian header berisi informasi tentang nama trace file dan sort option. Trace file ini saya peroleh dari session yang terkoneksi dengan dedicated server, jadi SQL statement yang terkandung di dalamnya pasti juga berasal dari session yang sama. Memang ada pengecualian, misalnya pada operating system Windows saya pernah menjumpai trace file dari session yang berbeda berada dalam satu file walaupun koneksinya dedicated server. Ada informasi yang tidak muncul pada TKPROF report yang saya hasilkan yaitu informasi mengenai identitas session yang bersangkutan (sid,serial#,timing information), hal ini dipengaruhi oleh parameter aggregate yang default-nya bernilai true. Jika parameter ini bernilai false identitas session ini akan muncul sebagai pemisah SQL statement yang dieksekusi oleh session berbeda (shared server).

TKPROF: Release 11.1.0.6.0 - Production on Thu Sep 18 11:34:45 2008

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

Trace file: rac3_ora_6942.trc
Sort options: prsela  exeela  fchela
********************************************************************************
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
********************************************************************************

Setelah bagian header dapat dijumpai satu blok besar yang berisi SQL statement, execution statistic, query environment, execution plan dan wait event. Perlu diingat urutan statement yang muncul dalam TKPROF report ini bukan merupakan urutan kejadian tetapi diurutkan sesuai sort option yang saya spesifikasikan saat membentuk report ini.

SQL statement
Mengandung informasi tentang SQL statement beserta SQL ID yang profile eksekusinya terletak setelahnya.

SQL ID : d026689a03jpc
SELECT A.*
FROM
 (SELECT EMP.*, MGR.NAME MGR_NAME FROM T EMP, T MGR WHERE MGR.ID =
  EMP.MANAGER ORDER BY EMP.ID) A WHERE ROWNUM <= 100000

Execution statistics
Tabular report berikut menampilkan informasi statistik dari tiap-tiap database call. Ada tiga macam database call yang statistiknya dicatat dalam TKPROF report, yaitu:
1. Parse
Dalam fase ini, Oracle melakukan syntax, semantical dan access right checking. Kemudian Oracle mencari shareable cursor pada shared pool dan jika tidak ada maka membuat plan baru (hard parsing).
2. Execute
Merupakan tahap eksekusi statement oleh Oracle. Jika statement tersebut adalah DML maka pada tahap inilah semua perkerjaan diselesaikan. Sedangkan untuk select statement fase ini biasanya bernilai nol, karena load sesungguhnya berada pada fase fetch.
3. Fetch
Fase ini hanya untuk select statement saja dan merupakan fase dominan dari select statement. Jika query mengembalikan record/row maka dalam fase inilah record-record tersebut didapatkan.

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     1001      2.55       5.46      49517      39884          0      100000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1003      2.55       5.47      49517      39884          0      100000

Berikut saya jelaskan mengenai arti dari statistik pada tiap-tiap database call.
1. Count
Menyatakan jumlah eksekusi dari tiap-tiap database call.
2. CPU
Jumlah CPU time dalam second yang digunakan pada tiap-tiap database call.
3. Elapsed
Lama waktu dalam second yang dibutuhkan pada tiap-tiap database call. Jika nilai elapsed lebih besar dari cpu maka artinya session tersebut pernah mengalami penantian untuk sesuatu hal yang session tersebut butuhkan (wait event).
4. Disk
Jumlah data block yang dibaca secara langsung dari datafile (OS cache/disk subsystem cache/disk) pada tiap-tiap database call. Pembacaan langsung ke datafile ini juga dikenal dengan istilah physical IO (PIO).
5. Query
Jumlah data block yang dibaca dari buffer cache dengan consistent read artinya block yang kita baca adalah block yang sama saat query dimulai dan tidak akan terpengaruh perubahan yang dilakukan oleh session lain. Block yang semacam ini direkonstruksi dari rollback segment. Jumlah block yang terbaca dari statistik ini merupakan salah satu kontributor dari logical IO (LIO). LIO dengan consistent read ini ditimbulkan oleh select statement.
6. Current
Jumlah data block yang dibaca dari buffer cache dengan current read artinya block yang kita baca adalah isi block saat itu juga. Jumlah ini juga merupakan kontributor bagi LIO. Jadi LIO merupakan jumlah block yang dibaca baik dengan consistent maupun current read. LIO dengan current read ini ditimbulkan oleh DML (insert/update/delete/merge).
7. Rows
Jumlah row/record yang diproses pada tiap-tiap database call. Untuk select statement jumlah ini merupakan jumlah row yang di-fetch, sedangkan untuk DML merupakan jumlah row yang terpengaruh perubahan.

Query environment
Pada bagian ini berisi informasi tentang parsing. Jumlah misses pada bagian berikut menandakan Oracle melakukan satu kali hard parsing dan terjadi saat parse, sedangkan jika bernilai nol artinya Oracle melakukan soft parse. Selain informasi tentang kapan terjadinya hard parsing, dapat ditemukan parameter optimizer mode apa yang digunakan untuk mengoptimasi execution plan dan siapa yang melakukan parsing SQL statement tersebut.

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 109     (recursive depth: 1)

Execution plan
Row source operation atau yang sering disebut execution plan merupakan plan yang digunakan oleh Oracle ketika SQL statement tersebut dijalankan. Bagian ini terdiri dari dua kolom, kolom pertama adalah rows yang merupakan jumlah row/record yang dihasilkan pada operasi yang tertera disebelahnya. Sedangkan pada kolom kedua berisi tetang operasi yang dikerjakan oleh Oracle berikut dengan statistiknya.

Rows     Row Source Operation
-------  ---------------------------------------------------
 100000  COUNT STOPKEY (cr=39884 pr=49517 pw=49517 time=2873 us)
 100000   VIEW  (cr=39884 pr=49517 pw=49517 time=1856 us cost=61101 size=4104000000 card=1000000)
 100000    SORT ORDER BY STOPKEY (cr=39884 pr=49517 pw=49517 time=801 us cost=61101 size=192000000 card=1000000)
1000000     HASH JOIN  (cr=39884 pr=49517 pw=49517 time=18290 us cost=19093 size=192000000 card=1000000)
1000000      TABLE ACCESS FULL T (cr=19942 pr=19938 pw=19938 time=13449 us cost=4424 size=56000000 card=1000000)
1000000      TABLE ACCESS FULL T (cr=19942 pr=19938 pw=19938 time=11271 us cost=4430 size=136000000 card=1000000)

Berikut saya sertakan penjelasan dari statistik yang menyertai row source operation:
– cr (consitent read) merupakan jumlah block yang dibaca dari buffer cache dengan consistent read.
– pr (physical read) merupakan jumlah block yang dibaca dari datafile.
– pw (physical write) merupakan jumlah block yang ditulis ke disk.
– time merupakan jumlah waktu dalam microsecond (us) yang dibutuhkan hingga mencapai langkah tersebut.
– cost merupakan perkiraan cost yang diberikan oleh optimizer sampai dengan operasi tersebut.
– size merupakan perkiraan jumlah data yang dihasilkan sampai dengan operasi tersebut dalam byte.
– card merupakan perkiraan jumlah row yang dihasilkan pada operasi tersebut.

Untuk tiga parameter terakhir hanya ada mulai Oracle 11g. Selain cardinalty (card), nilai di atas sifatnya akumulatif artinya juga mengandung nilai dari child operation-nya. Untuk time, nilainya tidak akurat karena dalam hal ini saya menggunakan parameter statistics_level default yaitu TYPICAL. Ada dua cara untuk memperoleh statistik time yang akurat (1) mengubah parameter statistics_level menjadi ALL atau (2) mengubah hidden parameter “_rowsource_statistics_sampfreq” menjadi 1 (defaultnya 128) dan tentunya kedua cara ini menimbulkan overhead.

Wait event
Bagian ini sangatlah membantu saat tuning, terutama untuk menelusuri penggunaan waktu (elapsed) yang di luar pemakaian CPU. Bagian ini terdiri dari empat kolom yaitu:
– Event waited on, kolom ini menampilkan nama wait event. Wait event dapat berupa penantian resource untuk kembali tersedia, misalnya latch, enqueue; menunggu terselesaikannya suatu pekerjaan, misalnya I/O operation; menunggu pekerjaan selanjutnya, misalnya menunggu SQL statement yang akan di-submit oleh client (idle event).
– Times Waited, menampilkan jumlah terjadinya wait event tersebut.
– Max. Wait, menampilkan lama waktu maksimal dalam second untuk sebuah wait event ini.
– Total Waited, menampilkan total lama waktu dalam second yang dibutuhkan untuk wait event ini.

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  rdbms ipc reply                                77        0.00          0.00
  KJC: Wait for msg sends to complete             2        0.00          0.00
  reliable message                                2        0.00          0.01
  enq: KO - fast object checkpoint                4        0.04          0.04
  ges inquiry response                            2        0.00          0.00
  direct path read                             2682        0.00          0.01
  enq: TT - contention                           32        0.00          0.01
  direct path write temp                        311        0.00          0.00
  direct path read temp                         311        0.00          0.00
********************************************************************************

Idealnya total cpu time (2.55 s) ditambah total wait event time (0.07 s) sama dengan total elapsed time (5.47 s), namun pada contoh ini terdapat selisih sebesar 2.85 second. Selisih waktu ini disebut juga unaccounted for time. Terdapat banyak hal mengapa timbul unaccounted for time, misalnya un-instrumented Oracle kernel code, quantization error, measurement intrusion effect.

Perlu diingat penjelasan ini bukan merupakan penjelasan keseluruhan dari report yang terbentuk, jadi ada beberapa bagian dari report yang tidak saya munculkan di sini, misalnya bagian PL/SQL yang memanggil SQL statement di atas karena memiliki struktur yang sama dengan penjelasan di atas.

Selanjutnya kita jumpai bagian summary dari TKPROF report ini. Pada bagian berikut tampak total statistik yang dipisahkan menjadi dua bagian yaitu total statistik untuk non-recursive statement (dalam hal ini PL/SQL yang kita trace) dan total statistik untuk recursive statement. Bagian ini secara garis besar memiliki struktur yang sama seperti struktur yang saya jelaskan di atas.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.04       0.04          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.04       0.04          0          0          0           1

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00
  library cache lock                              1        0.00          0.00
  library cache pin                               1        0.00          0.00
  rdbms ipc reply                                77        0.00          0.00

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

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     1001      2.55       5.46      49517      39884          0      100000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1003      2.55       5.47      49517      39884          0      100000

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  KJC: Wait for msg sends to complete             2        0.00          0.00
  reliable message                                2        0.00          0.01
  enq: KO - fast object checkpoint                4        0.04          0.04
  ges inquiry response                            2        0.00          0.00
  direct path read                             2682        0.00          0.01
  enq: TT - contention                           32        0.00          0.01
  direct path write temp                        311        0.00          0.00
  direct path read temp                         311        0.00          0.00

Di akhir summary terdapat informasi mengenai jumlah SQL statement baik yang di-eksekusi oleh user ataupun oleh sys. Setelah itu terdapat informasi mengenai nama trace file beserta lokasinya, kompatibilitas/versi dari trace file, sorting option yang digunakan, total jumlah SQL statement dari beberapa perspektif, berikut total elapsed time dalam second untuk seluruh SQL statement.

    3  user  SQL statements in session.
    0  internal SQL statements in session.
    3  SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/rac/rac3/trace/rac3_ora_6942.trc
Trace file compatibility: 11.01.00
Sort options: prsela  exeela  fchela
       1  session in tracefile.
       3  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  SQL statements in trace file.
       3  unique SQL statements in trace file.
    4499  lines in trace file.
       5  elapsed seconds in trace file.

Walaupun TKPROF ini merupakan tool untuk troubleshooting yang handal, namun TKPROF ini juga memiliki kelemahan, yaitu kita tidak selalu dapat memperoleh trace file dari session yang bermasalah karena event 10046 tidak otomatis aktif, ditambah lagi jika kemunculan masalah tersebut random. Selain itu tracing event ini juga menambah overhead pada session yang di-trace karena masih harus menuliskan informasi debug pada file.