Введение

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

Этой статьей я открываю серию публикаций, посвященных средствам трассировки СУБД Oracle. К счастью (а, может, и к сожалению для многих кандидатов в "шаманы"), эта СУБД с каждой версией расширяла предоставляемые возможности трассировки и теперь, в версии 10g, в ее ядре трассировкой охвачено около 99% кода... Цель данной серии статей состоит в том, чтобы представить наиболее важные для разработки успешных приложений средства трассировки Oracle.

Трассировка - практические аспекты

Начиная с версии 6, СУБД Oracle официально предоставляет воможность создавать на сервере трассировочные файлы, содержащие детальную информацию о ходе выполнения SQL-операторов тем или иным серверным процессом. Самым простым способом начать трассировку является выполнение в сеансе SQL*Plus или в приложении следующего SQL-оператора:

alter session set sql_trace=true;

С этого момента информация о выполнении этого и всех последующих SQL-операторов записывается в так называемый трассировочный файл (trace file). Это текстовый файл определенного формата, создаваемый в каталоге, который задается параметром инициализации user_dump_dest. Формат имен трассировочных файлов зависит от версии сервера (например, в версии 9.2.0.1 для Windows он по умолчанию имеет вид SID_ora_PID.trc, где SID - идентификатор экземпляра, а PID - идентификатор серверного процесса Oracle, который создал этот трассировочный файл). Ниже представлено типичное начало трассировочного файла.

Листинг 1. Начало типичного трассировочного файла.

Dump file c:\oracle\admin\openxs\udump\openxs_ora_3532.trc
Sun Apr 17 17:26:14 2005
ORACLE V9.2.0.1.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.1.0 - Production
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Instance name: openxs

Redo thread mounted by this instance: 1

Oracle process number: 12

Windows thread id: 3532, image: ORACLE.EXE


*** 2005-04-17 17:26:14.000
*** SESSION ID:(9.500) 2005-04-17 17:26:14.000
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #1 len=34 dep=0 uid=59 oct=42 lid=59 tim=16127574484 hv=32029095 ad='12f4863c'
alter session set sql_trace = true
END OF STMT
EXEC #1:c=0,e=39642,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=16127528244
...

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

alter session set sql_trace=false;

Размер создаваемого трассировочного файла ограничивается параметром инициализации max_dump_file_size (по умолчанию - 5 Мбайт). При достижении этого объема запись в файл прекращается. Для трассировки реальных приложений, выполняющих десятки SQL-операторов, значение этого параметра надо существенно увеличить.

Чтобы генерируемая трассировочная информация была действительно полезной, необходимо установить значение параметра инициализации timed_statistics = true. В противном случае, время выполнения различных этапов обработки SQL-оператора регистрироваться не будет. Обычно этот параметр устанавливается даже в производственных системах, поскольку пока трассировка не ведется, его влияние минимально, а если уж она ведется, то чем больше информации будет собрано - тем лучше.

Как найти нужный трассировочный файл

Как уже упоминалось, все трассировочные файлы пользовательских сеансов находятся в файловой системе компьютера, на котором работает сервер Oracle, в каталоге, заданном параметром инициализации user_dump_dest. Если трассируется только один сеанс, обычно ему соответствует последний по времени создания трассировочный файл. При интенсивном использовании трассировки, однако, файлов в каталоге user_dump_dest может быть очень много, и найти файл, соответствующий исследуемому сеансу, может оказаться непросто.

Имя файла содержит идентификатор процесса Oracle, который его создал. Определить идентификатор этого процесса можно разными способами. В сеансе или приложении, в котором включалась трассировка, достаточно выполнить запрос:

select p.spid
from v$process p, v$session s
where p.addr = s.paddr
  and s.audsid = userenv('SESSIONID');

Для успешного выполнения этого запроса необходима привилегия SELECT на представления словаря данных v_$process и v_$session (v$process и v$session - это их общедоступные синонимы). Эту привилегию должен предоставить владелец словаря данных (пользователь sys):

SQL> connect sys/change_on_install as sysdba
Connected.
SQL> grant select on v_$process to scott;

Grant succeeded.

SQL> grant select on v_$session to scott;

Grant succeeded.

Можно включить в имя трассировочного файла любую строку для облегчения поиска (она будет добавлена перед расширением, .trc). Для этого перед включением трассировки надо выполнить:

alter session set tracefile_identifier='УникальнаяСтрока';

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

select p.spid
from v$process p, v$session s
where p.addr = s.paddr
  and s.sid = some_sid;

Эти способы позволят определить единственный нужный трассировочный файл, если приложение подключено к выделенному серверу. Проблемы трассировки при работе с разделяемым сервером (в режиме MTS) рассматриваются далее.

Различные способы включить трассировку

Параметр sql_trace можно установить в файле параметров инициализации для всех сеансов. На практике так делают редко, поскольку трассировка всех сеансов может заметно замедлить работу, да и общих объем созданных файлов может оказаться очень большим.

В современных версиях Oracle (например, 9.2) избирательно включить трассировку для сеанса можно несколькими способами.

1. Сеанс или приложение, которое необходимо трассировать, выполняет один из следующих операторов.

   alter session set sql_trace=true;
   

   Этот способ мы уже рассматривали. В трассировочный файл записывается базовая информация - какие операторы выполнялись и сколько времени потребовалось серверу на выполнение основных стадий обработки.

2. Сеанс или приложение, которое необходимо трассировать, выполняет оператор:

   alter session set events '10046 trace name context forever, level уровень';
   

   Так, с помощью установки события 10046, можно включить расширенную трассировку. В зависимости от указанного уровня, в трассировочный файл будет включаться дополнительная информация (см. табл. 1 далее). Чтобы завершить трассировку в этом случае надо выполнить:

   alter session set events '10046 trace name context off';
   

3. АБД может включить и отключить трассировку любого сеанса с помощью процедур пакета dbms_system:

   sys.dbms_system.set_sql_trace_in_session(SID, serial#, true);
   sys.dbms_system.set_ev(SID, serial#, 10046, уровень, '');
   

   Значения SID и serial# можно получить из представления v$session, например:

   select sid, serial# from v$session where username = 'SCOTT';
   

   Допустимые уровни трассировки представлены ниже в табл. 1.

4. Начиная с версии 8, можно включить и отключить трассировку любого сеанса с помощью процедур пакета dbms_support:

   dbms_support.start_trace_in_session(SID, serial#, true, true)
   dbms_support.stop_trace_in_session(SID, serial#)
   

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

   create or replace trigger logon_trigger
   after logon on database
   begin
     if ( user = '&1' ) then
       execute immediate
       'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL &2''';
     end if;
   end;
   /
   

   При выполнении этого кода в SQL*Plus надо будет указать имя пользователя и требуемый уровень трассировки. Триггер можно отключить (alter trigger ... disable) сразу после успешного создания и включать (alter trigger ... enable), только когда нужна трассировка. В результате, без изменения кода приложения, можно обеспечить автоматическое включение трассировки для всех сеансов, подключающихся после включения триггера от имени указанного пользователя.

Таблица 1. Уровни трассировки SQL.

Уровень	Информация, которая записывается в трассировочный файл
0	Отключить трассировку
1	Базовая информация, как при установке sql_trace=true
4	Добавляется также информация о значениях связываемых переменных (bind variables) в SQL-операторах
8	Добавляется также информация о событиях ожидания (wait events)
12	Комбинация уровней 4 и 8

Анализ трассировочных файлов

Полученные трассировочные файлы можно анализировать непосредственно. Форматы всех записей описаны в документации [2], а сам процесс анализа неоднократно описывал, например, Том Кайт [4]. Тем не менее, обычно достаточно проанализировать намного меньший объем более удобно структурированной информации, которую можно получить по трассировочному файлу с помощью утилиты tkprof:

C:\oracle\admin\openxs\udump>tkprof openxs_ora_3532.trc 3532.tkp

Формат результатов и опции утилиты tkprof также подробно описаны в документации (см. [2]), но обычно полученный файл во многом понятен и без чтения документации. (В Листинге 2 я перевел начальные комментарии на русский, чтобы представленные основные показатели были понятнее широкой аудитории.)

Листинг 2. Результат обработки трассировочного файла утилитой tkprof

TKPROF: Release 9.2.0.1.0 - Production on Нд. Квт 17 20:02:56 2005

Copyright (c) 1982, 2002, Oracle Corporation.  All rights reserved.

Trace file: openxs_ora_3532.trc
Sort options: default

********************************************************************************
count    = сколько раз была выполнена соотвествующая функция OCI
cpu      = процессорное время выполнения
elapsed  = реальное время выполнения
disk     = количество физических чтений блоков с диска
query    = количество блоков, полученных согласованным чтением
current  = количество блоков, полученных в текущем режиме (обычно - для измнения)
rows     = количество строк, обработанных вызовом fetch или execute
********************************************************************************

alter session set sql_trace = true


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.03          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.03          0          0          0           0

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 59  
********************************************************************************
...
********************************************************************************

select * 
from
 emp


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.03       0.13          1          1          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1          4          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.03       0.13          2          5          0          14

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 59  

Rows     Row Source Operation
-------  ---------------------------------------------------
     14  TABLE ACCESS FULL EMP 

********************************************************************************
...

Trace file: openxs_ora_3532.trc
Trace file compatibility: 9.00.01
Sort options: default

       1  session in tracefile.
       3  user  SQL statements in trace file.
      12  internal SQL statements in trace file.
      15  SQL statements in trace file.
      13  unique SQL statements in trace file.
     149  lines in trace file.

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

Важность полученной информации очевидна любому разработчику и администратору. Мы еще не раз подчекнем это далее, описывая историю развития средств трассировки SQL-операторов в Oracle.

Появление и развитие средств трассировки SQL-операторов в Oracle

Теперь позвольте отвлечься от практики и кратко пересказать историю создания и развития средств трассировки SQL-операторов. По ходу будут также рассмотрены основные воможности и особенности трассировки SQL-операторов в различных версиях СУБД Oracle. Мы также представим основные подходы к анализу полученной информации и проблемы, которые возникают при их интерпретации в различных версиях Oracle.

Расширенные средства трассировки SQL-операторов Oracle существуют сегодня потому, что, к счастью, проблемами производительности приложений Oracle занимались не только их конечные пользователи. Создатели ядра Oracle тоже вынуждены были решать эти проблемы, как в процессе поддержки пользователей, так и в ходе борьбы за первеноство в сравнительных тестах производительности различных СУБД, когда ими еще занимались. Процитирую Хуана Лоайзу (Juan Loaiza), разработчика архитектуры ядра Oracle в прошлом и вице-президента корпорации Oracle в настоящее время:

"Я всегда думал, что решение проблем производительности сводится к выяснению, на что уходит время в системе. Если можно точно понять, на что тратится время, то причина проблемы становится очевидной."

Все АБД и разработчики должны быть признательны Хуану и его команде - с помощью разработанных ими средств мы все может узнать, как ядро СУБД Oracle тратит время при выполнении запросов пользователей.

Версия 5

Средства трассировки SQL-операторов появились в Oracle версии 5, выпущенной в 1986 году. Для включения и отключения трассировки использовались простые операторы:

select trace('sql',1) from dual
...
select trace('sql',0) from dual

Вероятно, немногие знали о возможности трассировки SQL-операторов в Oracle версии 5, и еще меньше людей ее реально использовали. Сама корпорация Oracle во внутренних документах описывала эту возможность как не документированную, не поддерживаемую и явно не подлежащую переносу в версию 6.

По современным стандартам, функция trace версии 5 делала нет так уж много. Все, что вы могли получить в результате - поток секций PARSING IN CURSOR примерно такого вида:

=====================
PARSING IN CURSOR 3:
"select tab$pid,tab$rba,tab$tbl,tab$type,tab$sowner,tab$sname"
" from sys.tables where tab$owner=:1 and tab$name=:2"
=====================
PARSING IN CURSOR 4:
"select idx$cky from indexes['1.f.1'] where idx$tbl=:1 and id"
"x$cky is not null"
=====================
PARSING IN CURSOR 1:
"select * from dept "
=====================

Кроме 'sql', были и другие параметры трассировки. С помощью функции trace пользователь Oracle мог получить информацию о планах выполнения, операциях сортировки и использовании памяти.

Версия 6

В Oracle версии 6 трассировка SQL-операторов стала базовой, описанной в документации возможностью, которую мог использовать каждый. В версии 6 Oracle представил операторы, которые работают и в версиях 7, 8, 9 и 10:

alter session set sql_trace=true
...
alter session set sql_trace=false

Установка sql_trace была существенным шагом вперед для всех занимающихся анализом производительности приложений. Она позволила получить последовательность SQL-операторов, выполненных приложением, а также оценить нагрузку на СУБД, которую они представляли. Необработанные результаты трассировки (см. Листинг 1 ранее) выглядели весьма непонятно, но это не имело большого значения, поскольку корпорация Oracle предоставила средство обработки трассировочных файлов tkprof, которое выдавало информацию во вполне понятном виде. (См. Листинг 2 ранее. Листинг 2 получен на версии 9.2.0.1, но, хотя с версии 6 формат представления результатов немного изменился, по сути, выдаются те же данные.)

Теперь на лучших курсах по "настройке" Oracle, помимо использования магических коэффициентов (вроде процента попадания в буферный кеш), слушателей обучали интерпретации результатов tkprof. При этом предалаглись следующие весьма простые правила:

1. Надо уменьшать значения в столбце count. Т.е. надо сокращать количество обращений к СУБД. Наиболее действеным способом для этого будет изменение кода приложения.
2. Надо уменьшать значения в столбцах query и current (они получаются по значениям полей cr и cu в трассировочных файлах, соответственно). Другими словами, надо читать из буферного кеша как можно меньше блоков. Иногда для этого достаточно создать или удалить индекс, а иногда - переписать по-другому SQL-оператор.
3. Если сумма query + current сведена к минимуму, а в столбце disk - ненулевое значение, рекомендовалось увеличить буферный кеш. Т.е. избавиться от лишних "физических" чтений, но только после того, как избавились от всех лишних логических.

Конечно, к таким рекомендациям пришли не сразу. Многие советовали сначала сводить к нулю значения в столбце disk. Сейчас многим уже известно, что при этом мы провоцируем серьезную проблему производительности: SQL-оператор может находить все необходимые блоки данных в буферном кеше, но при этом быть ужасно неэффективным. Но во времена версии 6 об этом еще не задумывались.

Когда проблема была связана с неэффективными SQL-операторами, неудачной структурой схемы, недостающими индексами, избыточным анализом или неиспользованием возможностей сервера Oracle по обработке множеств, результаты трассировки позволяли выявить проблему. Но для решения некоторых проблем информации в трассировочных файлах было явно недостаточно. Стандартной трассировочной информации недостаточно, когда реальное время выполнения SQL-операторов существенно превосходит процессорное. Например, запрос выполняется 23 секунды, но процессорного времени для него потребовалось лишь 0,17. Что вы можете сказать по остальные 22,83 секунды? При использовании стандартной трассировочной информации ничего определенного сказать нельзя.

Конечно, незнание не мешает выдвигать гипотезы. Наиболее популярной гипотезой, "объясняющей" все проблемы производительности в те времена был ввод-вывод с диска. Это предположение было верно в некоторых случаях, но лишь в некоторых. Что, если проблема не связана с чрезмерной нагрузкой на процессор и с вводом-выводом с диска?

Листинг 3 содержит пример, иллюстрирующий проблему. Простой оператор UPDATE изменяет строку по первичному ключу. Он затронул только одну строку (r=1), но выполнялся 10,56 секунды (e=1056). Куда ушло столько времени? Понятно, что не на вычисления, поскольку процессорного времени ушло всего около 0,02 секунды (c=2). Дисковый ввод-вывод тоже не при чем, поскольку, судя по данным трассировки, ядро при изменении не выполнило ни одной операции чтения ОС (p=0). Как узнать, почему это изменение выполнялось более 10 секунд?

Листинг 3. Трассировка уровня 1, показывающая, что общее время выполнения значительно превосходит процессорное

=====================
PARSING IN CURSOR #1 len=31 dep=0 uid=73 oct=6 lid=73 tim=27139911 hv=1169598682 ad
='68f56dc8'
update c set v1='y' where key=1
END OF STMT
PARSE #1:c=0,e=902,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=27139911
EXEC #1:c=2,e=1056,p=0,cr=3,cu=3,mis=0,r=1,dep=0,og=4,tim=27140969

Версия 7

Версия Oracle 7 предоставила решение для продемонстрированной выше проблемы. В версии 7, Oracle представил средства расширенной трассировки SQL-операторов. При включении расширенной трассировки (уровень 8 в табл. 1), ядро Oracle может сообщить, на что именно потрачено время. (Кстати, я начал практически работать с Oracle как раз версии 7.0.16 в 1994 году. Тогда меня подобные проблемы вообще не интересовали - важно было установить сервер и научиться компилировать код на Pro*C. Следующих 5-6 лет трассировку я так и не использовал...) Раньше предполагали, что время уходит на ввод-вывод с диска. Однако Листинг 4 точно показывает, на что реально было затрачено время в ситуации, представленной ранее в Листинге 3: ядро Oracle ждало 4 раза, в итоге - около 10 секунд, событий enqueue. Другими словами, изменение было заблокировано - сеанс не мог установить блокировку.

Листинг 4. Трассировка уровня 8 показывает, на что ушло время

=====================
PARSING IN CURSOR #1 len=31 dep=0 uid=73 oct=6 lid=73 tim=27139911 hv=1169598682 ad
='68f56dc8'
update c set v1='y' where key=1
END OF STMT
PARSE #1:c=0,e=902,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=27139911
WAIT #1: nam='enqueue' ela= 307 p1=1415053318 p2=393254 p3=35925
WAIT #1: nam='enqueue' ela= 307 p1=1415053318 p2=393254 p3=35925
WAIT #1: nam='enqueue' ela= 307 p1=1415053318 p2=393254 p3=35925
WAIT #1: nam='enqueue' ela= 132 p1=1415053318 p2=393254 p3=35925
EXEC #1:c=2,e=1056,p=0,cr=3,cu=3,mis=0,r=1,dep=0,og=4,tim=27140969
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0

Можно было догадаться? Да. В конечном итоге, оператор UPDATE в Oracle может быть заблокирован. Но причина могла быть и в чем-то другом. На самом деле, скажем, в версии Oracle 7.3.4, это могло произойти по одной из 106 причин, поскольку в версии 7.3.4 трассировкой было охвачено 106 различных веток кода ядра Oracle.

Так что, при среднем "везении", вероятность угадать была около 1%. Но даже если бы вы и угадали, без средств расширенной трассировки вы бы не могли этого доказать. Можете угадать, что это была за блокировка и в каком режиме? Интерпретируя трассировочные данные (p1=1415053318) в соответствии со статьями Oracle Metalink, например, 55541.999 и 62354.1, можно точно сказать, что это исключительная блокировка TX.

Для включения расширенной трассировки в Oracle версии 7 как раз и появился уже представленный ранее оператор ALTER SESSION, устанавливающий событие 10046:

alter session set events '10046 trace name context forever, level 12'
...
alter session set events '10046 trace name context off'

Поддерживаемые уровни трассировки были представлены ранее в табл. 1.

С помощью этого оператора можно включить трассировку в приложении, создатели которого об этом позаботились. (А вы, господа, в нынешнем 2006 году, через 13 (!) лет после выхода версии 7, предоставляете возможность включения и отключения трассировки в своих приложениях? То-то же...). Хорошо, если доступен исходный код приложения - тогда вы сможете его дополнить... А если нет?

Можно, конечно, включить трассировку нужного уровня для всей системы с помощью оператора ALTER SYSTEM. Но от этого будет больше проблем, чем пользы. Диски могут оказаться забиты трассировочными файлами. А если места и хватит, большая часть информации окажется абсолютно бесполезной.

Стадартный пакет Oracle, DBMS_SYSTEM, позволяет действовать намного избирательнее. Упоминавшаяся выше (в разделе "Различные способы включить трассировку") процедура DBMS_SYSTEM.SET_EV позволяет АБД (пользователю sys) включить расширенную трассировку любого сеанса в системе:

dbms_system.set_ev(sid, serial, 10046, 12, ")
...
dbms_system.set_ev(sid, serial, 10046, 0, ")

Однако процедура эта и по сей день (официально) не поддерживается. Причем, по соображениям, скорее, "политическим", чем техническим.

На первый взгляд, отказ от поддержки процедуры SET_EV выглядит вполне обоснованным. Привилегию на выполнение пакета DBMS_SYSTEM АБД в производственной системе никому предоставлять не должен - при этом пользователи получат слишком широкие права. Да и сам АБД, при неправильном использовании процедуры SET_EV, может нанести серьезный ущерб системе. Например, если указать вместо события 10046 событие 10004, будет сымитировано разрушение управляющего файла, а это вряд ли полезно в производственной среде... Тем не менее, на практике использование пакета DBMS_SYSTEM зачастую более чем оправдано. Странно, что использование расширенной трассировки поддерживается официально уже много лет, а вот средства избирательного ее выключения - нет.

Версия 8

В Oracle версии 8 поддержка расширенной трассировки SQL была дополнена за счет добавления пакета dbms_support (см. файл $ORACLE_HOME/rdbms/admin/dbmssupp.sql). Он защищает пользователей от ужасных последствий ошибок при использовании процедуры dbms_system.set_ev. Этот пакет позволяет легко управлять трассировкой как в своем, так и в любом другом сеансе:

create or replace package dbms_support as

  function package_version return varchar2;
  pragma restrict_references (package_version, WNDS, WNPS, RNPS);

  function mysid return number;
  pragma restrict_references (mysid, WNDS, WNPS, RNPS);

  procedure start_trace(waits IN boolean  default TRUE,
                        binds IN boolean  default FALSE);

  procedure stop_trace;

  procedure start_trace_in_session(sid    IN number,
                                   serial IN number,
                                   waits  IN boolean  default TRUE,
                                   binds  IN boolean  default FALSE);

  procedure stop_trace_in_session(sid IN number,
                                  serial IN number);

end dbms_support;
/

Проблема лишь в том, что в файле dbmssupp.sql в комментариях указано следующее:

Rem NOTES
Rem This package should only be installed when requested by Oracle
Rem Support. It is not documented in the server documentation.
Rem It is to be used only as directed by Oracle Support.

Другими словами, он тоже не поддерживается; однако, статья 62294.1 на Metalink, по сути, поощряет использование пакета DBMS_SUPPORT.

В остальном, в версии 8 механизм расширенной трассировки SQL по сравнению с версией 7 не сильно изменился. Разве что, количество событий ожидания возросло до 215.

В средствах трассировки Oracle тоже иногда выявлялись ошибки. Тем не менее, при установке соответствующих пакетов исправлений, стредства трассировки SQL-операторов в Oracle 8 и 8i работают точно и надежно.

Версия 9

СУБД Oracle версии 9 внесла существенные дополнения в устоявшийся механизм трассировки:

• Повышение точности регистрации времени. Теперь вместо одной сотой секунды (0,01) измерения ведутся с точность до микросекунды (0,000001). За счет большей точности измерения можно лучше разобраться с непродолжительными обращениями к СУБД и ожиданиями.
• Возможность включения информации об ожиданиях в отчет tkprof. Наконец-то утилита tkprof начала обрабатывать расширенную информацию в трассировочных файлах (раньше приходилось анализировать их непосредственно).
• Расширен спектр трассируемых действий. В версии 9.2.0.4 количество событий ожидания выросло до 399.
• Учитывается статистика и время работы с каждым сегментом (источником строк). Это помогает определить, сколько времени уходит на работу с источником строк на каждом шаге плана выполнения. См. например мой перевод [3].

Добавление статической информации уровня сегмента в версии 9.2.0.2 стало давно ожидаемым лучом света в темном царстве трассировочных файлов. Начиная с версии, сервер Oracle выдавал в трассировочный файл строки STAT при закрытии курсора. Именно по этим строкам утилита tkprof легко собирала реальный план выполнения, а также получала количество строк на выходе каждого шага. Однако проблемы производительности - это проблемы времени выполнения операций, а по количеству обработанных строк время определить, в общем случае, нельзя. Начиная с версии 9.2.0.2, строки STAT имеют вид:

STAT #1 id=5 cnt=23607 pid=4 pos=1 obj=0 op='NESTED LOOPS (cr=1750 r=156 w=0 time=
1900310 us)'

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

Поле time=1900310 us в данном случае говорит, что на выполнение шага потребовалось 1,900310 секунды.

Время выполнения каждого шага плана - полезная информация. Правда, сначала для получения этой информации требовалось столько ресурсов, что использование трассировки SQL-операторов в версиях с 9.2.0.2 по 9.2.0.4 оказалось зачастую практически нереальным - на трассировку уходило раз в пять больше времени, чем в любой из прежних версий. Это была ошибка Oracle 3009359. К счастью, корпорация Oracle решила эту проблему в версии 9.2.0.5 (вот почему именно ее или более новые и рекомендуется использовать в производственной среде).

Версия 10

У средств трассировки версий 6/7/8/9 есть один архитектурный недостаток. Во времена версий 5 и 6, когда эти средства проектировались, большинство приложений имело архитектуру клиент-сервер. Каждое приложение организовывало один сеанс взаимодействия с сервером Oracle, который обслуживался одним выделенным серверным процессом, который и генерировал трассировочный файл. Достаточно было включить трассировку только для этого процесса, и мы могли получить всю необходимую информацию.

Однако с конца 1980-ых годов многое в архитектуре приложений Oracle изменилось. Появился Oracle Multi-Threaded Server (режим MTS), и это было лишь первое усложнение для механизма трассировки, поскольку операторы одного сеанса потенциально могли выполнять несколько разделяемых серверных процессов Oracle. В режиме MTS, трассировка одного пользовательского сеанса приводила к созданию нескольких трассировочных файлов, объединение информации из которых надо было делать вручную или с помощью специальных программных средств, используемых серьезными консалтинговыми компаниями. Трассировка в режиме MTS дает столько же полезные результаты, но вот правильно собрать их вместе обычно было нелегко.

Распараллеливание в Oracle еще более усложнило ситуацию: одно действие приложения может выполняться несколькими серверными процессами Oracle. Трассировка оператора со степенью распараллеливания n приведет к созданию одного трассировочного файла в каталоге user_dump_dest и еще до 2n трассировочных файлов в каталоге дампов фоновых процессов. Средства трассировки SQL (как стандартной, так и расширенной) прекрасно работают и при распараллеливании, но чтобы собрать информацию из нескольких трассировочных файлов придется потрудиться или использовать соответствующее программное обеспечение сторонних производителей.

Многоуровневые архитектуры усложнили задачи трассировки еще больше - к некоторым приложениям одновременно могут подключаться сотни тысяч пользователей. Сегодня одно действие конечного пользователя может отразиться в десятке трассировочных файлов на нескольких компьютерах. Но самая большая проблема состоит в том, что трассировкой можно управлять на уровне сеанса Oracle, и трассируя действия одного пользователя вы получаете в трассировочном файле информацию и о действиях многих других пользователей - тех, кто совместно использует один и тот же сеанс (или сеансы), скажем, из пула сервера приложений. И как теперь выделить информацию, касающуюся действий одного пользователя из всех этих данных, полученных при трассировке?

Появившаяся в версии 10 модель сквозной трассировки (end-to-end tracing) призвана решить эту проблему, причем, с обеспечением официальной поддержки всех используемых при этом средств. В версии 10 расширенная трассировка SQL-операторов наконец-то полностью описана в документации и поддерживается (а количество трассируемых событий возросло до 808 в версии 10.1.0.2.). Более того, трассировать в версии 10 теперь можно отдельные модули и действия (функциональные единицы) в сеансе.

Пакет dbms_monitor позволяет включать и отключать трассировку следующим образом:

dbms_monitor.serv_mod_act_trace_enable(service, module, action, true, true)
...
dbms_monitor.serv_mod_act_trace_disable(service, module, action)

Кроме того, в версии 10 Oracle предлагает новое инструментальное средство, trcsess, позволяющее автоматически объединить все соответствующие трассировочные файлы, так, чтобы можно было получить линейных поток операторов, выполненных отдельным пользователем.

Конечно, идентифицировать функциональные единицы в подходящем для пакета dbms_monitor виде должно само приложение. Уже давно опытные разработчики приложений использовали для идентификации текущего состояния приложения соответствующие подпрограммы пакета dbms_application_info. Проблема при использовании пакета dbms_application_info была в том, что для установки каждого атрибута (модуля, действия) требовались отдельные вызовы, что отрицательно сказывалось на производительности приложений. Oracle в версии 10 внес изменения в Oracle Call Interface (OCI), позволяющие разработчику приложения включить идентифицирующую информацию в стандартные обращения к СУБД.

При корректной реализации, модель сквозной трассировки версии 10 - это именно то, чего все так долго ждали. Теперь можно ответить на вопрос: "Что именно потребовало столько времени?" для любого оператора в приложении, независимо от сложности ахитектуры системы, в которой оно работает.

Что еще можно включить в трассировочные файлы?

Поскольку средства трассировки корпорация Oracle создавала, прежде всего, для своих собственных целей - в качестве стредства отладки различных компонентов и средств сервера, содержимое трассировочных файлов не ограничивается информацией о ходе выполнения SQL-операторов. На самом деле, с помощью механизма событий, одним из которых является уже упоминавшееся событие 10046, можно включить выдачу в трассировочные файлы и другой важной информации.

Всего событий для трассировки и управления работой отдельных компонентов зарезервировано 1000. Краткую информацию о назначении каждого события можно получить, например, выполнив следующий PL/SQL-блок:

DECLARE
  err_msg VARCHAR2(120);
BEGIN
  dbms_output.enable (1000000);
  FOR err_num IN 10000..10999
  LOOP
    err_msg := SQLERRM (-err_num);
    IF err_msg NOT LIKE '%Message '||err_num||' not found%' THEN
      dbms_output.put_line (err_msg);
    END IF;
  END LOOP;
END;
/

В серии статей о средствах трассировки я собираюсь рассмотреть еще результаты трассировки события 10053, позволяющие понять, почему стоимостной оптимизатор (CBO) выбрал тот или иной план.

Предупреждение

Большинство этих событий не описаны в документации и должны использоваться только по рекомендации службы поддержки Oracle. Используйте их осторожно (как минимум, проверьте, что номер события указан правильно), только в тестовой среде и только если точно знаете, что делаете.

Также в трассировочные файлы можно сбросить текстовое представление (дамп) содержимого управляющего файла, любого блока и другую ценную информацию. Об этих возможностях я планирую рассказать в следующих статьях данной серии.

Резюме

Использование заложенных в СУБД Oracle средств трассировки SQL-операторов позволяет избавиться от синдрома "черного ящика" при разработке и эксплуатации приложений. АБД и разработчики в любой момент могут получить исчерпывающую информацию о том, какие SQL-операторы выполнялись, сколько раз, с какими параметрами, и сколько времени потребовалось серверу на выполнение каждого из них. В данной статье мы рассмотрели, как практически использовать трассировку SQL, а также описали историю развития и возможности средств трассировки СУБД Oracle вплоть до версии 10g.

Надеюсь, эта статья подтолкнет многих разработчиков приложений Oracle к тому, чтобы задуматься над производительностью создаваемого кода и использовать в повседневной практике не только установки set timing on и set autotrace on в утилите SQL*Plus... (Надеюсь, вы иногда занимаетесь тестированием производительности приложений в условиях, близких к производственным?) Ваши пользователи достойны того, чтобы работать с эффективными приложениями, а СУБД Oracle уже давно дает вам достаточно средств, чтобы эту эффективность обеспечить. Причем, без всяких шаманских танцев с бубном.

Литература и другие источники информации

1. Oracle Insights: Tales of the Oak Table, Mogens N?rgaard, James Morle, Dave Ensor и др., Apress, 2004, ISBN 1-59059-387-1
2. Oracle9i Database Performance Tuning Guide and Reference http://download-west.oracle.com/docs/cd/B10501_01/server.920/a96533/toc.htm
3. Статистическая информация уровня сегмента в событии 10046 Oracle 9.2 http://ln.com.ua/~openxs/projects/oracle/ora066.html
4. Том Кайт, "Oracle для професионалов", Книга 1, "Ахитектура и основные особенности", ООО "Диасофт ЮП", 2002, ISBN 5-93772-072-5.
5. Сайт технической поддержки пользователей Oracle http://metalink.oracle.com.