Re: Script for getting a table of reponse-time breakdown - Mailing list pgsql-performance

Josh,

The description of the Oracle script is:

This script can be used to focus tuning attention on the most important
issues. It reports a breakdown of total foreground response time into
four major categories: CPU usage, disk I/O, resource waits, and routine
latencies. These categories are broken down further into sub-categories,
and the component wait events are shown.

The 8.1.6 version of the script uses the ratio_to_report analytic
function to calculate percentages. The 8.1.5 version can be used if
percentages are not required. The 8.1.5 version of the script should
work on Oracle8 also, but has not yet been tested.

The print out of this script is:
SQL> @response_time_breakdown

MAJOR    MINOR         WAIT_EVENT                                SECONDS    PCT
-------- ------------- ---------------------------------------- -------- ------
CPU time parsing       n/a                                           497   .57%
         reloads       n/a                                            13   .01%
         execution     n/a                                         52618 59.99%

disk I/O normal I/O    db file sequential read                     21980 25.06%
         full scans    db file scattered read                       9192 10.48%
         direct I/O    direct path read                             1484  1.69%
                       direct path write                             354   .40%
         other I/O     log file sequential read                        9   .01%
                       db file parallel read                           0   .00%
                       control file sequential read                    0   .00%
                       control file parallel write                     0   .00%

waits    DBWn writes   rdbms ipc reply                               143   .16%
                       free buffer waits                              36   .04%
                       checkpoint completed                           31   .04%
         LGWR writes   log file switch completion                    698   .80%
         other locks   latch free                                    496   .57%
                       sort segment request                          108   .12%

latency  commits       log file sync                                   6   .01%
         network       SQL*Net break/reset to client                  18   .02%
                       SQL*Net more data to client                     8   .01%
                       SQL*Net message to client                       7   .01%
                       SQL*Net more data from client                   3   .00%
         file ops      file open                                       4   .01%
                       file identify                                   1   .00%
         misc          instance state change                           0   .00%


The script is pretty long:

-------------------------------------------------------------------------------
--
-- Script:    response_time_breakdown.sql
-- Purpose:    to report the components of foreground response time in % terms
-- For:        8.0 to 8.1.5
--
-- Copyright:    (c) Ixora Pty Ltd
-- Author:    Steve Adams
--
-------------------------------------------------------------------------------
@save_sqlplus_settings

column major      format a8
column wait_event format a40 trunc
column seconds    format 9999999
column pct        justify right
break on major skip 1 on minor

select
  substr(n_major, 3)  major,
  substr(n_minor, 3)  minor,
  wait_event,
  round(time/100)  seconds
from
  (
    select /*+ ordered use_hash(b) */
      '1 CPU time'  n_major,
      decode(t.ksusdnam,
    'redo size', '2 reloads',
    'parse time cpu', '1 parsing',
    '3 execution'
      )  n_minor,
      'n/a'  wait_event,
      decode(t.ksusdnam,
    'redo size', nvl(r.time, 0),
    'parse time cpu', t.ksusgstv - nvl(b.time, 0),
    t.ksusgstv - nvl(b.time, 0) - nvl(r.time, 0)
      )  time
    from
      sys.x_$ksusgsta  t,
      (
    select /*+ ordered use_nl(s) */        -- star query: few rows from d and b
      s.ksusestn,                -- statistic#
      sum(s.ksusestv)  time            -- time used by backgrounds
    from
      sys.x_$ksusd  d,            -- statname
      sys.x_$ksuse  b,            -- session
      sys.x_$ksbdp  p,            -- background process
      sys.x_$ksusesta  s            -- sesstat
    where
      d.ksusdnam in (
        'parse time cpu',
        'CPU used when call started') and
      b.ksspaown = p.ksbdppro and
      s.ksusestn = d.indx and
      s.indx = b.indx
    group by
      s.ksusestn
      )  b,
      (
    select /*+ no_merge */
      ksusgstv *                -- parse cpu time *
      kglstrld /                -- SQL AREA reloads /
      (1 + kglstget - kglstght)        -- SQL AREA misses
        time
    from
      sys.x_$kglst  k,
      sys.x_$ksusgsta  g
    where
      k.indx = 0 and
      g.ksusdnam = 'parse time cpu'
      )  r
    where
      t.ksusdnam in (
    'redo size',                -- arbitrary: to get a row to replace
    'parse time cpu',            --   with the 'reload cpu time'
    'CPU used when call started') and
      b.ksusestn (+) = t.indx
    union all
    select
      decode(n_minor,
    '1 normal I/O',        '2 disk I/O',
    '2 full scans',        '2 disk I/O',
    '3 direct I/O',        '2 disk I/O',
    '4 BFILE reads',    '2 disk I/O',
    '5 other I/O',        '2 disk I/O',
    '1 DBWn writes',    '3 waits',
    '2 LGWR writes',    '3 waits',
    '3 ARCn writes',    '3 waits',
    '4 enqueue locks',    '3 waits',
    '5 PCM locks',        '3 waits',
    '6 other locks',    '3 waits',
    '1 commits',        '4 latency',
    '2 network',        '4 latency',
    '3 file ops',        '4 latency',
    '4 process ctl',    '4 latency',
    '5 global locks',    '4 latency',
    '6 misc',        '4 latency'
      )  n_major,
      n_minor,
      wait_event,
      time
    from
      (
    select /*+ ordered use_hash(b) use_nl(d) */
      decode(
        d.kslednam,
                            -- disk I/O
        'db file sequential read',            '1 normal I/O',
        'db file scattered read',            '2 full scans',
        'BFILE read',                '4 BFILE reads',
        'KOLF: Register LFI read',            '4 BFILE reads',
        'log file sequential read',            '5 other I/O',
        'log file single write',            '5 other I/O',
                        -- resource waits
        'checkpoint completed',            '1 DBWn writes',
        'free buffer waits',            '1 DBWn writes',
        'write complete waits',            '1 DBWn writes',
        'local write wait',                '1 DBWn writes',
        'log file switch (checkpoint incomplete)',    '1 DBWn writes',
        'rdbms ipc reply',                '1 DBWn writes',
        'log file switch (archiving needed)',    '3 ARCn writes',
        'enqueue',                    '4 enqueue locks',
        'buffer busy due to global cache',        '5 PCM locks',
        'global cache cr request',            '5 PCM locks',
        'global cache lock cleanup',        '5 PCM locks',
        'global cache lock null to s',        '5 PCM locks',
        'global cache lock null to x',        '5 PCM locks',
        'global cache lock s to x',            '5 PCM locks',
        'lock element cleanup',            '5 PCM locks',
        'checkpoint range buffer not saved',    '6 other locks',
        'dupl. cluster key',            '6 other locks',
        'PX Deq Credit: free buffer',        '6 other locks',
        'PX Deq Credit: need buffer',        '6 other locks',
        'PX Deq Credit: send blkd',            '6 other locks',
        'PX qref latch',                '6 other locks',
        'Wait for credit - free buffer',        '6 other locks',
        'Wait for credit - need buffer to send',    '6 other locks',
        'Wait for credit - send blocked',        '6 other locks',
        'global cache freelist wait',        '6 other locks',
        'global cache lock busy',            '6 other locks',
        'index block split',            '6 other locks',
        'lock element waits',            '6 other locks',
        'parallel query qref latch',        '6 other locks',
        'pipe put',                    '6 other locks',
        'rdbms ipc message block',            '6 other locks',
        'row cache lock',                '6 other locks',
        'sort segment request',            '6 other locks',
        'transaction',                '6 other locks',
        'unbound tx',                '6 other locks',
                        -- routine waits
        'log file sync',                '1 commits',
        'name-service call wait',            '2 network',
        'Test if message present',            '4 process ctl',
        'process startup',                '4 process ctl',
        'read SCN lock',                '5 global locks',
        decode(substr(d.kslednam, 1, instr(d.kslednam, ' ')),
                        -- disk I/O
          'direct ',                '3 direct I/O',
          'control ',                '5 other I/O',
          'db ',                    '5 other I/O',
                        -- resource waits
          'log ',                    '2 LGWR writes',
          'buffer ',                '6 other locks',
          'free ',                    '6 other locks',
          'latch ',                    '6 other locks',
          'library ',                '6 other locks',
          'undo ',                    '6 other locks',
                        -- routine waits
          'SQL*Net ',                '2 network',
          'BFILE ',                    '3 file ops',
          'KOLF: ',                    '3 file ops',
          'file ',                    '3 file ops',
          'KXFQ: ',                    '4 process ctl',
          'KXFX: ',                    '4 process ctl',
          'PX ',                    '4 process ctl',
          'Wait ',                    '4 process ctl',
          'inactive ',                '4 process ctl',
          'multiple ',                '4 process ctl',
          'parallel ',                '4 process ctl',
          'DFS ',                    '5 global locks',
          'batched ',                '5 global locks',
          'on-going ',                '5 global locks',
          'global ',                '5 global locks',
          'wait ',                    '5 global locks',
          'writes ',                '5 global locks',
                                  '6 misc'
        )
      )  n_minor,
      d.kslednam  wait_event,        -- event name
      i.kslestim - nvl(b.time, 0)  time    -- non-background time
    from
      sys.x_$kslei  i,            -- system events
      (
        select /*+ ordered use_hash(e) */    -- no fixed index on e
          e.kslesenm,            -- event number
          sum(e.kslestim)  time        -- time waited by backgrounds
        from
          sys.x_$ksuse  s,            -- sessions
          sys.x_$ksbdp  b,            -- backgrounds
          sys.x_$ksles  e            -- session events
        where
          s.ksspaown = b.ksbdppro and    -- background session
          e.kslessid = s.indx
        group by
          e.kslesenm
        having
          sum(e.kslestim) > 0
      )  b,
      sys.x_$ksled  d
    where
      i.kslestim > 0 and
      b.kslesenm (+) = i.indx and
      nvl(b.time, 0) < i.kslestim and
      d.indx = i.indx and
      d.kslednam not in (
        'Null event',
        'KXFQ: Dequeue Range Keys - Slave',
        'KXFQ: Dequeuing samples',
        'KXFQ: kxfqdeq - dequeue from specific qref',
        'KXFQ: kxfqdeq - normal deqeue',
        'KXFX: Execution Message Dequeue - Slave',
        'KXFX: Parse Reply Dequeue - Query Coord',
        'KXFX: Reply Message Dequeue - Query Coord',
        'PAR RECOV : Dequeue msg - Slave',
        'PAR RECOV : Wait for reply - Query Coord',
        'Parallel Query Idle Wait - Slaves',
        'PL/SQL lock timer',
        'PX Deq: Execute Reply',
        'PX Deq: Execution Msg',
        'PX Deq: Index Merge Execute',
        'PX Deq: Index Merge Reply',
        'PX Deq: Par Recov Change Vector',
        'PX Deq: Par Recov Execute',
        'PX Deq: Par Recov Reply',
        'PX Deq: Parse Reply',
        'PX Deq: Table Q Get Keys',
        'PX Deq: Table Q Normal',
        'PX Deq: Table Q Sample',
        'PX Deq: Table Q qref',
        'PX Deq: Txn Recovery Reply',
        'PX Deq: Txn Recovery Start',
        'PX Deque wait',
        'PX Idle Wait',
        'Replication Dequeue',
        'Replication Dequeue ',
        'SQL*Net message from client',
        'SQL*Net message from dblink',
        'debugger command',
        'dispatcher timer',
        'parallel query dequeue wait',
        'pipe get',
        'queue messages',
        'rdbms ipc message',
        'secondary event',
        'single-task message',
        'slave wait',
        'virtual circuit status'
      ) and
      d.kslednam not like 'resmgr:%'
      )
  )
order by
  n_major,
  n_minor,
  time desc
/

@restore_sqlplus_settings

Do we have some similar for Postgres?

Thanks.

-Jack


On Fri, 2005-03-25 at 12:40, Josh Berkus wrote:
> Jack,
>
> > I am thinking about how to continuously monitor the performance of a
> > PostgreSQL 8 database. I am interested in two things: (1) the growth of
> > tables with TOAST and indexes;
>
> This is queryable from the system tables, if you don't mind an approximate.
>
> > and (2) the respond time breakdown for a
> > query.
>
> The what?  You mean EXPLAIN ANALYZE?
>
> > In Chapters 23 and 24 of the big manual, I found enough materials to
> > teach me how to do the 1st job. But I have difficulty with the 2nd one.
> > I found some script for Oracle
> > (http://www.ixora.com.au/scripts/waits.htm).
>
> Life's too short for reading Oracle docs.   Can you just explain, in
> step-by-step detail, what you want?