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

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

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

В СУБД Oracle 11g главным инструментом профилирования PL/SQL является иерархический профайлер (hierarchical profiler). Иерархический профайлер, в частности, обеспечивает

регистрацию времени выполнения отдельно для SQL и PL/SQL кода,
подсчет числа вызовов каждой подпрограммы PL/SQL и времени, затраченного на ее выполнение,
генерацию набора отчетов для анализа данных о выполнении программы.

Работая с иерархическим профайлером, разработчик использует

пакет SYS.DBMS_HPROF, для сбора и обработки данных профилирования, и
утитлиту plshprof, для формирования html-отчетов о профилировании.

Профилирование включается вызовом процедуры DBMS_HPROF.START_PROFILING и отключается вызовом DBMS_HPROF.STOP_PROFILING. В промежутке между вызовами этих процедур данные о выполнении PL/SQL кода пишутся во внешний текстовый файл. Имя файла задается параметром процедуры DBMS_HPROF.START_PROFILING.

После того, как профилирование остановлено, разработчик может

изучить данные профилирования в файле,
загрузить данные профилирования из файла в таблицы БД для изучения,
сформировать по данным профилирования из файла набор html-отчетов для изучения.

После краткого введения, перейдем к практике.

Для начала, я создам PL/SQL процедуру, данные о выполнении которой буду собирать и анализировать:

SQL> create or replace procedure hello_users is
  2      function hello(p_name varchar2) return varchar2 is
  3      begin
  4          return 'Hello, ' || p_name;
  5      end hello;
  6  begin
  7      for x in (select username from all_users where rownum <= 3) loop
  8          dbms_output.put_line(hello(x.username));
  9      end loop;
 10  end hello_users;
 11  /
Procedure created

Созданная процедура содержит команду SQL, а также многократные вызовы локальной функции HELLO и процедуры DBMS_OUTPUT.PUT_LINE.

Для выполнения профилирования пользователю БД необходимы права

на выполнение SYS.DBMS_HPROF (их должен выдать SYS) и
на запись в объект directory, задающий директорию файловой системы, где будет создан файл с данными профилирования.

Если подходящего объекта directory не существует, создадим его:

SQL> create directory files_dir as '/home/oracle/files';
Directory created

Итак, выполню профилирование процедуры HELLO_USERS:

SQL> set serveroutput on

SQL> begin
  2      dbms_hprof.start_profiling('FILES_DIR', 'hello_users.hprof');
  3      hello_users;
  4      dbms_hprof.stop_profiling;
  5  end;
  6  /
Hello, SYS
Hello, SYSTEM
Hello, OUTLN

PL/SQL procedure successfully completed

Что содержится в сформированном файле hello_users.hprof?

[oracle@tsuki files]$ ls -l hello_users.hprof
-rw-r--r-- 1 oracle oinstall 1304 Sep  6 12:16 hello_users.hprof

[oracle@tsuki files]$ cat hello_users.hprof
P#V PLSHPROF Internal Version 1.0
P#! PL/SQL Timer Started
P#C PLSQL."AY"."HELLO_USERS"::7."HELLO_USERS"#980980e97e42f8ec #1
P#X 50
P#C SQL."AY"."HELLO_USERS"::7."__sql_fetch_line7" #7
P#X 5995
P#R
P#X 8
P#C PLSQL."AY"."HELLO_USERS"::7."HELLO_USERS.HELLO"#28dc3402baeb2b0d #2
P#X 9
P#R
P#X 53
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT_LINE"#5892e4d73b579470 #109
P#X 1
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT"#5892e4d73b579470 #77
P#X 22
P#R
P#X 1
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."NEW_LINE"#980980e97e42f8ec #117
P#X 2
P#R
P#X 1
P#R
P#X 1
P#C PLSQL."AY"."HELLO_USERS"::7."HELLO_USERS.HELLO"#28dc3402baeb2b0d #2
P#X 1
P#R
P#X 1
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT_LINE"#5892e4d73b579470 #109
P#X 1
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT"#5892e4d73b579470 #77
P#X 2
P#R
P#X 1
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."NEW_LINE"#980980e97e42f8ec #117
P#X 1
P#R
P#X 1
P#R
P#X 1
P#C PLSQL."AY"."HELLO_USERS"::7."HELLO_USERS.HELLO"#28dc3402baeb2b0d #2
P#X 1
P#R
P#X 1
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT_LINE"#5892e4d73b579470 #109
P#X 0
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT"#5892e4d73b579470 #77
P#X 5
P#R
P#X 0
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."NEW_LINE"#980980e97e42f8ec #117
P#X 1
P#R
P#X 0
P#R
P#X 33
P#R
P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #59
P#R
P#! PL/SQL Timer Stopped

В файле отчетливо выделяются три группы строк, соответствующие трем итерациям цикла FOR. Любопытно видеть, что процедура DBMS_OUTPUT.PUT_LINE реализована через вызовы процедур PUT и NEW_LINE.

Для дальнейшего исследования данных профилирования загружу их в таблицы БД с помощью функции DBMS_HPROF.ANALYZE.

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

Необходимые таблицы создаются скриптом $ORACLE_HOME/rdbms/admin/dbmshptab.sql. Вот эти таблицы (и один сиквенс):

`DBMSHP_RUNS`	Загруженный профиль.
`DBMSHP_FUNCTION_INFO`	Данные о выполнении функций/процедур.
`DBMSHP_PARENT_CHILD_INFO`	Деревья вызовов функций/процедур.
`DBMSHP_RUNNUMBER`	Генератор номеров загрузок.

Я создал таблицы в схеме AY. Теперь можно загрузить в них данные из файла hello_users.hprof для дальнейшего анализа:

SQL> var nrun number

SQL> exec :nrun := dbms_hprof.analyze('FILES_DIR', 'hello_users.hprof');
PL/SQL procedure successfully completed

SQL> print nrun
nrun
---------
1

Исследую загруженные данные:

SQL> select runid, total_elapsed_time total_microseconds from dbmshp_runs;
     RUNID                      TOTAL_MICROSECONDS
---------- ---------------------------------------
         1                                    6193

SQL> select namespace, owner, module, type, function, function_elapsed_time ft,calls, subtree_elapsed_time st
  2  from dbmshp_function_info
  3  where runid = 1;

NAMESPACE       OWNER           MODULE          TYPE            FUNCTION             FUNCTION_TIME   CALLS           SUBTREE_TIME   
--------------- --------------- --------------- --------------- -------------------- --------------- --------------- ---------------
PLSQL           AY              HELLO_USERS     PROCEDURE       HELLO_USERS                      148               1            6193
PLSQL           AY              HELLO_USERS     PROCEDURE       HELLO_USERS.HELLO                 11               3              11
PLSQL           SYS             DBMS_HPROF      PACKAGE BODY    STOP_PROFILING                     0               1               0
PLSQL           SYS             DBMS_OUTPUT     PACKAGE BODY    NEW_LINE                           4               3               4
PLSQL           SYS             DBMS_OUTPUT     PACKAGE BODY    PUT                               29               3              29
PLSQL           SYS             DBMS_OUTPUT     PACKAGE BODY    PUT_LINE                           6               3              39
SQL             AY              HELLO_USERS     PROCEDURE       __sql_fetch_line7               5995               1            5995

7 rows selected

Длительность выполнения подпрограмм регистрируется в микросекундах.

Даже беглый взгляд на результат последнего запроса позволяет увидеть, что более 90% времени выполнения HELLO_USERS занимает выполнение команды SQL. (Вспомните известную рекомендацию начинать оптимизацию PL/SQL c оптимизации SQL.)

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

SQL> select lpad(' ', (level-1)*4, ' ')||owner||'.'||case when function like module||'%' then function else module||'.'||function end module,
  2      fi.function_elapsed_time function_time,
  3      fi.calls,
  4      fi.subtree_elapsed_time subtree_time
  5  from dbmshp_function_info fi left outer join dbmshp_parent_child_info pci on fi.symbolid = pci.childsymid and fi.runid = pci.runid
  6  connect by prior fi.symbolid = pci.parentsymid and prior fi.runid = pci.runid
  7  start with pci.parentsymid is null and fi.runid = 1;

MODULE                                   FUNCTION_TIME   CALLS           SUBTREE_TIME
---------------------------------------- --------------- --------------- ---------------
AY.HELLO_USERS                                       148               1            6193
    AY.HELLO_USERS.HELLO                              11               3              11
    SYS.DBMS_OUTPUT.PUT_LINE                           6               3              39
        SYS.DBMS_OUTPUT.NEW_LINE                       4               3               4
        SYS.DBMS_OUTPUT.PUT                           29               3              29
    AY.HELLO_USERS.__sql_fetch_line7                5995               1            5995
SYS.DBMS_HPROF.STOP_PROFILING                          0               1               0

7 rows selected

Среди собранных профайлером данных есть явно лишние - о запуске процедуры DBMS_HPROF.STOP_PROFILING. Можно ли исключить из анализа лишние данные?

У процедуры DBMS_HPROF.ANALYZE есть параметр trace. С его помощью можно указать корень поддерева вызовов, для которого будут загружены данные профилирования, а данные, не относящиеся к указанному поддереву - проигнорированы. Корень поддерева задается квалифицированным именем из трех частей вида "USER"."MODULE"."PROCEDURE".

Загружу поддерево "AY"."HELLO_USERS"."HELLO_USERS":

SQL> var nrun number

SQL> exec :nrun := dbms_hprof.analyze('FILES_DIR', 'hello_users.hprof', trace => '"AY"."HELLO_USERS"."HELLO_USERS"');
PL/SQL procedure successfully completed

SQL> select lpad(' ', (level-1)*4, ' ')||owner||'.'||case when function like module||'%' then function else module||'.'||function end module,
  2      fi.function_elapsed_time function_time,
  3      fi.calls,
  4      fi.subtree_elapsed_time subtree_time
  5  from dbmshp_function_info fi left outer join dbmshp_parent_child_info pci on fi.symbolid = pci.childsymid and fi.runid = pci.runid
  6  connect by prior fi.symbolid = pci.parentsymid and prior fi.runid = pci.runid
  7  start with pci.parentsymid is null and fi.runid = :nrun;

MODULE                                   FUNCTION_TIME   CALLS           SUBTREE_TIME
---------------------------------------- --------------- --------------- ---------------
AY.HELLO_USERS                                       148               1            6193
    AY.HELLO_USERS.HELLO                              11               3              11
    SYS.DBMS_OUTPUT.PUT_LINE                           6               3              39
        SYS.DBMS_OUTPUT.NEW_LINE                       4               3               4
        SYS.DBMS_OUTPUT.PUT                           29               3              29
    AY.HELLO_USERS.__sql_fetch_line7                5995               1            5995

6 rows selected

Это то, что требовалось получить.

Следующая таблица содержит все параметры процедуры DBMS_HPROF.ANALYZE и дает представление о ее гибкости:

Параметр	Описание
`location`	Имя объекта directory.
`filename`	Имя файла с данными профилирования.
`summary_mode`	`TRUE` - загрузить только обощенные данные профилирования; `FALSE` (по умолчанию) - загрузить детальные данные.
`trace`	Имя корня поддерева, для которого загрузить данные профилирования. По умолчанию (`NULL`) загружаются все данные из файла.
`skip`	Сколько первых случаев обнаружения поддерева `trace` пропустить и не загружать. По умолчанию 0.
`collect`	Сколько случаев обнаружения поддерева `trace`, начиная со `skip+1`, загрузить. По умолчанию (1) загружается только первый случай.
`run_comment`	Комментарий к загруженным данным (попадает в столбец `DBMSHP_RUNS.RUN_COMMENT`).

Утилита plshprof предоставляет возможности, аналогичные возможностям процедуры DBMS_HPROF.ANALYZE. Опции утилиты соответствуют параметрам процедуры:

[oracle@tsuki files]$ plshprof
PLSHPROF: Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
Usage: plshprof [<option>...] <tracefile1> [<tracefile2>]
  Options:
    -trace <symbol>    (no default)     specify function name of tree root
    -skip <count>      (default=0)      skip first <count> invokations
    -collect <count>   (default=1)      collect info for <count> invokations
    -output <filename> (default=<symbol>.html or <tracefile1>.html)
    -summary                            print time only

Получу обобщенную информацию о выполнении процедуры HELLO_USERS:

[oracle@tsuki files]$ plshprof -summary hello_users.hprof
PLSHPROF: Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
Total subtree time: 6193 microsecs (elapsed time)

Теперь сформирую html-отчет по поддереву "AY"."HELLO_USERS"."HELLO_USERS":

[oracle@tsuki files]$ plshprof -trace '"AY"."HELLO_USERS"."HELLO_USERS"' hello_users.hprof
PLSHPROF: Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
[6 symbols processed]
[Report written to 'hello_users.hprof.html']

[oracle@tsuki files]$ ls -1
hello_users.hprof
hello_users.hprof_2c.html
hello_users.hprof_2f.html
hello_users.hprof_2n.html
hello_users.hprof_fn.html
hello_users.hprof.html
hello_users.hprof_md.html
hello_users.hprof_mf.html
hello_users.hprof_ms.html
hello_users.hprof_nsc.html
hello_users.hprof_nsf.html
hello_users.hprof_nsp.html
hello_users.hprof_pc.html
hello_users.hprof_tc.html
hello_users.hprof_td.html
hello_users.hprof_tf.html
hello_users.hprof_ts.html

С главной страницы hello_users.hprof.html ссылки ведут на все сгенерированные отчеты, в том числе отчет по длительности выполнения функций:

Какой-либо существенно новой информации, по сравнению с той, которую можно извлечь из таблиц DBMSHP_% с помощью запросов, сгенерированные html-отчеты не содержат.

Выбор инструмента и формата для анализа данных профилирования остается за разработчиком. Очевидно, что презентовать результаты анализа другим людям удобней в виде html-отчетов.

Для удаления данных профилирования из таблиц DBMSHP_% достаточно удалить строки из таблицы DBMSHP_RUNS - строки в других таблицах будут удалены каскадно. Удалю данные профилирования и процедуру HELLO_USERS, с которой экспериментировал:

SQL> delete from dbmshp_runs where runid in (1,2);
2 rows deleted

SQL> drop procedure hello_users;
Procedure dropped

В заключение покажу, как подготовить БД, чтобы можно было легко давать пользователям возможность работать с иерархическим профайлером.

Пусть /home/oracle/helper будет директория для файлов профилирования на сервере. Вначале, как SYS создадим "центральную" схему HELPER с необходимыми привилегиями:

create user helper identified by password 
default tablespace users
temporary tablespace temp 
quota unlimited on users;

grant connect, resource to helper;

create directory helper_dir as '/home/oracle/helper';

grant execute, read, write on directory helper_dir to helper;

grant execute on dbms_hprof to helper;

Далее, как HELPER создадим таблицы профилирования:

[oracle@tsuki ~]$ cd $ORACLE_HOME/rdbms/admin

[oracle@tsuki admin]$ sqlplus helper/password @dbmshptab.sql
...

Как SYS создадим публичные синонимы для таблиц профилирования:

create public synonym dbmshp_runs for helper.dbmshp_runs;

create public synonym dbmshp_function_info for helper.dbmshp_function_info;

create public synonym dbmshp_parent_child_info for helper.dbmshp_parent_child_info;

create public synonym dbmshp_runnumber for helper.dbmshp_runnumber;

Перечисленные действия необходимо выполнить в БД один раз.

После этого, для предоставления произвольному пользователю БД возможности работать с иерархическим профайлером, достаточно выполнить следующий скрипт как SYS в SQL*Plus:

undefine usr

grant execute, read, write on directory helper_dir to &&usr;
grant execute on dbms_hprof to &usr; 
grant select, insert, update, delete on helper.dbmshp_runs to &usr;
grant select, insert, update, delete on helper.dbmshp_function_info to &usr;
grant select, insert, update, delete on helper.dbmshp_parent_child_info to &usr;
grant select on helper.dbmshp_runnumber to &usr;

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

/привет/мир/etc

среда, 16 сентября 2015 г.

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

1 комментарий:

среда, 16 сентября 2015 г.

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

1 комментарий:

среда, 16 сентября 2015 г.