Oracle mechanics

27.08.2010

Несвязанные переменные и CURSOR SHARING

Нагрузочные тесты (веб) приложения Apache+PHP+Oracle 11.2 (описание результатов — Test case: 44 хита в секунду – Битрикс «Большой бизнес» на Oracle 11g), специалисты клиента видят грустные цифры в отчёте AWR:

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.97    In-memory Sort %:  100.00
            Library Hit   %:   57.34        Soft Parse %:   97.83
         Execute to Parse %:   18.35         Latch Hit %:   99.84
Parse CPU to Parse Elapsd %:    2.62     % Non-Parse CPU:   39.39
...
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                          Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ -----------
library cache lock                1,664,128      70,558     42   81.7 Concurrency
cursor: mutex S                     249,587       6,444     26    7.5 Concurrency
library cache: mutex X              155,245       4,719     30    5.5 Concurrency
DB CPU                                            3,321           3.8
log file sync                        94,484         663      7     .8 Commit
...
Operating System Statistics - Detail
Snap Time           Load    %busy    %user     %sys    %idle  %iowait
--------------- -------- -------- -------- -------- -------- --------
44-Aug 16:00:10     70.0     24.3     21.6      1.8     75.7      0.3
-------------------------------------------------------------
...
Foreground Wait Class
Wait Class                      Waits -outs         Time (s)     (ms)  %DB time
-------------------- ---------------- ----- ---------------- -------- ---------
Concurrency                 2,075,334    12           81,762       39      94.6
DB CPU                                                 3,321                3.8

и (на первый взгляд) обоснованно писали:

«… низкая производительность под нагрузкой обусловлена ситуацией с использованием несвязанных переменных («небиндованные») в запросах и 60% работы CPU уходит на парсинг и вышеуказанные изменения мало повлияют на производительность в целом»

Формально выводы специалистов клиента логичны:

  • коэффициенты Execute to Parse, Non-Parse CPU, Parse CPU to Parse Elapsd имеют низкие значения, что косвенно указывает на то, что бд тратит основную часть процессорного времени на разбор (parse), вместо выполнения запросов (execute)
  • топ ожиданий пользовательских сессий подтверждает предыдущее предположение — на первом месте с большим отрывом ожидания library cache lock, cursor: mutex S, library cache: mutex X

Но для приложений, не использующих связанные переменные, у Oracle есть отличный механизм cursor sharing, позволяющий повторно использовать курсоры независимо от использования в запросах связанных переменных. И клиент честно пытался его использовать, установив cursor_sharing=similar «согласно рекомендациям разработчиков»

Поскольку с проблемой конкуренции за shared pool мы уже сталкивались, постарался обратить внимание специалистов клиента на ожидание log file sync со средним временем 7 мс, что близко к неоптимизированной скорости записи на диск (без RAID, кэширования и т.п.)

Чтобы выяснить, почему не сработал cursor sharing, смотрим отчёт AWR дальше:

...
Time Model Statistics
Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
parse time elapsed                                   76,934.9         89.0
failed parse elapsed time                            74,365.4         86.1
sql execute elapsed time                              8,550.1          9.9
DB CPU                                                3,321.4          3.8
hard parse (sharing criteria) elapsed time              168.0           .2
hard parse elapsed time                                 167.9           .2
connection management call elapsed time                  44.9           .1
hard parse (bind mismatch) elapsed time                  36.4           .0
PL/SQL execution elapsed time                             3.8           .0
sequence load elapsed time                                2.1           .0
repeated bind elapsed time                                0.0           .0
DB time                                              86,399.6
...
SQL ordered by Version Count
 Version
 Count   Executions     SQL Id
-------- ------------ -------------
 5,076          N/A 62zbzmcjbhxxj
 4,526          N/A 2033a9s8byzdd
 3,479          N/A 62d0ntyvxg6aw
...

В разделе Time Model Statistics обращает внимание непонятная метрика failed parse elapsed time, занимающая более 96% от  parse time elapsed и 86% от всего DB time (!) — похоже на время каких-то проблем (блокировок, latches) во время разбора SQL (parse time elapsed), точно не имеющее отношения к неправильному синтаксису запросов (что будет видно дальше). Из оценки затраченного времени можно сделать вывод, что failed parse elapsed time связано (учитывает) с ожиданиями library cache*

Из системного обзора V$SQL_SHARED_CURSOR можно узнать причину, по которой Oracle вынужден создать новый курсор (вместо того, чтобы повторно использовать уже присутствующие в shared pool «разобранные» курсоры) с помощью запроса или используя универсальную (9iR2 , 10gR1, 10gR2, 11gR1, 11gR2) процедуру c поддержки Formated V$SQL_SHARED_CURSOR Report by SQLID or Hash Value [ID 438755.1]. Итак, причина называется HASH_MATCH_FAILED

SQL> select CHILD_NUMBER, HASH_MATCH_FAILED
 2  from V$SQL_SHARED_CURSOR where sql_id = '62zbzmcjbhxxj'
 3  order by CHILD_NUMBER
 4  /

CHILD_NUMBER HASH_MATCH_FAILED
------------ -----------------
 0 N
 1 Y
 2 Y
...

В текущей документации Oracle 11.2 стобец V$SQL_SHARED_CURSOR.HASH_MATCH_FAILED описан небогато:

HASH_MATCH_FAILED     VARCHAR2(1)     (Y|N) ???

Из документа Unsafe Literals or Peeked Bind Variables [ID 377847.1]:

«Начиная с 11g R2 (и 11.1.0.7 Patchset) в V$SQL_SHARED_CURSOR добавлен новый столбец для случаев использования текстовых подстановок (literal replacement) при значении параметра CURSOR_SHARING=SIMILAR. HASH_MATCH_FAILED устанавливается равным «Y» если повторное использование курсора невозможно из-за hash mismatch,.. Неразделяемые курсоры (unshared child cursors) могут иметь гистограммы на ключевых столбцах, используемых в условиях равенства (equality predicates «=» и «!=»), либо условия по диапазону значений (range predicates [точнее, по любым другим условиям, кроме равенства и неравенства, imho]) с текстовыми подстановками (literal replacements), которые оптимизатор считает небезопасными (unsafe literals, в том смысле, что значения этих текстовых констант (literals) могут влиять на план выполнения)»

У клиента действительно установлен CURSOR_SHARING=SIMILAR в соответствии с рекомендациями:

установить параметр cursor_sharing=similar и отключить гистограммы
или
установить cursor_sharing=force

К сожалению, вторая часть первого варианта рекомендаций (отключить гистограммы) выполнена не была:

SQL> select histogram, count(*) from dba_tab_columns where owner = 'SCOTT' group by histogram;

HISTOGRAM         COUNT(*)
--------------- ----------
FREQUENCY               89
HEIGHT BALANCED         12
NONE                  3660

Проблема известна и  описана в документе поддержки High Version Count with CURSOR_SHARING = SIMILAR or FORCE [ID 261020.1], где, в частности, перечислены возможные проблемы (практически на 100% совпадающие с наблюдаемыми у нашего клиента):

«Высокие значения version counts часто могут быть причиной высокой конкуренции за library cache latches.
Клиентский процесс Oracle при разборе SQL с большим количеством версий (children cursors) вынужден сканировать все эти дочерние курсоры, удерживая library cache latch. Т.о. другие процессы, при необходимости получить тот же latch вынуждены ждать, что может приводить к значительному ухудшению производительности всей бд.
СИМПТОМЫ
———
— Значительная часть DB time тратится на ожидание library cache latch
— Высокие коэффициенты разбора запросов в AWR/Statspack отчётах
High version counts в AWR/Statspack отчётах
— использование значения параметра cursor_sharing = SIMILAR
— Периодическое падение производительности бд в целом»

В нашем случае важно, что большое количество версий (version count) порождённых курсоров (children cursors) для синтаксически одинаковых запросов (идентифицируемых по HASH_VALUE) после разбора используют один план выполнения (PLAN_HASH_VALUE):

SQL> select hash_value,plan_hash_value,count(*) from v$sql
 2  where sql_id = '62zbzmcjbhxxj'
 3  group by hash_value,plan_hash_value
 4  /

HASH_VALUE PLAN_HASH_VALUE   COUNT(*)
---------- --------------- ----------
 582514609      2273822293       3693

В таком случае указанный документ рекомендует установить значение параметра CURSOR_SHARING=FORCE, что понятно — значение текстовых констант не влияют на выбранный оптимизатором план выполнения запросов, при значительном потреблении процессорных ресурсов процессом создания новых курсоров.

После изменений картина в отчёте AWR/Statspack за период последующих тестов стала выглядеть совсем по-другому:

Instance Efficiency Indicators
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 Buffer Nowait %:  100.00               Redo NoWait %:  100.00
 Buffer  Hit   %:   99.98               Optimal W/A Exec %:  100.00
 Library Hit   %:  100.00               Soft Parse %:  100.00
 Execute to Parse %:   17.16            Latch Hit %:   99.92
 Parse CPU to Parse Elapsd %:   91.66   % Non-Parse CPU:   92.83

Коэффициенты Parse CPU to Parse Elapsd, %Non-Parse CPU имеют вполне удовлетворительные значения > 90%. Значение Execute to Parse невысокое, однако это количественный коэффициент, отражающий относительно большое количество «мягких» разборов (soft parse, Soft Parse % = 100), которые по времени занимают ~ 7% от полезного процессорного времени (значение %Non-Parse CPU ~ 93%) или ~ 3.5% от DB time (см. статистику parse time elapsed ниже)

Нагрузка на процессор нормализовалась

Host CPU  (CPUs: 4  Cores: 4  Sockets: 2)
 ~~~~~~~~              Load Average
 Begin     End      User  System    Idle     WIO     WCPU
 ------- -------   ------- ------- ------- ------- --------
  1.58    2.98      26.52   6.24    63.47    0.71

Time Model System Stats
 -> Ordered by % of DB time desc, Statistic name
 Statistic                                       Time (s) % DB time
 ----------------------------------- -------------------- ---------
 DB CPU                                           4,756.4      56.0
 sql execute elapsed time                         2,679.6      31.6
 parse time elapsed                                 295.1       3.5
 connection management call elapsed                  26.7        .3
 PL/SQL execution elapsed time                        9.8        .1
 sequence load elapsed time                           7.0        .1
 hard parse elapsed time                              1.5        .0
...
Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     3,597          41.9
log file sync                                  316,732       3,235     10   37.7
LNS wait on SENDREQ                            318,657         739      2    8.6
LGWR-LNS wait on channel                       338,121         641      2    7.5
log file parallel write                        548,076         247      0    2.9

Как и ожидалось, после решения проблемы с блокировками shared pool, узким местом стали ожидания, связанные с записью redo log файлов: ожидание log file sync клиентских процессов:

Foreground Wait Events
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
log file sync                     316,728    0      3,235     10      1.1   37.7

и связанные ожидания серверного процесса LGWR (см. описание Data Guard Wait Events [ID 233491.1])

Background Wait Events
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
LNS wait on SENDREQ               318,657    0        739      2      1.1    8.6
LGWR-LNS wait on channel          338,121   11        641      2      1.1    7.5
log file parallel write           548,076    0        247      0      1.9    2.9
control file parallel write        10,872    0         16      1      0.0     .2

Это были данные в усреднённом виде из отчета AWR, выполнение отчёта по суммарным ожиданиям  активных сессий во время нагрузочных тестов даёт ещё более грустную картину:

WAIT_EVENT                     WAIT_PCT    WAIT_AVG_MS    TIME_WAITED_MS    TOTAL_WAITS    TOTAL_TIMEOUTS
log file sync                     58,3%          35,37             40345          11126                 0
CPU used when call started        40,4%              0             27988              0                 0
SQL*Net break/reset to client      0,3%           2,07               263           1286                 0

После установки в качестве эксперимента commit_write = ‘BATCH, NOWAIT’ (что категорически не рекомендуется для production систем) на аналогичной нагрузке получили:

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     4,909          54.2
log file sync                                   21,942       2,516    115   27.8
log file parallel write                         35,198         690     20    7.6
db file async I/O submit                        15,229         227     15    2.5
LNS wait on SENDREQ                             24,629         176      7    1.9
 -------------------------------------------------------------
Host CPU  (CPUs: 4  Cores: 4  Sockets: 2)
~~~~~~~~              Load Average
 Begin     End      User  System    Idle     WIO     WCPU
 ------- -------   ------- ------- ------- ------- --------
 18.35   27.55     79.85    6.17   10.23    0.12

уменьшение % ожидания log file sync при соответствующем увеличениий доли полезной нагрузки CPU time (и неожиданно возросшей системной загрузке Load Average), уменьшение количества при увеличении среднего времени ожиданий log file sync (Avg wait (ms) = 115 мс!)

Но это уже другая история, связанная с конфигурацией redo log, конфигурацией дисковой и сетевой подсистем, Data Guard и т.д.

2 комментария »

  1. Oracle — это прямо стихотворение Ломоносова.
    Открылась бездна звезд полна.
    Звездам числа нет, бездне дна.

    комментарий от Константин Комаш — 02.11.2010 @ 10:36 | Ответить

    • недаром старые печатные мануалы Oracle (до 6 версии включительно) были усыпаны цитатами титанов мысли
      Жаль традиция не сохранилась :(

      комментарий от Igor Usoltsev — 02.11.2010 @ 12:25 | Ответить


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 такие блоггеры, как: