DeepEdit!

Этот случай имел место на заключительном этапе занятий Hotsos Clinic. После двух с половиной дней лекций, которые я читал вместе с одним коллегой, мы предложили слушателям принести в класс файлы трас­сировки и попробовать открыто продиагностировать их совместными усилиями. Идея была в том, что мы мужественно брались за диагно­стику файла любого, кто не побоялся бы рассказать на публике о мед­ленной работе своих приложений. Было очень весело. Студенты имели возможность увидеть, действительно ли работает на практике то, чему мы их учили, и могли поделиться с аудиторией своими новыми идеями. Студент, представивший свою программу на рассмотрение, обычно по­лучал готовое решение серьезной проблемы. А мы могли познакомить­ся с множеством чрезвычайно интересных проблем производительно­сти приложений.

И вот в последний день занятий очаровательная молодая девушка, си­девшая в последнем ряду, принесла нам компакт-диск. Она объяснила, что файл трассировки, записанный на этом диске, относится к куплен­ному приложению, созданному на PowerBuilder, которое всегда работа­ло очень медленно. Более того, компания, офис которой находился на противоположной стороне улицы, применяла то же самое приложение и также имела серьезные претензии к его производительности. История продолжалась бесконечно - на каждой встрече пользователи интересо­вались друг у друга, не удалось ли кому-то заставить его работать быст­рее. Никто не понимал, почему приложение работает так медленно.

Все происходит естественным путем.

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

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

Когда я увидел профиль ресурсов, построенный по файлу трассировки, мое сердце опустилось. Там присутствовало множество событий SQL*Net message from client, и практически ничего больше (пример 12.6). Заго­ворив, я в первую очередь высказал сожаление - эффективность на­шей помощи, наверное, не могла быть такой, как нам бы этого хоте­лось. Очевидно было, что профиль состоял в основном из времени без­действия пользователя или из времени выполнения неизмеряемого кода на сервере приложений или еще из чего-то подобного.

Response Time Component	Duration		# Calls	Dur/Call
SQL*Net message from client	166.6s	91.8°%	6,094	0.027338s
CPU service	9.7s	5.3%	18,750	0.000515s
unaccounted-for	1.9s	1.1%
db file sequential read	1.6s	0.9%	1,740	0.000914s
log file sync	1.1s	0.6%	681	0.001645s
SQL*Net more data from client	0.3s	0.1%	71	0.003521s
SQL*Net more data to client	0.1s	0.1%	108	0.001019s
free buffer waits	0.1s	0.0%	4	0.022500s
db file scattered read	0.0s	0.0%	34	0.001176s
SQL*Net message to client	0.0s	0.0%	6,094	0.000007s
log file switch completion	0.0s	0.0%	1	0.030000s
latch free	0.0s	0.0%	1	0.010000s
log buffer space	0.0s	0.0%	2	0.005000s
direct path read	0.0s	0.0%	5	0.000000s
direct path write	0.0s	0.0%	2	0.000000s
Total	181.5s	100.0%

Но слушательница уверяла нас, что не спала на лекциях и что хорошо знакома с ошибками сбора данных и временем бездействия пользова­теля, и что ничего подобного в ее файле трассировки нет. Она начала сбор данных расширенной трассировки SQL непосредственно перед тем, как пользователь нажал кнопку «OK» для запуска операции, и завершила сбор данных сразу же, как только заметила, что система вернула результат (пользователь отключился от приложения). Пользователь действительно ждал отключения около трех минут после на­жатия кнопки. Приложение было двухзвенным, промежуточного при­кладного звена не существовало, следовательно, не было и неизмеряе-мого прикладного кода. Более того, для сбора данных она применяла наше средство - Sparky.

Н-да...

Если честно, то одну улику я пропустил. Выходные данные текущей версии Hotsos Profiler содержат не только информацию о средней дли­тельности вызова, но и минимальное и максимальное значения време­ни ожидания для каждого события (я не привожу все эти сведения в тексте примера 12.6, т. к. ширина страницы слишком мала). Макси­мальная продолжительность события SQL*Net message from client соста­вила около нескольких секунд. И если бы я обратил более пристальное внимание на количество вызовов (# Calls в примере 12.6), то понял бы, что речь не идет об ошибке сбора данных или задумчивом пользователе.

В то время у меня еще не было ясного представления о том, как именно бороться с такой проблемой, и мы, под руководством Джеффа, приня­лись изучать вывод Hotsos Profiler. Руководствуясь принципом опере­жающего атрибутирования (см. главу 11), мы искали вызовы базы данных, которые следовали за событиями SQL*Net message from client. С тех пор компания Hotsos доработала программу Hotsos Profiler, и теперь подобные проблемы легко решаются всего за пару минут. Здесь описан процесс диагностики, реализованный в современной усовершенствованной версии.

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

Для того чтобы ничего не упустить, мы чуть внимательнее посмотрели на продолжительности событий SQL*Net message from client. В примере 12.6 этого не видно, т. к. страницы книги недостаточно широки, но на самом деле вывод Hotsos Profiler показывает, что максимальная продолжительность выполнения SQL*Net message from client составила 17,43 секунды. Быстрый поиск строки ela= 1743 (обратите внимание на про­бел, который ядро Oracle вставляет между символами = и 1) в файле трассировки показал, что в хвосте файла действительно присутству­ет небольшая ошибка сбора данных. Между двумя строками XCTEND притаилось событие SQL* Net message from client со значением ela, равным 17,43 секунды. Первая фиксация соответствовала концу пользователь­ской операции. Вторая фиксация имела место, когда пользователь от­ключился от приложения. Девушке потребовалось несколько секунд на то, чтобы заметить, что операция завершилась. После исправления этой небольшой ошибки сбора данных профиль ресурсов пользователь­ской операции стал выглядеть так, как показано в примере 12.7.

Response Time Component	Duration		# Calls	Dur/Call
SQL*Net message from client	149.2s	91.0%%	6,093	0.024482s
CPU service	9.7s	5.9%	18,750	0.000515s
unaccounted-for	1.9s	1.2%
db file sequential read	1.6s	1.0%	1,740	0.000914s
log file sync	1.1s	0.7%	681	0.001645s
SQL*Net more data from client	0.3s	0.2%	71	0.003521s
SQL*Net more data to client	0.1s	0.1%	108	0.001019s
free buffer waits	0.1s	0.1%	4	0.022500s
db file scattered read	0.0s	0.0%	34	0.001176s
SQL*Net message to client	0.0s	0.0%	6,094	0.000007s
log file switch completion	0.0s	0.0%	1	0.030000s
latch free	0.0s	0.0%	1	0.010000s
log buffer space	0.0s	0.0%	2	0.005000s
direct path read	0.0s	0.0%	5	0.000000s
direct path write	0.0s	0.0%	2	0.000000s
Total	164.0s	100.0%

Следующий вопрос, требующий ответа, звучит так: «Какая команда SQL несет ответственность за оставшуюся длительность SQL*Net message from client?*. Выходные данные Hotsos Profiler автоматически предос­тавляют ответ на этот вопрос (см. пример 12.8).1

SQL Statement Id 1525010069	D 23.1s	uration 15.5%
2038166283	18.7s	12.5%
1966856986	17.6s	11.8°%
1547563725	13.9s	9.3%
3230460720	10.8s	7.2%
77 others	65.1s	43.6%
Total	149.2s	100.0%

Процентное соотношение, приведенное в примере 12.8, показывает, что не существует какой-то одной команды SQL, отвечающей за непро­порционально большой вклад в длительность события SQL*Net message from client. Вот почему нельзя заметно сократить длительность этого события, ограничившись рассмотрением только одной команды SQL. Но начнем все же с первой, текст и статистики производительности которой приведены в примере 12.9.

Cursor	Action		Response Time		LIO	PIO
Action	Count	Rows	Elapsed        CPU	Other	Blocks	Blocks
Parse	696	0	0.9       0.8	0.1	0	0
Execute	348	348	1.7           1.6	0.0	5,251	351
Fetch	0	0	0.0       0.0	0.0	0	0
Total	1,044	348	2.6          2.4	0.1	5,251	351
Per Exe	1	1	0.0       0.0	0.0	15	1
Per Row	1	1	0.0       0.0	0.0	15	1

Я не включил это в показанный здесь вывод, но по данным Hotsos Pro­filer в файле трассировки имелось 347 «похожих» команд. Profiler считает две команды SQL похожими в том и только в том случае, если они идентичны во всем (с точки зрения ядра Oracle), кроме значений литералов. Утилита Oracle tkprof не производит подобного суммирова­ния неразделяемых команд SQL; вместо этого она вывела бы 348 раз­личных команд SQL, указав, что каждая из них потребляет очень мало ресурсов. Конечно, это несколько усложнило бы анализ, но вся инфор­мация, необходимая для того, чтобы определить, что команды долж­ны быть разделяемыми, присутствует в файле трассировки SQL.

Данные примера 12.9 поясняют, почему различных команд SQL так много. Команды место заполнителей (переменных связывания) зани­мают литералы:

Значение, которое сразу же бросается в глаза как абсолютно препятст­вующее повторному использованию - это значение даты в последней позиции. Оно соответствует столбцу TMSP_LAST_UPDT - временной метке последнего обновления. Сколько раз приложение могло бы повторно использовать идентичную команду SQL, содержащую жестко запро­граммированное значение времени с секундным разрешением?

Конечно, вы наверняка думаете, что правильный ответ - ноль, но на са­мом деле тут есть небольшая хитрость. Данное конкретное приложе­ние повторно использует команду ровно один раз (т. е. данное прило­жение в целом делает это ровно два раза). Обратите внимание на коли­чество разборов и выполнений данной команды (и ей подобных): для 348 команд в целом насчитывается 696 вызовов разбора и 348 выпол­нений. Именно так, количество разборов в два раза больше количества выполнений! В разделе «Оптимизация разбора» главы 11 я советовал выносить вызовы разбора из циклов, чтобы приложение могло повтор­но использовать курсор, подготовленный одним вызовом разбора, не­сколько раз. Вывод Hotsos Profiler показывает (хотя этого и не видно в примере 12.9), что 696 вызовам разбора соответствует 348 непопада­ний в библиотечный кэш (из статистики mis необработанных данных трассировки). Невероятно, но данное приложение действительно раз­бирает каждую из этих команд SQL дважды для каждого вызова вы­полнения, как показано в примере 12.10.

Первый вызов разбора для каждой команды приводит к непопаданию в библиотечный кэш (полный разбор), а второй - к попаданию в биб­лиотечный кэш (частичный разбор).

Теперь давайте вспомним о том, в чем собственно состоит наша цель. События SQL*Net message from client занимают основную часть пользова­тельского времени отклика. Пример 12.7 показывает, что данная поль­зовательская операция выполняет в целом 6093 таких события, общий вклад которых в значение времени отклика составляет 149,2 секунды (каждое потребляет приблизительно 0,024482 секунды за вызов). SQL*Net message from client - это событие ожидания, которое ядро Oracle выполняет между вызовами базы данных. Поэтому избавление от вы­зовов базы данных приведет к ликвидации некоторой части времени отклика, относящейся к событиям SQL*Net message from client. К счастью, мы только что обнаружили возможность избавления от 348 вызовов разбора. Надо просто найти способ прекратить двойной разбор для каждого вызова выполнения. Ожидаемая экономия при этом составит около 8,5 секунды за сеанс (около 5% общего времени отклика сеанса).

Не очень впечатляющее начало, но мы еще не закончили. В главе 11 я говорил, что при удалении вызова разбора из цикла удается устра­нить все вызовы разбора, кроме одного. Если мы используем перемен­ные связывания и сделаем код похожим на масштабируемый код приложения, приведенный в примере 11.2, то при этом мы избавимся от 695 ненужных вызовов разбора. Ожидаемая экономия пользователь­ского времени при этом составит около 17 секунд (приблизительно 10% общего времени отклика сеанса).

Нас заинтересовало, сколько еще команд SQL может страдать от тех же проблем, что и первая исследованная нами. Обратившись к подроб­ной статистике для всех команд в выводе Hotsos Profiler, мы обнару­жили, что кандидатами на устранение являются более 3000 вызовов базы данных. Ожидаемое улучшение времени отклика должно было составить около 73 секунд, т. е. порядка 45% общего времени отклика сеанса.

Но и это еще не все. Если помните, пользователь нажимает клавишу «OK» всего один раз, а затем более 180 секунд ждет результата, при этом никакие другие входные данные для приложения не предполага­ются. Но что же мы видим в примере 12.9? Команда INSERT, выполняю­щая вставку одной строки, выполняется 348 раз, обрабатывая в целом 348 строк. Зачем приложению выполнять 348 вызовов базы данных для вставки 348 строк? В Oracle имеется функция вставки массивом, которая может уменьшить количество команд INSERT с 348 до 4 (если приложение может работать с массивами из 100 строк). Если удастся реализовать подобное сокращение количества вызовов базы данных, то общее число вызовов в сеансе уменьшится более чем на 650 вызовов. Дополнительная экономия составит около 16 секунд, т. е. еще 10% об­щего времени отклика сеанса.

Если удастся осуществить все предложенные исключения вызовов ба­зы данных, то будет удалено около 3650 вызовов, в результате чего время отклика сократится приблизительно на 89 секунд или на 54%. После избавления от этих вызовов базы данных пользователь может рассчитывать на улучшение времени отклика со 164 секунд до при­мерно 75 секунд. Возможно, что с приложением одновременно работа­ет множество пользователей, тогда ненужные вызовы базы данных поглощают значительную часть пропускной способности сети. Если дело обстоит именно так, то избавление от ненужных вызовов базы данных может снизить и задержки в очереди к сети, так что 0,024-секундная задержка событий SQL*Net message from client может уменьшиться до приблизительно 0,015 секунды. В этом случае оставшиеся после опти­мизации примерно 2400 событий SQL*Net message from client будут вы­полнены всего за 37 секунд, тогда общее уменьшение пользователь­ского времени отклика составит около 110 секунд.

Результаты

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

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

Использовать переменные связывания и вынести вызовы разбора из циклов для дальнейшего снижения количества вызовов разбора до одного на курсор.

Уменьшить общее количество вызовов базы данных за счет приме­нения обработки массивами вместо построчной обработки.

Когда я пишу эту главу, мы и наша слушательница все еще ждем реак­ции поставщика. Ее компания планирует переход на новую версию программы вскоре после выхода книги. Мы будем держать вас в курсе происходящего на нашем сайте в Интернете.

Мораль

Эта история учит нас следующему:

Нельзя просто игнорировать события ожидания SQL*Net message from client. Если они вносят значительный вклад во время отклика кор­ректно выбранной пользовательской операции, то необходимо об­ратить на них внимание.

Даже если с кодом SQL все в порядке, слишком большое количество вызовов базы данных может привести к ухудшению производи­тельности. В этом случае может обнаружиться, что в командах SQL на самом деле есть изъяны. Но решение этой проблемы до устране­ния избыточных вызовов базы данных приведет к незначительным и практически незаметным результатам.