Rudi Kristanto’s BLOG

September 28, 2008

Reading TKPROF Output

Filed under: Performance Toolkit,Trace File,Troubleshooting — Rudi Kristanto @ 5:56 am
Tags: ,

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.

About these ads

19 Comments »

  1. […] menggunakan TKPROF saya memformat raw trace file yang dihasilkan, dan berikut adalah bagian yang perlu dianalisa lebih […]

    Pingback by Don’t trigger to code Trigger « Rudi Kristanto’s BLOG — October 29, 2008 @ 5:15 am | Reply

  2. saya ingin menanyakan tentang keterhubungan antara cpu time,elapsed time,dan disk i/o.
    apakah saling mempengaruhi 1 dengan yang lain,misalkan pembacaan block disk i/o sedikit,apakah nilai dari cpu time dan elapsed time nya juga akan lebih cepat?terimakasih

    Comment by eko — September 3, 2009 @ 11:51 am | Reply

    • Tentu ketiganya saling berkaitan. Semakin banyak jumlah block yang dibaca dari disk, akan semakin banyak juga jumlah wait time (I/O). Dan jika block-block yang dibaca ini dimasukkan ke dalam buffer cache, untuk memasukkannya saja dibutuhkan latch. Untuk memperoleh latch pada high concurrent system akan mengkonsumsi banyak CPU time (spinning). Belum lagi menghitung jumlah CPU yang juga dibutuhkan untuk mengekstrak row-row dalam block-block tersebut. Sedangkan elapsed time sendiri adalah CPU time ditambah wait time.

      Semoga penjelasannya cukup jelas :)

      Comment by Rudi Kristanto — September 3, 2009 @ 1:32 pm | Reply

  3. pgn tanya lagi
    kira2,gmn ya cara hitung2annya dpt elapsed time,cpu time dan disk i/o klo pakai contoh hasil yang ada diartikel ini…atau yg ada diatas…
    terima kasih…

    Comment by eko — September 3, 2009 @ 9:07 pm | Reply

    • Untuk CPU time bukan dihitung, tapi diukur untuk tiap operationnya (lain lagi kalau CPU dalam component cost). Untuk lebih jelasnya ada dapat membaca bukunya Cary Millsap, Optimizing Oracle Performance.

      Untuk perkiraan statistik disk, karena dari operation di atas Oracle menggunakan direct path read bukan melalui buffer cache (SGA), maka jumlah perkiraannya akan mirip dengan jumlah block object T ditambah seberapa banyak dirty block dari table T yang berada dalam cache (Oracle harus melakukan segment checkpoint terlebih dahulu). Ini hanya untuk jumlah disk per table yang diakses. Belum operasi hash joinnya apakah 1 phase atau 2 phase. TKPROF sendiri pada bagian row source operation, menampilkan statistik cr dan pr pada setiap stepnya. Sehingga jumlah disk = pr dan query = cr. Untuk perhitungan exactnya saya sendiri tidak pernah melakukannya.

      Elapsed time (5.47) = CPU time (2.55) + wait time (2.92), padahal sesuai statistik di atas jumlah wait time yang tercatat adalah (0.07). Dalam hal ini sebanyak 2.85 second adalah unaccounted-for time.

      Comment by Rudi Kristanto — September 4, 2009 @ 1:05 am | Reply

  4. di oracle 10g,hasil dari sql trace ko tidak ada keterangan wait time nya??apa hanya di oracle 11g saja??

    Comment by eko — September 4, 2009 @ 12:05 pm | Reply

    • Tidak, event 10046 harus di enable dengan level 8 atau 12. Anda dapat membaca penjelasan saya di artikel yang berjudul Activate Extended SQL Trace di blog ini.

      Comment by Rudi Kristanto — September 4, 2009 @ 1:07 pm | Reply

  5. Malam Pak.
    Mau nanya soal perhitungan seperti pentanyaan kang eko diatas?
    Hatur nuhun

    Comment by danang — September 4, 2009 @ 3:13 pm | Reply

  6. mau tanya lagi,ketika saya melakukan query yang sama,knapa hasil sql trace nya bertambah menjadi 2 kali lebih besar(seperti dijumlahkan)misal:

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

    select *
    from
    work

    call count cpu elapsed disk query current rows
    ——- —— ——– ———- ———- ———- ———- ———-
    Parse 1 0.00 0.02 0 0 0 0
    Execute 1 0.00 0.00 0 0 0 0
    Fetch 2 0.00 0.01 6 8 0 22
    ——- —— ——– ———- ———- ———- ———- ———-
    total 4 0.00 0.04 6 8 0 22
    ************************************************************************************
    select *
    from
    work

    call count cpu elapsed disk query current rows
    ——- —— ——– ———- ———- ———- ———- ———-
    Parse 2 0.00 0.03 0 0 0 0
    Execute 2 0.00 0.00 0 0 0 0
    Fetch 4 0.00 0.02 12 16 0 44
    ——- —— ——– ———- ———- ———- ———- ———-
    total 8 0.00 0.06 12 16 0 44

    Comment by eko — October 8, 2009 @ 1:14 pm | Reply

  7. agar tidak terjadi seperti diatas bagaimana?
    aggregate dirubah menjadi yes atau no?saya coba sama saja

    Comment by eko — October 9, 2009 @ 1:33 am | Reply

  8. sebenarnya,sql trace mendapatkan nilai ini dari mana sih?
    1 call count cpu elapsed disk query current rows
    2 ——- —— ——– ———- ———- ———- ———- ———-
    3 Parse 1 0.00 0.00 0 0 0 0
    4 Execute 1 0.00 0.00 0 0 0 0
    5 Fetch 1001 2.55 5.46 49517 39884 0 100000
    6 ——- —— ——– ———- ———- ———- ———- ———-
    7 total 1003 2.55 5.47 49517 39884 0 100000

    Comment by devi — February 16, 2010 @ 9:07 pm | Reply

  9. saya mau tanya, untuk membuka file dengan format TRC itu menggunakan apa ya pak?
    terimakasih.

    Comment by Rizki — March 29, 2010 @ 4:12 am | Reply

    • bisa dibuka dengan text editor seperti notepad jika di windows atau vi jika di linux.

      Comment by Rudi Kristanto — March 29, 2010 @ 12:59 pm | Reply

  10. select *
    from
    x where TO_CHAR(time_stamp,’mm/yy’)=(’02/09′)

    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 1557 5.51 7.28 25242 26800 0 1157583
    ——- —— ——– ———- ———- ———- ———- ———-
    total 1559 5.51 7.29 25242 26800 0 1157583

    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 56 (NUGRAHA)

    Rows Execution Plan
    ——- —————————————————
    0 SELECT STATEMENT MODE: ALL_ROWS
    0 TABLE ACCESS MODE: ANALYZED (FULL) OF ‘x’
    (TABLE)

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total Waited
    —————————————- Waited ———- ————
    SQL*Net message to client 1557 0.00 0.00
    db file sequential read 4 0.01 0.03
    db file scattered read 1598 0.03 2.04
    SQL*Net message from client 1557 0.03 7.00
    SQL*Net more data to client 9181 0.00 0.19

    mau tanya tentang total elapsed time, dari beberapa pertanyaan di atas,
    elapsed time=cpu time + total wait time
    kalau untuk kasus ini bagaimana?
    elapsed time=cpu time+wait time
    =5.51+9.26
    =14.77
    tetapi pada total elapsed time hanya 7.29
    bagaimana menghitung elapsed time yang benar??terima kasih

    Comment by nugraha — June 28, 2010 @ 12:17 am | Reply

    • Nugraha,

      Setelah saya buka kembali arsip trace file yang saya miliki, saya juga menemukan case seperti yang anda alami, hanya saja jumlahnya sangat kecil dan mungkin saat itu saya abaikan.

      Setelah saya pelajari kembali raw trace file-nya, saya berkesimpulan sebagai berikut.
      1. Statistik elapsed yang terdapat di bagian Execution Statistics adalah cpu time ditambah dengan syscall (diawali kata WAIT di-raw trace) yang ditimbulkan oleh dbcall tersebut (PARSE, EXECUTE, FETCH)
      2. WAIT yang terjadi diantara dbcall TIDAK ditambahkan ke statistik elapsed karena model pelaporan pada bagian Execution Statistics, dikelompokkan berdasarkan dbcall.
      3. WAIT yang terjadi diantara dbcall biasanya mudah dikenali, contohnya “SQL*Net message from client”, dan tetap dilaporkan pada bagian Wait Event yang mengikuti Execution Statistics.

      Jadi pada dasarnya elapsed statistik dihitung dengan menambahkan total cpu time dengan total wait yang terjadi oleh sebab dbcall tersebut. Jika anda masih ingin mengirim trace file, silahkan saja anda kirim ke : rkristanto.blog@gmail.com

      Comment by Rudi Kristanto — June 30, 2010 @ 5:28 am | Reply

      • saya sudah mengirimkan file trace ke email anda,mohon bantuan nya mas…
        untuk SQL * net message from client kenapa selalu besar ya mas nilainya?? sebenernya SQL * net message from client itu proses apa?

        Comment by nugraha — July 1, 2010 @ 8:52 am

      • Nugraha,

        SQL*Net message from client merupakan kategori idle wait events, tapi bukan berarti dapat kita abaikan, kalau anda lihat case di buku OOP event ini merupakan kontributor terbesar yang dapat di-tuning.

        Untuk definisi event ini dapat anda lihat di sini.

        Comment by Rudi Kristanto — July 2, 2010 @ 1:03 pm


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: