Функция трассировки SQL входит в состав ядра Oracle начиная с версии 6. В 1992 году, с выпуском версии 7.0.12, корпорация Oracle значительно усовершенствовала трассировку SQL, дополнив ее информацией о продолжительности не потребляющих времени процессора инструкций, выполняемых ядром Oracle.
В примере приведен один из простейших сеансов SQL*Plus, который можно себе представить. Сеанс активирует для себя механизм расширенной трассировки SQL. Затем он запрашивает из базы данных строку "Hello, world; today is sysdate" и завершается. Сгенерируем для него расширенную трассировку:
alter session set max_dump_file_size=unlimited; alter session set timed_statistics=true; alter session set events '10046 trace name context forever, level 12'; select 'Hello, world; today is '|| sysdate from dual; exit /
Файл трассировки приводит последовательность действий, выполненных ядром Oracle от имени данного сеанса.
/oracle/admin/orcl/udump/orcl_ora_27968.trc Oracle9i Enterprise Edition Release 9.2.0.8.0 - Production With the Partitioning option JServer Release 9.2.0.8.0 - Production ORACLE_HOME = /u01/app/oracle/product/9.2.0 System name: Linux Node name: linux Release: 2.4.18 Version: #5 SMP Sat May 14 12:11:48 MSD 2005 Machine: i686 Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 30 Unix process pid: 27968, image: oracle@linux (TNS V1-V3) *** 2010-03-19 08:20:36.131 *** SESSION ID:(31.33589) 2010-03-19 08:20:36.129 APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240 ===================== PARSING IN CURSOR #3 len=70 dep=0 uid=21 oct=42 lid=21 tim=1239234410284776 hv=2573003165 ad='6995c3dc' alter session set events '10046 trace name context forever, level 12' END OF STMT EXEC #3:c=0,e=313,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1239234410282668 WAIT #3: nam='SQL*Net message to client' ela= 4 p1=675562835 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 4328 p1=675562835 p2=1 p3=0 ===================== PARSING IN CURSOR #3 len=53 dep=0 uid=21 oct=3 lid=21 tim=1239234410290769 hv=1159297995 ad='66eacf80' select 'Hello, world; today is '|| sysdate from dual END OF STMT PARSE #3:c=0,e=1091,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1239234410290755 BINDS #3: EXEC #3:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1239234410291125 WAIT #3: nam='SQL*Net message to client' ela= 4 p1=675562835 p2=1 p3=0 FETCH #3:c=0,e=118,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1239234410291365 WAIT #3: nam='SQL*Net message from client' ela= 541 p1=675562835 p2=1 p3=0 FETCH #3:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1239234410292133 WAIT #3: nam='SQL*Net message to client' ela= 2 p1=675562835 p2=1 p3=0 WAIT #3: nam='SQL*Net message from client' ela= 3666998 p1=675562835 p2=1 p3=0 XCTEND rlbk=0, rd_only=1 STAT #3 id=1 cnt=1 pid=0 pos=1 obj=222 op='TABLE ACCESS FULL OBJ#(222) '
Такой маленький файл трассировки несложно пройти вручную. Обратим внимание на некоторые наиболее значимые пункты.
В начале файла трассировки содержится преамбула - заголовок, включающий в себя сведения о файле: его имя, версию сформировавшего его ядра Oracle и т.д. Затем идет строка, в которой определен сеанс, для которого выполняется трассировка (в нашем случае сеанс 31, порядковый номер 33589), и время выполнения данной строки. Ядро идентифицирует каждую команду SQL, используемую сеансом, в секции PARSING IN CURSOR. В этой секции приводятся атрибуты используемого текста SQL, в том числе и сам текст.
Рабочие строки файла трассировки начинаются с лексем PARSE, EXEC и FETCH (а также некоторых других), также к ним относятся строки WAIT. Каждая из строк PARSE, EXEC и FETCH отображает выполнение одного вызова базы данных. Статистики c и e сообщают, сколько было потрачено на данный вызов времени процессора и какова была общая продолжительность вызова соответственно. Другие статистические показатели, присутствующие в строке, представляют собой количество блоков Oracle, полученных системными вызовами чтения (p) или обращениями к кэшу буферов базы данных в двух режимах (cr для чтения в согласованном режиме и cu для чтения в текущем режиме), количество непопаданий в библиотечный кэш (mis) и количество возвращаемых строк (r). Значение tim в конце строки позволяет приблизительно оценить время, когда этот вызов был завершен.
Строки WAIT как раз относится к тому, что отличает данные расширенной трассировки SQL от обычных старых трассировочных данных. Каждая строка WAIT сообщает о продолжительности определенной последовательности инструкций, выполняемой внутри процессора ядра Oracle. Статистика ela содержит время отклика такой последовательности инструкций. Атрибут nam определяет вызов; значения p1, p2 и p3 предоставляют полезную информацию о вызове, формат который зависит от значений nam.
Строки STAT не передавали непосредственной информации о времени отклика до версии 9.2. Однако и до выхода версии 9.2 они широко применялись при анализе производительности, т.к. содержали сведения о плане выполнения, выбранном оптимизатором запросов Oracle для выполнения команд SQL. Наконец, строка XCTEND появляется в том случае, когда исследуемое приложение выполняет команду фиксации или отката.
Комментариев нет:
Отправить комментарий