Você escreveu seu código PL/SQL (Procedure, Function ou Package) e na hora de testar descobre que o desempenho não esta satisfatório, e agora? o que fazer? A versão do banco Oracle 11g dispõe do recurso Hierarchical Profiler que permite medir o desempenho de cada linha de código do PL/SQL, com a…
Você sabe identificar consultas demoradas no código PL/SQL?
Durante o desenvolvimento ou alteração de um código PL/SQL eventualmente o desempenho ou tempo de execução deste código pode ser insatisfatório, dependendo do tamanho código e de quantas instruções SQL existem nele pode haver certa dificuldade para identificar qual ou quais instruções SQL estão causando a perda de desempenho, para ajudar a identificar as instruções do código que estão com baixo desempenho você pode utilizar o pacote DBMS_TRACE.
A proposta deste artigo é mostrar um exemplo prático de como podemos utilizar o pacote DBMS_TRACE para identificar num código PL/SQL qual é a consulta que está com baixo desempenho, fazer a melhoria necessária e validar a solução apresentada.
Para realizar esta demonstração prática vamos executar as seguintes etapas:
1) Configurar o banco para usar o pacote DBMS_TRACE
2) Criar os objetos para a demonstração
3) Executar a procedure habilitando o trace
4) Analisar as informações geradas no trace
5) Aplicar melhoria no banco
6) Executar a procedure novamente habilitando o trace
7) Analisar as informações geradas no trace após melhoria
1) Configurar o banco para usar o pacote DBMS_TRACE
Nesta etapa vamos executar o script TRACETAB.sql que esta disponível no diretório HOME do banco, para criar os objetos necessários na utilização do pacote DBMS_TRACE.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 | [oracle@odbsrv11 ~]$ sqlplus / as sysdba SQL*Plus: Release 11.2.0.4.0 Production on Mon Jul 15 10:05:19 2020 Copyright (c) 1982, 2013, Oracle. All rights reserved. Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP, Data Mining and Real Application Testing options SQL> @?/rdbms/admin/tracetab.sql Table dropped. Table dropped. Sequence dropped. Table created. Comment created. Table created. Comment created. Sequence created. SQL> grant select on PLSQL_TRACE_EVENTS to public; Grant succeeded. SQL> grant select on PLSQL_TRACE_RUNS to public; Grant succeeded. SQL> grant execute on DBMS_TRACE to SH; Grant succeeded. SQL> create public synonym PLSQL_TRACE_RUNS for SYS.PLSQL_TRACE_RUNS; Synonym created. SQL> create public synonym PLSQL_TRACE_EVENTS for SYS.PLSQL_TRACE_EVENTS; Synonym created. SQL> set lines 300 pages 100 col OWNER for a16; col OBJECT_NAME for a30; col OBJECT_TYPE for a30; SELECT owner, object_name, object_type FROM dba_objects WHERE object_name like 'PLSQL_TRACE%' ORDER by 2, 1; SQL> SQL> SQL> SQL> 2 3 4 OWNER OBJECT_NAME OBJECT_TYPE ---------------- ------------------------------ ------------------------------ PUBLIC PLSQL_TRACE_EVENTS SYNONYM SYS PLSQL_TRACE_EVENTS TABLE SYS PLSQL_TRACE_RUNNUMBER SEQUENCE PUBLIC PLSQL_TRACE_RUNS SYNONYM SYS PLSQL_TRACE_RUNS TABLE SQL> |
Obs: Foi atribuído o grant de EXECUTE no pacote DBMS_TRACE para o owner SH, pois vamos utilizar este usuário em nossa simulação.
2) Criar os objetos para a demonstração
Ajudo DBAs e analistas de sistema a se destacarem em suas empresas
e obter um crescimento mais acelerado em suas carreiras, quer saber mais click no link abaixo:
Agora vamos criar os objetos para nossa demonstração, uma tabela e uma procedure no schema SH.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 | NOT CONNECTED > conn sh/sh@lab11 Connected. SQL > SQL > alter session set workarea_size_policy=MANUAL; Session altered. Elapsed: 00:00:00.00 SQL > SQL > alter session set sort_area_size=2000000000; Session altered. Elapsed: 00:00:00.00 SQL > SQL > create table dbtw065 as 2 select 'DBTimeWizard - Performance and Tuning' as produto, 3 mod(rownum,5) as codigo, 4 mod(rownum,1000) as cliente_id , 5 round(dbms_random.value(10000,0))as postal_id, 6 5000 as total_vendas, 7 trunc(sysdate - 9999 + mod(rownum,10000)) as data_venda 8 from dual connect by level<=2e7; Table created. Elapsed: 00:03:48.77 SQL > SQL > SQL > alter table dbtw065 nologging; Table altered. Elapsed: 00:00:00.15 SQL > SQL > insert /*+ append */ into dbtw065 select * from dbtw065; 20000000 rows created. Elapsed: 00:02:11.83 SQL > SQL > commit; Commit complete. Elapsed: 00:00:00.01 SQL > SQL > exec dbms_stats.gather_table_stats(ownname=> USER, tabname=> 'DBTW065', cascade=> true, method_opt=> 'FOR ALL COLUMNS SIZE SKEWONLY'); PL/SQL procedure successfully completed. Elapsed: 00:04:44.33 SQL > SQL > alter table dbtw065 logging; Table altered. Elapsed: 00:00:00.03 SQL > SQL > CREATE OR REPLACE PROCEDURE dbtw065_prc 2 IS 3 contador number; 4 CURSOR c_dbtw IS 5 select /* dbtw-065.2 */ * 6 from dbtw065 7 where cliente_id = 711 8 and postal_id = 7348; 9 r_dbtw c_dbtw%ROWTYPE; 10 11 12 BEGIN 13 14 -- Consulta 1 15 select /* dbtw-065.1 */ count(1) into contador from ( 16 select c.CUST_ID, 17 sum(amount_sold) total_sold 18 from sh.sales s, 19 sh.customers c 20 where c.cust_id=s.cust_id 21 and cust_state_province = 'Barcelona' 22 group by c.cust_id) 23 where total_sold > 50000; 24 25 -- Consulta 2 26 OPEN c_dbtw; 27 LOOP 28 FETCH c_dbtw INTO r_dbtw; 29 EXIT WHEN c_dbtw%NOTFOUND; 30 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id||' postal_id: '||r_dbtw.postal_id); 31 END LOOP; 32 CLOSE c_dbtw; 33 34 -- Consulta 3 35 SELECT /* dbtw-065.3 */ count(1) into contador 36 FROM sh.customers c, 37 sh.sales s 38 WHERE c.cust_id = s.cust_id 39 AND c.country_id = 52776 40 AND s.channel_id = 2 41 AND (c.cust_last_name like 'Ly%' 42 OR c.cust_last_name like 'Ry%'); 43 44 END; 45 / Procedure created. Elapsed: 00:00:00.40 SQL > |
3) Executar a procedure habilitando o trace
Para realizar o trace da procedure precisamos habilita-lo antes da execução e desativa-lo após a execução, a seguir vamos executar um bloco PL/SQL anonimo com esta sequência.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 | SQL > set serveroutput on size 9999 SQL > alter session set current_schema = sh; Session altered. Elapsed: 00:00:00.00 SQL > SQL > begin 2 3 dbms_trace.set_plsql_trace(dbms_trace.trace_all_lines); 4 dbtw065_prc; 5 dbms_trace.clear_plsql_trace; 6 7 end; 8 / cliente_id: 711 postal_id: 7348 cliente_id: 711 postal_id: 7348 cliente_id: 711 postal_id: 7348 cliente_id: 711 postal_id: 7348 PL/SQL procedure successfully completed. Elapsed: 00:00:59.89 SQL > |
4) Analisar as informações geradas no trace
Consultando a tabela PLSQL_TRACE_EVENTS podemos obter um relatório da execução da nossa procedure mostrando os tempos consumidos em cada passo.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 | SQL > set lines 300 pages 100 SQL > col EVENT_TIME for a24; SQL > col PROC_OWNER for a16; SQL > col EVENT_COMMENT for a40; SQL > col CMD-PROC for a60; SQL > SQL > select te.EVENT_SEQ 2 ,to_char(te.EVENT_TIME,'dd-mm-yyyy hh24:mi:ss') EVENT_TIME 3 ,SUBSTR(src.text,1,60) "CMD-PROC" 4 from plsql_trace_events te 5 left JOIN (select * 6 from all_source 7 where name = 'DBTW065_PRC' 8 AND owner = 'SH') src 9 ON (te.event_unit_owner=src.owner and te.event_unit=src.name and te.event_line=src.line) 10 where te.runid = (select max(runid) from plsql_trace_runs) 11 and te.event_unit_owner <> 'SYS' 12 order by 1; EVENT_SEQ EVENT_TIME CMD-PROC ---------- ------------------------ ------------------------------------------------------------ 8 15-07-2020 10:53:40 PROCEDURE dbtw065_prc 9 15-07-2020 10:53:40 select /* dbtw-065.1 */ count(1) into contador from ( 10 15-07-2020 10:53:42 OPEN c_dbtw; 11 15-07-2020 10:53:42 select /* dbtw-065.2 */ * 12 15-07-2020 10:53:42 OPEN c_dbtw; 13 15-07-2020 10:53:42 LOOP 14 15-07-2020 10:53:42 FETCH c_dbtw INTO r_dbtw; 15 15-07-2020 10:54:01 EXIT WHEN c_dbtw%NOTFOUND; 16 15-07-2020 10:54:01 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 45 15-07-2020 10:54:01 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 46 15-07-2020 10:54:01 LOOP 47 15-07-2020 10:54:01 FETCH c_dbtw INTO r_dbtw; 48 15-07-2020 10:54:04 EXIT WHEN c_dbtw%NOTFOUND; 49 15-07-2020 10:54:04 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 70 15-07-2020 10:54:04 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 71 15-07-2020 10:54:04 LOOP 72 15-07-2020 10:54:04 FETCH c_dbtw INTO r_dbtw; 73 15-07-2020 10:54:30 EXIT WHEN c_dbtw%NOTFOUND; 74 15-07-2020 10:54:30 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 95 15-07-2020 10:54:30 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 96 15-07-2020 10:54:30 LOOP 97 15-07-2020 10:54:30 FETCH c_dbtw INTO r_dbtw; 98 15-07-2020 10:54:31 EXIT WHEN c_dbtw%NOTFOUND; 99 15-07-2020 10:54:31 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 120 15-07-2020 10:54:31 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 121 15-07-2020 10:54:31 LOOP 122 15-07-2020 10:54:31 FETCH c_dbtw INTO r_dbtw; 123 15-07-2020 10:54:38 EXIT WHEN c_dbtw%NOTFOUND; 124 15-07-2020 10:54:38 CLOSE c_dbtw; 125 15-07-2020 10:54:38 SELECT /* dbtw-065.3 */ count(1) into contador 126 15-07-2020 10:54:40 END; 31 rows selected. SQL > |
Observe que a subtração do tempo final da execução pelo tempo inicial corresponde a 60 segundos que é o tempo de execução procedure.
O ponto da procedure que consumiu mais tempo foi entre os EVENT_SEQ 72 e 73, neste ponto foram gastos 26 segundos para realizar o comando FETCH no cursor C_DBTW, este cursor executa a consulta DBTW-065.2.
Os outros pontos onde os tempos de duração foram elevados na procedure são todos relacionados ao comando FETCH no cursor C_DBTW, portanto concluímos que precisamos otimizar a consulta DBTW-065.2 para baixar o tempo de execução da procedure.
5) Aplicar melhoria no banco
A consulta DBTW-065.2 possui dois filtros na clausula WHERE para as colunas POSTAL_ID e CLIENTE_ID, vamos criar um índice composto na tabela DBTW065 incluindo estas duas colunas. Se você quiser saber mais sobre índice composto leia o artigo: Quando devemos criar um índice composto?
1 2 3 4 5 6 7 8 9 10 11 12 | SQL > create index idx_dbtw065 on dbtw065(postal_id,cliente_id) parallel 16; Index created. Elapsed: 00:00:24.94 SQL > SQL > alter index idx_dbtw065 noparallel; Index altered. Elapsed: 00:00:00.01 SQL > |
6) Executar a procedure novamente habilitando o trace
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 | SQL > set serveroutput on size 9999 SQL > alter session set current_schema = sh; Session altered. Elapsed: 00:00:00.00 SQL > SQL > begin 2 3 dbms_trace.set_plsql_trace(dbms_trace.trace_all_lines); 4 dbtw065_prc; 5 dbms_trace.clear_plsql_trace; 6 7 end; 8 / cliente_id: 711 postal_id: 7348 cliente_id: 711 postal_id: 7348 cliente_id: 711 postal_id: 7348 cliente_id: 711 postal_id: 7348 PL/SQL procedure successfully completed. Elapsed: 00:00:04.46 SQL > |
Observando o tempo de execução da procedure podemos verificar que houve uma melhora significativa, o tempo de execução da procedure caiu de 60 segundos para 4 segundos e 46 centésimos de segundo. Houve uma redução de 92,5% no tempo de execução da procedure.
7) Analisar as informações geradas no trace após melhoria
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 | SQL > set lines 300 pages 100 SQL > col EVENT_TIME for a24; SQL > col PROC_OWNER for a16; SQL > col EVENT_COMMENT for a40; SQL > col CMD-PROC for a60; SQL > SQL > select te.EVENT_SEQ 2 ,to_char(te.EVENT_TIME,'dd-mm-yyyy hh24:mi:ss') EVENT_TIME 3 ,SUBSTR(src.text,1,60) "CMD-PROC" 4 from plsql_trace_events te 5 left JOIN (select * 6 from all_source 7 where name = 'DBTW065_PRC' 8 AND owner = 'SH') src 9 ON (te.event_unit_owner=src.owner and te.event_unit=src.name and te.event_line=src.line) 10 where te.runid = (select max(runid) from plsql_trace_runs) 11 and te.event_unit_owner <> 'SYS' 12 order by 1; EVENT_SEQ EVENT_TIME CMD-PROC ---------- ------------------------ ------------------------------------------------------------ 7 15-07-2020 10:59:11 PROCEDURE dbtw065_prc 8 15-07-2020 10:59:11 select /* dbtw-065.1 */ count(1) into contador from ( 9 15-07-2020 10:59:13 OPEN c_dbtw; 10 15-07-2020 10:59:13 select /* dbtw-065.2 */ * 11 15-07-2020 10:59:13 OPEN c_dbtw; 12 15-07-2020 10:59:13 LOOP 13 15-07-2020 10:59:13 FETCH c_dbtw INTO r_dbtw; 14 15-07-2020 10:59:13 EXIT WHEN c_dbtw%NOTFOUND; 15 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 44 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 45 15-07-2020 10:59:13 LOOP 46 15-07-2020 10:59:13 FETCH c_dbtw INTO r_dbtw; 47 15-07-2020 10:59:13 EXIT WHEN c_dbtw%NOTFOUND; 48 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 69 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 70 15-07-2020 10:59:13 LOOP 71 15-07-2020 10:59:13 FETCH c_dbtw INTO r_dbtw; 72 15-07-2020 10:59:13 EXIT WHEN c_dbtw%NOTFOUND; 73 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 94 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 95 15-07-2020 10:59:13 LOOP 96 15-07-2020 10:59:13 FETCH c_dbtw INTO r_dbtw; 97 15-07-2020 10:59:13 EXIT WHEN c_dbtw%NOTFOUND; 98 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 119 15-07-2020 10:59:13 dbms_output.put_line('cliente_id: '||r_dbtw.cliente_id 120 15-07-2020 10:59:13 LOOP 121 15-07-2020 10:59:13 FETCH c_dbtw INTO r_dbtw; 122 15-07-2020 10:59:13 EXIT WHEN c_dbtw%NOTFOUND; 123 15-07-2020 10:59:13 CLOSE c_dbtw; 124 15-07-2020 10:59:13 SELECT /* dbtw-065.3 */ count(1) into contador 125 15-07-2020 10:59:15 END; 31 rows selected. SQL > |
Verificando o relatório gerado pela consulta na tabela PLSQL_TRACE_EVENTS, constatamos que todas as chamadas do comando FETCH foram executadas em menos de 1 segundo e os quatro segundos gastos na execução da procedure foram consumidos pelas outras duas consultas que faziam parte da procedure.
Referências
https://docs.oracle.com/cd/E18283_01/appdev.112/
