DeepEdit!

Время от времени все мы попадаем в такую ситуацию: звонит, скажем, Нэнси и сообщает, что «ее сеанс повис». Она уже спросила своих кол­лег, не остановлена ли система, но у них все работает прекрасно. Воз­можно, Нэнси позвонила вам потому, что во время «обеденного сове-щания»1 на прошлой неделе вы рассказывали пользователям, почему им не следует перезагружать их персональные компьютеры, когда случается нечто подобное. Зная, как определить идентификатор сеан­са Нэнси (глава 6), нетрудно узнать, что с ним происходит. Предполо­жим, мы выяснили, что ID сеанса Нэнси равен 42. Тогда причину за­висания поможет выяснить следующий запрос:

Означает ли это, что сеанс Нэнси завис в ожидании ввода/вывода? Нет, в действительности этот запрос говорит об обратном. Последнее событие ожидания, которое выполнил процесс ядра для сеанса Нэнси, представляло собой операцию файлового чтения, которая заверши­лась примерно 174 секунды назад (плюс-минус 3 секунды). Более того, время выполнения этой операции было меньше разрешающей способ­ности таймера Oracle. (Для Oracle8i это означает, что фактическое вре­мя операции чтения составило менее 0,01 секунды.) Так чего же ждет сеанс Нэнси?

Ответ заключается в том, что ее сеанс (на самом деле это выделенный ей серверный процесс Oracle) либо занимается вычислениями, потреб­ляя процессорное время, либо стоит в очереди на выполнение, ожидая следующей возможности заняться вычислениями и потратить процес­сорное время. Посмотреть, чем занят сеанс, можно с помощью ряда по­следовательных запросов к V$SESS_IO:

Включив в запрос текущее время, можно получить представление о скорости, с которой система Oracle способна обрабатывать вызовы LIO. Показанная здесь система обработала 735505 вызовов LIO пример но за 17 секунд, что соответствует скорости 43265 операций LIO в секунду. По этим данным вы начинаете понимать, в чем тут дело. Ее про грамма потратила на выполнение более 22 000 000 операций LIO почти девять минут к тому моменту, как вы начали смотреть на нее. Теперь надо выяснить, какие команды выполняются в этой программе, чтобы впоследствии их исправить. Это можно сделать посредством запроса с соединением к представлениям V$OPEN_CURSOR и V$SQL. Я бы предпочел воспользоваться данными расширенной трассировки SQL, будь у меня такая возможность, но если вы лишены такой роскоши, грамотное при­менение фиксированных представлений поможет решить проблему.

Обнаружение причин зависания системы

Иногда, отвечая на звонок Нэнси, которая еще не успела изложить свою проблему, вы замечаете, что вам уже звонят по второй линии. За­тем в течение двух минут вы выслушиваете жалобы четырех пользова­телей и получаете еще семь голосовых сообщений. Что делать? Если ваша система допускает выполнение запросов, я бы посоветовал сле­дующий:

Приведенный результат показывает наличие 440 сеансов. Во время вы­полнения этого запроса более 200 процессов ядра Oracle заблокировано на операции чтения сокета SQL*Net, в то время как их пользователь­ские приложения заняты выполнением операций в промежутке между вызовами базы данных. Вероятно, многие из этих 211 процессов нахо­дятся в неактивном состоянии, пока пользователи работают с не-Oracle приложениями, разговаривают с коллегами или вышли освежиться. Хуже то, что 187 сеансов заблокированы в ожидании события log file switch (archiving needed). Это сообщение говорит о том, что процесс ARCH не успевает за формированием оперативного журнала.

Оставшиеся несколько пользователей продолжают работать (36 заня­ты чтением файлов базы данных), но каждый, кто попытается выпол­нить вызов COMMIT, вынужден будет ждать завершения события log file switch (archiving needed). Чем дольше эта проблема будет оставаться не­решенной, тем больше пользователей застынут в ожидании этого со­бытия. Администратор системы, на которой был получен вышеопи­санный результат, пренебрег предупреждениями о скором переполне­нии выделенной процессу ARCH файловой системы.

Построение приблизительного профиля ресурсов для сеанса

Сделанная на скорую руку программа vprof, приведенная в примере 8.3, предназначена для сбора временных характеристик Oracle для задан­ного сеанса на определенном интервале времени. Я написал ее не для промышленного применения (я считаю, что она для этого не подхо­дит), а для иллюстрации некоторых трудностей использования SQL-за­просов к фиксированным представлениям с целью получения диагно­стических данных в заданных областях. Думаю, vprof может приме­няться в образовательных целях для пояснения следующих моментов:

Посредством соединения представлений V$SESSTAT и V$SESSION_EVENT можно получить приближенную оценку полного времени отклика пользовательской операции.

Попытки получения временных характеристик пользовательской операции из фиксированных представлений Oracle наталкиваются на трудность определения временной области.

Диагностика причины ухудшения производительности выбранной пользовательской операции требует значительно больших усилий, чем просто создание профиля ресурсов этой операции.

Главное достоинство программы vprof состоит в том, что она выводит загрузку процессора, неучтенное время и реальные события ожидания Oracle в таблицу, формируя настоящий профиль ресурсов. Вывод vprof особенно интересен, когда вы экспериментируете со временем каждого из двух интерактивных вводов. Например, если выбрать время t0 на несколько секунд раньше того, как диагностируемый сеанс начнет что-либо делать, то vprof выдаст большое количество отрицательного неучтенного времени, как показано ниже:

t0 =	23:48:18.072254
t1 =	23:49:09.992339
interval duration =	51.920085s
accounted-for duration =	86.990000s
Response Time Component	Duration	(seconds)	Calls	Dur/Call
SQL*Net message from client	54.04	104.1%	2	27.020000
CPU service	31.98	61.6%	3	10.660000
db file sequential read	0.93	1. 8%	29181	0.000032
async disk IO	0.03	0.1%	6954	0.000004
direct path read	0.01	0.0%	1228	0.000008
SQL*Net message to client	0.00	0.0%	2	0.000000
db file scattered read	0.00	0.0%	4	0.000000
direct path write	0.00	0.0%	2	0.000000
unaccounted-for	-35.07	-67.5%	1	-35.069915
Total	51.92	100. 0°%

В момент t0 выполнялось длительное событие SQL*Net message from client, при этом данные о его продолжительности еще не попали в V$SESSION_ EVENT. При наступлении момента t1 длительное событие SQL*Net message from client целиком попадает в V$SESSION_EVENT, но часть этой длительности относится к периоду до начала интервала наблюдения. Програм­ма vprof вычисляет длительность интервала именно как t1- t0, но об­щее время события Oracle, учтенное в период между моментами t1 и t0, превышает значение t1-t0, поэтому vprof вводит отрицательное псевдособытие unaccounted-for для того, чтобы скорректировать профиль.

Это хороший пример ошибки сбора данных, которая может подпортить диагностические данные (ошибки сбора данных подробно рассматри­вались в главе 6). Для того чтобы сделать вывод vprof более ценным, можно проверить V$SESSION_WAIT на предмет выполнения незавершен­ного события в момент t0, а затем внести исправления в соответствии с полученным результатом. Нечто подобное мы делали в 2000 г. в од­ном большом проекте, где анализировали данные V$ - после того, как нашли решение ряда проблем и, столкнувшись с описанными выше ог­раничениями, решили сократить убытки от проекта. Например, что делать, если в верхних строках профиля ресурсов находятся события ожидания enqueue? Как определить, какой блокировки ожидала (в про­шедшем времени) исследуемая программа в процессе исполнения? Дальнейшая диагностика подобной проблемы при отсутствии коррект­но собранных (во временной области и области операций) данных - это недетерминированный процесс, который легко может привести к од­ной из катастроф, описанных в главе 1.

Исследование всех событий ожидания системы

Начиная с середины 1990-х годов из всех отчетов о производительно­сти системы чаще всего, вероятно, прибегали к отчету о событиях в масштабе всей системы. Самая простая из осмысленных версий та­кого отчета выглядит примерно так:

EVENT	SECONDS	CALLS
rdbms ipc message	13,841,814.91	3,671,093
pmon timer	3,652,242.44	1,305,093
smon timer	3,526,140.14	12,182
SQL*Net message from client	20,754.41	12,627
control file parallel write	2,153.49	1,218,538
db file sequential read	91.61	547,488
log file parallel write	55.66	23,726
db file scattered read	26.26	235,882
control file sequential read	8.12	365,643
control file heartbeat	3.99	1
latch activity	2.93	30
buffer busy waits	1.41	72
resmgr:waiting in end wait	0.93	44
latch free	0.80	39
resmgr:waiting in check	0.53	36
log file sync	0.28	19
process startup	0.22	6
rdbms ipc reply	0.14	9
db file parallel read	0.11	4
async disk IO	0.10	19,116
db file parallel write	0.09	24,420
SQL*Net more data to client	0.09	2,014
resmgr:waiting in check2	0.06	2
SQL*Net message to client	0.06	12,635
direct path read	0.05	5, 014
log file sequential read	0.03	4
refresh controlfile command	0.00	1
log file single write	0.00	4
SQL*Net break/reset to client	0.00	23
direct path write	0.00	10

