Ваша программа компилируется успешно, но в ходе выполнения тестового сценария происходит сбой: в программе где-то допущена ошибка. Как найти ее причину? Конечно, можно сразу взяться за отладчик (практически в любом редакторе PL/SQL имеется визуальный отладчик с возможностью установки точек прерывания и отслеживания состояния данных), но сначала стоит провести трассировку выполнения программы. Прежде чем рассматривать возможности трассировки, стоит сказать пару слов о различиях между отладкой и трассировкой. Разработчики часто смешивают эти два понятия, однако это далеко не одно и то же. В двух словах: вы сначала выполняете трассировку для получения расширенной информации о поведения приложения, которая помогает выявить источник проблем, а затем используете отладчик для поиска конкретных строк кода, порождающих ошибку.
Ключевое различие между трассировкой и отладкой заключается в том, что трассировка выполняется в «пакетном» режиме, а отладка является интерактивным процессом. Я включаю режим трассировки и выполняю код своего приложения. Когда его выполнение завершится, я открываю журнал и использую полученную информацию для проведения сеанса отладки. Во время отладки я выполняю код строку за строкой (обычно начиная с точки прерывания, близкой к источнику проблемы). Сеансы отладки обычно получаются слишком долгими и утомительными, поэтому стоит сделать все возможное, чтобы свести к минимуму время, проведенное за отладкой. Основательная упреждающая трассировка поможет вам в этом.
Каждое приложение должно включать определенные программистом трассировочные вызовы. В этом разделе представлены основные средства трассировки PL/SQL, но сначала нужно упомянуть принципы, которые должны соблюдаться при реализации трассировки:
- Трассировочные вызовы должны оставаться в коде на протяжении всех фаз разработки и развертывания. Иначе говоря, трассировочные вызовы, вставленные в ходе разработки, не следует удалять при переходе приложения в фазу реальной эксплуатации. Трассировка часто помогает понять, что происходит с вашим приложением при выполнении в реальной среде.
- Сведите затраты на вызов трассировочных средств к абсолютному минимуму. При отключенной трассировке их присутствие в коде не должно никак отражаться на быстродействии приложения.
- Не вызывайте программу
DBMS_OUTPUT.PUT_LINEдля выполнения трассировки прямо в коде приложения. Эта встроенная программа не обладает достаточной гибкостью или мощью для качественной трассировки. - Вызовите
DBMS_UTILITY.FORMAT_CALL_STACKили подпрограммуUTL_CALL_STACK(12c и выше) для сохранения стека вызовов в трассировочных данных. - Обеспечьте возможность простого включения и отключения трассировки в вашем коде. Включение трассировки не должно требовать вмешательства службы поддержки. Также не следует поставлять отдельную версию приложения с включенной трассировкой.
- Если кто-то уже создал механизм трассировки, который вы можете использовать в своей работе (и который соответствует этим принципам), не тратьте время на создание собственного механизма трассировки.
Начнем с последнего принципа. Какие средства трассировки PL/SQL существуют в настоящее время?
- DBMS_APPLICATION_INFO — этот встроенный пакет предоставляет API, при помощи которого приложения «регистрируют» свое текущее состояние выполнения в базе данных Oracle. Трассировочная информация записывается в динамические представления
V$. Подробное описание приводится в следующем разделе. - Log4PLSQL — инфраструктура с открытым исходным кодом, построенная по образцу (и на основе) log4J, очень популярного механизма протоколирования для языка Java.
- opp_trace — этот пакет, доступный на сайте книги, предоставляет простую, но эффективную функциональность трассировки.
- DBMS_TRACE — это встроенное средство обеспечивает трассировку кода
PL/SQL, но не позволяет включать в результаты какие-либо данные приложения. С другой стороны,DBMS_TRACEможет использоваться без модификации исходного кода программы.
Вы также можете воспользоваться одним из встроенных профайлеров PL/SQL для получения информации о профилях производительности каждой строки и подпрограммы вашего приложения.
DBMS_UTILITY.FORMAT_CALL_STACK
Функция DBMS_UTILITY.FORMAT_CALL_STACK возвращает отформатированную строку с содержимым стека вызовов: последовательностью вызовов процедур или функций, приведшей к точке вызова функции. Иначе говоря, эта функция отвечает на вопрос: «Как я сюда попал?»
Следующий пример демонстрирует использование этой функции и показывает, как выглядит отформатированная строка:
SQL> CREATE OR REPLACE PROCEDURE proc1
2 IS
3 BEGIN
4 DBMS_OUTPUT.put_line (DBMS_UTILITY.format_call_stack);
5 END;
6 /
Procedure created.
SQL> CREATE OR REPLACE PACKAGE pkg1
2 IS
3 PROCEDURE proc2;
4 END pkg1;
5 /
Package created.
SQL> CREATE OR REPLACE PACKAGE BODY pkg1
2 IS
3 PROCEDURE proc2
4 IS
5 BEGIN
6 proc1;
7 END;
8 END pkg1;
9 /
Package body created.
SQL> CREATE OR REPLACE PROCEDURE proc3
2 IS
3 BEGIN
4 FOR indx IN 1 .. 1000
5 LOOP
6 NULL;
7 END LOOP;
8
9 pkg1.proc2;
10 END;
11 /
Procedure created.
SQL> BEGIN
2 proc3;
3 END;
4 /
----- PL/SQL Call Stack -----
object line object
handle number name
000007FF7EA83240 4 procedure HR.PROC1
000007FF7E9CC3B0 6 package body HR.PKG1
000007FF7EA0A3B0 9 procedure HR.PROC3
000007FF7EA07C00 2 anonymous block
О чем необходимо помнить при использовании dbms_utility.format_call_stack:
- При вызове подпрограммы из пакета в отформатированном стеке вызовов выводится только имя пакета, но не имя подпрограммы (после того, как код был откомпилирован, все имена «теряются», то есть становятся недоступными для исполнительного ядра).
- Чтобы просмотреть фактический исполняемый код, создайте запрос к
ALL_SOURCEс именем программного модуля и номером строки. - Когда вы отслеживаете процесс выполнения (см. подробности далее) или регистрируете ошибки, вызовите эту функцию и сохраните вывод в журнале для последующего просмотра и анализа.
- Разработчики уже давно просили Oracle предоставить средства для разбора строки, и в Oracle Database 12c наконец-то появился новый пакет
UTL_CALL_STACK. (Если вы еще не перешли на версию 12.1 и выше, обратитесь к файлу callstack.pkg — он предоставляет аналогичную функциональность.)
UTL_CALL_STACK (Oracle Database 12c)
Oracle Database 12c предоставляет пакет UTL_CALL_STACK для получения информации о выполняемых подпрограммах. Хотя имя пакета создает впечатление, что пакет только предоставляет информацию о стеке вызовов, также предоставляется доступ к стеку ошибок и стеку трассировки.
Каждый стек обладает глубиной (индикатором позиции в стеке); вы можете запросить информацию на определенной глубине всех трех видов стеков, с которыми работает пакет. Одним из главных усовершенствований utl_call_stack по сравнению с dbms_utility. FORMAT_CALL_STACK стала возможность получения уточненных имен с именами программных модулей, всех лексических родителей подпрограммы и имени самой подпрограммы. Впрочем, для стека трассировки эта дополнительная информация недоступна.
Ниже приведена таблица подпрограмм пакета с парой примеров.
| Имя | Описание |
| BACKTRACE_DEPTH | Возвращает количество элементов в стеке трассировки |
| BACKTRACE_LINE | Возвращает номер строки для заданной глубины стека трассировки |
| BACKTRACE_UNIT | Возвращает имя программного модуля для заданной глубины стека трассировки |
| CONCATENATE_SUBPROGRAM | Возвращает полное имя, полученное посредством конкатенации |
| DYNAMIC_DEPTH | Возвращает количество подпрограмм в стеке вызовов, включая SQL, Java и другие не относящиеся к PL/SQL контексты. Например, если A вызывает B, затем B вызывает C и C вызывает B, то стек будет выгля- деть следующим образом (внизу выводится динамическая глубина): A B C B 4 3 2 1 |
| ERROR_DEPTH | Возвращает количество ошибок в стеке вызовов |
| ERROR_MSG | Возвращает сообщение об ошибке для заданной глубины стека ошибок |
| ERROR_NUMBER | Возвращает код ошибки для заданной глубины стека ошибок |
| LEXICAL_DEPTH | Возвращает лексическую глубину вложенности подпрограммы для заданной динамической глубины |
| OWNER | Возвращает имя владельца программного модуля подпрограммы на заданной динамической глубине |
| SUBPROGRAM | Возвращает полное имя подпрограммы для заданной динамической глубины |
| UNIT_LINE | Возвращает номер строки модуля для подпрограммы с заданной динамической глубиной |
Несколько типичных применений UTL_CALL_STACK:
- Получение полного имени подпрограммы. Вызов
utl_call_stack.subprogramвозвращает массив строк; функцияconcatenate_subprogramполучает этот массив и возвращает одну строку с именами, разделенными точками. В следующем фрагменте при вызове subprogram передается 1, потому что я хочу получить информацию о программе на вершине стека — текущей выполняемой подпрограмме:
CREATE OR REPLACE PACKAGE pkgl
IS
PROCEDURE proc1;
END pkg1;
/
CREATE OR REPLACE PACKAGE BODY pkg1
IS
PROCEDURE proc1
IS
PROCEDURE nested_in_proc1
IS
BEGIN
DBMS_OUTPUT.put_line (
utl_call_stack.concatenate_subprogram (utl_call_stack.subprogram (1)));
END;
BEGIN
nested in proc1;
END;
END pkg1;
/
BEGIN
pkg1.proc1;
END;
/
PKG1.PROC1.NESTED IN PROC1
- Вывод имени программного модуля и номера строки позиции, в которой было инициировано текущее исключение. Сначала создается функция
backtrace_to, которая «скрывает» вызовы подпрограммutl_call_stack. Во всех вызовахbacktrace_ unitиbacktrace_lineпередается значение, возвращаемое функциейerror_depth. Значение глубины для ошибок отличается от значения для стека вызовов: в стеке вызовов 1 соответствует вершине стека (текущей выполняемой подпрограмме). В стеке ошибок позиция кода, в которой была инициирована ошибка, находится на глубинеerror_depth, а не на глубине 1:
CREATE OR REPLACE FUNCTION backtrace_to
RETURN VARCHAR2
IS
BEGIN
RETURN utl_call_stack.backtrace_unit (utl_call_stack.error_depth)
|| ' line '
|| utl_call_stack.backtrace_line (utl_call_stack.error_depth);
END;
/
CREATE OR REPLACE PACKAGE pkg1
IS
PROCEDURE proc1;
PROCEDURE proc2;
END;
/
CREATE OR REPLACE PACKAGE BODY pkg1
IS
PROCEDURE proc1
IS
PROCEDURE nested_in_proc1
IS
BEGIN
RAISE VALUE_ERROR;
END;
BEGIN
nested_in_proc1;
END;
PROCEDURE proc2
IS
BEGIN
proc1;
EXCEPTION
WHEN OTHERS THEN RAISE NO_DATA_FOUND;
END;
END pkg1;
/
CREATE OR REPLACE PROCEDURE proc3
IS
BEGIN
pkg1.proc2;
END;
/
BEGIN
proc3;
EXCEPTION
WHEN OTHERS
THEN
DBMS_OUTPUT.put_line (backtrace_to);
END;
/
HR.PKG1 line 19Несколько замечаний по поводу использования UTL_CALL_STACK:
- Оптимизации компилятора могут изменять глубину (лексическую, динамическую и глубину трассировки), поскольку процесс оптимизации может привести к пропуску вызовов подпрограмм.
- Не поддерживаются вызовы
UTL_CALL_STACKза границами RPC (Remote Procedure Call). Например, если procl вызывает удаленную процедуруremoteproc2, тоremoteproc2не сможет получить информацию о procl с использованиемUTL_CALL_STACK. - Информация о лексических элементах предоставляется средствами условной компиляции PL/SQL, а не через
utl_call_stack.
Пакет UTL_CALL_STACK чрезвычайно удобен, но для повседневного использования вам, скорее всего, придется построить собственные инструменты на базе подпрограмм пакета. Я написал вспомогательный пакет (см. файлы 12c_utl_call_stack_helper.sql и 12c_utl_call_stack_helper_demo.sql) с программами, которые, как мне кажется, могут вам пригодиться.
DBMS_APPLICATION_INFO
Встроенный пакет DBMS_APPLICATION_INFO предоставляет API для «регистрации» текущего состояния выполнения приложения в базе данных Oracle. Для внешнего наблюдения за сохраненной информацией о состоянии приложения используются виртуальные таблицы V$. Именно использование виртуальных таблиц V$ в качестве хранилища трассировочных данных отличает этот пакет от других решений.
Регистрация приложений средствами DBMS_APPLICATION_INFO открывает гораздо больше возможностей для анализа приложений на предмет производительности и потребления ресурсов, чем все остальные решения. Это открывает дополнительные возможности для оптимизации приложений и более точной оценки эксплуатационных затрат.
В следующей таблице перечислены подпрограммы этого пакета. Все они являются процедурами и не могут выполняться в коде SQL.
| Имя | Описание |
| DBMS_APPLICATION_INFO.SET_MODULE | Назначает имя выполняемого модуля |
| DBMS_APPLICATION_INFO.SET_ACTION | Назначает действие внутри модуля |
| DBMS_APPLICATION_INFO.READ_MODULE | Получает информацию о модуле и действии для текущего сеанса |
| DBMS_APPLICATION_INFO.SET_CLIENT_INFO | Назначает информацию о клиенте для сеанса |
| DBMS_APPLICATION_INFO.READ_CLIENT_INFO | Читает информацию о клиенте для сеанса |
| DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS | Записывает строку в таблицу LONGOPS (только в версии 8.0) |
Пример использования пакета DBMS_APPLICATION_INFO:
PROCEDURE drop_dept (
deptno_IN IN employees.department_id%TYPE
, reassign_deptno_IN IN employees.department_id%TYPE
)
IS
l_count PLS_INTEGER;
BEGIN
DBMS_APPLICATION_INFO.SET_MODULE
(module_name => 'DEPARTMENT FIXES'
,action_name => null);
DBMS_APPLICATION_INFO.SET_ACTION (action_name => 'GET COUNT IN DEPT');
SELECT COUNT(*)
INTO l_count
FROM employees
WHERE department_id = deptno_IN;
DBMS_OUTPUT.PUT_LINE ('Reassigning ' || l_count || ' employees');
IF l_count > 0
THEN
DBMS_APPLICATION_INFO.SET_ACTION (action_name => 'REASSIGN EMPLOYEES');
UPDATE employees
SET department_id = reassign_deptno_IN
WHERE department_id = deptno_IN;
END IF;
DBMS_APPLICATION_INFO.SET_ACTION (action_name => 'DROP DEPT');
DELETE FROM departments WHERE department_id = deptno_IN;
COMMIT;
DBMS_APPLICATION_INFO.SET_MODULE(null,null);
EXCEPTION
WHEN OTHERS THEN
DBMS_APPLICATION_INFO.SET_MODULE(null,null);
END drop_dept;Обратите внимание на три вызова DBMS_APPLICATION_INFO, определяющие три этапа процесса удаления. Это позволяет отслеживать состояние приложения с чрезвычайно высоким уровнем детализации.
Проследите за тем, чтобы имя действия описывало текущую транзакцию или логическую единицу работы внутри модуля.
При завершении транзакции следует вызвать процедуру DBMS_APPLICATION_INFO.SET_ACTION, передавая NULL в качестве значения параметра action_name. Это гарантирует, что последующие транзакции, не зарегистрированные средствами DBMS_APPLICATION_INFO, не будут ошибочно включены в текущее действие. Например, если программа обрабатывает исключения, обработчик исключения, вероятно, должен сбрасывать информацию о текущем действии.
Трассировка с использованием opp_trace
Программа opp_trace доступна на сайте 5-го издания этой книги. Она реализует мощный механизм трассировки, позволяющий направить выходные данные на экран или в таблицу (opp_trace). Выполните сценарий opp_trace.sql, чтобы создать объекты базы данных (для удаления этих объектов используется сценарий opp_trace_uninstall.sql). Читателю разрешается вносить необходимые изменения в код opp_trace для использования его в вашей рабочей среде.
Включение трассировки всех вызовов через opp_trace API происходит так:
opp_trace.turn_on_trace;В следующем вызове set_tracing трассировка включается только для контекстов, содержащих строку «balance»:
opp_trace.turn_on_trace ('balance');Теперь посмотрим, как совершаются вызовы opp_trace.trace_activity в ваших хранимых программах.
Процедура q$error_manager.trace почти никогда не вызывается напрямую. Вместо этого ее вызов вкладывается в вызов q$error_manager.trace_enabled, как показано в следующем фрагменте:
IF opp_trace.trace_is_on
THEN
opp_trace.trace_activity (
context_in => 'generate_test_code for program'
, data_in => qu_program_qp.name_for_id (l_program_key)
);
END IF;
Такой способ вызова программы trace сводит к минимуму затраты на трассировку. Функция trace_enabled возвращает одно логическое значение; она не передает фактических аргументов и завершает свою работу эффективно. Если функция возвращает TRUE, то база данных Oracle вычисляет все выражения в списке параметров и вызывает процедуру trace, которая также проверит, что для этого конкретного контекста трассировка включена.
Если вызвать процедуру trace напрямую в коде приложения, то при каждом переходе к этой строке исполнительное ядро будет вычислять все фактические аргументы в списке параметров и вызывать процедуру trace, которая будет проверять, что трассировка включена для этого контекста. Если трассировка отключена, то ничего не происходит, — но приложение уже затратило процессорное время на вычисление аргументов и их передачу trace.
Заметит ли пользователь лишние затраты на избыточное вычисление аргументов? Вероятно, не заметит, но с добавлением новых трассировочных вызовов повышается вероятность того, что они повлияют на ощущения пользователя от работы с приложением. Лучше заведите привычку всегда скрывать трассировочные вызовы в команде IF, которая сводит лишние затраты к минимуму. Я использую специальный фрагмент кода, чтобы вставка команды IF с шаблонным вызовом не требовала ввода большого количества символов.
Пакет DBMS_TRACE
Встроенный пакет DBMS_TRACE предоставляет средства для запуска и остановки трассировки PL/SQL в ходе сеанса. При включенной трассировке ядро собирает данные в ходе выполнения программы. Собранная информация выводится в файл на сервере.
Файл, полученный в результате трассировки, содержит информацию о конкретных шагах, выполняемых вашим кодом. DBMS_PR0FILER и DBMS_HPROF (иерархический профайлер), позволяют провести более полный анализ вашего приложения с получением хронометражной информации и данных о количестве выполнений конкретной строки.
Установка пакета DBMS_TRACE
Этот пакет не всегда автоматически устанавливается вместе со всеми остальными встроенными пакетами. Чтобы определить, установлен ли он в вашей системе, подключитесь к базе данных в качестве пользователя с учетной записью SYS (или другой учетной записью с привилегиями SYSDBA) и выполните в SQL*Plus команду:
DESCRIBE DBMS_TRACE
Если на экране появится сообщение об ошибке:
ORA-04043: object dbms_trace does not existзначит, пакет нужно установить. Для этого, используя ту же учетную запись, выполните следующие файлы в указанном порядке:
$ORACLE_HOME/rdbms/admin/dbmspbt.sql
$ORACLE_HOME/rdbms/admin/prvtpbt.plb
Программы пакета DBMS_TRACE
Пакет DBMS_TRACE содержит три программы.
| Имя | Описание |
| SET_PLSQL_TRACE | Активизирует трассировку в текущем сеансе |
| CLEAR_PLSQL_TRACE | Останавливает трассировку в текущем сеансе |
| PLSQL_TRACE_VERSION | Возвращает основной и дополнительный номера версий пакета DBMS_TRACE |
Для трассировки кода PL/SQL в текущем сеансе выполняется следующий вызов:
DBMS_TRACE.SET_PLSQL_TRACE (уровень_трассировки INTEGER);Здесь значением аргумента уровень трассировки служит одна из следующих констант:
- Константы, определяющие, какие элементы программы PL/SQL подлежат трассировке:
DBMS_TRACE.trace_all_calls constant INTEGER := 1;
DBMS_TRACE.trace_enabled_calls constant INTEGER := 2;
DBMS_TRACE.trace_all_exceptions constant INTEGER := 4;
DBMS_TRACE.trace_enabled_exceptions constant INTEGER := 8;
DBMS_TRACE.trace_all_sql constant INTEGER := 32;
DBMS_TRACE.trace_enabled_sql constant INTEGER := 64;
DBMS_TRACE.trace_all_lines constant INTEGER := 128;
DBMS_TRACE.trace_enabled_lines constant INTEGER := 256;- Константы, управляющие процессом трассировки:
DBMS_TRACE.trace_stop constant INTEGER := 16384;
DBMS_TRACE.trace_pause constant INTEGER := 4096;
DBMS_TRACE.trace_resume constant INTEGER := 8192;
DBMS_TRACE.trace_limit constant INTEGER := 16;Комбинации констант из пакета DBMS_TRACE активизируют одновременную трассировку нескольких элементов языка PL/SQL. Учтите, что константы, управляющие процессом трассировки (например, DBMS_TRACE.trace_pauseDBMS_TRACE. trace_enabled_calls
Трассировка всех программ, выполняемых в текущем сеансе, активизируется следующим вызовом:
DBMS_TRACE.SET_PLSQL_TRACE (DBMS_TRACE.trace_all_calls);Трассировка всех исключений, инициируемых в течение текущего сеанса, активизируется следующим образом:
DBMS_TRACE.SET_PLSQL_TRACE (DBMS_TRACE.trace_all_exceptions);Далее запускается программный код. Трассировка прекращается вызовом
DBMS_TRACE.CLEAR_PLSQL_TRACE;После этого можно проанализировать содержимое файла трассировки. Имена файлов генерируются Oracle; нужный файл легко находится по дате модификации. О том, где эти файлы хранятся, рассказывается далее, в разделе «Формат собранных данных». Вы также можете установить идентификатор в файле трассировки, чтобы упростить его поиск в будущем:
SQL> alter session set tracefile_identifier = 'hello_steven!';
Session altered.
SQL> select tracefile from v$process where tracefile like '%hello_steven!%';
TRACEFILE
----------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_24446_hello_steven!.trc
Учтите, что трассировка PL/SQL не может использоваться на серверах коллективного доступа (ранее называвшихся многопоточными серверами, MTS).
Управление содержимым файла трассировки
Файлы, генерируемые пакетом DBMS_TRACE, могут быть очень большими. Чтобы уменьшить объем выходных данных, следует трассировать не все подряд, а только конкретные программы (этот прием не может использоваться с удаленными вызовами RPC). Чтобы включить трассировку всех программ, созданных или измененных в ходе сеанса, измените настройки сеанса следующей командой:
ALTER SESSION SET PLSQL_DEBUG=TRUE;Если вы не хотите менять конфигурацию всего сеанса, перекомпилируйте конкретный программный модуль в режиме отладки следующим образом (способ неприменим к анонимным блокам):
ALTER [PROCEDURE | FUNCTION | PACKAGE BODY] имя_программы COMPILE DEBUG;Затем инициируйте трассировку только этих программных модулей:
DBMS_TRACE.SET_PLSQL_TRACE (DBMS_TRACE.trace_enabled_calls);Трассировку также можно ограничить только теми исключениями, которые инициируются в доступных для данного процесса программах:
DBMS_TRACE.SET_PLSQL_TRACE (DBMS_TRACE.trace_enabled_exceptions);Если вы установили два уровня трассировки (для всех программ или исключений, а также для некоторых программ и исключений), будет действовать уровень «для всех».
Приостановление и возобновление трассировки
Процедура SET_PLSQL_TRACE способна не только определять информацию, подлежащую трассировке. С ее помощью также можно приостанавливать и возобновлять процесс трассировки. Например, следующая команда приостанавливает сбор данных вплоть до последующего возобновления трассировки:
DBMS_TRACE.SET_PLSQL_TRACE (DBMS_TRACE.trace_pause);Пакет DBMS_TRACE включает в файл трассировки записи с информацией о приостановлении и возобновлении трассировки.
При помощи константы DBMS_TRACE.trace_limit можно указать, что в файле трассировки должна сохраняться информация только о 8192 трассируемых событиях. Этот подход защищает базу данных от переполнения трассировочной информацией. По завершении сеанса трассировки будут сохранены лишь 8192 последние записи.
Формат собранных данных
Если вы запросили трассировку только для определенных программных модулей, но не текущей программы, данные трассировки сохраняться не будут. Если же включена трассировка текущей программы, в файл трассировки записываются ее тип, имя и глубина стека. При трассировке исключений определяется номер строки программы, в процессе выполнения которой оно было инициировано, его тип (пользовательское или предопределенное) и в случае предопределенного исключения — его номер (номер ошибки, связанной с пользовательским исключением, всегда равен 1).
Пример выходных данных трассировки для процедуры showemps:
Пример выходных данных трассировки для процедуры showemps:
*** 1999.06.14.09.59.25.394
*** SESSION ID:(9.7) 1999.06.14.09.59.25.344
------------PL/SQL TRACE INFORMATION-------------
Levels set : 1
Trace: ANONYMOUS BLOCK: Stack depth = 1
Trace: PROCEDURE SCOTT.SHOWEMPS: Call to entry at line 5 Stack depth = 2
Trace: PACKAGE BODY SYS.DBMS_SQL: Call to entry at line 1 Stack depth = 3
Trace: PACKAGE BODY SYS.DBMS_SYS_SQL: Call to entry at line 1 Stack depth = 4
Trace: PACKAGE BODY SYS.DBMS_SYS_SQL: ICD vector index = 21 Stack depth = 4
Trace: PACKAGE PLVPRO.P: Call to entry at line 26 Stack depth = 3
Trace: PACKAGE PLVPRO.P: ICD vector index = 6 Stack depth = 3
Trace: PACKAGE BODY PLVPRO.P: Call to entry at line 1 Stack depth = 3
Trace: PACKAGE BODY PLVPRO.P: Call to entry at line 1 Stack depth = 3
Trace: PACKAGE BODY PLVPRO.P: Call to entry at line 1 Stack depth = 4
Отладка программ PL/SQL
Тестирование программы PL/SQL — это поиск ошибок в программном коде, а ее отладка — это определение и устранение причин, обусловивших их появление. Это два совершенно разных процесса, которые не следует путать. Протестировав программу и выявив ошибки, разработчик должен их исправить. С этого момента и начинается отладка.
Многие программисты считают отладку самой трудной частью программирования. Причины ее сложности часто заключаются в следующем:
- Недостаточное понимание задачи, решаемой программой. Большинство разработчиков предпочитают заниматься лишь написанием программного кода и не любят тратить время на то, чтобы разбираться в спецификации. Вероятность того, что написанная таким образом программа будет соответствовать требованиям, ничтожно мала.
- Плохой стиль программирования. Трудные для чтения программы (плохо документированные, содержащие слишком обширную документацию, плохо отформатированные, с неудачными именами переменных и т. п.), а также программы, неправильно разделенные на модули, отлаживать гораздо сложнее, чем хорошо спроектированный и структурированный код.
- Большое количество ошибок в программе. Если разработчик не имеет необходимых навыков анализа и программирования, скорее всего, его код будет содержать множество ошибок. Без четко определенного, пошагового метода исправления ошибок вы, скорее всего, не устоите под их напором.
- Слабые навыки отладки. Существует много разных подходов к выявлению ошибок. Некоторые из них только затрудняют работу, поэтому неумение правильно выбрать технологию отладки оборачивается лишними затратами времени, головной болью и недовольством начальства.
В следующих разделах рассматриваются методы отладки, которыми лучше не пользоваться, а также методы, способные значительно облегчить этот процесс и сделать его более эффективным.
Неправильные способы организации отладки в PL/SQL
Вероятно, при виде приведенных ниже описаний почти каждый читатель скажет себе: «Ну разумеется, это же очевидно. Конечно, так поступать нельзя. Я никогда такого не сделаю».
И все же в следующий раз, сев за работу, многие из вас запросто могут последовать этим, таким очевидно неправильным методам отладки.
Надеюсь, если вы хотя бы отчасти узнаете себя в этих описаниях, это поможет вам изменить свой подход к делу.
Хаотичная отладка
Столкнувшись с ошибкой, вы начинаете бурную деятельность по поиску причины ее возникновения. И хотя сам факт ошибки может свидетельствовать о том, что задача плохо проанализирована или что не найден наиболее удачный метод ее решения, вы не пытаетесь разобраться в программе. Вместо этого вы включаете в программу множество команд MESSAGE (в Oracle Forms), SRW.MESSAGE (в Oracle Reports) или DBMS_OUTPUT.PUT_LINE (в хранимых модулях) и надеетесь, что это поможет.
Причем вы даже не сохраняете копию программы перед внесением изменений, чтобы не тратить лишнее время. Вам, как обычно, некогда, поэтому вы уверены, что ответы на все вопросы появятся сами собой, после чего можно будет удалить отладочные команды.
В результате масса времени тратится на просмотр ненужной информации. Вы проверяете все подряд, хотя большинство используемых конструкций давно выверены и отлажены.
Вы пропускаете обед, чтобы не отвлекаться от работы, поглощаете кофе, пытаясь максимально сконцентрировать свое внимание. Даже не имея ни малейшего понятия о причине возникновения проблемы, вы думаете, что если попробовать то-то и то-то, это может помочь. Вы вносите изменения, тратите несколько минут на компиляцию, написание и исполнение теста — и убеждаетесь в бесплодности всех усилий. В результате появляются новые проблемы, поскольку вы не учли влияния вносимых изменений на другие части программы. В итоге вы возвращаете программу в исходное состояние и пытаетесь сделать что- нибудь еще. Ваш коллега, заметив, что у вас уже дрожат руки, предлагает свою помощь. Однако вы не знаете, как описать проблему, и у вас даже нет исходной версии, которую можно было бы показать, — программа превратилась в минное поле, сплошь усеянное командами трассировки. В итоге вы отвергаете помощь лучшего программиста в группе, звоните домой и сообщаете, что к ужину вы сегодня не придете.
Почему? Потому, что нужно исправить ошибку!
Иррациональная отладка
Вы сгенерировали отчет, а он оказался пустым. При этом вы уверены, что вашей вины здесь нет, хотя в течение последнего часа занимались тем, что вносили изменения в структуры данных и программный код для их запроса и форматирования.
Вы звоните в отдел внутренней поддержки и спрашиваете, нет ли проблем с сетью, хотя File Manager показывает, что все сетевые диски доступны. Потом вы интересуетесь, не девалась ли куда-нибудь база данных, хотя только что успешно к ней подключались, отнимаете 10 минут времени у специалиста из отдела поддержки и, ничего не добившись, в раздражении вешаете трубку.
«Они там ничего не понимают», — бормочете вы. Но как бы там ни было, источник проблемы придется искать самостоятельно. Вы углубляетесь в только что измененный код и проверяете каждую строку. Следующие два часа вы вслух разговариваете с самим собой: «А это что? Я вызвал хранимую процедуру в команде IF. Раньше я этого никогда не делал. Может, хранимые программы так вызывать нельзя?» Вы удаляете команду IF, заменяя ее командой GOTO, но это не решает проблему.
Поиски продолжаются: «Вроде бы код правильный. Но он вызывает программу, которую когда-то написал Джо». Джо уже давно уволился, поэтому, конечно же, виноват он: «Программа, наверное, уже не работает, тем более что мы обновили систему голосовой почты». Вы решаете протестировать программу Джо, которая не изменялась уже два года. Программа работает… только не в вашем коде.
Вы постепенно приходите в отчаяние. «Может, этот отчет должен выполняться только на выходных? А если разместить локальный модуль в анонимном блоке? И вроде я что-то слышал об ошибках в этой служебной программе. Надо поискать обходное решение.»
Вскоре вы начинаете понимать своего восьмилетнего сына, который бьет по монитору, когда не может пройти последний уровень в своей любимой компьютерной игре. И уже собравшись домой, вы вдруг осознаете, что подключены к базе данных, предназначенной для разработки и почти не содержащей никаких данных. Вы подключаетесь к другому экземпляру базы данных, запускаете отчет, и все оказывается в порядке.
За исключением того, что ваш отчет теперь содержит лишние команды GOTO и массу других добавленных конструкций…
Полезные советы и стратегии отладки
Эта статья не претендует на звание исчерпывающего руководства по отладке. Однако приведенные здесь советы и приемы помогут вам улучшить навыки исправления ошибок.
Пользуйтесь отладчиком исходного кода
Самый эффективный способ сокращения времени отладки кода — использование отладчика. Отладчик присутствует в практически любой интегрированной среде разработки приложений (IDE) PL/SQL. И если вы пользуетесь SQL Navigator или Toad от Quest, PL/SQL Developer от Allround Automations, Oracle SQL Developer или другим сходным инструментом с графическим интерфейсом, то сможете легко устанавливать в программах точки останова, выполнять код в пошаговом режиме, просматривать значения переменных и т. д.
Советы, приведенные в этом разделе, полезны независимо от того, пользуетесь ли вы отладчиком с графическим интерфейсом, но если вы отлаживаете программы старым дедовским методом (вставляя в программный код многочисленные вызовы DBMS_OUTPUT. PUT_LINE), эффективность вашей работы оставляет желать лучшего. (К сожалению, если ваш код развернут на площадке клиента, отладка с использованием графических средств не всегда возможна; в таких случаях приходится использовать различные средства протоколирования.)
собирайте информацию
Соберите как можно больше сведений о том, где, когда и при каких условиях произошла ошибка. Маловероятно, что, столкнувшись с этой ошибкой впервые, вы получите о ней все необходимые данные. И помните, что многие проблемы, которые на первый взгляд кажутся простыми, на самом деле могут потребовать тщательного тестирования и анализа. Так что не бросайтесь сразу же модифицировать код в уверенности, что вы понимаете, в чем здесь дело, а сначала выполните следующие действия:
- Запустите программу еще раз и посмотрите, воспроизводится ли ошибка. Если ошибка не повторяется, вам вряд ли удастся понять ее причины и исправить ее. Так что постарайтесь определить условия, при которых ошибка повторяется, — это даст вам много полезной информации.
- Ограничьте область тестирования и отладки программы — возможно, так вы значительно быстрее найдете ошибку. Недавно я отлаживал один из своих модулей Oracle Forms, у которого в одном из всплывающих окон происходила потеря данных. На первый взгляд закономерность выглядела так: «Если для нового вызова ввести только один запрос, этот запрос будет потерян». Если бы я остановил тестирование в этот момент, мне пришлось бы проанализировать весь код инициализации записи вызова и отработки логики insert. Вместо этого я опробовал разные варианты ввода данных и вскоре обнаружил, что данные теряются только при переходе к всплывающему окну от конкретного элемента. Тестовый сценарий значительно сузился, и обнаружить ошибку в логике стало совсем несложно.
- Проанализируйте обстоятельства, при которых ошибка не возникает. Выявление подобных ситуаций помогает сузить область поиска и осознать причину ошибки. Чем больше информации об ошибке вы соберете, тем легче будет найти и устранить причину ее возникновения. Поэтому не жалейте времени на дополнительное тестирование и анализ поведения программы.
Не теряйте здравый смысл
Символическая логика — хлеб насущный для программистов. Какой бы язык программирования вы ни использовали, все программы строятся по определенным логическим правилам. Язык PL/SQL имеет один синтаксис, язык C — другой. В них применяются разные ключевые слова и команды (хотя есть и общие — например IF, но их спецификации несколько различаются). И уж совсем иначе выглядит программа на языке LISP. Однако за всеми этими языками стоит логика, выражаемая с помощью тех или иных операторов. Именно логическая строгость и облегчает изучение новых языков программирования. Если вы в состоянии четко определить для себя задачу и выработать последовательность ее решения, особенности конкретного языка вторичны.
И все же программисты удивительным образом ухитряются обходить всякую логику и здравый смысл и выбирают самые иррациональные пути решения проблем. Как только что-то идет не так, мы начинаем принимать желаемое за действительное, подозревать и обвинять всех и все вокруг: коллег, компьютер, компилятор, текстовый редактор… кого угодно, только не себя.
Но помните, что не желая признать свой промах, вы отказываетесь от поиска путей решения проблемы. Компьютеры и компиляторы не отличаются интеллектом, но они быстры, надежны и последовательны. Все, что они умеют, — это следовать правилам, записанным в вашей программе. Так что, обнаружив ошибку в программном коде, примите ответственность за нее. Признайте, что именно вы сделали что-то не так — вы, а не компилятор PL/SQL, не Oracle Forms и не текстовый редактор.
Если вы начинаете ставить под сомнение базовые элементы или правила компилятора, которые всегда работали в прошлом, лучше отдохнуть от работы. А еще лучше — показать ваш код кому-нибудь другому. Просто удивительно, как сторонний взгляд порой помогает направить ваши аналитические способности на истинную причину проблемы.
Будьте рациональны и бесстрастны. Соглашайтесь с тем, что логично. Отвергайте то, что не имеет объяснения.
Анализ вместо поспешных действий
Итак, когда вы собрали всю необходимую информацию об ошибке, ее нужно проанализировать. У многих программистов анализ выглядит так: «Хм, наверное, причина в этом. Сейчас внесу изменения, перекомпилирую и посмотрю, что получится».
Чем плох подобный подход? Если вы ищете решение методом проб и ошибок, это означает, что:
- вы не уверены в том, действительно ли данное изменение способно решить проблему; имея такую уверенность, вы бы не «проверяли», а просто тестировали внесенное изменение;
- вы не проанализировали ошибку, чтобы найти причины ее появления; если бы вы имели представление о том, чем вызвана ошибка, то знали бы, как ее исправить; не зная причин, вы пытаетесь что-то наобум изменить и проанализировать результат; это в высшей степени порочная логика;
- даже если внесенное вами изменение устраняет ошибку, вы не знаете наверняка, не приняла ли она другую форму и не появится ли вновь (если вы не понимаете суть проблемы, ее внешнее исчезновение еще не означает, что она не появится снова); все, что можно сказать в данном случае, — это то, что при известных вам условиях данная проблема больше не проявляется.
Чтобы действительно избавиться от проблемы, ее нужно полностью проанализировать и определить ее источник. Только тогда будет найдено правильное и надежное решение. Отыскав потенциальное решение, очень внимательно проанализируйте программный код, не выполняя его. Попробуйте придумать разные сценарии для проверки своей гипотезы. И лишь обретя уверенность в том, что вы действительно поняли проблему и нашли ее решение, внесите изменения и протестируйте новую версию программы. Помните: нужно не пробовать, а исправлять и тестировать.
Проанализируйте ошибку, прежде чем тестировать решения. Если вы говорите себе: «А почему бы не попробовать так?» в надежде, что это решит проблему, вы лишь напрасно тратите время, а отладка проходит неэффективно.
Делайте перерывы и обращайтесь за помощью
В том, что касается решения проблем — будь то ошибка в программе или личный кризис, — самым слабым звеном часто оказывается сам решающий. При слишком сильном погружении в проблему трудно сохранить способность оценивать ее объективно.
Если вы чувствуете, что застряли и не продвигаетесь вперед, если все средства перепробованы, а решения все нет, примите радикальные меры:
- Сделайте перерыв.
- Обратитесь за помощью.
Если накопились усталость и психологическое напряжение, если вы потеряли цель и начали действовать нерационально, если вы уже много часов не отрываете взгляда от экрана, попробуйте отвлечься и немного передохнуть — возможно, решение появится само собой.
Мой упадок духа нередко напрямую связан с тем временем, которое я провожу в своем эргономичном кресле, положив руки на клавиатуру с подкладками для кистей и уставившись в монитор с пониженным излучением. Часто достаточно отойти от компьютера, чтобы голова прояснилась и в ней забрезжило готовое решение. Вы никогда не просыпались утром после очень трудного рабочего дня, когда внезапно неуловимый ответ приходит сам собой?
Возьмите себе за правило хотя бы один раз в час вставать из-за стола, чтобы немного прогуляться. Расслабьтесь и позвольте нейросетям вашего мозга установить новые соединения — и возможно, у вас появятся новые идеи. Окружающий мир продолжает существовать, даже когда ваши глаза прикованы к экрану. Взгляните, что происходит за окном. Всегда полезно помнить об этом — хотя бы для того, чтобы увидеть, какая погода за пределами вашего кокона с кондиционером.
Еще более эффективный путь — попросить кого-нибудь просмотреть ваш код. Взгляд со стороны порой творит чудеса. Можно часами сражаться с программой, а потом, рассказывая кому-нибудь о своих затруднениях, вдруг понять, в чем дело. Ошибка может быть очень простой: например, это может быть несоответствие имен, неверное предположение или неправильная логика оператора IF. Но даже если на вас не снизойдет озарение, причину ошибки поможет выявить свежий взгляд постороннего человека, который:
- не писал этот код и не имеет неверных предположений о том, как он должен работать;
- не зациклен на программе и вообще не беспокоится о том, будет она работать или нет. Кроме того, обращаясь за помощью к коллегам, вы демонстрируете им, что уважаете их мнение и квалификацию. Это помогает создать атмосферу доверия, взаимопомощи и сотрудничества, что в конечном счете повышает эффективность работы всей группы.
Изменяйте и тестируйте разные области кода по очереди
Один из главных недостатков хорошего программиста заключается в том, что он слишком уверен в своих способностях и поэтому пытается решать одним махом множество проблем. Внеся пять-десять изменений и запустив тест, мы получаем ненадежные и практически бесполезные результаты. Во-первых, некоторые изменения порождают новые проблемы (весьма распространенное явление и верный признак того, что программа требует дополнительной отладки и тестирования); во-вторых, исчезают не все исходные ошибки, и мы понятия не имеем, какие изменения способствовали устранению ошибок, а какие послужили причиной появления новых.
Короче говоря, вся работа по отладке лишь вносит путаницу, поэтому приходится вернуться к исходной точке и действовать более последовательно.
Если только вы не ограничиваетесь очень простыми изменениями, старайтесь решать проблемы по одной, а затем тестировать решения. Возможно, это увеличит затраты времени на компиляцию, генерирование и тестирование кода, но в долгосрочной перспективе ваша работа станет более производительной.
Другой аспект пошагового тестирования и отладки — проведение модульного тестирования отдельных модулей перед тестированием программы, вызывающей эти модули. Если вы тестируете свои программы по отдельности и определяете, что они работают, то при отладке приложения в целом (общесистемный тест) вам не придется беспокоиться о том, возвращают ли эти модули правильные значения и выполняют ли они правильные действия. Вместо этого можно сконцентрироваться на коде, который вызывает модули (за дополнительной информацией о модульном тестировании обращайтесь к этой статье.
Также будет полезно найти систему для хранения информации о ваших усилиях по диагностике ошибок. Дэн Кламадж, рецензент этой книги, сообщает, что он ведет простой текстовый файл с комментариями о его усилиях по воспроизведению проблемы и о том, что было сделано для ее исправления. Обычно в этот файл включается весь код SQL, написанный для анализа ситуации, конфигурационные данные для тестовых сценариев, список проанализированных модулей и все остальные данные, которые могут представлять интерес в будущем. С таким файлом намного проще вернуться к проблеме в будущем (например, когда вы отоспитесь и будете снова готовы к работе) и воспроизвести исходную цепочку рассуждений.
Вас заинтересует / Intresting for you:
Трейсы, дампы, сигналы
Список ошибок Oracle, включая номера событий (Oracle events) на Unix/Linux платформах можно найти в файле $ORACLE_HOME/rdbms/mesg/oraus.msg.
218105.1 Introduction to ORACLE Diagnostic EVENTS
Diagnostic Events in 10g and 11g [VIDEO] [ID 1402625.1]
How To List All The Named Events Set For A Database (Doc ID 436036.1) — Oracle Internal Events, both named event (eg: ERRORSTACK) as numeric events (eg 10046) can be set at the session level. This document outlines how DataBase Administrators can verify which events have been set in a specific session or in the entire system
Event Reference описание недостаточно документированных событий от Julian Dyke
Описание события Oracle 11g с использованием функции sqlerrm
SQL> set serveroutput on SQL> declare 2 v_errm VARCHAR2(256); 3 begin 4 v_errm := SUBSTR(SQLERRM(-10046),1,256); 5 DBMS_OUTPUT.PUT_LINE( v_errm); 6 end; 7 / ORA-10046: enable SQL statement timing SQL> -- или списком: SQL> set serveroutput on SQL> exec for event in 10000..10999 loop dbms_output.put_line( sqlerrm(-event) ); end loop;
sqlplus preliminary connection — соединение с бд без создания сессии/пользовательского процесса для ashdump, diagnostic dump, etc
Список событий, установленных для текущей сессии:
SQL> alter session set events '10053 trace name context forever, level 1';
Session altered.
SQL> alter session set events '10046 trace name context forever, level 4';
Session altered.
SQL> oradebug setmypid
Statement processed.
SQL> oradebug eventdump session -- показывает все события
sql_trace level=4
trace [RDBMS.SQL_OPTIMIZER]
trace [RDBMS.SQL_Transform]
trace [RDBMS.SQL_MVRW]
trace [RDBMS.SQL_VMerge]
trace [RDBMS.SQL_Virtual]
trace [RDBMS.SQL_APA]
trace [RDBMS.SQL_Costing]
trace [RDBMS.SQL_Parallel_Optimization]
trace [RDBMS.SQL_Plan_Management]
10721 trace name context forever, level 3
11.2@ SQL> set serveroutput on
11.2@SQL> declare
2 event_level number;
3 counter number;
4 begin
5 counter := 0;
6 for i in 10000 .. 10999 loop
7 sys.dbms_system.read_ev(i, event_level); -- начиная с Oracle 11g показывает только цифровые события, соответствующие кодам ORA-10NNN
8 if (event_level > 0) then
9 dbms_output.put_line('Event ' || to_char(i) || ' set at level ' || to_char(event_level));
10 counter := counter + 1;
11 end if;
12 end loop;
13 if (counter = 0) then
14 dbms_output.put_line('No events set for this session');
15 end if;
16 end;
17 /
Event 10721 set at level 3
PL/SQL procedure successfully completed.
Трейс выполнения запроса / SQL trace/ 10046 event
«стандартный» Oracle SQL Trace, в зависимости от уровня может включать значения связанных переменных (binds) и информацию по статистике событий ожиданий (waits). «Уровни трейса (EVENT) 10046:
1 — стандартный уровень SQL_TRACE (Default)
4 — уровень 1 + трейс значений связанных переменных (binds)
8 — уровень 1 + трейс событий ожидания (waits)…
12 = 4+8 уровень 1 + трейсы значений связанных переменных (binds) и событий ожидания (waits)«
начиная с Oracle 11 список базовых уровней дополнен статистикой плана выполнения plan_stat — Christian Antognini. Event 10046 – Full List of Levels
| Level | Description | sql_trace |
|---|---|---|
| 0 | The debugging event is disabled. | |
| 1 | The debugging event is enabled. For each processed database call, the following information is given: SQL statement, response time, service time, number of processed rows, number of logical reads, number of physical reads and writes, execution plan, and little additional information. Up to 10.2 an execution plan is written to the trace file only when the cursor it is associated with is closed. The execution statistics associated to it are values aggregated over all executions. As of 11.1 an execution plan is written to the trace file only after the first execution of every cursor. The execution statistics associated to it are the ones of the first execution only. |
waits=FALSE, binds=FALSE, plan_stat=’first_execution’ |
| 4 | As in level 1, with additional information about bind variables. Mainly, the data type, its precision, and the value used for each execution. | waits=FALSE, binds=TRUE, plan_stat=’first_execution’ |
| 8 | As in level 1, plus detailed information about wait time. For each wait experienced during the processing, the following information is given: the name of the wait event, the duration, and a few additional parameters identifying the resource that has been waited for. | waits=TRUE, binds=FALSE, plan_stat=’first_execution’ |
| 16 | As in level 1, plus the execution plans information is written to the trace file for each execution. Available as of 11.1 only. | waits=FALSE, binds=FALSE, plan_stat=’all_executions’ |
| 32 | As in level 1, but without the execution plans information. Available as of 11.1 only. | waits=FALSE, binds=FALSE, plan_stat=never’ |
| 64 | As in level 1, plus the execution plans information might be written for executions following the first one. The condition is that, since the last write of execution plans information, a particular cursor consumed at least one additional minute of DB time. This level is interesting in two cases. First, when the information about the first execution is not enough for analysing a specific issue. Second, when the overhead of writing the information about every execution (level 16) is too high. Generally available as of 11.2.0.2 only. | waits=FALSE, binds=FALSE, plan_stat=’adaptive’ — not available yet |
Включить/выключить стандартные трейс в текущей сессии
SQL> alter session set SQL_TRACE= TRUE|FALSE;
или с указанием уровня трейса
SQL> alter session set events '10046 trace name context forever , level 12'; SQL> alter session set events '10046 trace name context off';
Включить/выключить трейс в любой сессии, используя пакет DBMS_SUPPORT:
SQL> exec sys.dbms_support.start_trace_in_session( &sid, &serial, waits=>TRUE, binds=>TRUE ); SQL> exec sys.dbms_support.stop_trace_in_session( &sid, &serial );
То же с использованием утилиты ORADEBUG:
SQL> select s.sid, s.serial#, p.spid ospid, p.pid orapid, s.username, s.osuser 2 from v$session s, v$process p 3 where s.paddr = p.addr 4 / SID SERIAL# OSPID ORAPID USERNAME OSUSER ------- ---------- -------- --------- ----------- ------------
— определить/установить сессию по orapid
SQL> oradebug setorapid &orapid
или по ospid
SQL> oradebug setospid &ospid
включить / проверить состояние / выключить трейс:
SQL> oradebug event 10046 trace name context forever , level 12 Statement processed. SQL> oradebug eventdump session sql_trace level=12 SQL> oradebug event 10046 trace name context off
1058210.6 How to Enable SQL_TRACE for Another Session or in MTS Using Oradebug
Включить/выключить трейс на уровне системы:
SQL> alter system set events '10046 trace name context forever[, level L]'; SQL> alter system set events '10046 trace name context off';
или с использованием параметра системы:
event='10046 trace name context forever[, level 12]'
Выключить все события для всех инстансов бд:
SQL> ALTER SYSTEM RESET EVENT SCOPE=SPFILE SID='*' ;
160178.1 How to set EVENTS in the SPFILE
all possible methods for sql trace / 10046 trace setup [ID 1274511.1] — специалисты Oracle сами всё описывают
с Oracle 10.2 можно определить наличие и уровень SQL_TRACE для сессии по значениям SQL_TRACE, SQL_TRACE_WAITS, SQL_TRACE_BINDS в V$SESSION
с Oracle 10g можно включить SQL трейс на уровне SERVICE [ MODULE [ ACTION ] ], устанавливаемых пакетом DBMS_APPLICATION_INFO, с помощью DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE или по CLIENT_ID с помощью DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE:
11.@SQL> EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE( service_name => 'SERV'-
> , module_name => 'MOD' -
> , action_name => 'ACT' -
> , waits => FALSE -
> , binds => TRUE -
> , instance_name => 'ORCL'-
> , plan_stat => 'ALL_EXECUTIONS') /*'NEVER', 'FIRST_EXECUTION' (equivalent to NULL) or 'ALL_EXECUTIONS'*/
PL/SQL procedure successfully completed.
SQL> select * from DBA_ENABLED_TRACES;
TRACE_TYPE PRIMARY_ID QUALIFIER_ID1 QUALIFIER_ID2 WAITS BINDS PLAN_STATS INSTANCE_NAME
--------------------- ----------- -------------- -------------- ----- ----- ---------- -------------
SERVICE_MODULE_ACTION SERV MOD ACT FALSE TRUE ALL_EXEC ORCL
1 row selected.
SQL> select * from SYS.WRI$_TRACING_ENABLED;
TRACE_TYPE PRIMARY_ID QUALIFIER_ID1 QUALIFIER_ID2 INSTANCE_NAME FLAGS
---------- ----------- --------------- -------------- ------------- -----
5 SERV MOD ACT ORCL 20
SQL> EXECUTE DBMS_SESSION.SET_IDENTIFIER ('123');
PL/SQL procedure successfully completed.
SQL> SELECT sid FROM v$session WHERE client_identifier = '123';
SID
----------
7
SQL> EXECUTE dbms_monitor.client_id_trace_enable (client_id=>'123');
PL/SQL procedure successfully completed.
SQL> select * from DBA_ENABLED_TRACES; -- отражает оба типа трейсов
TRACE_TYPE PRIMARY_ID QUALIFIER_ID1 QUALIFIER_ID2 WAITS BINDS PLAN_STATS INSTANCE_NAME
--------------------- ----------- -------------- -------------- ----- ----- ---------- -------------
SERVICE_MODULE_ACTION SERV MOD ACT FALSE TRUE ALL_EXEC ORCL
CLIENT_ID 123 TRUE FALSE FIRST_EXEC
SQL> EXECUTE dbms_monitor.client_id_trace_disable (client_id=>'123');
PL/SQL procedure successfully completed.
SQL> EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE( service_name => 'SERV'-
> , module_name => 'MOD' -
> , action_name => 'ACT' -
> , instance_name => 'ORCL');
PL/SQL procedure successfully completed.
SQL> select * from DBA_ENABLED_TRACES;
no rows selected
Tracing Enhancements In 10g and 11g Using DBMS_MONITOR [ID 293661.1]
Интерпретация результатов трейса 10046:
39817.1 Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output — структура информации необработанного (raw) трейс файла
На примере трассировке с уровнем 12 (LEVEL 12 = binds + waits) операции вставки массива строк (array insert, реализуемый с использованием FORALL кляузы в PL/SQL или host arrays) Oracle сразу после записи о разборе (PARSING IN CURSOR) запишет в файл только первый набор значений связанных переменных (первый элемент вставляемого массива строк):
PARSING IN CURSOR #139988089003064 len=227 dep=0 uid=21 oct=2 lid=21 tim=1323439560100077 hv=1512394967 ad='1f578f9c0' sqlid='291quzjd2an6r'
INSERT INTO "MY_TABLE" ("EVENTTIME", "TRANTIME", "BLOCK_ID", ...) VALUES(TO_DATE(:p1, 'YYYY-MM-DD HH24:MI:SS'), TO_DATE(:p2, 'YYYY-MM-DD HH24:MI:SS'), :p3, ...)
END OF STMT
BINDS #139988089003064: -- bind-значения для курсора #139988089003064
Bind#0 --
oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00 -- св-ва переменной: тип данных [oac]dty; макс.длина mxl;...
oacflg=00 fl2=1000000 frm=01 csi=196 siz=96 off=0
kxsbbbfp=7f5184562ab8 bln=32 avl=19 flg=05 -- bind address [kxsbb]bfp; размер bind буфера bln; актуальный размер переменной avl;...
value="2011-12-09 17:29:03" -- значение
...
далее — типичные ожидания (в случае array insert основные дисковые чтения приходятся на блоки индексов):
... WAIT #139988089003064: nam='db file sequential read' ela= 13105 file#=197 block#=576548 blocks=1 obj#=8483163 tim=1323439560207461 ...
и, собственно, выполнение курсора:
... EXEC #139988089003064:c=245963,e=29695833,p=683,cr=265,cu=3207,mis=0,r=1000,dep=0,og=1,plh=0,tim=1323439589795819
| Brevis | Description |
|---|---|
| c | CPU time (9i+ microseconds) |
| e | Elapsed time (9i+ microseconds) |
| p | # of Physical reads |
| cr | # of buffers retrieved for CR reads — соответствует статистике consistent gets |
| cu | Number of buffers retrieved in current mode — соответствует статистике db block gets |
| mis | Cursor missed in library cache, если > 0 — при выполнении запроса поребовался разбор курсора — hard parse |
| r | # of rows processed — кол-во обработанных строк, в этом случае 1000 |
| dep | Recursive call depth (0 = user SQL, >0 = recursive) |
| og | Optimizer Goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose |
| tim | Timestamp (9i+ microseconds) — может быть использован для определения времени между операциями в трейс файле, к реальному времени можно привязать через обзор v$timer |
| plh | sql PLan Hash |
trcsess
штатная утилита консолидации нескольких трейс-файлов, например, при параллельном выполнении, на основе:
- Session ID
- Client ID
- Service name
- Action name
- Module name
trcsess output=<output_file_name> session=<session_id> clientid=<client_id> service=<service_name> action=<action_name> module=<module_name> <trace_files>
What is TRCSESS and How to use it ? [ID 280543.1]
В консолидированном файле записи сгруппированы по курсорам, но могут нарушать хронологический порядок
tkprof
32951.1 Tkprof Interpretation: стандартно поставляемая с Oracle утилита tkprof для обработки и анализа содержимого трейс файлов
Из обработанного tkprof трейса:
******************************************************************************** count = number of times OCI procedure was executed -- кол-во выполнений процедур PARSE, FETCH, EXEC,... cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk -- соответствует статистике physical reads query = number of buffers gotten for consistent read -- соответствует статистике consistent gets current = number of buffers gotten in current mode (usually for update) -- соответствует статистике db block gets rows = number of rows processed by the fetch or execute call -- количество полеченных (SELECT) или вставленных/обновлённых (INSERT/UPDATE) строк ********************************************************************************
Обработанный трейс Array insert из предыдущего примера выглядит так:
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 7 1.34 136.54 3816 1828 19538 6032 -- за 7 выполнений вставлено 6032 строк, при этом прочитано 1828(query)+19538(current)=21366 блоков бд, из них 3816 блоков - с диска Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 7 1.34 136.54 3816 1828 19538 6032 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 21 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 3816 0.49 130.10 -- 3816 одноблочных чтений с диска были выполнены за 130 секунд SQL*Net more data from client 24 0.00 0.00 log file switch completion 1 0.41 0.41 SQL*Net message to client 7 0.00 0.00 SQL*Net message from client 7 0.01 0.08 read by other session 2 0.07 0.09 latch: object queue header operation 2 0.00 0.00 latch: cache buffers chains 1 0.00 0.00 ********************************************************************************
По крайней мере, начиная с версии 11g, tkprof пишет статистику плана выполнения (row source statistics):
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 173
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
2628 2628 2628 SORT AGGREGATE (cr=9913 pr=1028 pw=0 time=7379389 us) -- 1028 Physical Reads; 7.379389 seconds
2628 2628 2628 TABLE ACCESS BY INDEX ROWID CUSTOMER_TRX_ALL (cr=9913 pr=1028 pw=0 time=7373736 us cost=5 size=13 card=1)
2628 2628 2628 INDEX RANGE SCAN CUSTOMER_TRX_IDX3 (cr=7847 pr=1028 pw=0 time=7359145 us cost=4 size=0 card=1)(object id 29159)
TRCANLZR
224270.1 TRCANLZR «…reads a raw SQL Trace generated by standard SQL Trace or by EVENT 10046 (Level 4, 8 or 12), and generates a comprehensive HTML report with performance related details: time summary, call summary (parse, execute, fetch), identification of top SQL, row source plan, explain plan, CBO statistics, wait events, values of bind variables, I/O summary per schema object, latches, hot blocks, etc.» . Инструмент реализован в виде схемы БД, считывает трейс файл 10046 и генертрует подробный отчёт в формате HTML. Во время обработки данные загружаются в global temporary table и доступны из SQL, например, для создания на основе активности сессии тестового повторного сценария (Oracle session activity Replay)
Использование DBMS_SQLTUNE.SELECT_SQL_TRACE
для доступа и анализа трейс-файла, начиная с 11.1.0.7, описано у Christian Antognini.Analyzing a SQL Trace File with SQL Statements
events sql_trace
Начиная с Oracle 11g появилась возможность устанавливать SQL trace на уровнях отдельных запросов, процессов — см.описание в блоге Miladin Modrakovich:
SQL> alter session/system set events 'sql_trace [sql:|] wait=true | false, bind=true | false, planstat=never | first_execution | all_executionss | level = 12';
SQL> alter session/system set events 'sql_trace {process : pid = , pname = , orapid = } ...';
SQL> alter system set events 'sql_trace {process: pname = p000 | p005}';
например для конкретного SQL_ID на уровне системы:
11.@SYS SQL> alter system set events 'sql_trace [sql:b9wj15rg7qhv1] level 12'; System altered. 11.@SYS SQL> oradebug setmypid Statement processed. 11.@SYS SQL> oradebug eventdump system sql_trace [sql:b9wj15rg7qhv1] level 12 11.@SYS SQL> alter system set events 'sql_trace [sql:b9wj15rg7qhv1] off'; System altered. 11.@SYS SQL> oradebug eventdump system Statement processed.
, более подробно в Tanel Poder: The full power of Oracle’s diagnostic events, part 2: ORADEBUG DOC and 11g improvements
SQL> alter session set events ‘sql_trace [sql: &sql_id] crash’; — особый вариант использования события, использовать только с одобрения поддержки Oracle
Трейс вызовов Oracle kernel functions на уровне ОС/Linux
Life of an Oracle I/O: tracing logical and physical I/O with systemtap
trace Oracle Wait Interface function calls from the OS
10053 event / 10132 event
Трассировка действий оптимизатора (Cost-Based Optimizer) по выбору плана выполнения запроса, включая используемые параметры, статистику объектов (изпользуемых таблиц и индексов), использование правил,…
SQL> alter session set events '10053 trace name context forever'; SQL> select count(*) from emp ...; SQL> alter session set events '10053 trace name context off';
Событие 10132 — облегчённый вариант предыдущего события(?), без математики
SQL> alter session set events '10132 trace name context forever, level 12'; SQL> select ... SQL> alter session set events '10053 trace name context off';
В конце трейсов в случае применения в запросе подсказок можно найти отчёт об использовании подсказок (used=0/1 — неиспользована/использована):
Dumping Hints ============= atom_hint=(@=0x7ff72a34fce8 err=6 resol=1 used=0 token=453 org=1 lvl=2 txt=FIRST_ROWS ) atom_hint=(@=0x7ff72a348b18 err=6 resol=1 used=0 token=454 org=1 lvl=2 txt=ALL_ROWS ) ********** WARNING: SOME HINTS HAVE ERRORS *********
Wolfgang Breitling A LOOK UNDER THE HOOD OF CBO: THE 10053 EVENT
CASE STUDY: Analyzing 10053 Trace Files [ID 338137.1]
Bug 16923858 Diagnostic enhancement to annotate 10053 trace with accumulated parse time
— fix control доступен, начиная с 12.1.0.2.160419 (Apr 2016) PSU
Timing is only written out to trace if CPU or Elapsed time exceed a threshold based on the value of the fix control.
This threshold is 10^N microseconds where N is the value of the fix control and can be between 0 and 7 with default 6.
Value 0 means disabled. The min (1) is 10 microseconds, the default (6) is 1 sec and the max (7) is 10 sec.
alter session set "_fix_control"='16923858:N';
Optimizer Trace
Greg Rahn «Creating Optimizer Trace Files» — начиная с Oracle 11g:
SQL> oradebug doc component SQL_Compiler
SQL_Compiler SQL Compiler
SQL_Parser SQL Parser (qcs)
SQL_Semantic SQL Semantic Analysis (kkm)
SQL_Optimizer SQL Optimizer
SQL_Transform SQL Transformation (kkq, vop, nso)
SQL_MVRW SQL Materialized View Rewrite
SQL_VMerge SQL View Merging (kkqvm)
SQL_Virtual SQL Virtual Column (qksvc, kkfi)
SQL_APA SQL Access Path Analysis (apa)
SQL_Costing SQL Cost-based Analysis (kko, kke)
SQL_Parallel_Optimization SQL Parallel Optimization (kkopq)
SQL_Code_Generator SQL Code Generator (qka, qkn, qke, kkfd, qkx)
SQL_Parallel_Compilation SQL Parallel Compilation (kkfd)
SQL_Expression_Analysis SQL Expression Analysis (qke)
SQL_Plan_Management SQL Plan Managment (kkopm)
MPGE MPGE (qksctx)
SQL> alter session set events 'trace [SQL_Compiler.*]';
SQL> select * from scott.emp where ename = 'SCOTT';
SQL> alter session set events 'trace [SQL_Compiler.*] off';
, формат версии 12c:
12.1.0.2.@ SQL> oradebug doc component SQL_Compiler
SQL_Compiler SQL Compiler ((null))
SQL_Parser SQL Parser (qcs)
SQL_Semantic SQL Semantic Analysis (kkm)
SQL_Optimizer SQL Optimizer ((null))
SQL_Transform SQL Transformation (kkq, vop, nso)
SQL_MVRW SQL Materialized View Rewrite ((null))
SQL_VMerge SQL View Merging (kkqvm)
SQL_Virtual SQL Virtual Column (qksvc, kkfi)
SQL_APA SQL Access Path Analysis (apa)
SQL_Costing SQL Cost-based Analysis (kko, kke)
SQL_Parallel_Optimization SQL Parallel Optimization (kkopq)
SQL_Plan_Management SQL Plan Managment (kkopm) -- moved from SQL_Code_Generator scope,
SQL_Plan_Directive SQL Plan Directive (qosd) -- and was complemented by SPD
SQL_Code_Generator SQL Code Generator (qka, qkn, qke, kkfd, qkx)
SQL_Parallel_Compilation SQL Parallel Compilation (kkfd)
SQL_Expression_Analysis SQL Expression Analysis (qke)
MPGE MPGE (qksctx)
ADS ADS (kkoads) -- added Automatis Dynamic Statistics / Sampling
Начиная с Oracle 11.2 можно получить трейс оптимизатора для запроса, находящегося в shared pool (v$sql), без повторного выполнения запроса:
begin dbms_sqldiag.dump_trace( p_sql_id=>'d9m84krtg4yg1', p_child_number => 2, p_component=>'Optimizer', --Valid values are "Optimizer" and "Compiler" p_file_id=>'My_CBO_Trace'); end;
При выполнениии процедуры dbms_sqldiag.dump_trace для формирования трейса будет выполнен повторный разбор запроса, в текст которого добавляется соответствующий комментарий:
sql=/* SQL Analyze(129,0) */ SELECT "A1"."C" FROM "TEST" "A1"
, т.е. указание в качестве параметра процедуры p_child_number не позволяет получать трейс формирования конкретного дочернего курсора — Параметр CHILD NUMBER в процедуре DBMS_SQLDIAG.DUMP_TRACE по крайней мере в 11.2
Для трассировки разбора определённого запроса по SQL_ID, например, вызываемого из PL/SQL, или изменяющего план выполнения под влиянием Cardinality Feedback или рекурсивного запроса при удалённом выполнении, удобно выставлять трейс таким образом — How do I capture a 10053 trace for a SQL statement called in a PL/SQL package:
11.2.0.2.@SQL> alter system set events 'trace [rdbms.SQL_Compiler.*][sql:dvhxps45r7j8s]'; System altered. -- Полезная работа SQL> alter system set events 'trace [rdbms.SQL_Compiler.*] off'; System altered.
*) начиная с Oracle 11.1.0.6 при установленном параметре trace_enabled=false файлы любых трейсов оптимизатора (вкл. 10053 event) могут не генерироваться — Bug 7304656: TRACE_ENABLED=FALSE DISABLES EVENT 10053 TRACE IN 11G, при этом файлы обычного SQL_TRACE (10046 event) генерируются без проблем
SQL> alter system set trace_enabled=true; System altered. SQL> connect scott/tiger -- для последующих соединений проблем нет Connected.
та же проблема в 11.2.0.*
SQL Plan Directive (SPD) trace
Кроме того, что использование SPD отражается в трейсах 10053 и DBMS_SQLDIAG.DUMP_TRACE(p_component=>’Optimizer’), в стеке Optimizer 12c появилось отдельное событие для трассировки на уровне сессии:
SQL> alter session set events 'trace [SQL_Plan_Directive.*]'; Session altered SQL> alter session set events 'trace [SQL_Plan_Directive.*] off';
, или на уровне системы, например, для конкретного SQL_ID:
SQL> alter system set events 'trace [RDBMS.SQL_Plan_Directive] [sql:fppuw3hpvww2d]'; System altered. SQL> oradebug eventdump system trace [RDBMS.SQL_PLAN_DIRECTIVE] [sql:fppuw3hpvww2d] SQL> alter system set events 'trace [RDBMS.SQL_Plan_Directive] [sql:fppuw3hpvww2d] off';
SPD статус EXISTS в трейсе имеет положительную окраску, остальные NOCTX, NODIR — негативную
SQL PLAN MANAGEMENT trace
SQL PLAN MANAGEMENT TRACING [ID 789520.1]
SQL> exec dbms_spm.configure('spm_tracing',1);
PL/SQL procedure successfully completed
SQL> select parameter_value from SYS.SMB$CONFIG where parameter_name = 'SPM_TRACING';
PARAMETER_VALUE
---------------
1
SQL> exec dbms_spm.configure('spm_tracing',0);
PL/SQL procedure successfully completed
SQL> select parameter_value from SYS.SMB$CONFIG where parameter_name = 'SPM_TRACING';
PARAMETER_VALUE
---------------
0
или на уровне сессии:
11.1.@ SQL> alter session set events 'trace [sql_planmanagement.*]'; 11.2.@ SQL> alter system set events 'trace [SQL_Plan_Management.*][sql:g1jratsw6ujcz]'; System altered. SQL> oradebug setmypid Statement processed. SQL> oradebug eventdump system trace [RDBMS.SQL_PLAN_MANAGEMENT] [sql:g1jratsw6ujcz] SQL> alter system set events 'trace [RDBMS.SQL_PLAN_MANAGEMENT] [sql:g1jratsw6ujcz] off'; System altered. SQL> oradebug eventdump system Statement processed.
cursortrace event
событие для анализа причин повторного неиспользования курсоров, упоминается в «296377.1 Handling and resolving unshared cursors/large version_counts«
Включить трейс
SQL> alter system set events 'immediate trace name cursortrace level 577, address &hash_value'; SQL> alter system set events 'immediate trace name cursortrace level 612, address &hashvalue';
Отключить
SQL> alter system set events 'immediate trace name cursortrace level 128, address &hashvalue';
&hashvalue — значение hash_value курсора из обзора v$sql — тесты события описаны в блоге Tanya Hardy — Cursortrace event
High Parse Time Elapsed And High Cursor : Pin S Wait On X Wait Event With Parallelism (Doc ID 1675659.1)
Example: select sql_id, hash_value from v$sql where sql_text LIKE 'insert /*+ NOAPPEND */ into SR_TMP%'; SQL_ID HASH_VALUE ------------- ---------- 9ykqjuv9zgb96 3556224294 alter session set events 'immediate trace name cursortrace level 612, address 3556224294'; < Run the sql statement> To turn it off: alter system set events 'immediate trace name cursortrace level 128, address 3556224294';
drop_segments event
SQL> alter session set events 'immediate trace name DROP_SEGMENTS level TS#+1';
Событие для удаления временных сегментов, которые по каким-либо причинам не были удалены SMON. На практике бывает необходимо для очистки временных сегментов, оставшихся от прерванной операции создания индекса, например. Наличие таких «неочищенных» SMON’ом сегментов затрудняет создание новых объектов в ТС.
61997.1 SMON — Temporary Segment Cleanup and Free Space Coalescing
47400.1 EVENT: DROP_SEGMENTS — Forcing cleanup of TEMPORARY segments
DESCRIPTION
Finds all the temporary segments in a tablespace which are not
currently locked and drops them.
For the purpose of this event a «temp» segment is defined as a
segment (seg$ entry) with TYPE#=3. Sort space in a TEMPORARY
tablespace does not qualify under this definition as such
space is managed independently of SEG$ entries.
Bug 4882834 — Excessive SS and TS contention in RAC (Doc ID 4882834.8)
The fix for this issue provides a method for the user to manually free
up temp space from local instance’s cache. Each invocation of the command
will free up a maximum of (100 extents, 0.1% of cached free space).
The syntax is
ALTER SESSION SET events ‘immediate trace name drop_segments level tablespace_number+1’;
…
The performance benefit of using temp tablespace comes from
caching the free space information in the SGA. It avoids making very
expensive disk allocations. By issuing the command, subsequent space
allocations will happen from the disk. So the command should only be used
when the cost of stealing space (and its performance impact on throughput)
significantly outweighs the cost of space allocation from disk.
10949 event
# "Disable autotune direct path read for full table scan" # // *Cause: # // *Action: Disable autotune direct path read for serial full table scan. # //
Начиная с Oracle 11g, позволяет отключить автоматический выбор механизма многоблочного чтения между [обычным] чтением данных через buffer cache SGA (ожидания db file scattered read) и чтением блоков через PGA — serial direct path read (ожидания direct path read), отключая direct path read:
SQL> alter session set events '10949 trace name context forever, level 1';
trace name treedump
Выводит внутреннюю структуру индекса по id объекта
SQL> alter session set events 'immediate trace name treedump level &object_id';
Jonathan Lewis blog: treedump
Richard Foote. Oracle B-Tree Index Internals: Rebuilding The Truth
10231 event
позволяет на уровне сессии пропускать битые блоки (corrupted blocks), выдающие ORA-01578, ORA-08103 при сканировании таблиц. Удобно для переноса уцелевших данных (в случае отсутствия бэкапа) — EVENT: 10231 «skip corrupted blocks on _table_scans_» [ID 21205.1]
SQL> ALTER SESSION SET EVENTS '10231 TRACE NAME CONTEXT FOREVER, LEVEL 10'; SQL> ALTER TABLE ... MOVE; $ oerr ORA 10231 10231, 00000, "skip corrupted blocks on _table_scans_" // *Cause: // *Action: such blocks are skipped in table scans, and listed in trace files
установить режим пропуска «плохих» блоков (skip corrupted blocks) на уровне объекта бд:
EXEC DBMS_REPAIR.SKIP_CORRUPT_BLOCKS ( SCHEMA_NAME => '&OWNER', OBJECT_NAME => '&TABLE_NAME', OBJECT_TYPE => dbms_repair.table_object, FLAGS => dbms_repair.SKIP_FLAG);
event 43905
трассировка Result Cache — Julian Dyke «Result Cache Internals»:
SQL> ALTER SESSION SET EVENTS '43905 trace name context forever, level 1';
$ oerr ora 43905 43905, 0000, "result cache tracing event" // *Document: NO // *Cause: This is an internal event. // *Action: N/A
heapdump / memory heaps dump
SQL> ALTER SESSION SET EVENTS 'immediate trace name heapdump level &level'; SQL> oradebug dump heapdump &level
Уровни для Oracle 10.2.0.1:
| Level | Description |
| 1 | PGA summary |
| 2 | SGA summary |
| 4 | UGA summary |
| 8 | Callheap (Current) |
| 16 | Callheap (User) |
| 32 | Large pool |
| 64 | Streams pool |
| 128 | Java pool |
| 1025 | PGA with contents |
| 2050 | SGA with contents |
| 4100 | UGA with contents |
| 8200 | Callheap with contents (Current) |
| 16400 | Callheap with contents (User) |
| 32800 | Large pool with contents |
| 65600 | Streams pool with contents |
| 131200 | Java pool with contents |
shared pool heap dump / X$KSMSP — Oracle 11g
heapdump_addr
Memory Subheap Dump
Troubleshooting and Diagnosing ORA-4031 Error [Video] (Doc ID 396940.1)
4031
SQL> alter system set events ‘4031 {occurence:end_after 1} heapdump(536870914) library_cache(74)’;
library_cache_object
— пример практического применения heapdump, heapdump_addr и library_cache_object от Stefan Koehler
library_cache dump
ALTER SESSION SET EVENTS ‘immediate trace name library_cache level &level’;
or
ORADEBUG DUMP LIBRARY_CACHE &level
Level is a bitmap:
1 statistics
2 hash table bucket statistics
4 library cache contents
8 library cache contents including dependencies
16 library cache contents including dependencies and children
32 heap contents
alter session set events ‘immediate trace name library_cache level 90’;—???
_px_trace
Трейс паралельного выполнения, как запускать и что и как нужно читать описано в Tracing Parallel Execution with _px_trace. Part I [ID 444164.1]:
SQL> alter session set «_px_trace»=[[Verbosity,]area],[[Verbosity,]area],..,[time];
примеры:
SQL> alter session set "_px_trace"=high,execution,medium,execution,time; SQL> alter session set "_px_trace"="compilation","execution","messaging"; SQL> alter session set "_px_trace"="high","execution","medium","buffer","time"; SQL> alter session set "_px_trace"="all";
параметры:
Verbosity:
high
medium
low
Area:
scheduling — ( equivalent to some of event 10384 and some of 10390)
execution — (equivalent to some of event 10390)
granule — (equivalent to some of event 10390 and some of 10391)
messaging — (equivalent to event 10392 and event 10393)
buffer — (equivalent to event 10399)
compilation — ( no equivalent event)
all — all of the above
none — none of the above.
Timing
time
events 10384
Предназначен для выполнения запроса с использованием параллельного плана выполнения в непараллельном (serial) режиме — одним процессом без использования PX slave процессов. Может быть полезен для получения консолидированной статистики / трейса выполнения запроса
Доступен, начиная с Oracle 10.2 — How to force that a Parallel Query runs in serial with the Parallel Execution Plan [ID 1114405.1]:
alter session set events '10384 trace name context forever , level 16384'; alter session set events '10384 trace name context off';
dbms_space_admin.segment_dump(&tablespace_name, &relative_fno, &header_block)
дамп блоков заголовка сегмента и bitmap-карты в USER_DUMP_DEST
dump of datafile block[s]
How to dump a block within ASM [ID 280636.1] — дамп блоков бд по имени файла, по 1 блоку:
SQL> alter system dump datafile 'C:ORADATAORCL112SYSTEM01.DBF' block 288; System altered. SQL> alter system dump datafile '+DATA/orcl112/datafile/idx.259.765724117' block 2971572; System altered.
по номерам файлов бд, и по диапазонам блоков:
SQL> alter system dump datafile 85 block min 1956115 block max 1956118; System altered.
Формат дампа листового блока индекса (index leaf block) — Richard Foote: Index Block Dump
dump of datafile headers
SQL> Alter Session Set Events 'immediate trace name file_hdrs level 10';
dump of logfile
header или содержимое redo log
How to Dump Redo Log File Information [ID 1031381.6]
Graham Thornton. Dissassembling the Oracle Redolog
dump of controlfile
MOS ID 269352.1
SQL> Alter Session Set Events 'immediate trace name controlf level 4';
events 1652
может быть полезно для трассировки условий возникновения ORA-1652: unable to extend temp segment by 16 in tablespace TEMP
How Can Temporary Segment Usage Be Monitored Over Time? [ID 364417.1]
Trace «ORA-01652: unable to extend temp segment»
SQL> alter system set events '1652 trace name errorstack level 3'; SQL> alter system set events '1652 trace name errorstack level 12'; System altered. SQL> alter system set events '1652 trace name errorstack off';
events 10704
информация о блокировках (locks/enqueues), используемых сессией, включая время ожидания
SQL> alter session set events '10704 trace name context forever, level 10'; $ oerr ora 10704 10704, 00000, "Print out information about what enqueues are being obtained" // *Cause: When enabled, prints out arguments to calls to ksqcmi and // ksqlrl and the return values. // *Action: Level indicates details: // Level: 1-4: print out basic info for ksqlrl, ksqcmi // 5-9: also print out stuff in callbacks: ksqlac, ksqlop // 10+: also print out time for each line
events 10104
детали выполнения операций HASH JOIN
$ oerr ora 10104 10104, 00000, "dump hash join statistics to trace file" SQL> ALTER SESSION SET EVENTS '10104 trace name context forever, level 1'; Session altered SQL> ALTER SESSION SET EVENTS '10104 trace name context off';
уровни 1-10, к более подробному
events 10730
трассировка предикатов, добавляемых политиками VPD | RLS | FGAC, в Tracing VPD Predicates описан для диагностики ошибок типа ORA-28113: policy predicate has error
$ oerr ora 10730 10730, 00000, "trace row level security policy predicates" // *Document: NO SQL> ALTER SESSION SET events '10730 trace name context forever, level 1'; Session altered.
в трейс-файле — описание RLS view, в который преобразуется запрос к таблице/синониму:
------------------------------------------------------------- Logon user : SCOTT Synonym : SCOTT.SOME_SYN_NAME Policy name : MY_SEC Policy function: SCOTT.MY_SECURITY RLS view : SELECT ... FROM "SCOTT"."SOME_SYN_NAME" WHERE (sec_id = sys_context(... -------------------------------------------------------------
How To Diagnose Error ORA-28112 (Doc ID 751850.1):
execute sys.dbms_system.set_ev(<sid>,<serial>,10046,4,''); execute sys.dbms_system.set_ev(<sid>,<serial>,10730,3,'');
10513 event
в редких случаях рекомендуется для временного отключения SMON transaction recovery — автоматического восстановления незавершённых транзакций:
SQL> select pid, program from v$process where program like '%SMON%'; PID PROGRAM ---- ----------------- 22 oracle@... (SMON) -- определение PID SQL> oradebug setorapid 22 Oracle pid: 22, Unix process pid: 21214, image: oracle@stbyins2...ru (SMON) SQL> oradebug eventdump session Statement processed. -- список events сессии пуст SQL> oradebug event 10513 trace name context forever, level 2; Statement processed.SQL> oradebug eventdump session 10513 trace name context forever, level 2 -- список events сессии
обязательное последующее включение:
SQL> oradebug event 10513 trace name context off Statement processed. SQL> oradebug eventdump session Statement processed.
Database Hangs Because SMON Is Taking 100% CPU Doing Transaction Recovery [ID 414242.1]
ORADEBUG утилита
ORADEBUG — UNDOCUMENTED ORACLE UTILITY — подробное описание некоторых возможностей от Miladin Modrakovic’а
_swrf_test_action
трассировка процессов MMON:
SQL> alter session set "_swrf_test_action" = 28;-- включение трейса Session altered. SQL> alter session set "_swrf_test_action" = 29;-- выключение
и snapshot flush trace (M00x процессов):
SQL> alter session set "_swrf_test_action" = 10;-- включение Session altered. SQL> alter session set "_swrf_test_action" = 11;-- выключение
Могут быть полезны, в частности, для выявления проблем с генерацией AWR снапшотов — Troubleshooting: AWR Snapshot Collection issues [ID 1301503.1]
ashdump
запись данных Active Session History системы (v$active_session_history) в файл
SQL> alter session set events 'immediate trace name ashdump level 10'; --or SQL> alter system set events 'immediate trace name ashdump level 10'; --or SQL> oradebug setmypid SQL> oradebug dump ashdump 10;
10 => кол-во минут истории для дампа
10g and above Active Session History (Ash) And Analysis Of Ash Online And Offline [ID 243132.1]
ashdump* scripts and post-load processing of MMNL traces (Doc ID 555303.1)
oradebug setmypid oradebug unlimit oradebug dump ashdumpseconds 30 oradebug tracefile_name
event 16000
event 604
Для поиска причин ORA-16000 ORA-604 на Read Only Standby / Active Data Guard db:
11.@SQL> alter system set events '604 trace name errorstack level 10'; SQL> alter system set events '16000 trace name errorstack level 3'; -- SQL> alter system set events '604 trace name errorstack off'; SQL> alter system set events '16000 trace name errorstack off';
PHYSICAL: ORA-604 ORA-16000 on Standby Opened Read Only [ID 730659.1]
event 10442
Событие для трассировки ORA-1555, принимается/рекомендуется MOS — SRDC — ORA-1555: Checklist of Evidence to Supply (Doc ID 1682708.1)
SQL> Alter system set events '10442 trace name context forever , level 10';
CURSORTRACE event
CURSORDUMP event
Трассировка информации о причинах повторного неиспользования курсоров
10G@ SQL> alter system set events 'immediate trace name cursortrace level 577, address hash_value'; -- v$sqlarea.hash_value 11.2@ SQL> alter system set events 'immediate trace name cursordump level 16';
Troubleshooting: High Version Count Issues [ID 296377.1]
alter session set events '1000 cursordump(1)'; -- диагностика ORA-01000
10237 event
Тестовое событие, позволяет прервать выполнение запроса в другой сессии
$ oerr ora 10237
10237, 00000, "simulate ^C (for testing purposes)"
SQL> exec dbms_system.set_ev(489, 21321, 10237, 1, '')
PL/SQL procedure successfully completed
SID#489@ SQL> select
...
529 /
ERROR at line 346:
ORA-01013: user requested cancel of current operation
Elapsed: 00:53:50.19
SID#489@ SQL> select
...
529 /
ERROR at line 1:
ORA-01013: user requested cancel of current operation
Elapsed: 00:00:00.03 -- повторное выполнение невозможно
SQL> exec dbms_system.set_ev(489, 21321, 10237, 0, '') -- отключение события для возобновления работы сессии SID 489
PL/SQL procedure successfully completed
How To Cancel A Query Running In Another Session
10157 event
событие, позволяющее блокировать использование операции INLIST ITERATOR с индексным доступом; в документах MOS рекомендуется устанавливать на уровне системы, ввиду нестабильности, см., например, Конкатенация против INLIST ITERATOR
10119 event
событие отключения NOSORT опции для операции SORT GROUP BY:
$ oerr ora 10119 10119, 00000, "QKA Disable GBY sort elimination"
пример использования на стандартной схеме SCOTT:
11.2.0.3.ORCL1123@SCOTT SQL> alter table EMP modify deptno not null 2 / Table altered. SQL> create index EMP_DEPTNO_IDX on EMP (DEPTNO) 2 / Index created. SQL> select * 2 from (select max(sal) as top_salary from emp group by deptno) 3 where rownum < 2 4 / ------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 13 | 2 (0)| 00:00:01 | |* 1 | COUNT STOPKEY | | | | | | | 2 | VIEW | | 1 | 13 | 2 (0)| 00:00:01 | | 3 | SORT GROUP BY NOSORT | | 1 | 7 | 2 (0)| 00:00:01 | | 4 | TABLE ACCESS BY INDEX ROWID| EMP | 14 | 98 | 2 (0)| 00:00:01 | | 5 | INDEX FULL SCAN | EMP_DEPTNO_IDX | 1 | | 1 (0)| 00:00:01 | ------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(ROWNUM<2) SQL> alter session set events '10119 trace name context forever' 2 / Session altered. SQL> select * 2 from (select max(sal) as top_salary from emp group by deptno) 3 where rownum < 2 4 / ------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 13 | 2 (0)| 00:00:01 | |* 1 | COUNT STOPKEY | | | | | | | 2 | VIEW | | 1 | 13 | 2 (0)| 00:00:01 | |* 3 | SORT GROUP BY STOPKEY | | 1 | 7 | 2 (0)| 00:00:01 | | 4 | TABLE ACCESS BY INDEX ROWID| EMP | 14 | 98 | 2 (0)| 00:00:01 | | 5 | INDEX FULL SCAN | EMP_DEPTNO_IDX | 1 | | 1 (0)| 00:00:01 | ------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(ROWNUM<2) 3 - filter(ROWNUM<2)
Alexander Anokhin. Dynamic tracing of Oracle logical I/O
10128 event
Трассировка Partition Pruning, впрочем, достаточно бесполезная
$ oerr ora 10128 10128, 00000, "Dump Partition Pruning Information" // *Cause: // *Action: set this event only under the supervision of Oracle development // // LEVEL ACTION //--------------------------------------------------------------------------- // 0x0001 dump pruning decriptor for each partitioned object // 0x0002 dump partition iterators // 0x0004 dump optimizer decisions about partition-wise join // 0x0008 dump rowid range scan pruning information
How to see Partition Pruning Occurred? (Doc ID 166118.1)
Partition pruning monitoring (по-русски)
10507 event
Трассировка Adaptive Sharing Context (функций kkocs*); отображается в обзорах V$SQL_CS_%
Bug 10182051 : EXTENDED CURSOR SHARING GENERATES 100S OF SHAREABLE CHILD CURSORS FOR A QUERY
SQL> alter system set events '10507 [sql:4zk2kr23pqa5k] level 1023'; System altered SQL> alter system set events '10507 [sql:4zk2kr23pqa5k] off';
10505 event
$ oerr ora 10505 10505, 00000, "CBO enable dynamic sampling dump to table"
Включает сохранение рез-тов Dynamic Sampling в требующих создания таблицах бд KKEDSAMP_TABLE, KKEDSAMP_COLUMN, KKEDSAMP_INDEX — Mikhail Velikikh. Event 10505:
-- general table and dynamic sampling stats create table kkedsamp_table( table_name varchar2(30), dyn_sampling_level number, c3 number, -- unknown c4 number, -- unknown c5 number, -- unknown c6 number, -- unknown c7 number, -- unknown single_table_dyn_sel_est number, dynamic_sampling_card number, sample_pct number, c11 number, -- unknown, partitioning c12 number, -- unknown, partitioning c13 number, -- unknown, partitioning c14 number, -- unknown actual_sample_size number, filtered_sample_card number, orig_card number, block_cnt_for_sampling_tabstat number, c19 number, max_sample_block_cnt number, sample_block_cnt number, min_sel_est number); -- column stats create table kkedsamp_column( column_name varchar2(30), table_name varchar2(30), c3 number, -- unknown num_distinct number, num_distinct_scaled number, num_nulls number, num_nulls_scaled number); -- index stats create table kkedsamp_index( index_name varchar2(30), table_name varchar2(30), c3 number, -- unknown index_selectity_est number, min_sel_est number, c6 number, -- unknown num_blocks number); SQL> alter session set events '10505'; Session altered. SQL> select /*+ dynamic_sampling(4)*/... SQL> alter session set events '10505 off'; Session altered. SQL> select * from kkedsamp_table; SQL> select * from kkedsamp_column; SQL> select * from kkedsamp_index;
10979 event
Трассировка matview refresh процедур — PCT Refresh Issues Delete Where it Should Issue Truncate (Doc ID 733673.1)
alter session set events '10046 trace name context forever, level 12';
alter session set events '10979 trace name context forever';
exec dbms_mview.refresh('"SCOTT"."EMP_SNAPSHOT2"', method => '?', atomic_refresh => false, out_of_place => TRUE)
select operation#, sql_txt from sys.snap_refop$ where sowner='&1' and vname='&2'
$ oerr ora 10979
942 event
Трассировка ORA-00942: table or view does not exist, пример Grants to retrieve SQL_MONITOR:
SQL> alter system set events '942 trace name errorstack level 3'; ... SQL> alter system set events '942 trace name errorstack off';
Трассировка PL/SQL
Классическая трассировка с помощью events 10928, 10938, 10940 и параметра _PLSQL_DUMP_BUFFER_EVENTS — PL/SQL Tracing Features Available with PL/SQL 2.3.4 in Oracle 7.3.4 (Doc ID 52481.1)
С использованием пакета DBMS_TRACE и таблицы PLSQL_TRACE_EVENTS (@?/rdbms/admin/tracetab.sql) — How to Use DBMS_TRACE (Doc ID 104239.1)
Пример в блоге Саяна Малакшинова
28131 event
$ oerr ora 28131 28131, 00000, "Fine Grained Access Control enforced" // *Document: NO
Fine Grained Access Control Feature Is Not Available In the Oracle Server Standard Edition (Doc ID 219911.1):
«RLS can be enabled in the Standard Edition of the Oracle Server with special
event codes in the initialization file…»
trace[nsmtio]
SQL> oradebug doc component
...
KXD Exadata specific Kernel modules (kxd)
...
NSMTIO Trace Non Smart I/O (nsmtio)
SQL> alter session set events 'trace[nsmtio]';
Session altered.
SQL> alter session set events 'trace[nsmtio] off';
кроме того, полезная диагностика причин неприменения direct path read для NON-EXADATA систем:
Frits Hoogland. The full table scan direct path read decision for version 12.2
sqlmon_dump
GV$SQL_MONITOR Queries and SQLMON Generation Very Slow after Upgrade to 19c (Doc ID 2792268.1):
«…flush the high number of sqlmon entries by doing this from the CDB$ROOT; it will clear all existing sql monitor entries.
alter system set events ‘immediate sqlmon_dump(level=23)’;«
sql_monitor event
«If however, the SQL statement cannot be added with /*+ MONITOR */ hint since it is coming from a third part application etc. you can still force monitoring to occur by setting the event «sql_monitor» with the SQL_ID for the statement you want to monitor at the system level.«
SQL> ALTER SYSTEM SET EVENTS 'sql_monitor [sql:5hc07qvt8v737] force=true'; To disable: SQL> ALTER SYSTEM SET EVENTS 'sql_monitor [sql:5hc07qvt8v737] off';
listener_registration | trace[LREG]
How to Trace Dynamic Registration from PMON or LREG (12c) (Doc ID 787055.1):
Describes how to capture tracing for the PMON or LREG process. It is intended to help troubleshoot issues where dynamic service registration is failing or where the LSNRCTL services summary is not displaying services properly. SOLUTION 11 to 18 option From 11.1.0.7 to 18.0, tracing can be enabled using the following command: alter system set events='immediate trace name listener_registration level 3'; When finished collecting pmon traces,turn this off using: alter system set events='immediate trace name listener_registration level 0'; 19 tracing option To turn on tracing alter system set events 'trace[LREG] disk highest'; alter system set events = 'immediate trace name LREG_STATE level 3'; To turn off the tracing alter system set events 'trace[LREG] disk disable'; Default location for the file is /home/app/oracle/diag/rdbms/<instance>/<instance>/trace/<instance> ls -l | grep -i lreg
modified_parameters
Трейс модифицированных параметров другой сессии — Die aktuellen Oracle NLS Settings einer SQL Session ermittlen:
SQL> oradebug SETOSPID 7521 Oracle pid: 19, Unix process pid: 7521, image: oracle@host SQL> oradebug dump modified_parameters 0; Statement processed. SQL> oradebug dump modified_parameters 1; Statement processed. *** 2018-02-10 13:02:05.139 Received ORADEBUG command (#8) 'dump modified_parameters 0' from process 'Unix process pid: 7474, image: <none>' DYNAMICALLY MODIFIED PARAMETERS: nls_language = AMERICAN nls_territory = RUSSIA nls_currency = USD plsql_optimize_level = 2 plscope_settings = identifiers:all optimizer_dynamic_sampling= 0 *** 2018-02-10 13:02:05.139 Finished processing ORADEBUG command (#8) 'dump modified_parameters 0' *** 2018-02-10 13:02:10.357 Received ORADEBUG command (#9) 'dump modified_parameters 1' from process 'Unix process pid: 7474, image: <none>' DYNAMICALLY MODIFIED PARAMETERS: nls_language = AMERICAN nls_territory = RUSSIA nls_currency = USD plsql_optimize_level = 2 plscope_settings = identifiers:all optimizer_dynamic_sampling= 0 *** 2018-02-10 13:02:10.357 Finished processing ORADEBUG command (#9) 'dump modified_parameters 1'
Как найти название трейс файла процесса Oracle?
Для собственной сессии:
SQL> oradebug setmypid Statement processed. SQL> oradebug tracefile_name c:oraclediagrdbmsorcl112orcl112traceorcl112_ora_2076.trc
Несколько способов для любого (включая системные) процесса — из блога Laurent Schneider
1)
SQL> select p.pid from v$session s, v$process p 2 where s.paddr = p.ADDR 3 and s.program like '%LGWR%' 4 / PID ---------- 11 SQL> oradebug setorapid 11 Oracle pid: 11, Windows thread id: 5760, image: ORACLE.EXE (LGWR) SQL> oradebug tracefile_name c:oraclediagrdbmsorcl112orcl112traceorcl112_lgwr_5760.trc
2)
SQL> SELECT LOWER(d.name)||'_ora_'||p.spid||DECODE(p.value,'','','_'||value) tracefile_name 2 FROM v$parameter p, v$database d, sys.v_$session s, sys.v_$process p 3 ,(SELECT sid FROM v$session WHERE program like '%LGWR%') m 4 WHERE p.name = 'tracefile_identifier' 5 AND s.paddr = p.addr 6 AND s.sid = m.sid 7 / TRACEFILE_NAME -------------------------------------------------------------------------------- orcl112_ora_5760
3) начиная с версии Oracle 11g для собственной сессии
SQL> select value from v$diag_info where name='Default Trace File' 2 / VALUE ------------------------------------------------------------------ c:oraclediagrdbmsorcl112orcl112traceorcl112_ora_2284.trc
4) с версии Oracle 11g для любого процесса
SQL> select tracefile from v$process where pid=11; TRACEFILE ---------------------------------------------------------------- c:oraclediagrdbmsorcl112orcl112traceorcl112_lgwr_5760.trc
5) начиная с версии Oracle 12.2 сформированные трейсы и содержимое можно смотреть через V$DIAG_TRACE_FILE и V$DIAG_TRACE_FILE_CONTENTS — «directly from the database»
System call, Call stack, Stack traces
Stefan Koehler. Identifying performance issues beyond the Oracle wait interface — Perf, DTrace, GDB, Oradebug, Systemtap, Flame graph, Strace
EVENT: HANGANALYZE — Reference Note (Doc ID 130874.1)
Summary Syntax:
~~~~~~~~~~~~~~
ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level LL';
EVENT="60 trace name HANGANALYZE level 5"
ORADEBUG hanganalyze LL
Note that in 11g+ the "ORADEBUG HANGANALYZE NN" form will also try to
include SHORT_STACK dumps in the hanganalyze chains for level 3 and
higher. Short stacks will NOT be included in event triggered
HANGANALYZE (like from ALTER SESSION) nor from "ORADEBUG DUMP HANGANALYZE nn".
only from ORADEBUG HANGANALYZE nn (no DUMP keyword).
Levels:
~~~~~~
The level determines which processes on the system are asked to dump
an errorstack. The main levels are:
10 Dump all processes (not a good idea)
6 Dump errorstacks of processes involved in wait chains (can be high overhead)
5 Dump all processes involved in wait chains (can be a lot)
4 Dump leaf nodes in wait chains
3 Dump only processes thought to be in a hang <<< Most common level
2 Minimal output
1 Very minimal output
trace any OERR
ERROR at line 4: ORA-12801: error signaled in parallel query server P00P, instance host:CDBORCL2 (2) ORA-03254: unable to execute the sql in read only database SCOTT@orcl2/CDBORCL2 SQL> alter session set events '3254 trace name errorstack level 3'; Session altered. SCOTT@orcl2/CDBORCL2 SQL> select ... $ less CDBORCL2_p00p_19798.trc ----- Call Stack Trace ----- ... ========== FRAME [17] (ktspgb_adg()+879 -> ksesecl0()) ========== defined by frame pointers 0x7ffc60213f00 and 0x7ffc60213c70 CALL TYPE: call ERROR SIGNALED: yes COMPONENT: Space ...
TBD
Overview
In troubleshooting tough recurring ORA-nnnn errors you can configure your database to provide detailed information using event signaling. To do this at the database level you need to create an errorstack EVENT parameter entry and bounce the database.
Once set, an alert log entry and corresponding detailed trace file will be generated for future ORA- errors matching the error number. The trace file is created in your udump directory.
This method of tracing, though exhaustively used by Oracle support, is not «officially» documented by Oracle. Furthermore, event types like 10046 and 10053 should not be used unless directed by Oracle support.
Trace Levels
1 - Enable standard SQL_TRACE functionality (default). 4 - Level 1 PLUS trace bind values. 8 - Level 1 PLUS trace waits. 12 - Level 1 PLUS both trace bind values and waits.
Enable/Disable
Assuming the error you want detailed tracing on is: ORA-2291
Enable
ALTER SYSTEM SET EVENT ='<ORAError> trace name errorstack level <LevelNumber>' SCOPE=spfile;
ALTER SYSTEM SET EVENT ='2291 trace name errorstack level 4' SCOPE=spfile;
Disable
ALTER SYSTEM SET EVENT='<ORAError> trace name errorstack off';
ALTER SYSTEM SET EVENT='2291 trace name errorstack off';
Display Events
SQLPlus> show parameter event NAME TYPE VALUE -------- ----------- ---------------------------------- event string 2291 trace name errorstack level 4
If above does not show events try this script:
declare
event_level number;
begin
for i in 10000..10999 loop
sys.dbms_system.read_ev (i, event_level);
if ( event_level > 0 ) then
dbms_output.put_line ('Event '||to_char(i)||' set at level '||to_char(event_level));
end if;
end loop;
end;
/
If the above script does not show your event, try this from SQLPlus:
oradebug setmypid oradebug eventdump system
DBA_ENABLED_TRACES or WRI$_TRACING_ENABLED can be used to see status also:
SELECT TRACE_TYPE, PRIMARY_ID, QUALIFIER_ID1, WAITS, BINDS FROM DBA_ENABLED_TRACES; TRACE_TYPE PRIMARY_ID QUALIFIER_ WAITS BINDS --------------------- ---------- ---------- ----- ----- SERVICE_MODULE_ACTION Service S Module M TRUE FALSE
Change Session
-- Turn On ALTER SYSTEM SET events '4022 trace name hanganalyze_global level 3;name systemstate_global level 258'; System altered. -- Check Status oradebug setmypid Statement processed. oradebug eventdump system 4022 trace name hanganalyze_global level 3;name systemstate_global level 258 -- Turn Off ALTER SYSTEM SET events '4022 trace name hanganalyze_global off;name systemstate_global off'; System altered. -- Check Status oradebug setmypid Statement processed. oradebug eventdump system Statement processed.
References:
- How to Collect Diagnostics for Database Hanging Issues (Doc ID 452358.1).
- SQL TRACE GENERATING TO TRACE FILES NEVER STOPS (Doc ID 556756.1).
- How To List All The Named Events Set For A Database (Doc ID 436036.1).
Этот пост навеян статьями Часть 1. Логирование событий в Oracle PL/SQL и Часть 2. Идентификация событий происходящих в Oracle PL/SQL. В первую очередь, как специалисту по performance tuning и troubleshooting, хотелось бы прокомментировать некоторые нюансы.
1. Уровни детализации логгирования
В показанной системе не хватает гибкости настройки логгирования: как уровня детализации, так и места, куда их выводить. Можно было позаимствовать функциональность из широко известных систем логгирования а-ля java.util.logging (SLF4j, log4j и его вариации для других языков/систем, и тд), гибкую настройку для какого кода с какого уровня сообщений и куда их сохранять. Например, в том же log4plsql можно настроить вывод и в alert.log, и в trace file (с помощью `dbms_system.ksdwrt()`)
2. Пользовательские ошибки и сообщения
Из самой внутренней системы ошибок Оракл можно было позаимствовать использование UTL_LMS.FORMAT_MESSAGE. Кстати, сами ошибки(и events) можно посмотреть с помощью sys.standard.sqlerrm(N):
SQL> select sys.standard.sqlerrm(-1476) errmsg from dual;
ERRMSG
-------------------------------------
ORA-01476: divisor is equal to zero
Примеры: err_by_code.sql, trace_events.sql
Кроме того, я, конечно, понимаю, что не все ошибки можно предусмотреть, но все-таки считаю, что их надо добавлять в exception handler после того как они уже были отловлены. Это будет полезно как минимум при последующих изменениях логики и будет проще видеть нестандартные или непредусмотренные ранее ситуации.
3. Что же делать в случае незалоггированных ошибок
Естественно, может случиться так, что существующая система логгирования не регистрирует какие-то неординарные ошибки, или даже ее совсем нет в базе. Тут могут быть полезны триггеры `after servererror on database/schema`. Простой минимальный пример.
К сожалению, для полноценного и срочного решения неординарных проблем, ни системы логгирования, ни таких триггеров, может быть недостаточно, и тут на помощь приходит вся мощь самой встроенной системы событий Oracle.
Например, недавно Nenad Noveljic расследовал проблему c «TNS-12599: TNS:cryptographic checksum mismatch» для чего ему нужно было получить callstack:
К счастью, помимо использованного у него в статье «ERRORSTACK», есть еще большой список «ACTIONS», включающий в себя и «CALLSTACK»:
В этой команде 12599 — это номер события(event), callstack — инструктирует сделать дамп call стека, level 2 — указывает вывести еще и аргументы функций, lifetime 1 — только один раз.
Более подробно об этом у Tanel Poder с примерами:
-
http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc
-
https://tanelpoder.com/2010/06/23/the-full-power-of-oracles-diagnostic-events-part-2-oradebug-doc-and-11g-improvements/
Мало того, как сам Танел и посоветовал, можно еще воспользоваться и «trace()» для форматированного вывода shortstack():
Так что этим же мы можем воспользоваться этим для вывода callstack:
alter system set events '12599 trace("stack is: %n", shortstack())';Или в более новом формате:
alter system set events 'kg_event[12599]{occurence: start_after 1, end_after 1} trace("stack is: %n", shortstack())';Как вы видите, здесь я еще добавил фильтр на количество срабатываний: после первого выполнения и только 1 раз.
Покажу на примере «ORA-01476: divisor is equal to zero»:
alter system set events 'kg_event[1476]{occurence: start_after 1, end_after 1} trace("stack is: %n", shortstack())';Здесь kg_event — это Kernel Generic event, 1476 — ORA-1476. После этого запускаем в своей сессии:
SQL> alter session set events 'kg_event[1476]{occurence: start_after 1, end_after 1} trace("stack is: %n", shortstack())';
Session altered.
SQL> select 1/0 x from dual;
select 1/0 x from dual
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
SQL> select 1/0 x from dual;
select 1/0 x from dual
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
SQL> select 1/0 x from dual;
select 1/0 x from dual
*
ERROR at line 1:
ORA-01476: divisor is equal to zero
И в трейсфайле получаем:
# cat ORA19_ora_12981.trc
Trace file /opt/oracle/diag/rdbms/ora19/ORA19/trace/ORA19_ora_12981.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.9.0.0.0
Build label: RDBMS_19.9.0.0.0DBRU_LINUX.X64_200930
ORACLE_HOME: /opt/oracle/product/19c/dbhome_1
System name: Linux
Node name: b7c493c7f9b0
Release: 3.10.0-1062.12.1.el7.x86_64
Version: #1 SMP Tue Feb 4 23:02:59 UTC 2020
Machine: x86_64
Instance name: ORA19
Redo thread mounted by this instance: 1
Oracle process number: 66
Unix process pid: 12981, image: oracle@b7c493c7f9b0
*** 2021-05-08T14:12:27.000816+00:00 (PDB1(3))
*** SESSION ID:(251.9249) 2021-05-08T14:12:27.000846+00:00
*** CLIENT ID:() 2021-05-08T14:12:27.000851+00:00
*** SERVICE NAME:(pdb1) 2021-05-08T14:12:27.000855+00:00
*** MODULE NAME:(sqlplus.exe) 2021-05-08T14:12:27.000859+00:00
*** ACTION NAME:() 2021-05-08T14:12:27.000862+00:00
*** CLIENT DRIVER:(SQL*PLUS) 2021-05-08T14:12:27.000865+00:00
*** CONTAINER ID:(3) 2021-05-08T14:12:27.000868+00:00
stack is: dbgePostErrorKGE<-dbkePostKGE_kgsf<-kgeade<-kgeselv<-kgesecl0<-evadiv<-kpofcr<-qerfiFetch<-opifch2<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main
Или, например, недавно я посоветовал использовать alter system set events 'trace[sql_mon.*] [SQL: ...] disk=high,memory=high,get_time=highres'; для выяснения причин, почему конкретный запрос не мониторится/сохраняется real-time SQL монитором (RTSM — Real Time SQL Monitor).
Получилось несколько сумбурно, в связи с недостатком времени, но на этом, пожалуй, закончу. Будут рад вопросам — задавайте, и я постараюсь их раскрыть отдельно.
What is Event Tracing ? Does it Really Help — Explained with an Example
Yes, This question always arises in every Oracle DBA’s mind. One more question also comes in the mind and that is..
Does Event Tracing in Oracle really helps ?
Recently, I face an “ORA-00942: table or view does not exist” which seems very tiny to me, but soon i realize that, this was not small problem, because this error was coming from the same query but intermittent, How is this possible, that same table exists once but not another time. I assume some other situations like this could be table partition issue, but all my assumption were not helping at all.
— Advertisement —
Finally, I decide to Trace an Event for “ORA-00942” message and then solve the issue, which was due to a bug in Oracle. What if, I had not traced the event, definitely i was not able to overcome this challenge. Yes, Event tracing really helps …
What is Event Tracing ?
I believe, every DBA has seen ORA-00600 trace file generates every time ORA-00600 or ORA-07445 occurs which has each and every detail about this error. Generating trace file for ORA-00600 or ORA-07445 is default behavior of oracle, but Same doesn’t happen in case of other errors.
To solve any ORA-00600 or ORA-07445, Database Administrator analyze it’s call stack and try to match with some bug and find either some workaround or patch to fix this.
So Event Tracing is basically to note down each and every step for execution of particular query from starting to up to when issue or error Reoccurs in a file, which can be analyzed for troubleshooting.
— Advertisement —
Let’s take an Example to understand Tracing an Event in Oracle:- In below example I am generating an “ORA-01422” error and will trace it to find out root cause for the error.
SQL> select * from dept;
DEPTNO DNAME LOC
———- ————– ————-
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 operation BOSTON
SQL> insert into dept values(31,'SALES','USA');
1 row created.
SQL> commit;
Commit complete.
SQL> create or replace procedure test_proc1 as
v_two varchar2(5);
begin
select DNAME into v_two from dept where DNAME = 'SALES';
end;
/
Procedure created.
SQL> exec test_proc;
BEGIN test_proc1; END;
*
ERROR at line 1:
ORA-01422: exact fetch returns more than requested number of rows
ORA-06512: at “SCOTT.TEST_PROC1”, line 8
ORA-06512: at line 1
This is a very small piece of code, What if this has been a code of thousands lines. It has been very difficult for Remote DBA to find out which sql query or table is generating this error message.
But DBA can easily find out culprit command or table by setting up tracing on “ORA-01422: exact fetch returns more than requested number of rows” (Error messages are called as events)
How to Trace an Event ?
For event tracing DBA has to use “alter system/session set event {event_id} trace name {action} {parameter}” command. Unix Find command is used to find event file generated at OS level. In below steps Database Administrator is tracing “ORA-01422: exact fetch returns more than requested number of rows” and locating trace file with Linux find command. DBA has to first set the event for tracing then Re execute the query generating the issue to catch the event.
SQL> connect sys as sysdba
Enter password:
Connected.
SQL> ALTER SYSTEM SET EVENTS '1422 TRACE NAME ERRORSTACK LEVEL 3';
System altered.
SQL> set linesize 1000
SQL> show parameter user_dump_dest
NAME TYPE VALUE
———————————— ——————————– ——————————
user_dump_dest string /etc/oracle/diag/rdbms/orcl/orcl/trace
SQL> connect scott
Enter password:
Connected.
SQL> exec test_proc1;
BEGIN test_proc; END;
*
ERROR at line 1:
ORA-01422: exact fetch returns more than requested number of rows
ORA-06512: at “SCOTT.TEST_PROC1”, line 8
ORA-06512: at line 1
[[email protected] ~]$ cd /etc/oracle/diag/rdbms/orcl/orcl/trace
[[email protected] trace]$ find . -type f -print | xargs grep -li “ORA-01422” ./alert_orcl.log ./orcl_ora_3982.trc
Here is message from Alert log and trace file generated from database, Alert log shows name of trace file as well.
Sat Jun 08 23:58:49 2020
OS Pid: 3295 executed alter system set events ‘1422 TRACE NAME ERRORSTACK LEVEL 3’
Sat Jun 08 23:59:02 2020
Errors in file /etc/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3982.trc:
ORA-01422: exact fetch returns more than requested number of rows
Sat Jun 08 23:59:11 2020
Dumping diagnostic data in directory=[cdmp_20130608235911], requested by (instance=1, osid=3982), summary=[abnormal process termination].
“alert_orcl.log” 3253L, 137636C
Trace file orcl_ora_3982.trc
Trace file /etc/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3982.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 – Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /etc/oracle/oracle
System name: Linux
Node name: database.test.com
Release: 2.6.18-194.el5
Version: #1 SMP Mon Mar 29 20:06:41 EDT 2020
Machine: i686
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 20
Unix process pid: 3982, image: [email protected] (TNS V1-V3)
** 2020-06-08 23:59:02.829
*** SESSION ID:(45.27) 2020-06-08 23:59:02.829
*** CLIENT ID:() 2020-06-08 23:59:02.829
*** SERVICE NAME:(SYS$USERS) 2020-06-08 23:59:02.829
*** MODULE NAME:(SQL*Plus) 2020-06-08 23:59:02.829
*** ACTION NAME:() 2020-06-08 23:59:02.829
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
—– Error Stack Dump —–
ORA-01422: exact fetch returns more than requested number of rows
— Current SQL Statement for this session (sql_id=9hts4bbxq1k14) —–
SELECT DNAME FROM DEPT WHERE DNAME = ‘SALES’
—- PL/SQL Stack —–
—– PL/SQL Call Stack —–
object line object
handle number name
0x3de13254 8 procedure SCOTT.TEST_PROC1
From the above trace file DBA can easily identify for “Current SQL Statement for this session” is “SELECT DNAME FROM DEPT WHERE DNAME = ‘SALES’” which is causing “ORA-01422: exact fetch returns more than requested number of rows” error message. Call stack is also available for this query is trace file, Database Administrator can also analyze call stack for other issues.
This is how tracing helps in Oracle troubleshooting. Now, let’s talk about detail of tracing parameters and diff-2 levels in event tracing.
Syntax for Tracing and Event =>
{EVENT_ID} TRACE NAME {ACTION} {PARAMETERS}
Examples:
alter SYSTEM set events ‘WHAT TO TRACE?‘ scope = spfile;
alter SESSION set events ‘WHAT TO TRACE?‘;
ALTER SYSTEM set events ‘904 trace name ERRORSTACK LEVEL 3’;
ALTER SESSION set events ‘10046 trace name CONTEXT FOREVER, LEVEL 12’;
In above two examples DBA is tracing “ORA-00904: invalid identifier” error and Enable standard SQL_TRACE functionality for sql queries. These are called as events.
Now, The most common Actions in tracing an event are:
ERRORSTACK – This action with produce session errorstack trace as well see in the above example, This is used for tracing errors in code etc.
SYSTEMSTATE – System state dump is taken in case of database hang situation.
CONTEXT – configure some behavior. I have not seen so much use of this.
Examples of Actions:
ALTER SYSTEM set events '904 trace name ERRORSTACK LEVEL 3';
This setting causes an ERRORSTACK dump when an ORA-904 occurs.
ALTER SYSTEM set events 'IMMEDIATE trace name SYSTEMSTATE LEVEL 266';
This setting causes a SYSTEMSTATE dump to occur when the command is issued.
ALTER SESSION set events '10046 trace name CONTEXT FOREVER, LEVEL 12';
This setting enables level 12 SQL Tracing.
Parameters for Event Tracing
Every action has it’s own parameters, which are given below:
ERRORSTACK Parameters:
0 – Error stack only
1 – Error stack and function call stack (if implemented)
2 – As 1 plus the ProcessState
3 – As 2 plus the context area (all cursors and current cursor highlighted)
DBA’s Usually prefer to use 3 as the parameter of tracing, Since it include all details.
SYSTEMSTATE parameters:
1 – Very basic process information only
10 – Most common level – includes state object trees for all processes. Includes “interesting” RAC resources in the trace (in RAC only).
11 – In RAC level 11 includes a dump of any resources not on the freelist just after the “BUSY GLOBAL CACHE ELEMENTS” section.
LEVEL + 256 – Adding 256 to the level will try to dump short stack info for eac
CONTEXT parameters:
CONTEXT only seems to have two parameters:
FOREVER – enables the event until disabled
OFF – disables the event
Enabling Tracing at different Levels:
Database Administrator can enable Event tracing at System or session level or both. Enabling tracing at system level or permanent needs a instance restart. DBA has to add scope=spfile at end of trace command like
ALTER SYSTEM set events '904 trace name errorstack level 3' SCOPE=SPFILE;
Enabling tracing at Session level will take effect immediately and this is default as well, DBA has not to give any scope parameter for this.
alter SYSTEM set events '1042 trace name errorstack level 3' SCOPE = MEMORY;
alter SESSION set events '1042 trace name errorstack level 1';
To set event at both Spfile and Memory use scope=both;
Once you have done with tracing don’t forget to disable it otherwise it will generate lot of files at user_dump_dest location and mount point will be full.
Disabling Event Tracing:
alter session set events '1555 trace name errorstack off';
ALTER SYSTEM SET EVENTS '1422 TRACE NAME ERRORSTACK off';
Tracing an Event helps me a lot to solve my day to day issue. Stay connected with our Expert DBA Team Club blog for gaining more Oracle DBA Tutorials. This blog is running by Dbametrix for providing latest database news and tutorials.
— Advertisement —
This is a little lesson in trouble-shooting. It assumes you have the privilege to generate and edit trace files, and all I’m going to do is show how I worked out the answer to a fairly simple question that appeared recently on the Oracle Developer Community forum in a thread with the title Cannot drop table after start dropping unused columns checkpoint.
I have a table t1 which is reasonably large (1M rows) with a column v30, and I’ve issued the command.
rem rem Script: drop_column.sql rem Author: Jonathan Lewis rem Dated: Jan 2003 rem alter table t1 set unused column v30;
After this I’ve issued another command, pressed return, and immediately hit ctrl-C – I’ve got a brief window for this interrupt as the command is going to generate roughly 230MB of redo. If you want to try the experiment it might take a couple of attempts to get the timing right.
alter table t1
drop unused columns
checkpoint 1000
/
{ctrl-C}
Then I’ve tried to drop the table with the following result:
drop table t1
*
ERROR at line 1:
ORA-00604: error occurred at recursive SQL level 1
ORA-12986: columns in partially dropped state. Submit ALTER TABLE DROP COLUMNS CONTINUE
This emulates the problem that appeared on the forum but the OP didn’t really want to issue the “continue” command because their table was “large” and the drop had been running for 24 hours when it was interrupted. It’s worth noting that four columns had been specified as unused, which means the drop command was probably generating roughly 1KB of redo per row. It’s also worth mentioning that the table was 600 columns wide – so there may have been a few performance side effects due to the multiple (minimum 3) row-pieces per row and row-chaining.
Ignoring any questions about the possible impact of having 600 columns, the key question in this case is:
- Why isn’t it possible to drop the table (the manuals suggest it should be possible at this point)
- Is there a way to bypass the problem?
This is a repeatable error – we can try to drop the table as many times as we like and we will get the same error reported in fractions of a second. so an obvious strategy is to enable tracing and see if the trace file can tell us anything about why the error is happening. This is a particularly sensible strategy to follow since error ORA-00604 is telling us that there’s something wrong in the recursive SQL, which means there’s a very good chance that we will actually find an SQL statement in the trace file that is the rescursive statement triggering the error.
So, enable sql_trace (or set event 10046), or do whatever you like to do to enable basic tracing (no need for anything above level 1 just yet); try to execute the drop; then search the trace file for the word ERROR at the start of a line (“^ERROR”). Here’s what I found as the first match in my trace file:
ERROR #139987889121800:err=12986 tim=424276176462
Note that the err= value is the 12986 that was reported as the error under the ORA-00604 error. Sometimes it’s necessary to search backwards in the trace file until you find the matching cursor number (#139987889121800), but in this case it was already visible just a few lines further up the file. So here’s the fragment of the file around that ERROR line:
PARSING IN CURSOR #139987889121800 len=72 dep=1 uid=0 oct=15 lid=0 tim=424276175961 hv=1894278903 ad='75c06e38' sqlid='4wv7gq1sfhtrr' ALTER TABLE "TEST_USER"."T1" RENAME TO "BIN$rhxBELdQGMXgUwEAAH93eQ==$0" END OF STMT PARSE #139987889121800:c=2896,e=3035,p=0,cr=4,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=424276175960 EXEC #139987889121800:c=186,e=185,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=0,tim=424276176418 ERROR #139987889121800:err=12986 tim=424276176462 CLOSE #139987889121800:c=10,e=9,dep=1,type=0,tim=424276176712 EXEC #139987891478792:c=34686,e=35859,p=0,cr=73,cu=12,mis=0,r=0,dep=0,og=1,plh=0,tim=424276176774 ERROR #139987891478792:err=604 tim=424276176808
The error has come from an SQL statement that is trying to rename my table to some wierd and wonderful name which starts with the characters “BIN$” – that’s a “drop” command trying to move a table into the recycle bin by renaming it – and you’re not allowed to rename a table that is in a partially dropped state. So that’s why we get the error; and the obvious way to bypass it is: “drop table t1 purge;” – which works.
You’ll notice that I’ve included a couple of lines after the first ERROR. This is to show you the line that generated the ORA-00604 (err=604) error. It comes from cursor #139987891478792, and seraching backwards up the file for that cursor number I get to:
PARSING IN CURSOR #139987891478792 len=13 dep=0 uid=107 oct=12 lid=107 tim=424276140765 hv=202649412 ad='7f517dd3fe00' sqlid='d47kdkn618bu4' drop table t1 END OF STMT
That’s not a suprise, of course, but it is important to cross-check that you haven’t been chasing the wrong error. There are some cases where the Oracle code does something to see if an error will occur but has an exception handler that means the error doesn’t end up reaching the application, so you do need to do a check that the error you found first was the one that floated up to the top of the stack.
Footnote
From Oracle 12.2.0.1 you could arrange to read your own trace file – while your session is connected – through the dynamic performance view v$diag_trace_file_contents.
Oracle provides several tracing tools that can help you monitor and analyze applications running against an Oracle database.
End to End Application Tracing can identify the source of an excessive workload, such as a high load SQL statement, by client identifier, service, module, or action. This isolates the problem to a specific user, service, or application component.
Oracle provides the trcsess command-line utility that consolidates tracing information based on specific criteria.
The SQL Trace facility and TKPROF are two basic performance diagnostic tools that can help you monitor applications running against the Oracle Server.
This chapter contains the following sections:
- End to End Application Tracing
- Using the trcsess Utility
- Understanding SQL Trace and TKPROF
- Using the SQL Trace Facility and TKPROF
- Avoiding Pitfalls in TKPROF Interpretation
- Sample TKPROF Output
End to End Application Tracing
End to End Application Tracing simplifies the process of diagnosing performance problems in a multitier environments. In multitier environments, a request from an end client is routed to different database sessions by the middle tier making it difficult to track a client across different database sessions. End to End Application Tracing uses a client identifier to uniquely trace a specific end-client through all tiers to the database server.
This feature could identify the source of an excessive workload, such as a high load SQL statement, and allow you to contact the specific user responsible. Also, a user having problems can contact you and then you can identify what that user’s session is doing at the database level.
End to End Application Tracing also simplifies management of application workloads by tracking specific modules and actions in a service.
Workload problems can be identified by End to End Application Tracing for:
- Client identifier — specifies an end user based on the logon Id, such as
HR.HR - Service — specifies a group of applications with common attributes, service level thresholds, and priorities; or a single application, such as
ACCTGfor an accounting application - Module — specifies a functional block, such as Accounts Receivable or General Ledger, of an application
- Action — specifies an action, such as an INSERT or UPDATE operation, in a module
After tracing information is written to files, the information can be consolidated by the trcsess utility and diagnosed with an analysis utility such as TKPROF.
To to create services on single instance Oracle databases, you can use the CREATE_SERVICE procedure in the DBMS_SERVICE package or set the SERVICE_NAMES initialization parameter.
The module and action names are set by the application developer. For example, you would use the SET_MODULE and SET_ACTION procedures in the DBMS_APPICATION_INFO package to set these values in a PL/SQL program.
- Oracle Database Concepts for information on services
- Oracle Call Interface Programmer’s Guide for information on setting the necessary parameters in an OCI application
- PL/SQL Packages and Types Reference for information on the
DBMS_MONITOR,DBMS_SERVICE, andDBMS_APPICATION_INFOpackages - Oracle Database Reference for information on V$ views and initialization parameters
Accessing the End to End Tracing with Oracle Enterprise Manager
The primary interface for End to End Application Tracing is the Oracle Enterprise Manager Database Control. To manage End to End Application Tracing through Oracle Enterprise Manager Database Control:
- On the Performance page, select the Top Consumers link under Additional Monitoring Links.
- Click the Top Services, Top Modules, Top Actions, Top Clients, or Top Sessions links to display the top consumers.
- On the individual Top Consumers pages, you can enable and disable statistics gathering and tracing for specific consumers.
Managing End to End Tracing with APIs and Views
While the primary interface for End to End Application Tracing is the Oracle Enterprise Manager Database Control, this feature can be managed with DBMS_MONITOR package APIs.
Enabling and Disabling Statistic Gathering for End to End Tracing
To gather the appropriate statistics using PL/SQL, you need to enable statistics gathering for client identifier, service, module, or action using procedures in the DBMS_MONITOR package.
You can gather statistics by:
- Client identifier
- Service name
- Combination of service, module, and action names
The default level is the session-level statistics gathering. Statistics gathering is global for the database and continues after an instance is restarted.
Statistic Gathering for Client Identifier
The procedure CLIENT_ID_STAT_ENABLE enables statistic gathering for a given client identifier. For example, to enable statistics gathering for a specific client identifier:
EXECUTE DBMS_MONITOR.CLIENT_ID_STAT_ENABLE(client_id => 'OE.OE');
In the example, OE.OE is the client identifier for which you want to collect statistics. You can view client identifiers in the CLIENT_IDENTIFIER column in V$SESSION.
The procedure CLIENT_ID_STAT_DISABLE disables statistic gathering for a given client identifier. For example:
EXECUTE DBMS_MONITOR.CLIENT_ID_STAT_DISABLE(client_id => 'OE.OE');
Statistic Gathering for Service, Module, and Action
The procedure SERV_MOD_ACT_STAT_ENABLE enables statistic gathering for a combination of service, module, and action. For example:
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE(service_name => 'ACCTG',
module_name => 'PAYROLL');
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE(service_name => 'ACCTG',
module_name => 'GLEDGER', action_name => 'INSERT ITEM');
If both of the previous commands are executed, statistics are gathered as follows:
- For the
ACCTGservice, because accumulation for each service name is the default - For all actions in the
PAYROLLmodule - For the
INSERTITEMaction within theGLEDGERmodule
The procedure SERV_MOD_ACT_STAT_DISABLE disables statistic gathering for a combination of service, module, and action. For example:
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_STAT_DISABLE(service_name => 'ACCTG',
module_name => 'GLEDGER', action_name => 'INSERT ITEM');
Viewing Gathered Statistics for End to End Application Tracing
The statistics that have been gathered can be displayed with a number of dynamic views.
- The accumulated global statistics for the currently enabled statistics can be displayed with the
DBA_ENABLED_AGGREGATIONSview. - The accumulated statistics for a specified client identifier can be displayed in the
V$CLIENT_STATSview. - The accumulated statistics for a specified service can be displayed in
V$SERVICE_STATSview. - The accumulated statistics for a combination of specified service, module, and action can be displayed in the
V$SERV_MOD_ACT_STATSview. - The accumulated statistics for elapsed time of database calls and for CPU use can be displayed in the
V$SVCMETRICview.
Enabling and Disabling for End to End Tracing
To enable tracing for client identifier, service, module, or action, you need to execute the appropriate procedures in the DBMS_MONITOR package. You can enable tracing for specific diagnosis and workload management by the following criteria:
- Client identifier for specific clients
- Combination of service name, module, and action name
- Session
With the criteria that you provide, specific trace information is captured in a set of trace files and combined into a single output trace file.
Tracing for Client Identifier
The CLIENT_ID_TRACE_ENABLE procedure enables tracing globally for the database for a given client identifier. For example:
EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(client_id => 'OE.OE',
waits => TRUE, binds => FALSE);
In this example, OE.OE is the client identifier for which SQL tracing is to be enabled. The TRUE argument specifies that wait information will be present in the trace. The FALSE argument specifies that bind information will not be present in the trace.
The CLIENT_ID_TRACE_DISABLE procedure disables tracing globally for the database for a given client identifier. To disable tracing, for the previous example:
EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_DISABLE(client_id => 'OE.OE');
Tracing for Service, Module, and Action
The SERV_MOD_ACT_TRACE_ENABLE procedure enables SQL tracing for a given combination of service name, module, and action globally for a database, unless an instance name is specified in the procedure.
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(service_name => 'ACCTG',
waits => TRUE, binds => FALSE, instance_name => 'inst1');
In this example, the service ACCTG is specified. The module or action name is not specified. The TRUE argument specifies that wait information will be present in the trace. The FALSE argument specifies that bind information will not be present in the trace. The inst1 instance is specified to enable tracing only for that instance.
To enable tracing for all actions for a given combination of service and module:
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(service_name => 'ACCTG',
module_name => 'PAYROLL', waits => TRUE, binds => FALSE,
instance_name => 'inst1');
The SERV_MOD_ACT_TRACE_DISABLE procedure disables the trace at all enabled instances for a given combination of service name, module, and action name globally. For example, the following disables tracing for the first example in this section:
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE(service_name => 'ACCTG',
instance_name => 'inst1');
This example disables tracing for the second example in this section:
EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE(service_name => 'ACCTG',
module_name => 'PAYROLL', instance_name => 'inst1');
Tracing for Session
The SESSION_TRACE_ENABLE procedure enables the trace for a given database session identifier (SID), on the local instance.
To enable tracing for a specific session ID and serial number, determine the values for the session that you want to trace:
SELECT SID, SERIAL#, USERNAME FROM V$SESSION;
SID SERIAL# USERNAME
---------- ---------- ------------------------------
27 60 OE
...
Use the appropriate values to enable tracing for a specific session:
EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => 27, serial_num => 60,
waits => TRUE, binds => FALSE);
The TRUE argument specifies that wait information will be present in the trace. The FALSE argument specifies that bind information will not be present in the trace.
The SESSION_TRACE_DISABLE procedure disables the trace for a given database session identifier (SID) and serial number. For example:
EXECUTE DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id => 27, serial_num => 60);
Viewing Enabled Traces for End to End Tracing
All outstanding traces can be displayed in an Oracle Enterprise Manager report or with the DBA_ENABLED_TRACES view. In the DBA_ENABLED_TRACES view, you can determine detailed information about how a trace was enabled, including the trace type. The trace type specifies whether the trace is enabled for client identifier, session, service, or a combination of service, module, and action.
Using the trcsess Utility
The trcsess utility consolidates trace output from selected trace files based on several criteria:
- Session Id
- Client Id
- Service name
- Action name
- Module name
After trcsess merges the trace information into a single output file, the output file could be processed by TKPROF.
trcsess is useful for consolidating the tracing of a particular session for performance or debugging purposes. Tracing a specific session is usually not a problem in the dedicated server model as a single dedicated process serves a session during its lifetime. All the trace information for the session can be seen from the trace file belonging to the dedicated server serving it. However, in a shared server configuration a user session is serviced by different processes from time to time. The trace pertaining to the user session is scattered across different trace files belonging to different processes. This makes it difficult to get a complete picture of the life cycle of a session.
Syntax for trcsess
The syntax for the trcsess utility is:
trcsess [output=output_file_name]
[session=session_id]
[clientid=client_id]
[service=service_name]
[action=action_name]
[module=module_name]
[trace_files]
where
outputspecifies the file where the output is generated. If this option is not specified, then standard output is used for the output.sessionconsolidates the trace information for the session specified. The session identifier is a combination of session index and session serial number, such as21.2371. You can locate these values in theV$SESSIONview.clientidconsolidates the trace information given client Id.serviceconsolidates the trace information for the given service name.actionconsolidates the trace information for the given action name.moduleconsolidates the trace information for the given module name.trace_filesis a list of all the trace file names, separated by spaces, in whichtrcsessshould look for trace information. The wild card character*can be used to specify the trace file names. If trace files are not specified, all the files in the current directory are taken as input totrcsess.
One of the session, clientid, service, action, or module options must be specified. If more then one of the session, clientid, service, action, or module options is specified, then the trace files which satisfies all the criteria specified are consolidated into the output file.
Sample Output of trcsess
This sample output of trcsess shows the consolidation of traces for a particular session. In this example the session index and serial number is equal to 21.2371.
trcsess can be invoked with various options. In the following case, all files in current directory are taken as input:
trcsess session=21.2371
In this case, several trace files are specified:
trcsess session=21.2371 main_12359.trc main_12995.trc
The sample output is similar to the following:
[PROCESS ID = 12359] *** 2002-04-02 09:48:28.376 PARSING IN CURSOR #1 len=17 dep=0 uid=27 oct=3 lid=27 tim=868373970961 hv=887450622 ad='22683fb4' select * from cat END OF STMT PARSE #1:c=0,e=339,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=868373970944 EXEC #1:c=0,e=221,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=868373971411 FETCH #1:c=0,e=791,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=4,tim=868373972435 FETCH #1:c=0,e=1486,p=0,cr=20,cu=0,mis=0,r=6,dep=0,og=4,tim=868373986238 *** 2002-04-02 10:03:58.058 XCTEND rlbk=0, rd_only=1 STAT #1 id=1 cnt=7 pid=0 pos=1 obj=0 op='FILTER ' STAT #1 id=2 cnt=7 pid=1 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ ' STAT #1 id=3 cnt=7 pid=2 pos=1 obj=37 op='INDEX RANGE SCAN I_OBJ2 ' STAT #1 id=4 cnt=0 pid=1 pos=2 obj=4 op='TABLE ACCESS CLUSTER TAB$J2 ' STAT #1 id=5 cnt=6 pid=4 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# ' [PROCESS ID=12995] *** 2002-04-02 10:04:32.738 Archiving is disabled Archiving is disabled
Understanding SQL Trace and TKPROF
The SQL Trace facility and TKPROF let you accurately assess the efficiency of the SQL statements an application runs. For best results, use these tools with EXPLAIN PLAN rather than using EXPLAIN PLAN alone.
Understanding the SQL Trace Facility
The SQL Trace facility provides performance information on individual SQL statements. It generates the following statistics for each statement:
- Parse, execute, and fetch counts
- CPU and elapsed times
- Physical reads and logical reads
- Number of rows processed
- Misses on the library cache
- Username under which each parse occurred
- Each commit and rollback
- Wait event data for each SQL statement, and a summary for each trace file
If the cursor for the SQL statement is closed, SQL Trace also provides row source information that includes:
- Row operations showing the actual execution plan of each SQL statement
- Number of rows, number of consistent reads, number of physical reads, number of physical writes, and time elapsed for each operation on a row
You can enable the SQL Trace facility for a session or for an instance. When the SQL Trace facility is enabled, performance statistics for all SQL statements executed in a user session or in the instance are placed into trace files.
Oracle provides the trcsess command-line utility that consolidates tracing information from several trace files based on specific criteria, such as session or client Id. See «Using the trcsess Utility».
The additional overhead of running the SQL Trace facility against an application with performance problems is normally insignificant compared with the inherent overhead caused by the application’s inefficiency.
Note:
Try to enable SQL Trace only for statistics collection and on specific sessions. If you must enable the facility on an entire production environment, then you can minimize performance impact with the following:
- Maintain at least 25% idle CPU capacity.
- Maintain adequate disk space for the
USER_DUMP_DESTlocation. - Stripe disk space over sufficient disks.
Understanding TKPROF
You can run the TKPROF program to format the contents of the trace file and place the output into a readable output file. TKPROF can also:
- Create a SQL script that stores the statistics in the database
- Determine the execution plans of SQL statements
Note:
If the cursor for a SQL statement is not closed,
TKPROFoutput does not automatically include the actual execution plan of the SQL statement. In this situation, you can use theEXPLAINoption withTKPROFto generate an execution plan.
TKPROF reports each statement executed with the resources it has consumed, the number of times it was called, and the number of rows which it processed. This information lets you easily locate those statements that are using the greatest resource. With experience or with baselines available, you can assess whether the resources used are reasonable given the work done.
Using the SQL Trace Facility and TKPROF
Follow these steps to use the SQL Trace facility and TKPROF:
- Set initialization parameters for trace file management.
See «Step 1: Setting Initialization Parameters for Trace File Management».
- Enable the SQL Trace facility for the desired session, and run the application. This step produces a trace file containing statistics for the SQL statements issued by the application.
See «Step 2: Enabling the SQL Trace Facility».
- Run
TKPROFto translate the trace file created in Step 2 into a readable output file. This step can optionally create a SQL script that can be used to store the statistics in a database.See «Step 3: Formatting Trace Files with TKPROF».
- Interpret the output file created in Step 3.
See «Step 4: Interpreting TKPROF Output».
- Optionally, run the SQL script produced in Step 3 to store the statistics in the database.
See «Step 5: Storing SQL Trace Facility Statistics».
In the following sections, each of these steps is discussed in depth.
Step 1: Setting Initialization Parameters for Trace File Management
When the SQL Trace facility is enabled for a session, Oracle generates a trace file containing statistics for traced SQL statements for that session. When the SQL Trace facility is enabled for an instance, Oracle creates a separate trace file for each process. Before enabling the SQL Trace facility:
- Check the settings of the
TIMED_STATISTICS,MAX_DUMP_FILE_SIZE, andUSER_DUMP_DESTinitialization parameters. See Table 20-1.
Table 20-1 Initialization Parameters to Check Before Enabling SQL Trace
Parameter Description TIMED_STATISTICSThis enables and disables the collection of timed statistics, such as CPU and elapsed times, by the SQL Trace facility, as well as the collection of various statistics in the dynamic performance tables. The default value of false disables timing. A value of true enables timing. Enabling timing causes extra timing calls for low-level operations. This is a dynamic parameter. It is also a session parameter.
MAX_DUMP_FILE_SIZEWhen the SQL Trace facility is enabled at the instance level, every call to the server produces a text line in a file in the operating system’s file format. The maximum size of these files (in operating system blocks) is limited by this initialization parameter. The default is 500. If you find that the trace output is truncated, then increase the value of this parameter before generating another trace file. This is a dynamic parameter. It is also a session parameter.
USER_DUMP_DESTThis must fully specify the destination for the trace file according to the conventions of the operating system. The default value is the default destination for system dumps on the operating system.This value can be modified with
ALTERSYSTEMSETUSER_DUMP_DEST=newdir. This is a dynamic parameter. It is also a session parameter.See Also:- «Interpreting Statistics» for considerations when setting the
STATISTICS_LEVEL,DB_CACHE_ADVICE,TIMED_STATISTICS, orTIMED_OS_STATISTICSinitialization parameters - «Setting the Level of Statistics Collection» for information about
STATISTICS_LEVELsettings - Oracle Database Reference for information on the
STATISTICS_LEVELinitialization parameter - Oracle Database Reference for information about the dynamic performance
V$STATISTICS_LEVELview
- «Interpreting Statistics» for considerations when setting the
- Devise a way of recognizing the resulting trace file.
Be sure you know how to distinguish the trace files by name. Oracle writes them to the user dump destination specified by
USER_DUMP_DEST. However, this directory can soon contain many hundreds of files, usually with generated names. It might be difficult to match trace files back to the session or process that created them. You can tag trace files by including in your programs a statement likeSELECT'program_name'FROMDUAL. You can then trace each file back to the process that created it.You can also set the
TRACEFILE_IDENTIFIERinitialization parameter to specify a custom identifier that becomes part of the trace file name. For example, you can addmy_trace_idto subsequent trace file names for easy identification with the following:ALTER SESSION SET TRACEFILE_IDENTIFIER = 'my_trace_id';
- If the operating system retains multiple versions of files, then be sure that the version limit is high enough to accommodate the number of trace files you expect the SQL Trace facility to generate.
- The generated trace files can be owned by an operating system user other than yourself. This user must make the trace files available to you before you can use
TKPROFto format them.See Also:- «Setting the Level of Statistics Collection» for information about
STATISTICS_LEVELsettings - Oracle Database Reference for information on the
STATISTICS_LEVELinitialization parameter
- «Setting the Level of Statistics Collection» for information about
Step 2: Enabling the SQL Trace Facility
Enable the SQL Trace facility for the session by using one of the following:
DBMS_SESSION.SET_SQL_TRACEprocedureALTER SESSION SET SQL_TRACE = TRUE;
Caution:
Because running the SQL Trace facility increases system overhead, enable it only when tuning SQL statements, and disable it when you are finished.
You might need to modify an application to contain the
ALTERSESSIONstatement. For example, to issue theALTERSESSIONstatement in Oracle Forms, invoke Oracle Forms using the-soption, or invoke Oracle Forms (Design) using thestatisticsoption. For more information on Oracle Forms, see the Oracle Forms Reference.
To disable the SQL Trace facility for the session, enter:
ALTER SESSION SET SQL_TRACE = FALSE;
The SQL Trace facility is automatically disabled for the session when the application disconnects from Oracle.
You can enable the SQL Trace facility for an instance by setting the value of the SQL_TRACE initialization parameter to TRUE in the initialization file.
SQL_TRACE = TRUE
After the instance has been restarted with the updated initialization parameter file, SQL Trace is enabled for the instance and statistics are collected for all sessions. If the SQL Trace facility has been enabled for the instance, you can disable it for the instance by setting the value of the SQL_TRACE parameter to FALSE.
Step 3: Formatting Trace Files with TKPROF
TKPROF accepts as input a trace file produced by the SQL Trace facility, and it produces a formatted output file. TKPROF can also be used to generate execution plans.
After the SQL Trace facility has generated a number of trace files, you can:
- Run
TKPROFon each individual trace file, producing a number of formatted output files, one for each session. - Concatenate the trace files, and then run
TKPROFon the result to produce a formatted output file for the entire instance. - Run the
trcsesscommand-line utility to consolidate tracing information from several trace files, then runTKPROFon the result. See «Using the trcsess Utility».
TKPROF does not report COMMITs and ROLLBACKs that are recorded in the trace file.
Sample TKPROF Output
Sample output from TKPROF is as follows:
SELECT * FROM emp, dept WHERE emp.deptno = dept.deptno; call count cpu elapsed disk query current rows ---- ------- ------- --------- -------- -------- ------- ------ Parse 1 0.16 0.29 3 13 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.03 0.26 2 2 4 14 Misses in library cache during parse: 1 Parsing user id: (8) SCOTT Rows Execution Plan ------- --------------------------------------------------- 14 MERGE JOIN 4 SORT JOIN 4 TABLE ACCESS (FULL) OF 'DEPT' 14 SORT JOIN 14 TABLE ACCESS (FULL) OF 'EMP'
For this statement, TKPROF output includes the following information:
- The text of the SQL statement
- The SQL Trace statistics in tabular form
- The number of library cache misses for the parsing and execution of the statement.
- The user initially parsing the statement.
- The execution plan generated by
EXPLAINPLAN.
TKPROF also provides a summary of user level statements and recursive SQL calls for the trace file.
Syntax of TKPROF
TKPROF is run from the operating system prompt. The syntax is:
tkprof filename1 filename2 [waits=yes|no] [sort=option] [print=n]
[aggregate=yes|no] [insert=filename3] [sys=yes|no] [table=schema.table]
[explain=user/password] [record=filename4] [width=n]
The input and output files are the only required arguments. If you invoke TKPROF without arguments, then online help is displayed. Use the arguments in Table 20-2 with TKPROF.
Table 20-2 TKPROF Arguments
| Argument | Description |
|---|---|
|
|
Specifies the input file, a trace file containing statistics produced by the SQL Trace facility. This file can be either a trace file produced for a single session, or a file produced by concatenating individual trace files from multiple sessions. |
|
|
Specifies the file to which |
|
|
Specifies whether to record summary for any wait events found in the trace file. Values are |
|
|
Sorts traced SQL statements in descending order of specified sort option before listing them into the output file. If more than one option is specified, then the output is sorted in descending order by the sum of the values specified in the sort options. If you omit this parameter, then TKPROF lists statements into the output file in order of first use. Sort options are listed as follows: |
|
|
Number of times parsed. |
|
|
CPU time spent parsing. |
|
|
Elapsed time spent parsing. |
|
|
Number of physical reads from disk during parse. |
|
|
Number of consistent mode block reads during parse. |
|
|
Number of current mode block reads during parse. |
|
|
Number of library cache misses during parse. |
|
|
Number of executes. |
|
|
CPU time spent executing. |
|
|
Elapsed time spent executing. |
|
|
Number of physical reads from disk during execute. |
|
|
Number of consistent mode block reads during execute. |
|
|
Number of current mode block reads during execute. |
|
|
Number of rows processed during execute. |
|
|
Number of library cache misses during execute. |
|
|
Number of fetches. |
|
|
CPU time spent fetching. |
|
|
Elapsed time spent fetching. |
|
|
Number of physical reads from disk during fetch. |
|
|
Number of consistent mode block reads during fetch. |
|
|
Number of current mode block reads during fetch. |
|
|
Number of rows fetched. |
|
|
Userid of user that parsed the cursor. |
|
|
Lists only the first integer sorted SQL statements from the output file. If you omit this parameter, then |
|
|
If you specify |
|
|
Creates a SQL script that stores the trace file statistics in the database. |
|
|
Enables and disables the listing of SQL statements issued by the user |
|
|
Specifies the schema and name of the table into which The specified user must be able to issue This option allows multiple individuals to run If you use the If no plan table exists, |
|
|
Determines the execution plan for each SQL statement in the trace file and writes these execution plans to the output file. |
|
|
Creates a SQL script with the specified |
|
|
An integer that controls the output line width of some TKPROF output, such as the explain plan. This parameter is useful for post-processing of TKPROF output. |
Examples of TKPROF Statement
This section provides two brief examples of TKPROF usage. For an complete example of TKPROF output, see «Sample TKPROF Output».
TKPROF Example 1
If you are processing a large trace file using a combination of SORT parameters and the PRINT parameter, then you can produce a TKPROF output file containing only the highest resource-intensive statements. For example, the following statement prints the 10 statements in the trace file that have generated the most physical I/O:
TKPROF ora53269.trc ora53269.prf SORT = (PRSDSK, EXEDSK, FCHDSK) PRINT = 10
TKPROF Example 2
This example runs TKPROF, accepts a trace file named dlsun12_jane_fg_sqlplus_007.trc, and writes a formatted output file named outputa.prf:
TKPROF dlsun12_jane_fg_sqlplus_007.trc OUTPUTA.PRF EXPLAIN=scott/tiger TABLE=scott.temp_plan_table_a INSERT=STOREA.SQL SYS=NO SORT=(EXECPU,FCHCPU)
This example is likely to be longer than a single line on the screen, and you might need to use continuation characters, depending on the operating system.
Note the other parameters in this example:
- The
EXPLAINvalue causesTKPROFto connect as the userscottand use theEXPLAINPLANstatement to generate the execution plan for each traced SQL statement. You can use this to get access paths and row source counts.
Note:
If the cursor for a SQL statement is not closed, TKPROF output does not automatically include the actual execution plan of the SQL statement. In this situation, you can use the
EXPLAINoption withTKPROFto generate an execution plan.
- The
TABLEvalue causesTKPROFto use the tabletemp_plan_table_ain the schemascottas a temporary plan table. - The
INSERTvalue causesTKPROFto generate a SQL script namedSTOREA.SQLthat stores statistics for all traced SQL statements in the database. - The
SYSparameter with the value ofNOcausesTKPROFto omit recursive SQL statements from the output file. In this way, you can ignore internal Oracle statements such as temporary table operations. - The
SORTvalue causesTKPROFto sort the SQL statements in order of the sum of the CPU time spent executing and the CPU time spent fetching rows before writing them to the output file. For greatest efficiency, always useSORTparameters.
Step 4: Interpreting TKPROF Output
This section provides pointers for interpreting TKPROF output.
- Tabular Statistics in TKPROF
- Row Source Operations
- Wait Event Information
- Interpreting the Resolution of Statistics
- Understanding Recursive Calls
- Library Cache Misses in TKPROF
- Statement Truncation in SQL Trace
- Identification of User Issuing the SQL Statement in TKPROF
- Execution Plan in TKPROF
- Deciding Which Statements to Tune
While TKPROF provides a very useful analysis, the most accurate measure of efficiency is the actual performance of the application in question. At the end of the TKPROF output is a summary of the work done in the database engine by the process during the period that the trace was running.
Tabular Statistics in TKPROF
TKPROF lists the statistics for a SQL statement returned by the SQL Trace facility in rows and columns. Each row corresponds to one of three steps of SQL statement processing. Statistics are identified by the value of the CALL column. See Table 20-3.
Table 20-3 CALL Column Values
| CALL Value | Meaning |
|---|---|
|
|
Translates the SQL statement into an execution plan, including checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects. |
|
|
Actual execution of the statement by Oracle. For |
|
|
Retrieves rows returned by a query. Fetches are only performed for |
The other columns of the SQL Trace facility output are combined statistics for all parses, all executes, and all fetches of a statement. The sum of query and current is the total number of buffers accessed, also called Logical I/Os (LIOs). See Table 20-4.
Table 20-4 SQL Trace Statistics for Parses, Executes, and Fetches.
| SQL Trace Statistic | Meaning |
|---|---|
|
|
Number of times a statement was parsed, executed, or fetched. |
|
|
Total CPU time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if |
|
|
Total elapsed time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if |
|
|
Total number of data blocks physically read from the datafiles on disk for all parse, execute, or fetch calls. |
|
|
Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls. Usually, buffers are retrieved in consistent mode for queries. |
|
|
Total number of buffers retrieved in current mode. Buffers are retrieved in current mode for statements such as |
Statistics about the processed rows appear in the ROWS column. See Table 20-5.
Table 20-5 SQL Trace Statistics for the ROWS Column
| SQL Trace Statistic | Meaning |
|---|---|
|
|
Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement. |
For SELECT statements, the number of rows returned appears for the fetch step. For UPDATE, DELETE, and INSERT statements, the number of rows processed appears for the execute step.
Note:
The row source counts are displayed when a cursor is closed. In SQL*Plus, there is only one user cursor, so each statement executed causes the previous cursor to be closed; therefore, the row source counts are displayed. PL/SQL has its own cursor handling and does not close child cursors when the parent cursor is closed. Exiting (or reconnecting) causes the counts to be displayed.
Row Source Operations
Row source operations provide the number of rows processed for each operation executed on the rows and additional row source information, such as physical reads and writes. The following is a sample:
Rows Row Source Operation
------- ---------------------------------------------------
0 DELETE (cr=43141 r=266947 w=25854 time=60235565 us)
28144 HASH JOIN ANTI (cr=43057 r=262332 w=25854 time=48830056 us)
51427 TABLE ACCESS FULL STATS$SQLTEXT (cr=3465 r=3463 w=0 time=865083 us)
647529 INDEX FAST FULL SCAN STATS$SQL_SUMMARY_PK
(cr=39592 r=39325 w=0 time=10522877 us) (object id 7409)
In this sample TKPROF output, note the following under the Row Source Operation column:
crspecifies consistent reads performed by the row sourcerspecifies physical reads performed by the row sourcewspecifies physical writes performed by the row sourcetimespecifies time in microseconds
Wait Event Information
If wait event information exists, the TKPROF output includes a section similar to the following:
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 8084 0.12 5.34 direct path write 834 0.00 0.00 direct path write temp 834 0.00 0.05 db file parallel read 8 1.53 5.51 db file scattered read 4180 0.07 1.45 direct path read 7082 0.00 0.05 direct path read temp 7082 0.00 0.44 rdbms ipc reply 20 0.00 0.01 SQL*Net message to client 1 0.00 0.00 SQL*Net message from client 1 0.00 0.00
In addition, wait events are summed for the entire trace file at the end of the file.
To ensure that wait events information is written to the trace file for the session, run the following SQL statement:
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
Interpreting the Resolution of Statistics
Timing statistics have a resolution of one hundredth of a second; therefore, any operation on a cursor that takes a hundredth of a second or less might not be timed accurately. Keep this in mind when interpreting statistics. In particular, be careful when interpreting the results from simple queries that execute very quickly.
Understanding Recursive Calls
Sometimes, in order to execute a SQL statement issued by a user, Oracle must issue additional statements. Such statements are called recursive calls or recursive SQL statements. For example, if you insert a row into a table that does not have enough space to hold that row, then Oracle makes recursive calls to allocate the space dynamically. Recursive calls are also generated when data dictionary information is not available in the data dictionary cache and must be retrieved from disk.
If recursive calls occur while the SQL Trace facility is enabled, then TKPROF produces statistics for the recursive SQL statements and marks them clearly as recursive SQL statements in the output file. You can suppress the listing of Oracle internal recursive calls (for example, space management) in the output file by setting the SYS command-line parameter to NO. The statistics for a recursive SQL statement are included in the listing for that statement, not in the listing for the SQL statement that caused the recursive call. So, when you are calculating the total resources required to process a SQL statement, consider the statistics for that statement as well as those for recursive calls caused by that statement.
Note:
Recursive SQL statistics are not included for SQL-level operations. However, recursive SQL statistics are included for operations done under the SQL level, such as triggers. For more information, see «Avoiding the Trigger Trap».
Library Cache Misses in TKPROF
TKPROF also lists the number of library cache misses resulting from parse and execute steps for each SQL statement. These statistics appear on separate lines following the tabular statistics. If the statement resulted in no library cache misses, then TKPROF does not list the statistic. In «Sample TKPROF Output», the statement resulted in one library cache miss for the parse step and no misses for the execute step.
Statement Truncation in SQL Trace
The following SQL statements are truncated to 25 characters in the SQL Trace file:
SET ROLE GRANT ALTER USER ALTER ROLE CREATE USER CREATE ROLE
Identification of User Issuing the SQL Statement in TKPROF
TKPROF also lists the user ID of the user issuing each SQL statement. If the SQL Trace input file contained statistics from multiple users and the statement was issued by more than one user, then TKPROF lists the ID of the last user to parse the statement. The user ID of all database users appears in the data dictionary in the column ALL_USERS.USER_ID.
Execution Plan in TKPROF
If you specify the EXPLAIN parameter on the TKPROF statement line, then TKPROF uses the EXPLAIN PLAN statement to generate the execution plan of each SQL statement traced. TKPROF also displays the number of rows processed by each step of the execution plan.
Note:
Trace files generated immediately after instance startup contain data that reflects the activity of the startup process. In particular, they reflect a disproportionate amount of I/O activity as caches in the system global area (SGA) are filled. For the purposes of tuning, ignore such trace files.
Deciding Which Statements to Tune
You need to find which SQL statements use the most CPU or disk resource. If the TIMED_STATISTICS parameter is on, then you can find high CPU activity in the CPU column. If TIMED_STATISTICS is not on, then check the QUERY and CURRENT columns.
With the exception of locking problems and inefficient PL/SQL loops, neither the CPU time nor the elapsed time is necessary to find problem statements. The key is the number of block visits, both query (that is, subject to read consistency) and current (that is, not subject to read consistency). Segment headers and blocks that are going to be updated are acquired in current mode, but all query and subquery processing requests the data in query mode. These are precisely the same measures as the instance statistics CONSISTENT GETS and DB BLOCK GETS. You can find high disk activity in the disk column.
The following listing shows TKPROF output for one SQL statement as it appears in the output file:
SELECT * FROM emp, dept WHERE emp.deptno = dept.deptno; call count cpu elapsed disk query current rows ---- ------- ------- --------- -------- -------- ------- ------ Parse 11 0.08 0.18 0 0 0 0 Execute 11 0.23 0.66 0 3 6 0 Fetch 35 6.70 6.83 100 12326 2 824 ------------------------------------------------------------------ total 57 7.01 7.67 100 12329 8 826 Misses in library cache during parse: 0
If it is acceptable to have 7.01 CPU seconds and to retrieve 824 rows, then you need not look any further at this trace output. In fact, a major use of TKPROF reports in a tuning exercise is to eliminate processes from the detailed tuning phase.
You can also see that 10 unnecessary parse call were made (because there were 11 parse calls for this one statement) and that array fetch operations were performed. You know this because more rows were fetched than there were fetches performed. A large gap between CPU and elapsed timings indicates Physical I/Os (PIOs).
Step 5: Storing SQL Trace Facility Statistics
You might want to keep a history of the statistics generated by the SQL Trace facility for an application, and compare them over time. TKPROF can generate a SQL script that creates a table and inserts rows of statistics into it. This script contains:
- A
CREATETABLEstatement that creates an output table namedTKPROF_TABLE. INSERTstatements that add rows of statistics, one for each traced SQL statement, to theTKPROF_TABLE.
After running TKPROF, you can run this script to store the statistics in the database.
Generating the TKPROF Output SQL Script
When you run TKPROF, use the INSERT parameter to specify the name of the generated SQL script. If you omit this parameter, then TKPROF does not generate a script.
Editing the TKPROF Output SQL Script
After TKPROF has created the SQL script, you might want to edit the script before running it. If you have already created an output table for previously collected statistics and you want to add new statistics to this table, then remove the CREATE TABLE statement from the script. The script then inserts the new rows into the existing table.
If you have created multiple output tables, perhaps to store statistics from different databases in different tables, then edit the CREATE TABLE and INSERT statements to change the name of the output table.
Querying the Output Table
The following CREATE TABLE statement creates the TKPROF_TABLE:
CREATE TABLE TKPROF_TABLE ( DATE_OF_INSERT DATE, CURSOR_NUM NUMBER, DEPTH NUMBER, USER_ID NUMBER, PARSE_CNT NUMBER, PARSE_CPU NUMBER, PARSE_ELAP NUMBER, PARSE_DISK NUMBER, PARSE_QUERY NUMBER, PARSE_CURRENT NUMBER, PARSE_MISS NUMBER, EXE_COUNT NUMBER, EXE_CPU NUMBER, EXE_ELAP NUMBER, EXE_DISK NUMBER, EXE_QUERY NUMBER, EXE_CURRENT NUMBER, EXE_MISS NUMBER, EXE_ROWS NUMBER, FETCH_COUNT NUMBER, FETCH_CPU NUMBER, FETCH_ELAP NUMBER, FETCH_DISK NUMBER, FETCH_QUERY NUMBER, FETCH_CURRENT NUMBER, FETCH_ROWS NUMBER, CLOCK_TICKS NUMBER, SQL_STATEMENT LONG);
Most output table columns correspond directly to the statistics that appear in the formatted output file. For example, the PARSE_CNT column value corresponds to the count statistic for the parse step in the output file.
The columns in Table 20-6 help you identify a row of statistics.
Table 20-6 TKPROF_TABLE Columns for Identifying a Row of Statistics
| Column | Description |
|---|---|
|
|
This is the SQL statement for which the SQL Trace facility collected the row of statistics. Because this column has datatype |
|
|
This is the date and time when the row was inserted into the table. This value is not exactly the same as the time the statistics were collected by the SQL Trace facility. |
|
|
This indicates the level of recursion at which the SQL statement was issued. For example, a value of 0 indicates that a user issued the statement. A value of 1 indicates that Oracle generated the statement as a recursive call to process a statement with a value of 0 (a statement issued by a user). A value of n indicates that Oracle generated the statement as a recursive call to process a statement with a value of n-1. |
|
|
This identifies the user issuing the statement. This value also appears in the formatted output file. |
|
|
Oracle uses this column value to keep track of the cursor to which each SQL statement was assigned. |
The output table does not store the statement’s execution plan. The following query returns the statistics from the output table. These statistics correspond to the formatted output shown in the section «Sample TKPROF Output».
SELECT * FROM TKPROF_TABLE;
Oracle responds with something similar to:
DATE_OF_INSERT CURSOR_NUM DEPTH USER_ID PARSE_CNT PARSE_CPU PARSE_ELAP
-------------- ---------- ----- ------- --------- --------- ----------
21-DEC-1998 1 0 8 1 16 22
PARSE_DISK PARSE_QUERY PARSE_CURRENT PARSE_MISS EXE_COUNT EXE_CPU
---------- ----------- ------------- ---------- --------- -------
3 11 0 1 1 0
EXE_ELAP EXE_DISK EXE_QUERY EXE_CURRENT EXE_MISS EXE_ROWS FETCH_COUNT
-------- -------- --------- ----------- -------- -------- -----------
0 0 0 0 0 0 1
FETCH_CPU FETCH_ELAP FETCH_DISK FETCH_QUERY FETCH_CURRENT FETCH_ROWS
--------- ---------- ---------- ----------- ------------- ----------
2 20 2 2 4 10
SQL_STATEMENT
---------------------------------------------------------------------
SELECT * FROM EMP, DEPT WHERE EMP.DEPTNO = DEPT.DEPTNO
Avoiding Pitfalls in TKPROF Interpretation
This section describes some fine points of TKPROF interpretation:
- Avoiding the Argument Trap
- Avoiding the Read Consistency Trap
- Avoiding the Schema Trap
- Avoiding the Time Trap
- Avoiding the Trigger Trap
Avoiding the Argument Trap
If you are not aware of the values being bound at run time, then it is possible to fall into the argument trap. EXPLAIN PLAN cannot determine the type of a bind variable from the text of SQL statements, and it always assumes that the type is varchar. If the bind variable is actually a number or a date, then TKPROF can cause implicit data conversions, which can cause inefficient plans to be executed. To avoid this, experiment with different datatypes in the query.
To avoid this problem, perform the conversion yourself.
Avoiding the Read Consistency Trap
The next example illustrates the read consistency trap. Without knowing that an uncommitted transaction had made a series of updates to the NAME column, it is very difficult to see why so many block visits would be incurred.
Cases like this are not normally repeatable: if the process were run again, it is unlikely that another transaction would interact with it in the same way.
SELECT name_id FROM cq_names WHERE name = 'FLOOR'; call count cpu elapsed disk query current rows ---- ----- --- ------- ---- ----- ------- ---- Parse 1 0.10 0.18 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.11 0.21 2 101 0 1 Misses in library cache during parse: 1 Parsing user id: 01 (USER1) Rows Execution Plan ---- --------- ---- 0 SELECT STATEMENT 1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES' 2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON_UNIQUE)
Avoiding the Schema Trap
This example shows an extreme (and thus easily detected) example of the schema trap. At first, it is difficult to see why such an apparently straightforward indexed query needs to look at so many database blocks, or why it should access any blocks at all in current mode.
SELECT name_id
FROM cq_names
WHERE name = 'FLOOR';
call count cpu elapsed disk query current rows
-------- ------- -------- --------- ------- ------ ------- ----
Parse 1 0.06 0.10 0 0 0 0
Execute 1 0.02 0.02 0 0 0 0
Fetch 1 0.23 0.30 31 31 3 1
Misses in library cache during parse: 0
Parsing user id: 02 (USER2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT
2340 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
0 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)
Two statistics suggest that the query might have been executed with a full table scan. These statistics are the current mode block visits, plus the number of rows originating from the Table Access row source in the execution plan. The explanation is that the required index was built after the trace file had been produced, but before TKPROF had been run.
Generating a new trace file gives the following data:
SELECT name_id
FROM cq_names
WHERE name = 'FLOOR';
call count cpu elapsed disk query current rows
----- ------ ------ -------- ----- ------ ------- -----
Parse 1 0.01 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 1
Misses in library cache during parse: 0
Parsing user id: 02 (USER2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT
1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)
One of the marked features of this correct version is that the parse call took 10 milliseconds of CPU time and 20 milliseconds of elapsed time, but the query apparently took no time at all to execute and perform the fetch. These anomalies arise because the clock tick of 10 milliseconds is too long relative to the time taken to execute and fetch the data. In such cases, it is important to get lots of executions of the statements, so that you have statistically valid numbers.
Avoiding the Time Trap
Sometimes, as in the following example, you might wonder why a particular query has taken so long.
UPDATE cq_names SET ATTRIBUTES = lower(ATTRIBUTES)
WHERE ATTRIBUTES = :att
call count cpu elapsed disk query current rows
-------- ------- -------- --------- -------- -------- ------- ----------
Parse 1 0.06 0.24 0 0 0 0
Execute 1 0.62 19.62 22 526 12 7
Fetch 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
Parsing user id: 02 (USER2)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT
2519 TABLE ACCESS (FULL) OF 'CQ_NAMES'
Again, the answer is interference from another transaction. In this case, another transaction held a shared lock on the table cq_names for several seconds before and after the update was issued. It takes a fair amount of experience to diagnose that interference effects are occurring. On the one hand, comparative data is essential when the interference is contributing only a short delay (or a small increase in block visits in the previous example). On the other hand, if the interference is contributing only a modest overhead, and the statement is essentially efficient, then its statistics might not need to be analyzed.
Avoiding the Trigger Trap
The resources reported for a statement include those for all of the SQL issued while the statement was being processed. Therefore, they include any resources used within a trigger, along with the resources used by any other recursive SQL, such as that used in space allocation. Avoid trying to tune the DML statement if the resource is actually being consumed at a lower level of recursion.
If a DML statement appears to be consuming far more resources than you would expect, then check the tables involved in the statement for triggers and constraints that could be greatly increasing the resource usage.
Sample TKPROF Output
This section provides an example of TKPROF output. Portions have been edited out for the sake of brevity.
Sample TKPROF Header
TKPROF: Release 10.1.0.0.0 - Beta on Mon Feb 10 14:43:00 2003 (c) Copyright 2001 Oracle Corporation. All rights reserved. Trace file: main_ora_27621.trc Sort options: default ******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ********************************************************************************
Sample TKPROF Body
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.00 0 0 0 0
Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 44
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 28.59 28.59
********************************************************************************
select condition
from
cdef$ where rowid=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY USER ROWID OBJ#(31) (cr=1 r=0 w=0 time=151 us)
********************************************************************************
SELECT last_name, job_id, salary
FROM employees
WHERE salary =
(SELECT max(salary) FROM employees)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 15 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.02 0.01 0 15 0 1
Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 44
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL EMPLOYEES (cr=15 r=0 w=0 time=1743 us)
1 SORT AGGREGATE (cr=7 r=0 w=0 time=777 us)
107 TABLE ACCESS FULL EMPLOYEES (cr=7 r=0 w=0 time=655 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 9.62 9.62
********************************************************************************
********************************************************************************
delete
from stats$sqltext st
where (hash_value, text_subset) not in
(select --+ hash_aj
hash_value, text_subset
from stats$sql_summary ss
where ( ( snap_id < :lo_snap
or snap_id > :hi_snap
)
and dbid = :dbid
and instance_number = :inst_num
)
or ( dbid != :dbid
or instance_number != :inst_num)
)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 29.60 60.68 266984 43776 131172 28144
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 29.60 60.68 266984 43776 131172 28144
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: 22
Rows Row Source Operation
------- ---------------------------------------------------
0 DELETE (cr=43141 r=266947 w=25854 time=60235565 us)
28144 HASH JOIN ANTI (cr=43057 r=262332 w=25854 time=48830056 us)
51427 TABLE ACCESS FULL STATS$SQLTEXT (cr=3465 r=3463 w=0 time=865083 us)
647529 INDEX FAST FULL SCAN STATS$SQL_SUMMARY_PK
(cr=39592 r=39325 w=0 time=10522877 us) (object id 7409)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 8084 0.12 5.34
direct path write 834 0.00 0.00
direct path write temp 834 0.00 0.05
db file parallel read 8 1.53 5.51
db file scattered read 4180 0.07 1.45
direct path read 7082 0.00 0.05
direct path read temp 7082 0.00 0.44
rdbms ipc reply 20 0.00 0.01
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
Sample TKPROF Summary
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.04 0.01 0 0 0 0
Execute 5 0.00 0.04 0 0 0 0
Fetch 2 0.00 0.00 0 15 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11 0.04 0.06 0 15 0 1
Misses in library cache during parse: 4
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 5 77.77 128.88
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 1
5 user SQL statements in session.
1 internal SQL statements in session.
6 SQL statements in session.
********************************************************************************
Trace file: main_ora_27621.trc
Trace file compatibility: 9.00.01
Sort options: default
1 session in tracefile.
5 user SQL statements in trace file.
1 internal SQL statements in trace file.
6 SQL statements in trace file.
6 unique SQL statements in trace file.
76 lines in trace file.
128 elapsed seconds in trace file.