среда, 12 августа 2015 г.

Трассировка и профилирование PL/SQL в Oracle 11g, часть I

Что такое трассировка (tracing), профилирование (profiling) и чем они отличаются друг от друга?

Трассировка - это прогон программы c регистрацией того, какие строки (команды) каких модулей (подпрограмм) в какой последовательности были выполнены.

Профилирование - это прогон программы с регистрацией времени выполнения отдельных модулей (подпрограмм) и, возможно, внешних вызовов, выполняемых программой.

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

Я рассмотрю средства трассировки и профилирования, которые Oracle 11g предоставляет разработчику PL/SQL. И начну с трассировки.

Пакет SYS.DBMS_TRACE (имеется публичный синоним) позволяет включать и отключать режим трассировки в рамках текущего сеанса. Если при включенном режиме трассировки выполнить PL/SQL код, то данные о его выполнении будут записаны в трассировочные таблицы.

Если в БД трассировка ни разу не выполнялась, то трассировочные таблицы нужно вначале создать. Для этого нужно выполнить скрипт $ORACLE_HOME/rdbms/admin/tracetab.sql как пользователь SYS. Скрипт создает две таблицы и сиквенс для генерирования уникальных номеров трассировок:

PLSQL_TRACE_RUNSТрассировки.
PLSQL_TRACE_EVENTSЗарегистрированные в ходе трассировки события.
PLSQL_TRACE_RUNNUMBERГенератор номеров трассировок.

Предоставлю доступ к трассировочным таблицам всем пользователям БД:

SQL> grant select on plsql_trace_runs to public;
Grant succeeded.

SQL> grant select on plsql_trace_events to public;
Grant succeeded.

SQL> create public synonym plsql_trace_events for sys.plsql_trace_events;
Synonym created.

SQL> create public synonym plsql_trace_runs for sys.plsql_trace_runs;
Synonym created.

Пользователю AY, под которым буду выполнять трассировку, предоставлю право удалять трассировочные данные:

SQL> grant delete on plsql_trace_runs to ay;
Grant succeeded.

SQL> grant delete on plsql_trace_events to ay;
Grant succeeded.

Трассировка включается процедурой DBMS_TRACE.SET_PLSQL_TRACE и отключается процедурой DBMS_TRACE.CLEAR_PLSQL_TRACE.

Процедура DBMS_TRACE.SET_PLSQL_TRACE принимает в качестве параметра уровень трассировки, задаваемый с помощью констант пакета DBMS_TRACE:

TRACE_ALL_CALLSТрассировать все вызовы.
TRACE_ALL_EXCEPTIONSТрассировать все исключения.
TRACE_ALL_SQLТрассировать все команды SQL.
TRACE_ALL_LINESТрассировать все строки.
TRACE_ENABLED_CALLSТрассировать активированные вызовы.
TRACE_ENABLED_EXCEPTIONSТрассировать активированные исключения.
TRACE_ENABLED_SQLТрассировать активированные команды SQL.
TRACE_ENABLED_LINESТрассировать активированные строки.
NO_TRACE_ADMINISTRATIVEНе трассировать события виртуальной машины PL/SQL.
NO_TRACE_HANDLED_EXCEPTIONSНе трассировать обрабатываемые исключения.

Под активированными (enabled) событиями понимаются события, связанные с выполнением кода только тех процедур, функций и пакетов, которые были скомпилированы для отладки. Так, уровень TRACE_ALL_CALLS включает трассировку всех вызовов в любом выполняемом коде PL/SQL, а уровень TRACE_ENABLED_CALLS - трассировку только вызовов в коде модулей, скомпилированных для отладки:

alter [procedure|function|package body] имя compile debug;

Другой способ откомпилировать PL/SQL модуль для отладки - использовать параметр PLSQL_DEBUG на уровне системы (alter system set plsql_debug=true), сеанса (alter session set plsql_debug=true) или непосредственно при компиляции:

alter [procedure|function|package body] имя compile plsql_debug = true;

Однако, параметр PLSQL_DEBUG в версии Oracle 11g объявлен устаревшим, поэтому первый способ предпочтительнее (к тому же, компиляция с PLSQL_DEBUG=TRUE в версии 11g генерирует предупреждения о понижении уровня оптимизации компилируемого кода.)

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

SQL> create or replace procedure hello(p pls_integer default 1) is
  2      a pls_integer;
  3  begin
  4      a := 1;
  5      a := a + p;
  6      select 1 into a from dual where 1 != 1;
  7  exception
  8  when no_data_found then
  9     dbms_output.put_line('select failed!');
 10  end hello;
 11  /
Procedure created

SQL> select name, type, plsql_optimize_level, plsql_debug
  2  from user_plsql_object_settings o
  3  where o.name='HELLO';

NAME                           TYPE         PLSQL_OPTIMIZE_LEVEL PLSQL_DEBUG
------------------------------ ------------ -------------------- ---------------
HELLO                          PROCEDURE                       2 FALSE

SQL> alter procedure hello compile debug;
Procedure altered

SQL> 
SQL> select name, type, plsql_optimize_level, plsql_debug
  2  from user_plsql_object_settings o
  3  where o.name='HELLO';
NAME                           TYPE         PLSQL_OPTIMIZE_LEVEL PLSQL_DEBUG
------------------------------ ------------ -------------------- ---------------
HELLO                          PROCEDURE                       2 TRUE

SQL> alter procedure hello compile;
Procedure altered

SQL> 
SQL> select name, type, plsql_optimize_level, plsql_debug
  2  from user_plsql_object_settings o
  3  where o.name='HELLO';
NAME                           TYPE         PLSQL_OPTIMIZE_LEVEL PLSQL_DEBUG
------------------------------ ------------ -------------------- ---------------
HELLO                          PROCEDURE                       2 FALSE

Разобравшись с тем, как активировать код PL/SQL для целей трассировки, вернемся собственно к трассировке.

В качестве параметра для DBMS_TRACE.SET_PLSQL_TRACE можно использовать как отдельную константу пакета DBMS_TRACE, так и сумму нескольких констант. В последнем случае включается трассировка всех событий, соответствующих просуммированным константам. Например, DBMS_TRACE.TRACE_ALL_CALLS + DBMS_TRACE.TRACE_ENABLED_SQL включит трассировку всех вызовов и только активированных команд SQL.

Перехожу к экспериментам. Для начала, оттрассирую все выполняемые строки процедуры HELLO и изучу результат:

SQL> exec dbms_trace.set_plsql_trace(dbms_trace.trace_all_lines);
PL/SQL procedure successfully completed

SQL> exec hello
PL/SQL procedure successfully completed

SQL> exec dbms_trace.clear_plsql_trace
PL/SQL procedure successfully completed

В таблице PLSQL_TRACE_RUNS найду номер только что выполненной трассировки и по этому номеру выберу зарегистрированные события из PLSQL_TRACE_EVENTS:

SQL> select max(runid) from plsql_trace_runs where run_owner = user;
MAX(RUNID)
----------
        13

SQL> select event_seq, event_unit_owner, event_unit, event_line, event_comment 
     from plsql_trace_events
     where runid = 13
     order by event_seq;

 EVENT_SEQ EVENT_UNIT_OWNER     EVENT_UNIT           EVENT_LINE EVENT_COMMENT
---------- -------------------- -------------------- ---------- -------------------------------
         1                                                      PL/SQL Trace Tool started
         2                                                      Trace flags changed
         3 SYS                  DBMS_TRACE                   75 New line executed
         4 SYS                  DBMS_TRACE                   76 New line executed
         5 SYS                  DBMS_TRACE                   81 New line executed
         6                      <anonymous>                   1 New line executed
         7                                                      PL/SQL Virtual Machine stopped
         8                      <anonymous>                   0 PL/SQL Virtual Machine started
         9                      <anonymous>                   1 New line executed
        10 SYS                  DBMS_TRANSACTION            103 New line executed
        11 SYS                  DBMS_TRANSACTION            106 New line executed
        12 SYS                  DBMS_TRANSACTION            108 New line executed
        13                      <anonymous>                   1 New line executed
        14                      <anonymous>                   1 New line executed
        15                                                      PL/SQL Virtual Machine stopped
        16                      <anonymous>                   0 PL/SQL Virtual Machine started
        17                      <anonymous>                   1 New line executed
        18 SYS                  DBMS_TRANSACTION            103 New line executed
        19 SYS                  DBMS_TRANSACTION            106 New line executed
        20 SYS                  DBMS_TRANSACTION            108 New line executed
        21                      <anonymous>                   1 New line executed
        22                      <anonymous>                   1 New line executed
        23                                                      PL/SQL Virtual Machine stopped
        24                      <anonymous>                   0 PL/SQL Virtual Machine started
        25                      <anonymous>                   1 New line executed
        26 AY                   HELLO                         1 New line executed
        27 AY                   HELLO                         4 New line executed
        28 AY                   HELLO                         5 New line executed
        29 AY                   HELLO                         6 New line executed
        30 AY                   HELLO                         8 New line executed
        31 AY                   HELLO                         9 New line executed
        32 SYS                  DBMS_OUTPUT                 111 New line executed
        33 SYS                  DBMS_OUTPUT                 115 New line executed
        34 AY                   HELLO                        10 New line executed
        35                      <anonymous>                   1 New line executed
        36                                                      PL/SQL Virtual Machine stopped
        37                      <anonymous>                   0 PL/SQL Virtual Machine started
        38                      <anonymous>                   1 New line executed
        39 SYS                  DBMS_TRANSACTION            103 New line executed
        40 SYS                  DBMS_TRANSACTION            106 New line executed
        41 SYS                  DBMS_TRANSACTION            108 New line executed
        42                      <anonymous>                   1 New line executed
        43                      <anonymous>                   1 New line executed
        44                                                      PL/SQL Virtual Machine stopped
        45                      <anonymous>                   0 PL/SQL Virtual Machine started
        46                      <anonymous>                   1 New line executed
        47 SYS                  DBMS_TRANSACTION            103 New line executed
        48 SYS                  DBMS_TRANSACTION            106 New line executed
        49 SYS                  DBMS_TRANSACTION            108 New line executed
        50                      <anonymous>                   1 New line executed
        51                      <anonymous>                   1 New line executed
        52                                                      PL/SQL Virtual Machine stopped
        53                      <anonymous>                   0 PL/SQL Virtual Machine started
        54                      <anonymous>                   1 New line executed
        55 SYS                  DBMS_TRACE                   94 New line executed
        56 SYS                  DBMS_TRACE                   72 New line executed
        57 SYS                  DBMS_TRACE                   66 New line executed
        58 SYS                  DBMS_TRACE                   12 New line executed
        59 SYS                  DBMS_TRACE                   66 New line executed
        60 SYS                  DBMS_TRACE                   67 New line executed
        61 SYS                  DBMS_TRACE                   72 New line executed
        62 SYS                  DBMS_TRACE                   75 New line executed
        63 SYS                  DBMS_TRACE                   21 New line executed
        64                                                      PL/SQL trace stopped
64 rows selected

Очень много данных! В трассировочных таблицах зарегистрированы события, связанные не только с выполнением процедуры HELLO, но также

  • с выполнением кода пакета DBMS_TRACE, с помощью которого я включал и отключал трассировку,
  • c запуском и остановкой виртуальной машины PL/SQL,
  • с управлением транзакциями при помощи пакета DBMS_TRANSACTION.

Хочется сосредоточиться на работе HELLO и исключить сбор данных, не связанных с выполнением этой процедуры. Воспользуюсь константой DBMS_TRACE.NO_TRACE_ADMINISTRATIVE, чтобы отключить регистрацию лишних событий:

SQL> exec dbms_trace.set_plsql_trace(dbms_trace.trace_all_lines + dbms_trace.no_trace_administrative);
PL/SQL procedure successfully completed

SQL> exec hello
PL/SQL procedure successfully completed

SQL> exec dbms_trace.clear_plsql_trace
PL/SQL procedure successfully completed

SQL> select event_seq, event_unit_owner, event_unit, event_line, event_comment 
    from plsql_trace_events
    where runid = (select max(runid) from plsql_trace_runs where run_owner = user)
    order by event_seq;

 EVENT_SEQ EVENT_UNIT_OWNER     EVENT_UNIT            EVENT_LINE EVENT_COMMENT
---------- -------------------- --------------------- ---------- ------------------------------
         1 SYS                  DBMS_TRACE                    75 New line executed
         2 SYS                  DBMS_TRACE                    76 New line executed
         3 SYS                  DBMS_TRACE                    81 New line executed
         4                      <anonymous>                    1 New line executed
         5                      <anonymous>                    1 New line executed
         6 SYS                  DBMS_TRANSACTION             103 New line executed
         7 SYS                  DBMS_TRANSACTION             106 New line executed
         8 SYS                  DBMS_TRANSACTION             108 New line executed
         9                      <anonymous>                    1 New line executed
        10                      <anonymous>                    1 New line executed
        11                      <anonymous>                    1 New line executed
        12 SYS                  DBMS_TRANSACTION             103 New line executed
        13 SYS                  DBMS_TRANSACTION             106 New line executed
        14 SYS                  DBMS_TRANSACTION             108 New line executed
        15                      <anonymous>                    1 New line executed
        16                      <anonymous>                    1 New line executed
        17                      <anonymous>                    1 New line executed
        18 AY                   HELLO                          1 New line executed
        19 AY                   HELLO                          4 New line executed
        20 AY                   HELLO                          5 New line executed
        21 AY                   HELLO                          6 New line executed
        22 AY                   HELLO                          8 New line executed
        23 AY                   HELLO                          9 New line executed
        24 SYS                  DBMS_OUTPUT                  111 New line executed
        25 SYS                  DBMS_OUTPUT                  115 New line executed
        26 AY                   HELLO                         10 New line executed
        27                      <anonymous>                    1 New line executed
        28                      <anonymous>                    1 New line executed
        29 SYS                  DBMS_TRANSACTION             103 New line executed
        30 SYS                  DBMS_TRANSACTION             106 New line executed
        31 SYS                  DBMS_TRANSACTION             108 New line executed
        32                      <anonymous>                    1 New line executed
        33                      <anonymous>                    1 New line executed
        34                      <anonymous>                    1 New line executed
        35 SYS                  DBMS_TRANSACTION             103 New line executed
        36 SYS                  DBMS_TRANSACTION             106 New line executed
        37 SYS                  DBMS_TRANSACTION             108 New line executed
        38                      <anonymous>                    1 New line executed
        39                      <anonymous>                    1 New line executed
        40                      <anonymous>                    1 New line executed
        41 SYS                  DBMS_TRACE                    94 New line executed
        42 SYS                  DBMS_TRACE                    72 New line executed
        43 SYS                  DBMS_TRACE                    66 New line executed
        44 SYS                  DBMS_TRACE                    12 New line executed
        45 SYS                  DBMS_TRACE                    66 New line executed
        46 SYS                  DBMS_TRACE                    67 New line executed
        47 SYS                  DBMS_TRACE                    72 New line executed
        48 SYS                  DBMS_TRACE                    75 New line executed
        49 SYS                  DBMS_TRACE                    21 New line executed
49 rows selected

Исчезли запуски и остановы виртуальной машины PL/SQL, но все еще много лишних событий, не относящихся к выполнению кода процедуры HELLO. Попробую трассировать только активированные события, для чего откомпилирую процедуру HELLO с опцией DEBUG:

SQL> alter procedure hello compile debug;
Procedure altered

SQL> exec dbms_trace.set_plsql_trace(dbms_trace.trace_enabled_lines + dbms_trace.no_trace_administrative);
PL/SQL procedure successfully completed

SQL> exec hello
PL/SQL procedure successfully completed

SQL> exec dbms_trace.clear_plsql_trace
PL/SQL procedure successfully completed

SQL> select event_seq, event_unit_owner, event_unit, event_line, event_comment 
    from plsql_trace_events
    where runid = (select max(runid) from plsql_trace_runs where run_owner = user)
    order by event_seq;

 EVENT_SEQ EVENT_UNIT_OWNER     EVENT_UNIT           EVENT_LINE EVENT_COMMENT
---------- -------------------- -------------------- ---------- -------------------------------
         1 AY                   HELLO                         1 New line executed
         2 AY                   HELLO                         3 New line executed
         3 AY                   HELLO                         4 New line executed
         4 AY                   HELLO                         5 New line executed
         5 AY                   HELLO                         6 New line executed
         6 AY                   HELLO                         7 New line executed
         7 AY                   HELLO                         8 New line executed
         8 AY                   HELLO                         9 New line executed
         9 AY                   HELLO                        10 New line executed
9 rows selected

Отлично! Были зарегистрированы только выполнения строк процедуры HELLO и ничего кроме. А следующий запрос покажет строки процедуры HELLO, связанные с зарегистрированными событиями:

SQL> select event_seq, event_unit, event_comment, event_line, text
  2      from plsql_trace_events e, user_source s
  3      where runid = (select max(runid) from plsql_trace_runs where run_owner = user)
  4          and s.name = e.event_unit
  5          and s.line = e.event_line
  6      order by event_seq;

 EVENT_SEQ EVENT_UNIT           EVENT_COMMENT        EVENT_LINE TEXT
---------- -------------------- -------------------- ---------- ---------------------------------------------
         1 HELLO                New line executed             1 procedure hello(p pls_integer default 1) is
         2 HELLO                New line executed             3 begin
         3 HELLO                New line executed             4     a := 1;
         4 HELLO                New line executed             5     a := a + p;
         5 HELLO                New line executed             6     select 1 into a from dual where 1 != 1;
         6 HELLO                New line executed             7 exception
         7 HELLO                New line executed             8 when no_data_found then
         8 HELLO                New line executed             9     dbms_output.put_line('select failed!');
         9 HELLO                New line executed            10 end hello;
9 rows selected

Достаточно наглядно. Только строка 2 процедуры HELLO не была выполнена - в этой строке объявление переменной a pls_integer;. Можно сделать вывод, что данное объявление переменной не является исполняемой командой, а память под переменную выделяется в ходе загрузки программы в виртуальную машину PL/SQL.

Приведенный запрос, в случае трассировки одной и той же программы, запускаемой с разными параметрами, позволяет увидеть и сравнить последовательности выполнения строк программы в зависимости от параметров.

Проделаю еще один эксперимент с трассировкой. На этот раз я хочу видеть только активированные вызовы и выполнения команд SQL.

SQL> exec dbms_trace.set_plsql_trace(dbms_trace.trace_enabled_sql + dbms_trace.trace_enabled_calls + dbms_trace.no_trace_administrative);
PL/SQL procedure successfully completed

SQL> exec hello
PL/SQL procedure successfully completed

SQL> exec dbms_trace.clear_plsql_trace
PL/SQL procedure successfully completed

SQL> select event_seq, event_unit_owner, event_unit, event_line, event_comment 
    from plsql_trace_events
    where runid = (select max(runid) from plsql_trace_runs where run_owner = user)
    order by event_seq;

 EVENT_SEQ EVENT_UNIT_OWNER     EVENT_UNIT           EVENT_LINE EVENT_COMMENT
---------- -------------------- -------------------- ---------- --------------------------------
         1                      <anonymous>                   1 Procedure Call
         2 AY                   HELLO                         6 SELECT 1 FROM DUAL WHERE 1 != 1
         3 AY                   HELLO                         9 Procedure Call
         4 SYS                  DBMS_OUTPUT                 115 Return from procedure call
         5 AY                   HELLO                        10 Return from procedure call

А теперь - с исходным кодом строк процедуры HELLO:

SQL> select event_seq, event_unit, event_comment, event_line, text
  2      from plsql_trace_events e, user_source s
  3      where runid = 11 --(select max(runid) from plsql_trace_runs where run_owner = user)
  4          and s.name = e.event_unit
  5          and s.line = e.event_line
  6      order by event_seq;

 EVENT_SEQ EVENT_UNIT           EVENT_COMMENT                    EVENT_LINE TEXT
---------- -------------------- -------------------------------- ---------- -------------------------------------------
         2 HELLO                SELECT 1 FROM DUAL WHERE 1 != 1           6     select 1 into a from dual where 1 != 1;
         3 HELLO                Procedure Call                            9     dbms_output.put_line('select failed!');
         5 HELLO                Return from procedure call               10 end hello;

Что ж, получен ожидаемый результат.

Помимо уже упомянутых констант, в пакете DBMS_TRACE имеются и другие, предназначенные для настройки уровня трассировки. Кроме того, имеются "управляющие" константы, которые также могут передаваться при вызове DBMS_TRACE.SET_PLSQL_TRACE в качестве параметра:

Константа Описание Альтернатива использованию константы
TRACE_PAUSE Приостановить трассировку, не меняя уровень трассировки. DBMS_TRACE.PAUSE_PLSQL_TRACE
TRACE_RESUME Возобновить приостановленную трассировку. DBMS_TRACE.RESUME_PLSQL_TRACE
TRACE_STOP Остановить трассировку, очистив уровень трассировки. DBMS_TRACE.CLEAR_PLSQL_TRACE
TRACE_LIMIT Ограничить количество событий, хранимых в трассировочных таблицах, 8192 последними событиями. DBMS_TRACE.LIMIT_PLSQL_TRACE

Константы TRACE_PAUSE, TRACE_RESUME, TRACE_STOP нельзя комбинировать с другими константами при вызове DBMS_TRACE.SET_PLSQL_TRACE.

Как видно из таблицы, использованию "управляющих" констант с DBMS_TRACE.SET_PLSQL_TRACE имеется альтернатива - вызов соответствующей процедуры пакета DBMS_TRACE, приводящий к такому же результату: приостановка, возобновление и остановка трассировки.

Чтобы узнать больше о возможностях трассировки, рекомендую просмотреть спецификацию пакета DBMS_TRACE - в ней больше функций и констант, чем описано в официальном справочнике Database PL/SQL Packages and Types Reference для Oracle 11gR2.

В заключение, очищу трассировочные таблицы и удалю процедуру HELLO:

SQL> delete sys.plsql_trace_events e
  2  where e.runid in (select r.runid from sys.plsql_trace_runs r where r.run_owner = user);
405 rows deleted

SQL> delete sys.plsql_trace_runs r where r.run_owner = user;
19 rows deleted

SQL> drop procedure hello;
Procedure dropped

Во второй части статьи будет продемонстрирована работа с иерархическим профайлером - главным средством профлилирования программ PL/SQL в СУБД Oracle 11g.

Комментариев нет:

Отправить комментарий