30 rows selected.

Предполагается, что подобный отчет должен помочь аналитику сразу же определить природу проблемы производительности системы. Одна­ко у этого отчета есть множество недостатков, препятствующих этому.

Такие отчеты могут быть полезны в решении некоторых видов про­блем, но они не состоянии помочь решить многие проблемы, рассмот­ренные в этой книге:

Проблемы пользовательских операций, характеристики произво­дительности которых отличаются от средних значений для систе­мы. По агрегированным данным нельзя восстановить составляю­щие. Забыв об этом, можно неумышленно вызвать ухудшение про­изводительности важных пользовательских операций (см. главу 4).

Проблемы с пользовательскими операциями, которые легко выявля­ются по длительностям событий SQL*Net message from client, учитывае­мых во времени отклика пользовательских операций. Как узнать, связана ли приведенная в отчете V$SYSTEM_EVENT длительность собы­тия SQL*Net message from client с низкой производительностью сете­вого ввода/вывода, или же дело в том, что приложение совершает слишком много вызовов базы данных? Данные V$SYSTEM_EVENT не по­зволяют ответить на этот вопрос. Большие значения могут означать наличие проблем данного типа. Но такие же значения возникнут и в случае, если пользователи провели много времени, подключив­шись к системе и не совершая никаких полезных действий.

Ситуация с отчетами на основе данных V$SYSTEM_EVENT возвращает нас к уже поднимавшемуся в главе 3 вопросу о том, имеет ли смысл ре­шать разные задачи разными способами. Применение различных ме­тодов для решения различных проблем предполагает, что вы каким-то образом можете определить, что за задача стоит перед вами, до то­го, как начнете ее диагностику. В этом и заключается недостаток ме­тода, способный привести к полному провалу проекта, о чем я говорил в главе 1.

В последующих разделах будет описано несколько причин, по кото­рым отчеты на основе данных V$SYSTEM_EVENT не помогают в решении некоторых типов проблем производительности.

Проблема «событий простоя»

Глядя на приведенный выше отчет о событиях в системе, неопытный аналитик будет пребывать в уверенности, что событие rdbms ipc message составляет главную проблему системы. Однако такой диагноз, скорее всего, неверен. Как известно аналитикам, знакомым с «интерфейсом ожидания Oracle», rdbms ipc message - это одно из так называемых собы­тий простоя. С помощью этого события процессы Oracle DBWn, LGWR, CKPT и RECO указывают, что в данный период времени они ничем не заня­ты. По той же причине pmon timer, smon timer и SQL*Net message from client тоже рассматриваются как события простоя.

Стандартная рекомендация заключается в том, чтобы игнорировать со­бытия простоя. Однако такой совет таит в себе серьезную опасность: от­нося некоторые события к «простою», вы ограничиваете свои возмож­ности по диагностированию целых классов проблем, как это показано в ряде примеров главы 12. В исследованных нами начиная с 2000 г. пользовательских операциях событие SQL*Net message from client в зна­чительной части случаев оказывало наибольшее влияние на время от­клика для конечного пользователя.

Почему же тогда это событие рассматривается как «событие простоя»? Дело в том, что в профиле, соответствующем всему экземпляру в облас­ти операций и времени с момента старта во временной области, боль­шинство сеансов фактически простаивают в ожидании ввода от пользователя. Все то время, пока вы, установив соединение с Oracle, вместо выполнения запросов к базе данных пьете кофе, относится на счет со­бытия SQL*Net message from client. Поэтому в отчете о событиях ожида­ния для всей системы действительно необходимо игнорировать все эти события простоя. Более совершенные программы формирования отче­тов о событиях ожидания системы анализируют таблицу событий про­стоя, позволяющую полностью исключить такие события из отчета.

Проблема нормирования

Поизучав некоторое время простой отчет, построенный по представле­нию V$SYSTEM_EVENT, можно заинтересоваться тем, как же эти данные со­относятся со временем работы экземпляра. Едва ли не самая оригиналь­ная из виденных мной программ, предназначенных для ответа на этот вопрос, приведена в примере 8.4. Программа, написанная на SQL*Plus, осуществляет попытку формирования реального профиля ресурсов, по­казывающего общую продолжительность каждого события в процен­тах от полного времени работы экземпляра.

Как вам нравится идея подсчета процентной доли продолжительности событий ожидания в общем времени работы экземпляра? Вот пример такого отчета:

Event		Duration		%	Calls
rdbms ipc message		13,848,861.00		369.6	3,672,850
pmon timer		3,653,991.35		97.5	1,305,718
smon timer		3,527,940.29		94.2	12,188
CPU service		89,365.37		2.4	12,807
SQL*Net message from client		23,209.05		0.6	12,655
control file parallel write		2, 154.32		0.1	1,219,121
db file sequential read		91.66		0.0	547,493
log file parallel write	55.68		0.0			23,739
db file scattered read	26.66		0.0			236,079
control file sequential read	8.12		0.0			365,817
control file heartbeat	3.99		0.0			1
latch activity	2.93		0.0			30
buffer busy waits	1.41		0.0			72
resmgr:waiting in end wait	0.93		0.0			44
latch free	0.80		0.0			39
resmgr:waiting in check	0.53		0.0			36
log file sync	0.28		0.0			19
process startup	0.22		0.0			6
rdbms ipc reply	0.14		0.0			9
db file parallel read	0.11		0.0			4
async disk IO	0.10		0.0			19,116
SQL*Net more data to client	0.09		0.0			2, 018
db file parallel write	0.09		0.0			24,436
SQL*Net message to client	0.06		0.0			12,663
resmgr:waiting in check2	0.06		0.0			2
direct path read	0.05		0.0			5,014
log file sequential read	0.03		0.0			4
SQL*Net break/reset to client	0.00		0.0			25
direct path write	0.00		0.0			10
log file single write	0.00		0.0			4
refresh controlfile command	0.00		0.0			1
unaccounted for	-17,398,633.00		-464.3
TOTAL	3,747,082.32		100.0			7,472,020

Обратите внимание на долю, приходящуюся на событие rdbms ipc mes­sage event. Странно, не правда ли? Как может полная продолжитель­ность всего лишь одного события составлять 369,6% от времени рабо­ты экземпляра? На самом деле это просто. Причина в том, что в систе­ме, для которой построен этот отчет, существуют четыре процесса, сообщающие о событии rdbms ipc message, и каждый из них относит к этому событию почти 100% своего времени (моя тестовая система, в которой получен этот отчет, по большей части простаивает). Далее, что означают -17 398 633,00 секунд неучтенного времени? Это всего лишь артефакт, возникший вследствие попытки «подогнать» все уч­тенные длительности к общей продолжительности интервала наблю­дений, составляющей 3 747 082,32 секунд (наш экземпляр был запу­щен примерно 43 дня назад).

Возможно, целесообразно было бы построить отчет, показывающий затраты каждого из ресурсов в процентах от его полного имеющегося объема? Идея неплохая, но и она чревата рядом сюрпризов. Вы уже видели, что «объем» события rdbms ipc message для системы равен вре­мени работы экземпляра, умноженному на количество процессов, со­общающих о возникновении данного события. Рассмотрим еще не­сколько событий:

Объем доступного процессорного времени в системе равен количе­ству ЦПУ, умноженному на время работы экземпляра.

Максимально возможный промежуток времени «между вызовами» в системе равен сумме продолжительностей всех сеансов, имевших место с момента запуска экземпляра. Это значение может быть рас­считано по данным аудита на уровне соединений.

Объем операций чтения в системе равен произведению количества дисков на время работы экземпляра, правильно? Не торопитесь. Ядро Oracle относит к длительности событий ожидания не только время выполнения дисковых операций. Вспомните, в главе 7 мы выяснили, что кроме времени использования ресурса имеется так­же (наиболее значительное) время ожидания ресурса и время, про­веденное в состоянии готовности к выполнению. Таким образом, максимально возможная доля события db file scattered read в за­грузке системы также равна сумме продолжительностей всех сеан­сов, имевших место с момента запуска экземпляра.

Насколько я могу судить, нет нормирующего коэффициента, который позволил бы привести данные V$SYSTEM_EVENT к такому виду, чтобы сформировать из них корректный профиль ресурсов.