тсчет времени
Для того чтобы извлечь из исходных трассировочных данных сведения о времени отклика, потребуется корректно интерпретировать хронологическую последовательность событий, обратившись к процессу, который мы называем «отсчет времени». Для отсчета времени требуются определенные знания о том, каким образом ядро Oracle обрабатывает информацию о времени:
Значение поля tim в строке - это приблизительное время, в которое завершилось действие, представленное данной строкой.
Значение поля e для вызова базы данных содержит общую фактическую продолжительность данного действия. Это значение включает в себя время, потраченное на использование процессора (значение поля c), и время, потраченное на события, произошедшие в ходе выполнения действия (сумма соответствующих значений полей ela).
Рекурсивный SQL приводит к двойному учету. То есть значение поля e для вызова базы данных глубины dep=n+1 уже включено в последующее значение e для вызова глубины dep=n.
• Не ждите совершенства от измерений времени. В файлах трассировки Oracle8i часто встречаются ошибки занижения или завышения числа на единицу. На первый взгляд кажется, что в файлах трассировки Oracle9i нередко содержатся существенно более значимые ошибки; однако, учитывая то, что измерение времени в Oracle9i ведется в микросекундах, эти ошибки не так страшны, как кажутся.
Версии Oracle 8 и ниже
Р
ассмотрим некоторые данные трассировки, на которых покажем, как выполняется отсчет времени в файлах трассировки, сформированных ядром Oracle8i и более ранних версий:
В табл. 5.7 показан соответствующий отсчет времени.
Таблица 5.7. Отсчет времени tim для вызовов базы данных Oracle8i
Строка (к)
|
e
|
Предполагаемое время timk = timk-1+ ek
|
Реальное время timk
|
Погрешность
|
1
|
0
|
198360834
|
||
2
|
0
|
198360834 + 0 = 198360834
|
198360834
|
0
|
3
|
4
|
198360834 + 4 = 198360838
|
198360837
|
1
|
4
|
10
|
198360837 + 10 = 198360847
|
198360847
|
0
|
Здесь как раз встречается ошибка занижения/завышения на единицу -в строке 3, где наблюдается отличие прогнозируемого значения tim от фактического. Пусть подобные ошибки (±1 сотая секунды) вас не беспокоят. Ядра Oracle8i округляют значения времени до ближайшей сотой секунды, поэтому то, что кажется результатом сложения ...834 + 4, могло бы быть результатом сложения ...833,7048 + 3,5827, что после округления привело бы к имеющемуся значению ...837.
Следующий фрагмент файла трассировки Oracle8i содержит вызовы базы данных и события ожидания:
PARSE #494:c=4,e=5,p=11,cr=88,cu=0,mis=1,r=0,dep=2,og=0,tim=3864619462 WAIT #494: nam='latch free' ela= 2 p1=-2147434220 p2=95 p3=0 WAIT #494: nam='latch free' ela= 2 p1=-2147434220 p2=95 p3=1
EXEC #494:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=3864619466 FETCH #494:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=4,tim=3864619466
В табл. 5.8 приведен отсчет времени для этих строк. Исследуя этот фрагмент, обратите внимание, что метки k присвоены только строкам вызовов базы данных (но не строкам WAIT). Можно отслеживать ожидаемый ход времени tim для событий ожидания, но не забывайте о том, что значение e вызова базы данных уже включает в себя время, содержащееся в значениях ela событий ожидания, порожденных данным вызовом базы данных. Поэтому прогнозирование значения timk для вызова базы данных всегда основывается на значении timk-1 из предыдущей строки вызова базы данных.
Таблица 5.8. Отсчет времени tim для вызовов базы данных и событий ожидания Oracle8i
Строка (k)
|
e
|
Предполагаемое время tim^ = timk-1+ ek
|
Реальное время timk
|
Погрешность
|
1
|
5
|
38646194 62
|
||
2
|
3864619462 + 2 = 3864619464
|
|||
2
|
3864619464 + 2 = 3864619466
|
|||
2
|
4
|
3864619462 + 4 = 3864619466
|
38646194 66
|
0
|
3
|
0
|
3864619466 + 0 = 3864619466
|
38646194 66
|
0
|
Теперь рассмотрим более сложный фрагмент - проверим, насколько вы внимательны. Попробуйте объяснить, почему фактическое значение tim 198360796 в строке EXEC #8 настолько отличается от ожидаемого значения, 198360795 + 19 = 198360814?
Ответ заключается в том, что вызов базы данных EXEC #8 - это рекурсивный родитель глубины dep=1 всех операций глубины dep=2, приведенных для курсора #9. Поэтому поле e=19 содержит все указанные значения e курсора #9, а также некоторые другие не упомянутые операции, потребляющие время, и не указанные. Вероятно, операция EXEC #8 началась вблизи значения tim 198360796 - 19 = 198369777. Между значениями tim .„777 и ...796 произошел ряд операций с глубиной dep=2, каждая из которых потребляла время, отсчитываемое таймером tim. Но помните, что все эти действия с глубиной dep=2 состоялись во время выполнения одной операции EXEC #8.
Увеличение разрешения статистик времени до микросекунд, появившееся в Oracle9i, - очень полезное усовершенствование. При переходе на версию Oracle9i в данных трассировки в первую очередь обращает
на себя внимание появление - благодаря использованию микросекунд -реальных данных, в тех случаях, когда Oracle8i передавал бы только множество нулей.
Однако нет сомнений в целесообразности использования данных расширенной трассировки SQL в системах версий 8 или даже 7. Описанный в этой книге метод оптимизации надежно работает и для диагностических данных, измеряемых в сотых долях секунды. В большей части реальных проектов улучшения производительности вывод в микросекундах - это просто роскошь.
Новое разрешение позволяет чуть точнее представить себе поведение ядра Oracle. В этом разделе будет рассмотрено несколько случаев, в которых улучшенная точность вывода ядра Oracle позволяет извлечь больше информации.
Отсчет времени для файла трассировки версии Oracle9i требует чуть больше терпения. Первое отличие, которое сразу бросается в глаза, -числа стали гораздо больше, и осуществлять этот подсчет в уме становится несколько сложнее. Например:
Следующее, на что вы могли обратить внимание, - числа не сходятся. Посмотрите на большие числа в столбце «Погрешность» табл. 5.9.
Таблица 5.9. Отсчет времени tim для вызовов базы данных Oracle9i. Значения кажутся большими, но не забывайте о том, что на самом деле они очень даже маленькие, т. к. выражены в микросекундах
Строка
(k)
|
e
|
Предполагаемое время timk = timk_1+ ek
|
Реальное время timk
|
Погрешность
|
1
|
1863
|
.956134
|
||
2
|
2566
|
...956134 + 2566 = ...958700
|
.958821
|
-121
|
3
|
50
|
...958821 + 50 = ...958871
|
...959013
|
-142
|
4
|
34
|
...959013 + 34 = ...959047
|
.959155
|
-108
|
5
|
34
|
...959155 + 34 = ...959189
|
.959293
|
-104
|
6
|
35
|
.959293 + 35 = .959328
|
.959433
|
-105
|
Большие значения в столбце ошибок кажутся ужасающими, если не вспоминать, что они измерены в микросекундах. Небольшие временные погрешности, подобные этой, всегда присутствовали в диагностических данных Oracle. Они были незаметны, когда измерение велось в сотых долях секунды. Теперь же, когда мы видим данные в микросекундах, становится очевидным влияние другого типа ошибок измерения времени отклика: вызовы к gettimeofday и getrusage расходуют фактическое время, которое сами при этом не измеряют (см. обсуждение эффекта влияния измерителя в главе 7).
Можно заметить, файлы трассировки Oracle9i имеют одну раздражающую особенность - не все строки трассировки расположены в порядке возрастания времени. В частности, значение tim секции PARSING IN CURSOR всегда находится «в будущем», относительно значения tim вызова базы данных, следующего сразу же за секцией PARSING IN CURSOR. Например:
Для того чтобы объяснить, почему так происходит, выполним трассировку событий ожидания ядра Oracle при помощи strace или аналогичного средства. Ядро Oracle завершает обработку вызова EXEC прежде, чем начинает вычислять данные для секции PARSING IN CURSOR. Но ядро выводит секцию PARSING IN CURSOR прежде, чем печатает строку EXEC. В этом и заключается причина неупорядоченности по времени.
Надо сказать, что ядро Oracle8i ведет себя точно так же. Вы просто не обращали на это внимания, т. к. передаваемая Oracle8i статистика в сотых долях секунды в большинстве случаев скрывала реальную информацию о хронологической последовательности. Статистика Oracle9i, выдаваемая в микросекундах, делает порядок событий очевидным.
То есть значение поля tim следующей строки приблизительно равно значению поля tim текущей строки плюс значение поля e следующей строки. Формулу можно переписать так:
Познакомившись с несколькими примерами отсчета времени, можно уловить общую закономерность. Если вы еще помните, что не следует дважды учитывать наличие различных уровней рекурсивных вызовов базы данных, то согласитесь с тем, что значения полей tim и e связаны следующим отношением:
То есть значение поля tim текущей строки приблизительно равно значению поля tim следующей строки минус значение поля e следующей строки.
Конечно, в строке WAIT нет поля tim, поэтому, если надо оценить, каким будет для нее значение tim, необходимо сделать шаг вперед.
< Предыдущая | Следующая > |
---|