Одна из причин невероятного успеха корпорации Oracle на рынке вы­сокопроизводительных баз данных заключается в простоте доступа к подробным данным о времени отклика. Ядро Oracle обеспечивает аналитика всеми сведениями (в файлах расширенной трассировки SQL и различных фиксированных представлениях), необходимыми для того, чтобы понять, почему время отклика приложения было именно таким. Остается «только» понять, что делать со всей этой ин­формацией. Этот пробел мы надеемся заполнить нашей книгой.

Определения элементов файла трассировки

Форматы строк файла трассировки описаны во многих достойных ис­точниках [Oracle MetaLink note 39817.1; Kyte (2001) 464-475; Morle (2000) 133-142]. Однако ни один из них не предоставляет достаточной информации, чтобы сделать возможным полный учет времени откли­ка. А именно полный учет времени отклика - та цель, которой вы должны достичь при помощи этой книги. В последующих разделах описано значение каждой из связанных с производительностью стати­стик, встречающихся в данных расширенной трассировки SQL.

Номера курсоров

К аждая строка файла трассировки соответствует одному «действию», выполненному процессом ядра Oracle. Имеющиеся в каждой строке символы #ID идентифицируют курсор, согласно которому ядро выпол­няло действие. Например, приведенная ниже строка соответствует вы­борке по курсору #1:

Н о мера курсоров имеют значение только в рамках файла трассировки. Более того, ядро Oracle делает номер курсора доступным для повторно­го использования в файле трассировки после закрытия курсора.1 По­этому строки файла трассировки, содержащие ссылки на один и тот же номер курсора, совсем необязательно ссылаются на один и тот же курсор. К счастью, каждый конкретный файл трассировки содержит упорядоченную по времени историю создания всех курсоров; каждая лексема PARSING IN CURSOR указывает на рождение (или возрождение) курсора. Например, рассмотрим две строки PARSING IN CURSOR из файла трассировки в примере 5.2:

Первая секция PARSING IN CURSOR сообщает, что курсор #1 был сопостав­лен команде ALTER SESSION. Далее в том же самом файле трассировки яд­ро Oracle повторно использует идентификатор #1 для курсора, сопо­ставленного команде SELECT.

Идентификация сеанса и временные метки

Строка, начинающаяся с лексемы ***, указывает системное время, по­лученное непосредственно перед передачей строки *** в файл трасси­ровки. Например: и показаниями системных часов. Ядро Oracle любезно вставляет в файл трассировки строку *** каждый раз, когда после вывода предыдущей строки трассировки проходит значительное количество времени (десят­ки секунд). Это удобно, потому что позволяет восстановить синхрони­зацию событий с фактическим временем после больших интервалов строк WAIT, содержащих приблизительное истекшее время (ela), а не значения внутренних часов (tim). Такую строку можно вставить в свой файл данных самостоятельно, вызвав DBMS_SYSTEM.KSDDDT.

Строка, содержащая лексему SESSION ID:(m. n), идентифицирует строки файла трассировки, следующие за ней, как относящиеся к сеансу Ora­cle с идентификатором V$SESSION.SID=m и порядковым номером V$SES-SION.SERIAL#=n. Строки идентификации сеанса обеспечивают уверенность в том, что анализируется именно тот файл, который нужен. Эти строки особенно важны в многопоточной конфигурации Oracle, т. к. каждый процесс ядра может обслуживать запросы от многих сеансов. Строки с идентификатором сеанса показывают, работа какого из них представлена в последующих строках трассировки.

Обратили ли вы внимание на то, что приведенные строки идентифика­ции сеанса и временной метки выводятся не в хронологической после­довательности? В первой строке отмечено время 22:25:53.716, а во второй строке - время на 0,002 секунды раньше. Это явление анало­гично описанному ниже в разделе «Идентификация курсоров».

Идентификация приложения

Если название модуля или операции приложения заданы при помощи процедур пакета DBMS_APPLICATION_INFO, то при активации трассировки SQL уровня 1 ядро Oracle передает строку APPNAME. Например:

APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240

Рассмотрим входящие в эту строку значения:

mod

Имя модуля, заданное процедурой SET_MODULE.

mh

Хеш-значение, идентифицирующее модуль.

act

Имя операции, заданное процедурой SET_MODULE или SET_ACTION.

ah

Хеш-значение, идентифицирующее операцию.

Идентификация курсора

Секция PARSING IN CURSOR содержит информацию о курсоре, например:

Сама строка PARSING IN CURSOR содержит информацию об идентификато­ре курсора #ID. Текст между строкой PARSING IN CURSOR и соответствую­щей строкой END OF STMT - это собственно SQL-текст курсора. Ядро Ora­cle обычно отображает эту секцию по завершении вызова разбора, не­посредственно перед строкой курсора PARSE. Однако если трассировка была отключена в момент завершения вызова разбора, ядро обычно передает секцию где-то в начале данных трассировки (непосредствен­но перед завершением первого трассируемого вызова базы данных, возможно, после одной или нескольких строк WAIT), как если бы ядро выполняло следующий псевдокод:

Таким образом, Oracle показывает в файле трассировки данные о кур­соре, даже если трассировка была отключена в момент завершения вы­зова разбора курсора.

Каждая строка PARSING IN CURSOR содержит следующие сведения о кур­соре:

len

Длина текста SQL.

dep

Рекурсивная глубина курсора. Курсор глубиной dep=n +1 является потомком некоторого курсора глубиной dep=n (n = 0, 1, 2, ...). Некото­рые действия приводят к использованию рекурсивного SQL, напри­мер вызовы базы данных, которым необходима информация из сло­варя БД; команды, запускающие триггеры; PL/SQL-блоки, содер­жащие команды SQL. В разделе «Двойной учет рекурсивного SQL» далее в этой главе мы продолжим разговор о рекурсивных отноше­ниях в SQL.

uid

Идентификатор пользователя, выполняющего разбор команды.

oct

Идентификатор типа команды Oracle [Oracle OCI (1999)].

lid

Идентификатор пользователя, обладающего привилегиями. Так, если пользователь FRED вызывает пакет, принадлежащий пользова­телю JOE, то для команды SQL, выполненной внутри пакета, uid будет ссылаться на FRED, а lid - на JOE.

Проверка в Oracle версии 9 показала, что независимо от того, вы­полнялась ли программа под привилегиями владельца или под при­вилегиями вызвавшего ее пользователя, uid и lid в файле трасси­ровки имеют одно и то же значение: идентификатор пользователя, зарегистрировавшегося в системе и вызвавшего эту программу.

tim

Если значение tim равно 0, значит, параметр инициализации TIMED_ STATISTICS имел значение FALSE в момент, когда должно было подсчи-тываться время вызова. Таким образом, на основе значений tim мож­но сделать вывод о том, какое значение имел параметр инициализа­ции TIMEDSTATISTICS. В процессе работы мы с коллегами пришли к выводу о том, что конкретные ненулевые значения tim, относящиеся к секциям PARSING IN CURSOR, не представляют особого интереса.

В Oracle9i значение tim измеряется в микросекундах (1 цс = 0,000001 секунды). В некоторых системах (например, на наших Linux-серве-рах) значения поля tim - это чистые значения gettimeofday. В дру­гих системах (например, на наших Windows-компьютерах) проис­хождение значений поля tim может быть весьма загадочным. В вер­сиях, предшествующих Oracle9i, tim было значением V$TIMER.HSECS, выраженным в сотых долях секунды.

hv

Идентификатор команды SQL. Может показаться, что значение hv уникально, но это не так Может случиться (хотя это бывает редко), что разные тексты SQL имеют одинаковые значения hv.

ad

Адрес курсора в библиотечном кэше, как это показано в V$SQL. Вызовы базы данных

Вызов базы данных (database call) - это обращение к подпрограмме ядра Oracle. Если в момент завершения вызова базы данных активна трассировка SQL уровня 1, то ядро Oracle выводит в файл трассировки строку, информирующую о состоявшемся вызове. Чаще всего встреча­ются вызовы базы данных типа PARSE, EXEC и FETCH. Например:

О других типах вызовов (например, ERROR, UNMAP и SORT UNMAP) можно прочитать в документе Oracle MetaLink 39817.1. Каждая строка вызо­ва базы данных содержит следующие статистики:

c

Общее процессорное время, потраченное процессом Oracle в ходе вызова. Oracle9i измеряет c в микросекундах (1 цс = 0,000001 се­кунды). В более ранних версиях ядра значение c выражалось в со­тых долях секунды.

e

Фактическая продолжительность вызова. Oracle9i измеряет e в мик­росекундах (1 цс = 0,000001 секунды). В более ранних версиях ядра значение e выражалось в сотых долях секунды.

p

Количество блоков базы данных Oracle, полученных вызовом за счет обращения к дисковой подсистеме ОС. Предполагается, что p озна­чает первую букву слова «physical» - физический, но имейте в ви­ду, что не каждое так называемое «физическое» чтение Oracle обра­щается к физическому дисковому устройству. Многие такие чтения обслуживаются различными кэшами, расположенными между ядром Oracle и физическим диском.

cr

Количество блоков базы данных Oracle, полученных вызовом в ре­жиме согласованного чтения из кэша буферов базы данных Oracle. Чтение в согласованном режиме может потребовать дополнитель­ных согласованных чтений из блоков отката, хранящихся в сегмен­тах отката.

cu

Количество блоков базы данных Oracle, полученных вызовом в режи­ме текущего чтения из кэша буферов базы данных Oracle. Чтение в текущем режиме - это просто чтение текущего содержимого блока.

mis

Количество непопаданий в библиотечный кэш в ходе вызова. Ре­зультатом каждого непопадания в библиотечный кэш является опе­рация полного разбора (hard parse).

r

Количество строк, возвращаемых вызовом.

dep

Рекурсивная глубина курсора. Курсор глубиной dep=n + 1 является потомком некоторого курсора глубины dep=n (n = 0, 1, 2, ...). Под­робнее об этом рассказано ниже в разделе «Двойной учет рекурсив­ного SQL» данной главы.

og

Фактическая цель оптимизатора в ходе вызова. Oracle использует значения, приведенные в табл. 5.1.

tim

См. раздел «Идентификация курсора» ранее в этой же главе.

Таблица 5.1. Цели оптимизатора запросов Oracle, соответствующие значениям og (источник: документ Oracle MetaLink 39817.1)
Значение og	Цель оптимизатора запросов Oracle
1	ALL_ROWS
2	FIRST_ROWS
3	RULE
4	CHOOSE

Имейте в виду, что ядро Oracle не передает в файл трассировки строку вызова базы данных до тех пор, пока операция не завершена. То есть чрезвычайно долгая операция над базой данных может привести к то­му, что ядро Oracle будет работать несколько часов, ничего не переда­вая в файл трассировки. Плохо оптимизированный SQL может порож­дать вызовы EXEC (для обновлений или удалений) или FETCH (для выбо­рок), способные загрузить процессор на несколько дней.

События ожидания

Событие ожидания Oracle - это последовательность инструкций ядра Oracle, для которой время учитывается специальным образом. Если в момент завершения события ожидания включена трассировка SQL уровня 8 или 12, то ядро Oracle по завершении данного события встав­ляет в файл трассировки строку WAIT. Например:

Каждая строка WAIT содержит следующую информацию о работе, вы­полненной в ходе события:

nam

Имя, присвоенное кем-то из разработчиков ядра Oracle для обозна­чения того, какая часть ядра Oracle отвечает за данную часть време­ни отклика.

ela

Фактическое время, потраченное на исполнение названного события. Oracle9i измеряет ela в микросекундах (1 цс = 0,000001 секунды).

В более ранних версиях ядра значение ela выражалось в сотых до­лях секунды.

1, p2, p3

Значения данных параметров зависят от значения nam. Полный пе­речень описаний параметров для всех типов событий можно полу­чить, выполнив такой SQL-код:

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

Строки WAIT в файле трассировки SQL представляют собой интерфейс к чрезвычайно важной новой функциональности, введенной Oracle в 1992 г., которая коренным образом упрощает диагностику и реше­ние проблем производительности.