Эта статья посвящена анализу некоторых результатов общей оценки производительности системы. По мотивам интересной публикации на сайте Тома Кайта от 16 марта 2004 года. Надеюсь, вы еще помните и регулярно посещаете его сайт...
Statspack: кто ждет событий log file sync и LGWR wait for redo copy?
Прошу прощения за точ, что не могу кратко сформулировать вопрос.
Вот выдержка из отчета statspack:
Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 207 10-Mar-04 08:39:47 36 581,793.7
End Snap: 208 10-Mar-04 08:50:28 36 583,582.8
Elapsed: 10.68 (mins)
...
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time 3,747 66.52
enqueue 2,129 1,350 23.97
db file sequential read 37,842 286 5.07
log file sync 9,743 65 1.15
LGWR wait for redo copy 58,067 61 1.08
Я обратил внимание на CPU time - 3,747 секунды в системе с 4 HT-процессорами (в диспетчере задач Windows отображается 8 процессоров). Это означает, что на одну секунду реального времени приходится 5.85 секунды процессорного времени, затраченного многими одновременно работающими сеансами, загружающими данные в базу.
Теперь, возникает вопрос о событиях ожидания log file sync и LGWR wait for redo copy - я вижу время ожидания 65 секунд, и, насколько я понимаю, это время, которое провели в ожидании фоновые процессы. Если фоновые процессы ждали так долго, мне интересно, насколько это повлияло на пользовательские сеансы (сколько им пришлось ждать в это же время)... (или, возможно, именно это время сеансы конечного пользователя и ждали, поскольку надо было копировать журналы повторного выполнения). Другими словами, это время ожидания самих фоновых процессов или время, в течение которого пользовательские сеансы ожидали завершения фоновых процессов?
Мы только что перевели кэш-буфер диска в режим только записи, как советуется в книге Джонатана Льюиса "Practical Oracle 8i" (ранее он использовался поровну на чтение и запись). При похожей загрузке системы мы увидели уменьшение этих статистических показателей (как по количеству ожиданий, так и по времени):
log file sync 5,464 21 .44 LGWR wait for redo copy 22,215 18 .38
Могу задать вопрос и по-другому - если процесс LGWR прождал 3 секунды, пока копируются данные повторного выполнения, но ни один пользовательский сеанс из-за этого не ждал (если такое вообще возможно), отразится ли это на ожидании событий?
Ответ Тома Кайта
Рассмотрим процессорное время. При наличии продолжительных вызовов, оно легко может быть как больше, так и меньше, чем указано в отчете.
x-----------------x 50 секунд
x----------------------x 50 секунд
x-----------------------------------------------------x 500 секунд
x----------------x 30 секунд
x----------------------------------------x 60 секунд
^ ^
/ /
/------ снимок за этот период ----/ окно в 1 минуту
Пусть вы сделали снимок за период в 1 минуту. Пусть при этом происходили представленные выше "выполнения". statspack сообщит об использованных 80 секундах процессорного времени (50+30), поскольку статистика по процессорному времени учитывается при завершении вызова. Поэтому, вторая и четвертая строки внесли свой вклад в cpu time, а остальные - нет (они не завершились в рассматриваемый период). Учитывайте это.
log file sync - это клиентское ожидание события. Именно этого события ваши клиенты ждут, когда говорят "commit". Это ожидание, пока процесс LGWR фактически запишет их данные повторного выполнения на диск и фиксация транзакции будет завершена. Можно "настроить" этот процесс, ускорив работу процесса lgwr (отказавшись от использования raid 5, например) и фиксируя транзакции реже, генерируя меньше данных повторного выполнения (множественные изменения генерируют меньше данных повторного выполнения, чем построчные)
А вот другое ожидание - фоновое. Процесс LGWR ждет, пока приоритетные процессы закончат текущее копирование, затрагивающее данные, которые LGWR должен обработать.
ОДНАКО, с учетом всего вышесказанного, настройка любого из этих показателей, в любом случае, никак существенно не повлияет на производительность вашей системы! Похоже, основное ваше ожидание - "enqueue", и связано оно с особенностями приложения. Это тяжеловесные блокировки, связанные с алгоритмом работы приложения. Вы достигшнете лучших результатов, изучая в этот момент приложение, а не "систему" в целом.
Установите для приложения событие трассировки 10046 уровня 12 и посмотрите, чего именно оно ждет. Все дело - в настройке приложения.
Все равно не понимаю LGWR wait for redo copy
Спасибо за полезный ответ! Не могли бы вы уточнить, зачем нужны эти ожидания LGWR - какие "приоритетные процессы закончат текущее копирование" и чего именно?
Проясняю в отношении CPU. Наш снимок - за 10 минут, тогда как большинство транзакций (а, значит, и вызовов операторов) завершается не более? чем за минуту => возможность недосчитать или пересчитать составляет +/-10%.
Проясняю в отношении Equeues (я ожидал такого комментария, но не хотел выбрасывать эту строку из отчета statspack). Очереди, однако, хотя и выглядят подозрительно - не вызывают проблем в нашей системе, просто потому, что так и было задумано. Наша система спроектирована так, что ряд фоновых заданий выполняет завершающую обработку данных после их загрузки. И, иногда? фоновые процессы ждут завершения приоритетных процессов (с помощью SELECT...FOR UPDATE), чтобы гарантировать согласованность. Идея в том, что хотя приритетные задания по загрузке могут требовать до одной минуты на транзакцию, эти фоновые задания срабатывают за пару секунд. Большую часть времени наши процессы очереди заданий (6 из них) простаивают, а когда просыпаются (каждую минуту) для выполнения недавно переданных заданий по завершающей обработке, могут обнаружить, что им надо подождать завершения других загрузок. Вреда от этого нет - даже если некоторые процессы очереди заданий из-за этого "зависают", другие процессы свободны и могут выполнять другие задания, а в самом худшем случае завершающая обработка откладывается не более? чем на минуту. Так что, хотя и можно было избавиться от "Enqueues", изменив время выполнения заданий по завершающей обработке, это, вероятно, не повысит общую производительность системы.
Наконец, вы правы в том, что настройка процесса LGWR и log file sync в нашем случае не сильно повысит общую производительность системы (очевидно, что речь идет примерно о 2% общего времени). На самом деле? цель была не столько в настройке, сколько в изучении и доказательстве утверждения Джонатана (установка процента использования кэша для чтения и записи на диске заняла одну минуту).
Ответ Тома Кайта
Копирование данных повторного выполнения - приоритетные процессы это делают (например, lgwr пытается сбросить буфер журнала по одной из причин, которая такой сброс вызывает - 3 секунды, заполнение 1/3, заполнение 1 Мбайта, commit).
Но, серьезно, - эти ожидания ничего не значат, и я бы посоветовал их игнорировать ПОКА они не появятся в результатах трассировки приложения!
Ваши комментарии об очередях (enqueues) - прекрасное объяснение, почему настройка с помощью statspack - "не лучший способ" и почему надо изучать приложение. Любой, кто посмотрит на такой отчет statspack, обратит внимание на enqueues - но вы-то знаете, что в вашем случае они связаны с простоем ("idle-ing waits") :)
Серьезно, какие приоритетные процессы и что копируют?
Я понял, и про настройку больше не спрашиваю. Поделитесь, пожалуйста, как обычно, недостающими нам знаниями. Приведите пример "приоритеного" процесса (это пользовательский сеанс или что-то еще) и того, что именно он копирует (данные, буферы журнала или что-то еще)?
Еще меня удивляет следующий результат:
Event Waits Timeouts Time (s) (ms) /txn ---------------------------- ------------ ---------- ---------- ------- -------- log file sequential read 849 0 10 12 0.0
Почему Oracle читает файл журнала повторного выполнения (кроме как при восстановлении, но мы его не выполняли в период? охваченный этим отчетом statspack)?
Ответ Тома Кайта
Процесс LGWR собирается записать набор блоков журнала на диск. Он должен подождать, пока приоритетный процесс (мы, вы и я) не завершит любые текущие операции копирования, затрагивающие буферы, которые мы собираемся записывать. Раньше была защелка 'redo copy latch', но в 8i были сделаны изменения для повышения производительности, чтобы это делалось "быстрее".
Так что, это данные, связанные с журналом.
Вы же работаете в режиме archive log??
ops$tkyte@ORA9IR2> select * from v$system_event where event like 'log file sequential%' 2 / EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT ------------------------- ----------- -------------- ----------- ------------ log file sequential read 4 0 0 0 ops$tkyte@ORA9IR2> @connect "/ as sysdba" ops$tkyte@ORA9IR2> set termout off sys@ORA9IR2> REM GET afiedt.buf NOLIST sys@ORA9IR2> set termout on sys@ORA9IR2> alter system switch logfile; System altered. sys@ORA9IR2> archive log all; 1 log archived. sys@ORA9IR2> @connect / sys@ORA9IR2> set termout off ops$tkyte@ORA9IR2> REM GET afiedt.buf NOLIST ops$tkyte@ORA9IR2> set termout on ops$tkyte@ORA9IR2> select * from v$system_event where event like 'log file sequential%' 2 / EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT ------------------------- ----------- -------------- ----------- ------------ log file sequential read 69 0 26 0
;)