DeepEdit!

В начале главы я обещал привести подробное исследование файла трассировки из примера 5.2. Этот момент настал.

Любой файл трассировки SQL начинается с преамбулы, которая содер­жит информацию о файле: имя файла, версию ядра Oracle и различ­ные характеристики системного окружения и анализируемого сеанса. Вот преамбула из примера 5.2:

После преамбулы ядро Oracle выводит информацию, идентифицирую­щую сеанс, для которого выполняется трассировка, и время передачи первой строки трассировки:

*** SESSION ID:(7.6692) 2002-12-03 10:07:40.051

Следующая строка отображает сведения об имени модуля и операции, заданные клиентской программой (в нашем случае - SQL*Plus) при помощи процедур пакета DBMS_APPLICATION_INFO:

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

Первое реальное действие, которое ядро отобразило в файле трассиров­ки, - это исполнение команды ALTER SESSION. Ядро не передало данных оразборе команды ALTER SESSION, т. к. трассировка была включена толь­ко после завершения разбора. Для удобства ядро Oracle вывело секцию, описывающую курсор для вызова исполнения, перед информаци­ей о самом вызове EXEC. Вызов исполнения проделал очень небольшую работу. Значение e=1 показывает, что фактическая продолжитель­ность вызова составила всего 1 микросекунду (0,000001 секунды).

После завершения выполнения команды ALTER SESSION ядро Oracle от­правило результат обратно в клиентскую программу посредством за­писи в сокет, управляемый драйвером SQL*Net. На этот вызов ушло 5микросекунд.

WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0

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

WAIT #1: nam='SQL*Net message from client' ela= 1262 p1=1650815232 p2=1 p3=0

Запрос, полученный в результате чтения сокета, - это фактически ин­струкция по разбору запроса «Hello, world». Как видите, прежде чем печатать статистики для PARSE, ядро любезно выводит секцию, начи­нающуюся с последовательности символов « = » и заканчивающуюся строкой END OF STMT, которая описывает разбираемый курсор. Собствен­но вызов разбора продолжается 214 микросекунд.

Следующий вызов базы данных - это EXEC, который указывает на ис­полнение разобранного ядром курсора. Непосредственно перед стро­кой EXEC расположена пустая секция BINDS, означающая, что програм­ма SQL*Plus запросила операцию связывания, но связывать оказалось нечего. Общее время, потраченное на исполнение, составило 124 мик­росекунды.

После завершения вызова EXEC ядро отправляет результат обратно в кли­ентскую программу (т. е. в SQL*Plus). Запись в сокет занимает 5 микро­секунд.

WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0

Сразу же после записи в сокет ядро переходит к операции выборки. Статистика для FETCH показывает, что общая продолжительность со­ставила 177 микросекунд, возвращена была одна строка (r=1), что по­требовало трех чтений кэша буферов базы данных, одно из которых -в согласованном режиме (cr=1), а два - в текущем (cu=2).

FETCH #1:c=0,e=177,p=0,cr=1,cu=2,mis=0,r=1,dep=0,og=4,tim=1038931660054596

Следующий вызов базы данных, отображенный в файле трассировки, -это еще одна выборка, имевшая место после чтения сокета SQL*Net, потребовавшего 499 микросекунд. Эта выборка не возвращает строк, ее продолжительность составляет всего 2 микросекунды.

WAIT #1: nam='SQL*Net message from client' ela= 499 p1=1650815232 p2=1 p3=0 FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1038931660055374

Затем ядро передает результат обратно в клиентское приложение по­средством операции записи в сокет, выполненной за 4 микросекунды.

WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0

Отправив клиенту результат выборки, ядро ожидает следующего обра­щения к нему. И ожидание не будет долгим. Уже через 1261 микросе­кунду после инициации чтения сокета SQL*Net вызов чтения завер­шается.

WAIT #1: nam='SQL*Net message from client' ela= 1261 p1=1650815232 p2=1 p3=0

Инструкция, полученная ядром в результате вызова чтения сокета, приводит к закрытию курсора «Hello, world» и, в конечном счете, к за­вершению транзакции чтения. При закрытии курсора ядро выводит строку STAT, содержащую выбранный оптимизатором для данного за­проса план выполнения. В данном случае запрос потребовал полного просмотра таблицы DUAL.

STAT #1 id=1 cnt=1 pid=0 pos=0 obj=221 op='TABLE ACCESS FULL DUAL ' XCTEND rlbk=0, rd_only=1

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