Search Results

Keyword: ‘POISED’

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

February 20, 2012 1 comment

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.

Categories: DBA, Oracle, SQL

The golden rule of NOT tuning SQL

February 7, 2013 Leave a comment

Dear NoCOUG members and friends,

The golden rule of not tuning SQL is “operate with as little information as possible.” Not only will this increase your chances of failure but it will make it difficult for others to help you.

Every exercise in problem solving – no matter how little – has exactly six stages: Problem, Observation, Implication, Solution, Execution, and Documentation. I use the acronym POISED to remember the six stages. If you strive to operate with as little information as possible, you increase the chances that you will not progress beyond the Observation stage.

I recently saw a request for SQL tuning help (http://www.freelists.org/post/oracle-l/Query-tuning-help). The poster had provided the EXPLAIN PLAN output. You probably know that EXPLAIN PLAN output is not of much use in SQL tuning. He was asked to add the GATHER_PLAN_STATISTICS hint and provide the output of DBMS_XPLAN.DISPLAY_CURSOR (http://www.freelists.org/post/oracle-l/Query-tuning-help,7). The rowsource execution statistics in the DISPLAY_CURSOR output showed that hundreds of thousands of rows were being retrieved and then discarded. There was enough information to deduce the right joining order (http://www.freelists.org/post/oracle-l/Query-tuning-help,9) but not enough to explain why the query optimizer was not finding the right order.

The best tool for tuning SQL is SQLTXPLAIN because it collects all the information that is required for tuning SQL. The author of this tool is Carlos Sierra. He will be conducting a two-day SQL tuning master class at the CarrAmerica conference center in Pleasanton on February 19 and 20. He will also speak at our winter conference at the Oracle conference center in Redwood Shores on February 21. I hope that you can attend at least one event.

Kindest regards,

Iggy Fernandez
NoCOUG Journal editor

Categories: Announcements, DBA, NoCOUG, Oracle, SQL

Day 11: The Twelve Days of SQL: AWR and Statspack are a goldmine of historical performance data

December 15, 2011 Leave a comment

On the eleventh day of Christmas, my true love gave to me
Eleven pipers piping.

Day 11: AWR and Statspack are a goldmine of historical performance data (Day 10: Sometimes the optimizer needs a hint)(Day 12: Readers do not block writers; writers do not block readers)

You can and should review the past performance of badly performing SQL statements using Statspack or AWR. How often are they executed; when are they executed; how much time do they take; how many logical and physical reads do they perform; what execution plans do they use? Having this information can be invaluable in a SQL tuning exercise. You should therefore retain Statspack and AWR data for as long as possible.

Let me demonstrate the value of historical performance data with a case study of a troubleshooting method that I call POISED (Problem –> Observations –> Implications –> Solution –> Execution –> Documentation). POISED 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.

Note that Statspack is free but AWR requires a license for Diagnostics Pack. 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.

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.

Observations

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.

Implications

The query plan was unstable. We were the victims of Bind Variable Peeking.

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.

Day 10: Sometimes the optimizer needs a hint

Day 12: Readers do not block writers; writers do not block readers

Categories: DBA, Oracle, SQL
%d bloggers like this: