DeepEdit!

Мы регулярно получаем замечательные письма от людей, которые хо­тят рассказать нам о том, как им помогли наш метод и наши инстру­менты. Данный пример появился в результате одного такого письма от нашего исландского знакомого, которому удалось уменьшить время отклика запроса с 6,5 часа до 10,9 секунды и исправить не найденную ранее функциональную ошибку - и все это за счет добавления в код SQL четырех байтов. Здесь рассказывается, как Метод R помог ему найти вызывавшую проблемы команду SQL. В итоге время отклика важного пакетного задания уменьшилось с восьми часов до одного.

Определение цели

Выбор приложения осуществлялся стандартным образом. Система при­надлежала банку. Одно из пакетных заданий приложения выполня­лось так долго, что не укладывалось в отведенное для него время. Оно запускалось каждый вечер в 23:00, а заканчивалось зачастую не рань­ше следующего полудня. Банку приходилось ограничивать количество обновляемых счетов, чтобы пакетное задание успевало завершить рабо­ту к открытию учреждения. Именно для этого задания наш знакомый и собрал данные расширенной трассировки SQL. В примере 12.11 при­веден профиль ресурсов для восьмичасового выполнения программы.

Верхние строки ясно говорят о неэффективности SQL: множество со­бытий файлового чтения и использования процессора. Остается вы­явить команды SQL, потребляющие столько ресурсов. В данном слу­чае выполнение tkprof с параметром sort=prsdsk,exedsk,fchdsk приво­дит к тому, что во главе списка находится команда SQL, содержащая наибольшее количество блоков PIO.

Однако имейте в виду, что сортировка в tkprof по количеству блоков PIO - это не то же самое, что сортировка по общей про­должительности вызовов PIO. На самом деле нам нужна сорти­ровка команд по общей продолжительности ввода/вывода,  но tkprof предоставляет такую информацию только в версии 9i. Поэтому при работе с tkprof необходимо визуально исследовать ее выходные данные с тем, чтобы убедиться, что выявлена именно интересующая вас команда SQL.

Наш аналитик знал, какая команда SQL внесла наибольший вклад в ухудшение производительности db file scattered read, т. к. он опи­рался на данные Hotsos Profiler, приведенные в примере 12.12.

SQL Statement Id	Duration
1163242303	19,028.9s	99.9%
1626975503	6.7s	0.0%
808413641	5.2s	0.0%
3187134541	3.7s	0.0%
1594054818	2.4s	0.0%
8 others	4.3s	0.0%
Total	19,051.1s	100.0%

Диагностика и лечение

Теперь необходимо проанализировать производительность SQL-коман­ды 1163242303 (это значение hv для команды из секции PARSING IN CUR­SOR необработанных данных трассировки). Текст и статистики произ­водительности данной команды приведены в примере 12.13.

Имейте в виду, что значение hv лишь почти уникально (т. е. hv не уникально). Две разные команды SQL могут иметь одно и то же значение hv. Такое встречается нечасто, но все же встречается.

П ример 12.13. Код SQL и статистики производительности для команды 1163242303, вносящей основной вклад в длительность события db file scattered read в исследуемом сеансе

Action	Count	Rows	Elapsed	CPU	Other	Blocks	Blocks
Parse	3,739	0	1.9	0.7	1.2	147	17
Execute	3,739	0	1.7	1.6	0.2	0	0
Fetch	4, 212	473	23,466.4	4,135.6	19,330.8	36,566,201	36,550,345
Total	11,690	473	23,470.0	4,137.9	19,332.1	36,566,348	36,550,452
Per Exe	1	0	6.3	1.1	5.2	9,780	9,092
Per Row	8	1	49.6	8.8	40.9	77,307	71,868

Код SQL этой команды вполне понятен. Если отвлечься от исландских названий объектов, то команда - это просто запрос из одного объекта. Очевидно, что здесь нет даже соединения. Однако план выполнения запроса, полученный из строк STAT файла трассировки и приведенный в примере 12.14, показывает, что все обстоит немного по-другому.

Там происходит нечто более сложное, чем простой запрос к одной табли­це. В действительности V_SKULDABREF_AVOXTUN - это представление. Необ­работанный файл трассировки это подтверждает. Вызов разбора для SE­LECT, приведенный в примере 12.13, потребовал рекурсивных вызовов разбора, выполнения и выборки из VIEW$, аналогично запросу из DBAOBJECTS, описанному в главе 5, поэтому следующим объектом нашего внимания становится определение представления V_SKULDABREF_AVOXTUN. Файл расширенной трассировки SQL в Oracle не включает в себя опреде­ления всех представлений, к которым обращаются команды SQL, упо­мянутые в этом файле. Однако поскольку из файла трассировки ясно видно, что V_SKULDABREF_AVOXTUN является представлением, остается лишь обратиться за его определением к DBA_VIEWS. Определение интересующего нас представления приведено в примере 12.15.

Аналитик обсудил данное определение представления с разработчи­ком, который представлял себе его значение для бизнес-процессов. По результатам обсуждения они пришли к выводу, что определение пред­ставления было некорректным. Использование в определении пред­ставления объединения UNION двух команд SELECT вместо UNION ALL при­водило к возникновению двух проблем:

Выполнялась чрезвычайно дорогостоящая, но ненужная операция над источником строк SORT UNIQUE (новые данные, передаваемые яд­ром Oracle release 9.2 в строках STAT, ярче отражают чудовищность этих затрат).

Возникала и просто ошибка, т. к. операция UNION ошибочно исключа­ла строки, которые были необходимы пользователям приложения.

В примере 12.16 представлен план выполнения команды из приме­ра 12.13 после того, как было исправлено определение представления (в определение были добавлены байты ALL).

Пример 12.17 содержит более волнующие новости. Запрос, который раньше потреблял 23470,0 секунд времени отклика, теперь занимает всего 10,9 секунды. Он выводит тот же (а на самом деле - лучший) ре­зультат, причем тратит на это приблизительно на 6,5 часа меньше.

Пример 12.17. Код SQL и статистики производительности для команды 1163242303 после изменения представления. Обратите внимание, что текст SQL полностью повторяет приведенный в примере 12.13, изменилось только определение представления. В целом время отклика для команды уменьшилось с более чем 23 000 секунд до примерно 10

Cursor	Action		Response Time		LIO	PIO
Action	Count	Rows	Elapsed        CPU	Other	Blocks	Blocks
Parse	3,722	0	2.0       0.6	1.4	44	1
Execute	3,722	0	1.3           1.4	-0.1	14	0
Fetch	4,195	473	7.6       2.8	4.8	44,764	792
Total	11,639	473	10.9       4.8	6.2	44,822	793
Per Exe	1	0	0.0       0.0	0.0	12	0
Per Row	8	1	0.0       0.0	0.0	95	2

Результаты

Результаты были ошеломляющими. В примере 12.18 приведен профиль ресурсов задания после оптимизации. Общее время отклика для вось­мичасового пакетного задания сократилось до чуть более одного часа.

Response Time Component	Duration		# Calls	Dur/Call
CPU service	2,684.7s	73.9%	953,452	0.002816s
db file sequential read	847.6s	23.3%	77,944	0.010874s
unaccounted-for	93.2s	2. 6°%
db file scattered read	5.8s	0.2%	295	0.019627s
log file switch completion	1.6s	0.0%	7	0.234286s
latch free	1.0s	0.0%	362	0.002873s
file open	0.1s	0.0%	49	0.002041s
log file sync	0.1s	0.0%	7	0.011429s
buffer busy waits	0.0s	0.0%	1	0.010000s

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

Мораль

Этот случай обращает наше внимание на следующие важные факты:

Профиль ресурсов, отражающий большие длительности событий db file... и CPU service, обычно указывает, что где-то в пользовательской операции исполняется неэффективный код SQL. Для исправления ситуации необходимо найти этот код.

Файл расширенной трассировки SQL содержит всю информацию, необходимую аналитику для оптимизации процесса выбора цели (поиска основной причины проблемы производительности пакетно­го задания). Даже несмотря на то, что данные трассировки не вклю­чают в себя определение представления, они содержат сведения, которые обратили наше внимание на такой источник ухудшения производительности, как определение представления.

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