Что такое трассировка (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.
Комментариев нет:
Отправить комментарий