Ноябрь 2004
Профессионалу администратору
Роджер Шраг, Тэрри Саттон,
Database Specialists, Inc.
(
http://www.dbspecialists.com)
Настройка систем баз данных с помощью анализа событий ожидания: реальные примеры
(часть IV)
More Examples of Interpreting Wait Events to Boost System Performance,
by Roger Schrag and Terry Sutton, Database Specialists, Inc.
Источник: http://www.dbspecialists.com/presentations/wait_events2.html.
(перевод выполнен под редакцией Александра Соколова, компания РДТЕХ)
(Прим. ред. Для удобства читателя приводится полное содержание статьи. Текущие разделы выделены полужирным шрифтом.)
Общее содержание
Содержание частей 1-3, опубликованных в
предыдущем выпуске OM/RE
- Введение
- Что такое события ожидания?
- Определение термина "событие ожидания"
- Почему полезна информация о событиях ожиданияx
- Имена событий ожидания и что они означают
- Информация, которую не обеспечивают события ожидания
- Примечание: параметр инициализации "timed_statistics"
- Сбор информации о событиях ожидания
- Представление v$system_event
- Представление v$session_event
- Представление v$event_name
- Представление v$session_wait
- Трассировка событий ожидания
- Использование информации о событиях ожидания в целях повышения производительности систем
- Пример 1. События ожидания "buffer busy waits"
- Пример 2. Еще о событиях ожидания "buffer busy waits", а также о конкуренции за защелки
Содержание части 4
Содержание части 5
- Об авторах
- Приложение к русскому переводу
- Как можно использовать информацию о событиях ожидания в целях повышения производительности систем
- Пример 1. Медленная веб-страница
- Пример 2. Медленная пакетная обработка
- Пример 3. Медленное клиент-серверное приложение
- Пример 4. Сервер базы данных, "хромающий на обе ноги"
Пример 3. События ожидания, связанные с журнальными файлами
Приложение выполняло нерегулярные загрузки в небольшое хранилище данных. К сожалению, в промышленной системе для выполнения загрузок требовалось намного более продолжительное время, чем в тестовой среде. Чтобы узнать, что происходило в сервере промышленной базы данных во время загрузки данных, мы выполнили следующий скрипт, который через 30 секунд после запуска выдает список событий ожидания, происшедших на уровне всего экземпляра. Список событий в предложении NOT IN позволяет просто отфильтровать события простоя, делая вывод немного более легким для чтения:
DROP TABLE previous_events;
CREATE TABLE previous_events
AS
SELECT SYSDATE timestamp, v$system_event.*
FROM v$system_event;
EXECUTE dbms_lock.sleep (30);
SELECT A.event,
A.total_waits – NVL (B.total_waits, 0) total_waits,
A.time_waited – NVL (B.time_waited, 0) time_waited
FROM v$system_event A, previous_events B
WHERE B.event (+) = A.event
AND A.event NOT IN
(
'client message', 'dispatcher timer', 'gcs for action',
'gcs remote message', 'ges remote message', 'i/o slave wait',
'jobq slave wait', 'lock manager wait for remote message',
'null event', ‘Null event’, 'parallel query dequeue', 'pipe get',
'PL/SQL lock timer', 'pmon timer', 'PX Deq Credit: need buffer',
'PX Deq Credit: send blkd', 'PX Deq: Execute Reply',
'PX Deq: Execution Msg', 'PX Deq: Signal ACK',
'PX Deq: Table Q Normal', 'PX Deque Wait', 'PX Idle Wait',
'queue messages', 'rdbms ipc message', 'slave wait',
'smon timer', 'SQL*Net message to client',
'SQL*Net message from client', 'SQL*Net more data from client',
'virtual circuit status', 'wakeup time manager'
)
ORDER BY time_waited;
Выполняя этот скрипт во время загрузки данных, получаем следующее:
EVENT TOTAL_WAITS TIME_WAITED
----------------------------------- ----------- -----------
LGWR wait for redo copy 0 0
SQL*Net break/reset to client 2 0
SQL*Net more data to client 0 0
buffer busy waits 0 0
db file scattered read 6 0
direct path read 27 0
direct path write 34 0
direct path write (lob) 0 0
file identify 6 0
file open 93 0
library cache pin 0 0
local write wait 0 0
process startup 0 0
rdbms ipc reply 0 0
refresh controlfile command 0 0
single-task message 0 0
switch logfile command 0 0
control file sequential read 61 1
latch free 2 1
db file sequential read 6 7
control file parallel write 41 31
log file single write 6 164
db file parallel write 13 220
enqueue 6 486
log buffer space 24 2007
log file sequential read 30 2655
log file switch completion 33 2883
log file parallel write 19 3561
log file sync 113 10249
В течение интервала выборки, равного 30 секундам, процессы сервера Oracle затратили примерно 215 секунд на ожидания событий, связанных с оперативными журнальными файлами. Вероятный виновник в этой ситуации – недостаточная производительность дисковой подсистемы и конкуренция по доступу к дискам, на которых хранятся оперативные журнальные файлы. После небольшого исследования мы обнаружили, что в более быстрой тестовой системе все журнальные файлы хранились в RAID-массиве с автоматическим распределением операций ввода-вывода по дискам массива. В промышленной системе, однако, все журнальные файлы размещались на одном-единственном диске, на котором также размещались активно используемые другие файлы базы данных. Когда оперативные журнальные файлы были перемещены на отдельные диски, загрузка данных стала производиться быстрее, и количество ожиданий событий, связанных с журнальными файлами, существенно уменьшилось.
Пример 4. События ожидания, связанные с операциями чтения и записи в режиме прямого доступа
Компания испытывала задержки при запросе сводной информации о своих заказах. Запрос данных об индивидуальных заказах выполнялся быстро, но запросы с агрегатными группированиями данных выполнялись недопустимо долго. Мы применили наше инструментальное средство для мониторинга Database Rx, чтобы собрать информацию о производительности системы во время, когда пользователи выполняли свои типичные задачи. (Инструмент Database Rx – это средство превентивного мониторинга и сигнального оповещения, который мы разработали для удаленного администрирования баз данных наших клиентов. С демонстрационной версией инструмента можно ознакомиться на нашем веб-сайте dbrx.dbspecialists.com/guest.) Сводный отчет о производительности системы (Performance Summary) имел следующий вид:
Посмотрев раздел "Top 5 Wait Events" (5 самых продолжительных событий ожидания), мы видим, что лидируют следующие события: "direct path write" (запись в режиме прямого доступа), "db file scattered read" (чтение "вразброс" из файлов базы данных) и "direct path read" (чтение в режиме прямого доступа). В совокупности на эти три события ожидания приходится примерно 99% времени ожидания в системе (за вычетом времени простоя) в течение интервала выборки. Зная запросы в приложении, возникновение событий ожидания "db file scattered read" (то есть полный просмотр таблиц) не удивило нас. Отсутствие событий ожидания "db file sequential read" (последовательное чтение из файлов базы данных) также не удивляло нас, поскольку требуемые блоки для просмотров индексов и выборки строк по ROWID находились, вероятно, в кеше буферов.
Мы полагали, что были в состоянии уменьшить количество событий ожидания "db file scattered read" в ближайшей перспективе с помощью большего кеша буферов или разумного использования пула KEEP (удерживающий буферный пул), а в дальнейшей перспективе с помощью анализа и переписывания кода приложения. Однако казалось непонятным возникновение большого количества событий ожидания "direct path write" и "direct path read". Запрос к представлению v$session_wait во время работы приложения показал следующее:
SQL> SELECT sid, event, state, seconds_in_wait, wait_time, p1, p2, p3
2 FROM v$session_wait
3 WHERE event = 'direct path write'
4 ORDER BY sid;
SID EVENT STATE SECONDS_IN_WAIT WAIT_TIME P1 P2 P3
---- ----------------- ----- --------------- --------- ------ ------ ------
39 direct path write WAITI 0 0 201 65 7
47 direct path write WAITI 0 0 201 2248 7
SQL>
Запрос к представлению v$event_name показывает параметры события "direct path write":
SQL> SELECT * FROM v$event_name WHERE name = 'direct path write';
EVENT# NAME PARAMETER1 PARAMETER2 PARAMETER3
---------- -------------------- --------------- --------------- ---------------
115 direct path write file number first dba block cnt
SQL>
Как видим, предполагается, что первый параметр – номер файла данных (file number), содержащий записываемые блоки; но с помощью следующего запроса мы не смогли обнаружить файл данных 201:
SQL> SELECT tablespace_name, file_id "AFN", relative_fno "RFN"
2 FROM dba_data_files
3 WHERE file_id = 201;
no rows selected
SQL>
Это произошло потому, что сервер базы данных использовал временные файлы во временном табличном пространстве. Поэтому мы воспользовались следующим запросом:
SQL> SELECT tablespace_name, file_id + value "AFN", relative_fno "RFN"
2 FROM dba_temp_files, v$parameter
3 WHERE name = 'db_files';
TABLESPACE_NAME AFN RFN
------------------------------ ---------- ----------
TEMP 201 1
SQL>
Этот запрос показывает, что события ожидания "direct path write" возникают при работе с временным табличным пространством TEMP, и это не удивительно, поскольку операции прямого чтения и записи обычно происходят с временными сегментами при выполнении операций хеш-соединения и сортировки. Операции прямого ввода-вывода были ответственны за большую часть событий ожидания в системе и, казалось, были ее узким местом. После дальнейшей экспертизы мы обнаружили, что в параметре "sort_area_size" (размер области сортировки) было установлено значение по умолчанию, равное 65536. Так как сервер базы данных имел достаточно большой объем свободной оперативной памяти и не было слишком большого количества сеансов, одновременно соединенных с базой данных, мы увеличили параметр "sort_area_size" до 10 МБ, и ожидания "direct path…" исчезли, поскольку операции сортировки не должны были писать на диск.
Увеличение размера параметра "sort_area_size" было не единственным вариантом; можно было бы проверить быстродействие дисков, на которых размещаются временные файлы табличного пространства TEMP, и проверили бы наличие конкуренции ввода-вывода с другими компонентами системы. Целесообразно было бы также проанализировать код приложения, чтобы проверить возможность уменьшения количества операций сортировки и хеширования.
Этот пример также демонстрирует нечто, что могло бы на первый взгляд показаться странным. Во время периода сбора статистических данных утилитой Database Rx оказалось, что было больше физических чтений (physical reads), чем логических (logical reads). Как это может быть, разве не всем физическим чтениям также требуются и логические чтения? Это как раз то, на что указывает название операций direct path reads – чтение в режиме прямого доступа. В бюллетене корпорации Oracle номер 50415.1 на сайте Metalink сказано: "Чтения в режиме прямого доступа обычно используются сервером Oracle для чтения непосредственно в память PGA (в противоположность кешу буферов)". Так как чтения в режиме прямого доступа обходят кеш буферов, они не учитываются при подсчете логических чтений. В этом заключается причина, по которой некоторые специалисты подвергают сомнению традиционное определение коэффициента попадания в кеш буферов, потому что оно не принимает во внимание чтения в режиме прямого доступа. Мы не будем это обсуждать, но знайте: чтения в режиме прямого доступа могут искажать вычисленный вами коэффициент попадания в кеш буферов. В данном примере он был бы отрицательным!
Пример 5. События ожидания, относящиеся к связям баз данных
Некоторые сетевые события ожидания являются событиями простоя (idle events). Например, событие "SQL*Net message from client" (SQL*Net-сообщение от клиента) указывает, что процесс ждет, когда приложение предоставит ему для обработки SQL-оператор. Однако SQL*Net-события, относящиеся к связям баз данных, не являются событиями простоя – они начинают действовать, когда запросы используют связи баз данных для доступа к удаленным базам данных. Событие "SQL*Net message from dblink" (SQL*Net-сообщение из связи баз данных), например, указывает, что локальный процесс выдал запрос в удаленную базу данных и ждет ответа.
Компания развернула приложение импорта данных для получения от своих партнеров пакетов сделок с клиентами. Было пять баз данных Oracle, по одной на каждый географический регион. Сделки с клиентами были отсортированы по географическому местонахождению и загружены в соответствующие базы данных, обслуживающие конкретные регионы. Иногда из-за человеческой ошибки одна и та же сделка с клиентом могла быть импортирована в несколько баз данных Oracle. Для устранения этой ошибки компания разработала отчет согласования. Отчет представлял собой просто запрос, который сравнивал сделки, хранящиеся в двух базах данных, и выдавал список сделок, найденных в обеих базах. К сожалению, для подготовки отчета требовалось более 30 минут, и предполагалось, что время подготовки станет увеличиваться по мере роста клиентской базы.
Мы пришли к мнению, что львиную долю ресурсов потребляет основной запрос. Используя утилиту SQL*Plus, мы в одном окне вошли в систему как пользователь приложения, а в другом окне – как администратор базы данных. В сеансе администратора базы данных мы выполнили запрос к представлению v$session и нашли идентификатор сеанса (SID) нашего пользователя приложения. Затем мы в сеансе пользователя приложения запустили запрос, а в другом сеансе выполняли его мониторинг, используя представление v$session_event. Поскольку интерфейс событий ожидания не подсчитывает время использования центрального процессора, мы также использовали представление v$sesstat.
После завершения запроса через 31 минуту, мы выполнили последний раз запрос к представлению v$session_event и получили следующие результаты:
SQL> SELECT event, total_waits, time_waited, max_wait
2 FROM v$session_event
3 WHERE sid = 47
4 ORDER BY event;
EVENT TOTAL_WAITS TIME_WAITED MAX_WAIT
------------------------------ ----------- ----------- ----------
SQL*Net message from client 32 4435 2432
SQL*Net message from dblink 1525516 104919 31
SQL*Net message to client 33 0 0
SQL*Net message to dblink 1525516 466 9
db file sequential read 27199 8025 28
latch free 40 5 4
log file sync 1 2 2
7 rows selected.
SQL> SELECT A.name, B.value
2 FROM v$statname A, v$sesstat B
3 WHERE A.statistic# = 12
4 AND B.statistic# = A.statistic#
5 AND B.sid = 47;
NAME VALUE
------------------------------ ----------
CPU used by this session 67937
SQL>
Мы можем игнорировать событие ожидания "SQL*Net message from client", потому что оно только указывает, как долго сервер Oracle ждал от нас ввода запроса (в утилите SQL*Plus). Однако было более 1.5 миллионов "круговых" обменов (roundtrips) через сетевую связь базы данных (события ожидания "SQL*Net message from dblink" и "SQL*Net message to dblink" ), на что в общем потребовалось более 1053 секунд. (В эти 1053 секунды входит как время, затраченное на обмен по сети, так и время, израсходованное удаленным сервером базы данных на подготовку ответов на запросы.) Возникало также более 27,000 событий ожидания "db file sequential read" (последовательное чтение из файлов базы данных) – приблизительно 80 секунд времени ожидания. Наблюдались также события ожидания "latch free" (освобождение защелки) и "log file sync" (синхронизация журнальных файлов), но время ожиданий было незначительным. Запрос к представлению v$sesstat показал, что было использовано приблизительно 679 секунд процессорного времени.
Абстрагируясь от запроса, использованного для подготовки отчета, или размера базы данных, мы увидели, что количество "круговых" сетевых обменов было, вероятно, чрезмерно большим, и количество операций ввода-вывода одиночных блоков было, скорее всего, слишком большим. Прежде чем двигаться дальше, мы действительно должны были познакомиться с самим запросом и используемыми в нем таблицам. Запрос выглядел так:
SELECT customer_id, batch_serial_number, batch_date, load_date,
batch_comment, control_total, control_amount
FROM customer_transfer_batches A
WHERE exists
(
SELECT 1
FROM customer_transfer_batches@prdwest B
WHERE B.customer_id = A.customer_id
AND B.batch_serial_number = A.batch_serial_number
)
ORDER BY customer_id, batch_serial_number;
Оцененная статистика по таблице CUSTOMER_TRANSFER_BATCHES показала, что таблица имела приблизительно 1,526,000 строк, распределенных приблизительно по 21,825 блокам. Сравнивая информацию о событиях ожидания с размером таблицы, мы поняли, что сервер Oracle каждый раз читал по одному блоку локальной таблицы, запрашивая для каждой локальной строки удаленную таблицу. План выполнения этого запроса подтверждал это:
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT
1 0 FILTER
2 1 TABLE ACCESS (BY INDEX ROWID) OF 'CUSTOMER_TRANSFER_BATCHES'
3 2 INDEX (FULL SCAN) OF 'CUSTOMER_TRANSFER_BATCHES_PK' (UNIQUE)
4 1 REMOTE* PRDWEST
4 SERIAL_FROM_REMOTE SELECT "CUSTOMER_ID","BATCH_SERIAL_NUMBER"
FROM "CUSTOMER_TRANSFER_BATCHES" "B"
WHERE "BATCH_SERIAL_NUMBER"=:1
AND "CUSTOMER_ID"=:2
Выполнение 1.5 миллионов "круговых" сетевых обменов и выполнение 1.5 миллиона запросов в сервере удаленной базы данных не казалось самым эффективным способом решения поставленной задачи. Вероятно, было бы более эффективным сначала переместить все необходимые данные из удаленной базы данных в локальную, а затем соединить их с локальной таблицей. Можно было бы включить в запрос подсказку оптимизатору, чтобы заставить сервер Oracle преобразовывать подзапрос в соединение, но вместо этого мы захотели перезаписать запрос сами, чтобы оптимизатору запроса в сервере Oracle было легче принять правильное решение. Перезаписанный запрос имел следующий вид:
SELECT customer_id, batch_serial_number, batch_date, load_date,
batch_comment, control_total, control_amount
FROM customer_transfer_batches
WHERE (customer_id, batch_serial_number) IN
(
SELECT customer_id, batch_serial_number
FROM customer_transfer_batches
INTERSECT
SELECT customer_id, batch_serial_number
FROM customer_transfer_batches@prdwest
)
ORDER BY customer_id, batch_serial_number;
Мы выполнили исправленный запрос, и мониторинг (тот же, что и раньше) представлений v$session_event и v$sesstat показал следующие результаты:
SQL> SELECT event, total_waits, time_waited, max_wait
2 FROM v$session_event
3 WHERE sid = 49
4 ORDER BY event;
EVENT TOTAL_WAITS TIME_WAITED MAX_WAIT
------------------------------ ----------- ----------- ----------
SQL*Net message from client 46 3680 2481
SQL*Net message from dblink 24 31 18
SQL*Net message to client 47 0 0
SQL*Net message to dblink 24 0 0
SQL*Net more data from dblink 5978 1337 13
db file scattered read 3430 675 8
db file sequential read 182 60 2
direct path read 148 233 11
direct path write 920 3572 33
log file sync 1 2 2
10 rows selected.
SQL> SELECT A.name, B.value
2 FROM v$statname A, v$sesstat B
3 WHERE A.statistic# = 12
4 AND B.statistic# = A.statistic#
5 AND B.sid = 49;
NAME VALUE
------------------------------ ----------
CPU used by this session 3227
SQL>
На этот раз запрос закончился через 92 секунды. Как общее затраченное время, так и время использования центрального процессора сократились примерно на 95%. Время ожидания завершения обменов по связи баз данных, равное раньше приблизительно 1053 секундам, уменьшилось до менее чем 14 секунд, указывая на уменьшение сетевых накладных расходов и существенное уменьшение нагрузки на сервер удаленной базы данных. Время ожидания событий "db file sequential read" и "db file scattered read" (чтение "вразброс" из файлов базы данных) стало значительно короче времени ожидания событий "db file sequential read" в первоначальном запросе, потому что большое количество операций ввода-вывода одиночных блоков было заменено меньшим количеством операций многоблочного ввода-вывода.
Однако было затрачено приблизительно 38 секунд на ожидание завершения операций ввода-вывода в режиме прямого доступа (direct path…). Как мы видели раньше, ввод-вывод в режиме прямого доступа обычно происходит с временными сегментами при выполнении операций хеш-соединения и сортировки. Сервер Oracle для выполнения операции INTERSECT (пересечение результирующих наборов), добавленной к перезаписанному запросу, должен был выполнить небольшое количество операций сортировки, так что операции ввода-вывода в режиме прямого доступа не были неожиданны.
Повышение производительности, достигнутое за счет перезаписи запроса, было настолько существенным, что мы испытывали желание закончить работу по настройке прямо на этом месте. Однако компания-заказчик обратила внимание на то, что этот отчет является критическим для их работы, и они хотели бы заставить его работать еще быстрее, если это возможно. Итак, наш следующий шаг должен был ускорить операции сортировки и таким образом уменьшить время ожидания ввода-вывода в режиме прямого доступа.
В представлении v$parameter мы увидели, что в параметре "sort_area_size" (размер области сортировки) был установлено значение, равное 1 МБ. Большая область сортировки позволила бы серверу Oracle выполнять больше сортировок в оперативной памяти без использования диска, уменьшая, таким образом, ввод-вывод в режиме прямого доступа. Чтобы увидеть эффект от увеличения размера области сортировки, мы повторили процедуру мониторинга нашего запроса, предварительно установив в сеансе утилиты SQL*Plus, в котором выполнялся запрос, динамическое значение параметра "sort_area_size", равное 100 МБ. Запрос на этот раз закончился через 55 секунд, и статистические данные в представлениях v$session_event и v$sesstat были следующими:
SQL> SELECT event, total_waits, time_waited, max_wait
2 FROM v$session_event
3 WHERE sid = 46
4 ORDER BY event;
EVENT TOTAL_WAITS TIME_WAITED MAX_WAIT
------------------------------ ----------- ----------- ----------
SQL*Net message from client 47 442 287
SQL*Net message from dblink 25 25 14
SQL*Net message to client 48 0 0
SQL*Net message to dblink 25 0 0
SQL*Net more data from dblink 6050 1378 26
db file scattered read 3430 945 8
db file sequential read 191 59 1
log file sync 1 3 3
8 rows selected.
SQL> SELECT A.name, B.value
2 FROM v$statname A, v$sesstat B
3 WHERE A.statistic# = 12
4 AND B.statistic# = A.statistic#
5 AND B.sid = 46;
NAME VALUE
------------------------------ ----------
CPU used by this session 3296
SQL>
Как видим, увеличение размера области сортировки не позволило уменьшить процессорное время, как и время ожидания завершения сетевых обменов или чтений "вразброс" или последовательных чтений из файлов базы данных. Однако операции ввода-вывода в режиме прямого доступа полностью исчезли. Это указывает на то, что вся сортировка была выполнена в оперативной памяти. Конечно, по мере роста таблицы CUSTOMER_TRANSFER_BATCHES нереально выполнять сортировку полностью в оперативной памяти. Но большая область сортировки будет по-прежнему ускорять сортировку и уменьшать общее время выполнения запроса, даже если она не может быть полностью выполнена в оперативной памяти.
Этот пример продемонстрировал практику итеративной настройки: устранение одного узкого места часто создает другое узкое место или обнаруживает другую проблему производительности, которая была замаскирована большей проблемой. Повышение производительности сложных систем – обычно итеративный процесс.
Заключение
Поскольку события ожидания затрагивают все сферы функционирования сервера Oracle, интерфейс событий ожидания может помочь вам проникнуть в суть почти всех проблем производительности, которые вас беспокоят. Другие статистически показатели, такие, как коэффициенты попаданий в кеши, также могут дать вам ценную информацию, но интерфейс событий ожидания позволяет связать все вместе. В примерах, обсуждаемых здесь, данные о событиях ожидания помогали нам быстро диагностировать каждую проблему производительности.
Интерфейс событий ожидания с его четырьмя динамическими представлениями производительности и средствами трассировки позволяет вам видеть, на что затрачивается время процессов сервера Oracle, когда они не используют центральный процессор. Информация о событиях ожидания, возможно, не обеспечивает вас всем необходимым для решения каждой проблемы производительности, но она открывает вам доступ ко всему богатству информации, которая может помочь вам выбрать путь к достижению более оптимальной производительности системы.
Основные концепции интерфейса событий ожидания не менялись, начиная с сервера Oracle 7. Но в каждой новой версии сервера появляются усовершенствования, которые облегчают использование интерфейса событий ожидания или делают его более информативным. В сервере Oracle 9i была усовершенствована утилита TKPROF; теперь она может анализировать информацию о событиях ожидания, записанную в трассировочных файлах и форматировать ее в виде удобного отчета. Кроме того, некоторая информация о затраченном времени трассируется в микросекундах (для повышения разрешающей способности); появился пакет DBMS_SUPPORT, облегчающий активацию трассировки. Однако все это – "бантики". Интерфейс событий ожидания стал добротным инструментом для управления производительностью сервера Oracle, начиная с сервера Oracle 7.
Окончание следует
|
