Oracle mechanics

25.08.2011

Медленный разбор SQL запроса (long parse time)

Filed under: CBO,heuristics,Oracle,RBO — Игорь Усольцев @ 19:14
Tags: , , ,

Периодически попадаются запросы на подготовку планов выполнения которых (фаза разбора SQL — parse) Oracle тратит значительно больше времени, чем на собственно выполнение (execute) и извлечение результатов (fetch)

Например, при первом выполнении громоздкого (но несложного) запроса с обращением к 18 таблицам:

SQL> set autotrace traceonly stat
SQL> select
...
/
Elapsed: 00:00:05.07
...
Statistics
----------------------------------------------------------
43  recursive calls
0  db block gets
16891  consistent gets
0  physical reads
...
1  rows processed

а при каждом последующем:

SQL> /
Elapsed: 00:00:00.34
...
Statistics
----------------------------------------------------------
0  recursive calls
0  db block gets
16864  consistent gets
0  physical reads
...
1  rows processed

Судя по выдаваемой sqlplus autotrace статистике разница во времени выполнения не может быть объяснена «холодным» кэшэм бд (buffer cache) — с диска в обоих случаях ничего не читается — physical reads = 0, картина ожиданий «медленного» запроса также не показывают ничего, что могло бы замедлить выполнение:

SQL> select event, wait_class, total_waits, total_timeouts, time_waited, average_wait
2  from GV$session_event
3  where sid in (937)
4  and INST_ID = 2
5  order by time_waited desc
6  /

EVENT                          WAIT_CLASS    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT
------------------------------ ------------- ----------- -------------- ----------- ------------
SQL*Net message from client    Idle                   14              0       25984      1855,99
gc cr block 2-way              Cluster                50              0           2         0,04
gc current block 2-way         Cluster                38              0           2         0,04
SQL*Net more data from client  Network                 2              0           0         0,01
events in waitclass Other      Other                   1              0           0         0,02
SQL*Net message to client      Network                15              0           0            0
SQL*Net more data to client    Network                 1              0           0            0

Распределение времени сессии из v$sess_time_model точно указывает на основного потребителя времени — parse time elapsed (точнее, hard parse elapsed time):

STAT_NAME                VALUE
------------------------ ---------
DB time                    5189665
DB CPU                     5189665
parse time elapsed         4927216
hard parse elapsed time    4926532
sql execute elapsed time    260363

Статистика сессии (v$sesstat) подтверждает, что физических чтений с диска не было (полное отсутствие physical reads) — только логические чтения из buffer cache:

consistent gets from cache    16891
session logical reads    16891
consistent gets    16891

и указывает, что основное время (recursive cpu usage = 503 из 526 csec  CPU used by this session) потрачено на 43 recursive calls (указаные в autotrace, выше):

DB time    532
CPU used by this session    526
CPU used when call started    526
parse time elapsed    505
parse time cpu    503
recursive cpu usage    503
...
recursive calls    43

Ту же информацию о значительном времени разбора (long parse time) можно найти в SQL трейсе (event 10046 level 12):

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      4.72       4.63          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.28       0.33          0      16596          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      5.01       4.97          0      16596          0           1

, однако в SQL трейсе не отображаются данные обо всех 43-х рекурсивных запросах, упомянутых выше и, судя по статистике сессии, выполненных за время разбора:

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        7      0.00       0.00          0          0          0           0
Execute      7      0.00       0.00          0          0          0           0
Fetch        7      0.00       0.00          0         15          0           6
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21      0.00       0.00          0         15          0           6
...
7  internal SQL statements in session.

А вот трейс оптимизатора (10053 event) хорошо показывает на что уходит процессорное время, суммарно показываемое как recursive cpu usage — на перебор 740 вариантов соединений 18 таблиц:

Join order[1]
...
--> 102 Megabytes raw trace file :(
...
*********************************
Number of join permutations tried: 740
*********************************
...
Final - All Rows Plan:  Best join order: 549

Трейс оптимизатора получается > 100 MB (для типового запроса ~ 100-200 KB), при включении трассировки 10053 время выполнения увеличивается до 24+ сек — оптимизатору тяжело приходится с комбинаторикой из 18-и таблиц и максимальным допустимым количеством вариантов перестановок = 2000 (значение по умолчанию параметра _OPTIMIZER_MAX_PERMUTATIONS):

Elapsed: 00:00:24.63

Пути уменьшения времени разбора сложных запросов можно найти в замечательном документе поддержки Advice for Reduction of Long Parse Time [ID 106922.1] (вполне современный, с датой последнего обновления 01-AUG-2011), где в качестве одной из причин медленной работы CBO указано:

Large FROM clause lists — typically 10+ tables

— наш случай, а в качестве решений:

* Use RBO

* Consider the use of parameters such as <PARAMETER:OPTIMIZER_MAX_PERMUTATIONS>
  parameter to change the maximum number of permutations considered

* Use hints to try to reduce the work done by the optimizer, especially:
    ORDERED NO_EXPAND USE_NL USE_MERGE USE_HASH

* Storing an outline of a statement records a parsed# representation of it.
  This means that the statement only needs to be parsed once.
  Applying the outline may avoid repeat re-parses.

1) обращает внимание первая (и в моём случае оказавшаяся лучшей) рекомендация — RBO (Rule Based Optimizer) действительно «рулит» и справляется лучше (точнее, быстрее, но выбирает не самый эффективный план и по количеству consistent gets ~ 52000 проигрывает плану, выбираемому стоимостным оптимизатором (Cost Based Optimizer) ~ 17000) других решений:

SQL> select --+ rule
...
/
Elapsed: 00:00:00.33 <- первое выполнение
...
Statistics
----------------------------------------------------------
18  recursive calls
0  db block gets
51940  consistent gets
0  physical reads
...
SQL> /
Elapsed: 00:00:00.36 <- последующие выполнения
...
Statistics
----------------------------------------------------------
0  recursive calls
0  db block gets
51934  consistent gets
0  physical reads
...

2) Параметр _optimizer_max_permutations можно устанавливать на уровне запроса — также действительно помогает:

SQL> select  --+ opt_param( '_optimizer_max_permutations' 20 )
...
/
Elapsed: 00:00:00.76
SQL> /
Elapsed: 00:00:00.34

3) кроме указанных можно успешно использовать подсказки и/или параметры, отключающие отдельные фичи оптимизатора (и за счёт этого экономящие время оптимизации):

  • NO_QUERY_TRANSFORMATION
  • _optimizer_cost_based_transformation
  • query_rewrite_enabled
  • _simple_view_merging
  • _complex_view_merging
  • _unnest_subquery

, либо subquery factoring (WITH + MATERIALIZE), который отключает некоторые фичи / преобразования запросов оптимизатором

, либо использовать подсказки с указанием оптимизатору конкретных операций доступа к данным (CBO access path):

  • NO_UNNEST
  • NO_MERGE
  • INDEX
SQL> select --+ no_merge(a.i)
from (select--+ no_unnest
...
/
Elapsed: 00:00:01.03
SQL> /
Elapsed: 00:00:00.36

То есть использовать всё, что может облегчить жизнь оптимизатору — либо указзывая что и как делать, либо — на что не тратить время :)

4) использование STORED OUTLINE (по крайней мере в версии 10.2.0.4) — не помогло абсолютно, т.е. OUTLINE создаётся и, судя по значению поля V$SQL_PLAN.OTHER_XML и записям в трейсе 10053 корректно используются, но не уменьшают время первого разбора (и, соответсвенно, всего выполнения):

SQL> select
...
/
...
Elapsed: 00:00:05.60
...
Note
-----
- outline "SYS_OUTLINE_11082412011271001" used for this statement

Statistics
----------------------------------------------------------
43  recursive calls
0  db block gets
17119  consistent gets
0  physical reads
...
1  rows processed
SQL> /
Elapsed: 00:00:00.38

При этом в трейсе 10053 (такого же гиганского размера > 100 MB, как и без OUTLINE) перебираются всё те же 740 вариантов соединений таблиц (Join order[1]…Join order[740]), судя по статистике выполняются всё те же, что и без OUTLINE 43  recursive calls. В конце трейса 10053 указывается на использование OUTLINE:

Content of other_xml column
===========================
db_version     : 10.2.0.4
parse_schema   : SYSTEM
plan_hash      : 1410754801
outline        : SYS_OUTLINE_11082412011271001
Outline Data:

— при этом остаётся совершенно непонятно для чего оптимизатор при готовом шаблоне плана выполнения повторно проделывает всю гиганскую работу — возможно баг 10.2.0.4 ?

http://www.freelists.org/post/oracle-l/Long-Parse-Time
Affect of Number of Tables on Join Order Permutations [ID 73489.1]

Добавить комментарий »

Комментариев нет.

RSS feed for comments on this post. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Создайте бесплатный сайт или блог на WordPress.com.

%d такие блоггеры, как: