Home > DBA, Oracle, SQL > POISED: A systematic six-step method for solving database performance problems (and every other problem)

POISED: A systematic six-step method for solving database performance problems (and every other problem)


POISED stands for “Problem Observation Implication Solution Execution Documentation.” It is the name I like to use for the systematic six-step troubleshooting method described by Chris Lawson in The Art and Science of Oracle Performance Tuning. Here is an example.

Problem

A batch job was running much slower than normal. The code had been deployed a few months ago. The batch job had been run previously without incident. This was the first time anybody had complained.

Observation

We reviewed an AWR report for the time periods during which the batch job was running. A certain query stood out because it accounted for more than 60% of the sum of the elapsed times of all SQL queries in those time periods.

We then reviewed the execution history of this SQL statement using the following query.

SELECT s.begin_interval_time,
  ss.plan_hash_value,
  ss.executions_delta,
  ceil(ss.elapsed_time_delta / DECODE(ss.executions_delta,0,1,ss.executions_delta)/1000) AS milliseconds_per_exec,
  ceil(ss.rows_processed_delta / DECODE(ss.executions_delta,0,1,ss.executions_delta)) AS rows_per_exec,
  ceil(ss.buffer_gets_delta / DECODE(ss.executions_delta,0,1,ss.executions_delta)) AS gets_per_exec
FROM wrh$_sqlstat ss,
  wrm$_snapshot s
WHERE sql_id  ='&&sql_id'
AND s.snap_id = ss.snap_id
ORDER BY s.snap_id;

We observed that the query ran tens of thousands of times in each time period. Every execution returned exactly one row. However, it used one query plan in some time periods and another in other time periods. One of the query plans was superbly efficient and the other was terribly inefficient as indicated by the milliseconds per execution and the logical reads per execution for each plan.

BEGIN_INTERVAL_TIME            PLAN_HASH_VALUE EXECUTIONS_DELTA MILLISECONDS_PER_EXEC ROWS_PER_EXEC GETS_PER_EXEC
------------------------------ --------------- ---------------- --------------------- ------------- -------------
05-NOV-11 11.00.30.841 PM           2101851078           700602                     1             1             5
07-NOV-11 11.00.33.909 PM            678606576            36684                    86             1          8314
08-NOV-11 12.00.46.931 AM            678606576            36467                    95             1         14958
08-NOV-11 01.00.59.421 AM            678606576            33362                   105             1         21338
08-NOV-11 02.00.16.515 AM            678606576            31459                   113             1         27309
08-NOV-11 03.00.31.731 AM            678606576            30036                   117             1         33041
08-NOV-11 04.00.44.350 AM            678606576            29472                   120             1             0
08-NOV-11 05.00.57.796 AM            678606576            28380                   123             1         43244
08-NOV-11 06.00.19.314 AM           2101851078           719603                     2             2           447
08-NOV-11 07.01.29.795 AM           2101851078           620172                     1             1             5
08-NOV-11 11.00.41.855 PM           2101851078           223994                     1             1             5
09-NOV-11 12.00.54.171 AM           2101851078           124423                     1             1             5
09-NOV-11 01.00.15.835 AM           2101851078            63494                     1             1             5
09-NOV-11 02.00.35.291 AM           2101851078            40250                     1             1             5
11-NOV-11 10.00.41.882 AM            678606576            30824                    87             1          8576
11-NOV-11 11.01.00.367 AM            678606576            30611                    96             2         14041
11-NOV-11 12.00.16.638 PM            678606576            28931                   104             2         19366
11-NOV-11 01.00.34.647 PM            678606576            27226                   112             1         24359
11-NOV-11 02.00.50.466 PM            678606576            12706                   118             1         28010
11-NOV-11 08.31.17.062 PM            678606576              523                   119             2         29448
11-NOV-11 08.32.38.815 PM            678606576            31990                   121             1         32319
11-NOV-11 04.00.22.209 PM            678606576            20755                   124             1         36908
11-NOV-11 05.00.45.353 PM            678606576            19480                   126             2             0
11-NOV-11 06.01.05.591 PM            678606576            18711                   128             1         44001
11-NOV-11 07.00.20.132 PM            678606576            18186                   129             1         47090
11-NOV-11 08.00.31.884 PM            678606576            17697                   130             2         50213
11-NOV-11 09.00.53.077 PM            678606576             8056                   134             1         54533
13-NOV-11 12.00.56.346 AM            678606576             8498                   137             1         57579
13-NOV-11 01.01.11.023 AM            678606576            19666                   137             1             0
13-NOV-11 02.00.28.031 AM            678606576            19478                   138             1         57819
13-NOV-11 03.00.49.370 AM            678606576            19300                   139             1         57988
13-NOV-11 04.01.08.797 AM            678606576            19023                   139             2         58138
13-NOV-11 05.00.18.912 AM            678606576            19259                   139             1             0
13-NOV-11 06.00.32.517 AM            678606576            19237                   140             1         58418
13-NOV-11 07.00.42.553 AM            678606576            18737                   141             1         58545
13-NOV-11 08.01.09.011 AM            678606576            17908                   137             1             0
13-NOV-11 09.00.21.430 AM            678606576            18036                   137             2         58587
13-NOV-11 10.00.45.130 AM            678606576            17386                   137             1         58619
13-NOV-11 11.01.02.976 AM            678606576            16831                   138             2         58662

We also reviewed the query plans using DBMS_XPLAN.DISPLAY_AWR and noticed that bind variables were being used.

Implication

The query plan was unstable. We were the victims of Bind Variable Peeking. The query plan with hash value 678606576 was unsuitable for general use while the query plan with hash value 2101851078 was more suitable.

Solution

We brainstormed our options and decided to use Kerry Osborne’s method of creating a SQL profile from the AWR repository to force Oracle to use a known good plan. Note that SQL Profiles require a license for Tuning Pack.

Execution

We followed our change management process and packaged the solution as a hotfix.

Documentation

We recorded all the steps from problem to execution in detail in the trouble ticket. We summarized the trouble ticket in a short memo to the development and production teams.

P.S. Note that AWR requires a license for Diagnostics Pack. If you don’t have a license for Diagnostics Pack, you can use Statspack. Statspack is alive and well in Oracle Database 11g Release 2 even though it is no longer documented in the Oracle manuals. You can find detailed installation and usage instructions in $ORACLE_HOME/rdbms/admin/spdoc.txt. Section 9 of spdoc.txt describes the new features added to Statspack in Oracle Database 10g and 11g.

About these ads
Categories: DBA, Oracle, SQL
  1. March 22, 2012 at 2:42 pm

    buen blog,

    visita el mio

    http://dbasqlserver.wordpress.com/

    saludos

  1. No trackbacks yet.

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

Follow

Get every new post delivered to your Inbox.

Join 743 other followers

%d bloggers like this: