Profile PL/SQL applications package DBMS_HPROF

Por Tércio Silva Costa
Publicado em Abril 2019

Revisado por Juan Pablo Guizado

Aqui, neste artículo, iremos demonstrar o uso da package DBMS_HPROF lançado na versão 11g, que faz o profile hierárquico. Antes da versão 11g se usava a package DBMS_PROFILER, mas que não capturava informações de maneira hierárquica, em que capturava apenas quanto tempo cada módulo gastou. O profiler hierárquico faz mais do que isto. Ele nos diz que programa invocou qual programa e quantas vezes essa rotina foi invocada, além de calcular o tempo gasto em cada chamada subprogramas dentro do subprogama. Dividindo as informações por programas, relação entre eles e também divide o tempo de execução do SQL e do PL/SQL.

O profile é um processo de duas etapas. Primeiro geramos a informação ou dados do processo e depois esses dados é analisado. Na fase de coletar os dados, o Oracle armazena todas essas informações em um arquivo de texto no O.S. em um formato raw. Na segunda parte o Oracle pega o conteúdo desse arquivo e armazena nas tabelas de profiler para depois o usuário analisar as informações e até mesmo criar um arquivo HTML com esses dados.

Para fazer o profile no Oracle, primeiro é preciso criar as tabelas que não vem instaladas por padrão, pode-se fazer isso por executar um script como sys, dbmshptab.sql, e logo após verificar os objetos criados como no exemplo abaixo.

$ sqlplus / as sysdba
 
SQL*Plus: Release 12.2.0.1.0 Production on Wed Jan 30 09:07:38 2019
 
Copyright (c) 1982, 2016, Oracle.  All rights reserved.
 
 
Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
 
SQL> @?/rdbms/admin/dbmshptab.sql
drop table dbmshp_runs                   cascade constraints
           *
ERROR at line 1:
ORA-00942: table or view does not exist
 
 
drop table dbmshp_function_info          cascade constraints
           *
ERROR at line 1:
ORA-00942: table or view does not exist
 
 
drop table dbmshp_parent_child_info      cascade constraints
           *
ERROR at line 1:
ORA-00942: table or view does not exist
 
 
drop sequence dbmshp_runnumber
              *
ERROR at line 1:
ORA-02289: sequence does not exist
 
 
 
Table created.
 
 
Comment created.
 
 
Table created.
 
 
Comment created.
 
 
Table created.
 
 
Comment created.
 
 
Sequence created.
 
SQL> column object_name format a35
SQL> column obejct_type format a20
SQL> SELECT object_name, object_type
  2  FROM   dba_objects
  3  WHERE  object_name LIKE 'DBMSH%';
 
OBJECT_NAME                       OBJECT_TYPE
----------------------------------- -----------------------
DBMSHADOOPLIB                     LIBRARY
DBMSHP_FUNCTION_INFO              TABLE
DBMSHP_PARENT_CHILD_INFO          TABLE
DBMSHP_RUNNUMBER                  SEQUENCE
DBMSHP_RUNS                       TABLE
DBMSHSXP                          PACKAGE
DBMSHSXP                          PACKAGE BODY
DBMSHSXP_SQL_PROFILE_ATTR         VIEW
DBMSHSXP                          SYNONYM
DBMSHSXP_SQL_PROFILE_ATTR         SYNONYM
 
10 rows selected.
 
SQL>

Foram criadas 3 tabelas e uma sequence. Os outros objetos já existiam e a package estava inválida antes por não existir as tabelas no banco.

Será necessário dar os privilégios,SELECT, INSERT, nas tabelas e na sequence, bem como criar PUBLIC SYNONYMS para esses objetos, para que outros usuários, além do sys, possa utilizar o profiler. E claro, o privilégio de EXECUTE na package DBMS_HPROF.

Após isso devemos criar um directory para armazenar os dados em formato raw do profile. Lembrando que o usuário que executar a package deverá ter privilégios de read/write neste directório já que a package é executada em invoker rights.

$ mkdir -p /home/oracle/profiler
[oracle@oel76-lab1 ~]$ sqlplus / as sysdba
 
SQL*Plus: Release 12.2.0.1.0 Production on Wed Jan 30 10:06:49 2019
 
Copyright (c) 1982, 2016, Oracle.  All rights reserved.
 
 
Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
 
SQL> CREATE DIRECTORY PROFILER_DIR AS '/home/oracle/profiler';
 
Directory created.

Agora, vamos criar alguns objetos que serão analisados com o profiler

sqlplus terciocosta
 
SQL*Plus: Release 12.2.0.1.0 Production on Mon Mar 4 17:30:35 2019
 
Copyright (c) 1982, 2016, Oracle.  All rights reserved.
 
Enter password:
Last Successful login time: Mon Mar 04 2019 17:21:46 -03:00
 
Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
 
SQL> CREATE OR REPLACE PROCEDURE test IS
  2
  3  n NUMBER;
  4
  5  PROCEDURE subprg IS
  6  BEGIN
  7    SELECT COUNT(*) INTO n FROM hr.employees;
  8  END;
  9
 10  BEGIN
 11
 12  FOR idx IN 1..3 LOOP
 13    subprg;
 14  END LOOP;
 15
 16  END;
 17  /
 
Procedure created.

Agora vamos fazer o profiler da procedure pr1

SQL> BEGIN
  2  DBMS_HPROF.start_profiling('PROFILER_DIR','PROFILER_TESTE.txt');
  3  test;
  4  DBMS_HPROF.stop_profiling;
  5  END;
  6  /
 
PL/SQL procedure successfully completed.
 
SQL> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
 
$ cat /home/oracle/profiler/PROFILER_TESTE.txt
P#V PLSHPROF Internal Version 1.0
P#! PL/SQL Timer Started
P#C PLSQL."TERCIOCOSTA"."TEST"::7."TEST"#980980e97e42f8ec #1
P#X 174
P#C PLSQL."TERCIOCOSTA"."TEST"::7."TEST.SUBPRG"#980980e97e42f8ec #5
P#X 19
P#C SQL."TERCIOCOSTA"."TEST"::7."__static_sql_exec_line7" #7."buc0ct9v58ufn"
P#! SELECT COUNT(*) FROM HR.EMPLOYEES
P#X 1349
P#R
P#X 22
P#R
P#X 2
P#C PLSQL."TERCIOCOSTA"."TEST"::7."TEST.SUBPRG"#980980e97e42f8ec #5
P#X 7
P#C SQL."TERCIOCOSTA"."TEST"::7."__static_sql_exec_line7" #7."buc0ct9v58ufn"
P#! SELECT COUNT(*) FROM HR.EMPLOYEES
P#X 54
P#R
P#X 3
P#R
P#X 0
P#C PLSQL."TERCIOCOSTA"."TEST"::7."TEST.SUBPRG"#980980e97e42f8ec #5
P#X 1
P#C SQL."TERCIOCOSTA"."TEST"::7."__static_sql_exec_line7" #7."buc0ct9v58ufn"
P#! SELECT COUNT(*) FROM HR.EMPLOYEES
P#X 39
P#R
P#X 2
P#R
P#X 2
P#R
P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #453
P#R
P#! PL/SQL Timer Stopped

O trecho de código acima, o profiler foi iniciado, executamos a procedure e depois parei o profiler. Após isso eu saí da ferramenta SQL*PLUS, verifiquei que o arquivo no diretório foi criado e logo após imprime na tela o conteúdo do arquivo, que não é muito significante ou utilizável, mas tem alguma lógica, e podemos verificar alguns identificadores, conforme lista abaixo.

P#V – Banner PLSHPROF com o número de versão.
P#C – Chamada a um subprograma
P#R – Retorno do subprograma
P#X – Tempo utilizado entre o evento anterior e o próximo
P#! – Comentário
E para cada chamada a subprograma, o profiler adiciona as seguintes informações:

Namespace ao qual o subprograma pertence, que pode ser PL/SQL ou SQL.
Nome do módulo PL/SQL
Tipo do módulo PL/SQL, que é um número inteiro que representa módulos como procedures, functions e package.
Nome do subprograma.
Valor hexadecimal que representa o MD5 da assinatura do subprograma
E o número da linha em que o subprograma é definido.
Para entender melhor a lista acima, vamos ver na prática o output do profiler feito anteriormente:

P#C PLSQL.”TERCIOCOSTA”.”TEST”::7.”TEST.SUBPRG”#980980e97e42f8ec #5

Namespace: PLSQL
Módulo PL/SQL: terciocosta.test
Tipo do módulo PL/SQL: 7 (representando uma procedure)
Nome do módulo PL/SQL test.subprg
Valor hexadecimal: #980980e97e42f8ec
Linha: 5

__plsql_vm – Chamada ao vitual machine PL/SQL
__anonymous_block – Bloco anônimo
__pkg_init – Execução do bloco de inicialização da package
__dyn_sql_exec_line# - Instrução dinâmica SQL executada na linha informada
__sql_fetch_line# - SQL fetch na linha informada.

Agora vamos para a segunda parte que seria analisar esses dados. Primeiro, vamos fazer o Oracle inserir esses dados nas tabelas que criamos no início do post.

SQL> DECLARE
  2  v_id NUMBER;
  3  BEGIN
  4  v_id := DBMS_HPROF.analyze(location => 'PROFILER_DIR',
  5                             filename => 'PROFILER_TESTE.txt',
  6                             run_comment => 'Profiler teste do blog 
  oraclepress.wordpress.com by Tercio Costa');
  7   dbms_output.put_line('RUN_ID: '||v_id);
  8  END;
  9  /
RUN_ID: 1

PL/SQL procedure successfully completed.

Após isso, as tabelas do profiler já foram preenchidas com as informações necessárias. Na tabela runs podemos ver cada profiler executado.

SELECT *
  2  FROM   dbmshp_runs;
 
     RUNID
----------
RUN_TIMESTAMP
---------------------------------------------------------------------------
TOTAL_ELAPSED_TIME
------------------
RUN_COMMENT
--------------------------------------------------------------------------------
         1
02-FEB-19 01.37.26.005460 AM
               826
Profiler teste do blog oraclepress.wordpress.com by Tercio Costa

Como foi executado apenas uma vez o profiler, a tabela tem apenas uma linha. Agora vamos ver informações sobre o profiler com ID 1.

SQL> SELECT fi.symbolid,
  2       fi.function,
  3       fi.line#,
  4       fi.subtree_elapsed_time  AS SUBTREE_TIME,
  5       fi.function_elapsed_time AS FUNCTION_TIME,
  6       fi.calls
  7  FROM   dbmshp_function_info fi
  8  WHERE  fi.runid = 1;
 
  SYMBOLID FUNCTION                   LINE# SUBTREE_TIME FUNCTION_TIME CALLS
---------- ----------------------- ---------- ------------ ------------- -----
         1 STOP_PROFILING               453     0           0   1
         2 TEST                         1       1674         178   1
         3 TEST.SUBPRG                  5       1496          54   3
         4 __static_sql_exec_line7      7       1442        1442   3
 
SQL> SELECT pc.parentsymid,
  2         pc.childsymid
  3  FROM   dbmshp_parent_child_info pc
  4  WHERE  pc.runid = 1;
 
PARENTSYMID CHILDSYMID
----------- ----------
          2      3
          3      4
 
SQL>

A tabela DBMSHP_FUNCTION_INFO contêm informações sobre os programas executados, além de quantas vezes foram executados e também o tempo que levou. Já na tabela DBMSHP_PARENT_CHILD_INFO, contem informações sobre que programa invocou qual sobprograma. Que no caso nos mostra que o programa 2 chamou o programa 3 e o 3 chamou o 4. Podemos ver esses IDs na tabela DBMSHP_FUNCTION_INFO na coluna SYMBOLID. Com respeito ao tempo, a coluna FUNCTION_ELAPSED_TIME nos mostra o tempo que levou para executar o bloco em questão, e já a coluna SUBTREE_ELAPSED_TIME nos mostra o tempo total, inclusive o tempo gasto nos subprogramas invocados.

Agora, para finalizar, vamos ver o utilitário PLSHPROF, que gera um HTML do profiler executado. Veja como é simples criar esse arquivo HTML logo abaixo

$ plshprof -output hprof PROFILER_TESTE.txt
PLSHPROF: Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
[4 symbols processed]
[Report written to 'hprof.html']

Agora, vamos abrir o arquivo hprof.html no nosso browser, o Google Chorme no caso:

Início da página, com os links para as demais áreas da página.

Exemplo das primeiras partes do arquivo com as informações do profiler

Tércio Costa Formado em Ciências da Computação pela UFPB com experiência em Servidores Windows Server e Linux e banco de dados Oracle desde 2008 juntamente com os seus serviços. Desenvolvimento de Sistemas em Java SE com banco de dados Oracle e MySQL. Certificado Oracle Certified SQL Expert, mantendo o blog https://oraclepress.wordpress.com/ reconhecido pela OTN e articulista no portal http://www.profissionaloracle.com.br/gpo

Este artigo foi revisto pela equipe de produtos Oracle e está em conformidade com as normas e práticas para o uso de produtos Oracle.