Você sabe identificar consultas demoradas no código PL/SQL?

Otimizar PLSQL

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

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/

 
 
 
Promo-D75L

video-02
 
 
 
 
 
 
 
 
 
 
 
 

Deixe uma resposta

O seu endereço de email não será publicado. Campos obrigatórios são marcados com *