Nas publicações anteriores foram abordados os tópicos: como determinar a sequência de execução do plano, como interpretar a estatísticas estimadas e as estatísticas geradas durante a execução do plano, agora vamos abordar algumas seções complementares que fornecem informações importantes para entender por que o plano de execução foi criado com…
Execution Plan: Como interpretar os valores estatísticos coletados durante a execução
No artigo anterior foram abordadas as estatísticas estimadas pelo Otimizador para o plano de execução, agora vamos tratar das estatísticas geradas após a execução do plano, é nesse momento que temos condições de avaliar se o Otimizador acertou em suas estimativas. A eficácia do plano de execução esta diretamente relacionada com a precisão da estimativa dessas estatísticas, ou seja, quanto melhor for a estimativa melhor será o plano de execução.
As estatísticas geradas durante a execução da instrução SQL são também chamadas pelo termo técnico de “Rowsource execution statistics” e suas informações estão disponíveis na visão V$SQL_PLAN_STATISTICS_ALL, nela podemos obter informações do trabalho realizado por cada uma das operações do plano de execução, incluindo o número de vezes que cada operação foi chamada, numero de “buffers” acessados, se o acesso foi em “consistent mode” ou “current mode”, número de leituras físicas e lógicas, total de tempo gasto por cada operação e varias outras informações sobre utilização “workarea”.
A base utilizada para gerar os planos de execução nesse artigo foi Oracle Database 11.2.0.4 e para gerar esse planos utilizamos o pacote DBMS_XPLAN, se você tiver dúvidas quanto a utilização deste pacote consulte o artigo “DBMS_XPLAN: você sabe usar esse extraordinário pacote?“
WORKAREA
As instruções SQL utilizadas nesse artigo foram escritas de forma a gerar planos de execução que possibilitem a explicação das estatísticas geradas em tempo de execução e não são bons exemplos de consultas em termos de desempenho. A seguir vamos executar uma instrução SQL simples sem ativar “Rowsource execution statistics” e verificar o que o pacote DBMS_XPLAN.DISPLAY_CURSOR() nos fornece de informação:
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 | dbauser@LAB11 >ALTER SESSION SET statistics_level=TYPICAL; Session altered. dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 >select /*+ UNNEST */ object_type, 2 count(1) as sub_total 3 from (select owner, object_type, count(1) as qtde from my_objects group by owner, object_type) 4 group by object_type 5 order by 2 desc; OBJECT_TYPE SUB_TOTAL ------------------- ---------- TABLE 125 INDEX 119 SEQUENCE 103 SYNONYM 93 PACKAGE 91 ... ... EDITION 1 CLUSTER 1 TABLE SUBPARTITION 1 46 rows selected. dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 >column sql_id new_value m_sql_id dbauser@LAB11 >column child_number new_value m_child_no dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 >SELECT sql_id, child_number 2 FROM v$sql 3 WHERE sql_text LIKE '%UNNEST%' 4 and sql_text LIKE '%my_objects%' 5 AND sql_text NOT LIKE '%v$sql%'; SQL_ID CHILD_NUMBER ------------- ------------ bpv0k45r54w9y 0 bpv0k45r54w9y 1 dbauser@LAB11 > dbauser@LAB11 >SELECT * 2 FROM TABLE (dbms_xplan.display_cursor ('&m_sql_id',&m_child_no,'allstats last')); old 2: FROM TABLE (dbms_xplan.display_cursor ('&m_sql_id',&m_child_no,'allstats last')) new 2: FROM TABLE (dbms_xplan.display_cursor ('bpv0k45r54w9y', 1,'allstats last')) PLAN_TABLE_OUTPUT ---------------------------------------------------------------------------------------------------------------- SQL_ID bpv0k45r54w9y, child number 1 ------------------------------------- select /*+ UNNEST */ object_type, count(:"SYS_B_0") as sub_total from (select owner, object_type, count(:"SYS_B_1") as qtde from my_objects group by owner, object_type) group by object_type order by :"SYS_B_2" desc Plan hash value: 2143035820 -------------------------------------------------------------------------------- | Id | Operation | Name | E-Rows | OMem | 1Mem | Used-Mem | -------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | | | | 1 | SORT ORDER BY | | 46 | 2048 | 2048 | 2048 (0)| | 2 | HASH GROUP BY | | 46 | 1200K| 1200K| 1335K (0)| | 3 | VIEW | | 5920 | | | | | 4 | HASH GROUP BY | | 5920 | 10M| 2855K| 2610K (0)| | 5 | TABLE ACCESS FULL| MY_OBJECTS | 119K| | | | -------------------------------------------------------------------------------- Note ----- - Warning: basic plan statistics not available. These are only collected when: * hint 'gather_plan_statistics' is used for the statement or * parameter 'statistics_level' is set to 'ALL', at session or system level 26 rows selected. dbauser@LAB11 > |
No inicio do processo acima, o parâmetro “statistics_level” foi definido como “TYPICAL”, nesta situação a coleta de estatísticas “Rowsource execution” esta desativada e o plano de execução vai omitir varias informações estatísticas importantes, alem disso se você verificar na seção “Note” logo abaixo do plano de execução existe a informação de que para obter essas informações estatísticas temos que utilizar o “hint gather_plan_statistics” ou definir o parâmetro ‘statistics_level’ como ‘ALL’.
O parâmetro “LAST” utilizado na função “DISPLAY_CURSOR” do pacote DBMS_XPLAN determina que somente as estatísticas da ultima execução serão exibidas. Nesta simulação o plano de execução mostra três colunas estatísticas relativas a “WORKAREA” ou área de trabalho:
OMem: Quantidade de espaço na memoria que o Oracle estima que será necessária para executar a operação.
1Mem: Valor de memoria acima do qual o Oracle ainda consegue realizar a operação com “ONE-PASS WORKAREA”.
Used-Mem: Memoria que foi utilizada na ultima execução.
Caso você deseje saber como foi a utilização da memoria de varias execuções do mesma instrução SQL, podemos executar a função DISPLAY_CURSOR sem a opção “LAST”.
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 | dbauser@LAB11 >SELECT * 2 FROM TABLE (dbms_xplan.display_cursor ('&m_sql_id',&m_child_no,'allstats')); old 2: FROM TABLE (dbms_xplan.display_cursor ('&m_sql_id',&m_child_no,'allstats')) new 2: FROM TABLE (dbms_xplan.display_cursor ('bpv0k45r54w9y', 0,'allstats')) PLAN_TABLE_OUTPUT ---------------------------------------------------------------------------------------------- SQL_ID bpv0k45r54w9y, child number 0 ------------------------------------- select /*+ UNNEST */ object_type, count(:"SYS_B_0") as sub_total from (select owner, object_type, count(:"SYS_B_1") as qtde from my_objects group by owner, object_type) group by object_type order by :"SYS_B_2" desc Plan hash value: 2143035820 -------------------------------------------------------------------------------- | Id | Operation | Name | E-Rows | OMem | 1Mem | O/1/M | -------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | | | | 1 | SORT ORDER BY | | 46 | 2048 | 2048 | 3/0/0| | 2 | HASH GROUP BY | | 46 | 1200K| 1200K| 3/0/0| | 3 | VIEW | | 5920 | | | | | 4 | HASH GROUP BY | | 5920 | 10M| 2855K| 3/0/0| | 5 | TABLE ACCESS FULL| MY_OBJECTS | 119K| | | | -------------------------------------------------------------------------------- Note ----- - Warning: basic plan statistics not available. These are only collected when: * hint 'gather_plan_statistics' is used for the statement or * parameter 'statistics_level' is set to 'ALL', at session or system level 26 rows selected. dbauser@LAB11 > |
Na simulação acima podemos observar que a coluna “Used-Mem” foi substituída por “O/1/M”, essa coluna mostra as estatísticas de três situações na sequência, a primeira representa o numero de vezes que o Oracle realizou a operação na memoria, no caso acima foram 3 vezes, a segunda representa o numero de execuções com “ONE-PASS”, ou seja, não foi possível realizar toda a operação na memória que para a nossa simulação foi zero e a terceira representa o numero de execuções com “MULTI-PASS”, quando esta situação ocorrer o tempo de reposta da instrução SQL fica muito ruim, também neste caso a nossa simulação indica que não houve ocorrência.
EXECUTION STATISTICS
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:
A seguir vamos analisar um plano de execução onde as “Rowsource execution statistics” vão ser ativadas utilizando o parâmetro “statistics_level” definido a nível de sessão como “ALL”. É importante lembrar que não é recomendado definir esse parâmetro como “ALL” a nível de sistema, pois isso vai causar um carga extra no banco de dados e degradar o tempo de resposta de todas as instruções SQL desse banco. Outra observação importante é que se for utilizado o “hint gather_plan_statistics” para ativar as “Rowsource execution statistics” a coluna “A-TIME” que representa o tempo gasto nas operações apresentará valores não confiáveis.
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 | dbauser@LAB11 >ALTER SESSION SET statistics_level=ALL; Session altered. dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 >WITH OBJ AS ( 2 select owner, object_type, object_name, status from my_objects order by 1,2,3 3 ) 4 select /*+ USE_NL(o t) */ t.owner, 5 o.object_type, 6 count(1) nunber_of_obj 7 from OBJ o, 8 MY_TABLES t 9 where t.owner = o.owner 10 and t.owner in ('XDB','SYSMAN','SYS') 11 group by t.owner, o.object_type 12 order by 1,2; OWNER OBJECT_TYPE NUNBER_OF_OBJ ------------------------------ ------------------- ------------- SYS CLUSTER 10220 SYS CONSUMER GROUP 25550 SYS CONTEXT 7154 ... SYSMAN EVALUATION CONTEXT 1456 SYSMAN FUNCTION 8736 SYSMAN INDEX 748384 ... XDB FUNCTION 192 XDB INDEX 14464 XDB INDEXTYPE 64 ... 73 rows selected. dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 >column sql_id new_value m_sql_id dbauser@LAB11 >column child_number new_value m_child_no dbauser@LAB11 > dbauser@LAB11 > dbauser@LAB11 >SELECT sql_id, child_number 2 FROM v$sql 3 WHERE sql_text LIKE '%USE_NL(o t)%' 4 AND sql_text NOT LIKE '%v$sql%'; SQL_ID CHILD_NUMBER ------------- ------------ caj292vwr7n01 0 dz461gr7wmqh7 0 2 rows selected. dbauser@LAB11 > dbauser@LAB11 >SELECT * 2 FROM TABLE (dbms_xplan.display_cursor ('&m_sql_id',&m_child_no,'allstats last')); PLAN_TABLE_OUTPUT ---------------------------------------------------------------------------------------------------------------------------------------------------------------- SQL_ID dz461gr7wmqh7, child number 0 ------------------------------------- WITH OBJ AS ( select owner, object_type, object_name, status from my_objects order by :"SYS_B_0",:"SYS_B_1",:"SYS_B_2" ) select /*+ USE_NL(o t) */ t.owner, o.object_type, count(:"SYS_B_3") nunber_of_obj from OBJ o, MY_TABLES t where t.owner = o.owner and t.owner in (:"SYS_B_4",:"SYS_B_5",:"SYS_B_6") group by t.owner, o.object_type order by :"SYS_B_7",:"SYS_B_8" Plan hash value: 1844763738 -------------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp| -------------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 73 |00:00:22.05 | 246K| 885 | 873 | | | | | | 1 | SORT GROUP BY NOSORT | | 1 | 98 | 73 |00:00:22.05 | 246K| 885 | 873 | | | | | | 2 | NESTED LOOPS | | 1 | 33945 | 41M|00:00:14.45 | 246K| 885 | 873 | | | | | | 3 | VIEW | | 1 | 15474 | 42603 |00:00:02.24 | 1802 | 873 | 873 | | | | | | 4 | SORT ORDER BY | | 1 | 15474 | 42603 |00:00:02.23 | 1802 | 873 | 873 | 2772K| 749K|67584 (25| 3072 | |* 5 | TABLE ACCESS FULL| MY_OBJECTS | 1 | 15474 | 42603 |00:00:00.03 | 1701 | 0 | 0 | | | | | |* 6 | INDEX RANGE SCAN | MY_TABLES_IDX | 42603 | 2 | 41M|00:00:07.76 | 245K| 12 | 0 | | | | | -------------------------------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 5 - filter((INTERNAL_FUNCTION("OWNER") AND INTERNAL_FUNCTION("OWNER"))) 6 - access("T"."OWNER"="O"."OWNER") filter(("T"."OWNER"=:SYS_B_4 OR "T"."OWNER"=:SYS_B_5 OR "T"."OWNER"=:SYS_B_6)) 30 rows selected. dbauser@LAB11 > |
Analisando o plano acima verificamos que foram incluídas varias colunas estatísticas, a seguir vamos descrever o que representa cada uma delas:
Starts: Número de vezes que a operação dessa linha foi executada.
E-rows: Estimativa de registros que serão entregues a operação pai por uma execução da operação dessa linha.
A-rows: Número acumulado de registros que serão entregues a operação pai de todas as execuções da operação dessa linha.
A-time: Tempo gasto na execução da operação dessa linha incluindo os tempos da operações descendentes.
Buffers: Número de “buffers” acessados na execução da operação dessa linha incluindo seus descendentes.
Reads: Número de blocos lidos do disco na execução da operação dessa linha incluído seus descendentes.
Writes: Número de blocos gravados em disco na execução da operação dessa linha incluindo seus descendentes.
Used-Tmp: Quantidade de espaço utilizando na tablespace temporária em KB para execução da operação dessa linha.
LEITURA DO PLANO DE EXECUÇÃO
1 2 3 4 5 6 7 8 9 10 11 12 13 | Plan hash value: 1844763738 -------------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp| -------------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 73 |00:00:22.05 | 246K| 885 | 873 | | | | | | 1 | SORT GROUP BY NOSORT | | 1 | 98 | 73 |00:00:22.05 | 246K| 885 | 873 | | | | | | 2 | NESTED LOOPS | | 1 | 33945 | 41M|00:00:14.45 | 246K| 885 | 873 | | | | | | 3 | VIEW | | 1 | 15474 | 42603 |00:00:02.24 | 1802 | 873 | 873 | | | | | | 4 | SORT ORDER BY | | 1 | 15474 | 42603 |00:00:02.23 | 1802 | 873 | 873 | 2772K| 749K|67584 (25| 3072 | |* 5 | TABLE ACCESS FULL| MY_OBJECTS | 1 | 15474 | 42603 |00:00:00.03 | 1701 | 0 | 0 | | | | | |* 6 | INDEX RANGE SCAN | MY_TABLES_IDX | 42603 | 2 | 41M|00:00:07.76 | 245K| 12 | 0 | | | | | -------------------------------------------------------------------------------------------------------------------------------------------------------- |
Utilizando as regras apresentadas no artigo “Execution Plan: Como verificar a ordem que as operações são realizadas?” chegamos a conclusão que as operações desse plano são executadas na seguinte ordem: 5,4,3,6,2,1,0.
(5) A primeira operação a ser executada foi “TABLE ACCESS FULL” na tabela “MY_OBJECTS”, o Otimizador estimou que seriam lidos 15.474 registros e durante a execução foram lidos 42.603 registros, o tempo gasto nesta operação foi de 3 centésimos de segundo e foram lidos 1701 blocos do “Buffer cache”.
(4) A segunda operação a ser executada foi “SORT ORDER BY” dos registros (42.603) selecionados na operação filha (5), essa operação teve uma duração de 2 segundos e 20 centésimos de segundo, porem na linha da operação temos 2 segundos e 23 centésimos de segundo pois esse valor acumula os tempos da operações filhas, nessa operação alem dos 101 blocos de lidos do “Buffer cache” (1701 + 101 = 1802), temos 873 blocos de leitura de disco, 873 blocos de gravação em disco e 3.072 KB de utilização da tablespace de segmentos temporários. Essas estatísticas adicionais aparecem pois a operação “SORT ORDER BY” precisa de uma área de trabalho e nesse caso a área de memoria (SORT_AREA_SIZE) destinada para esta atividade foi insuficiente e o banco teve que utilizar a tablespace de segmentos temporários para concluir a operação.
(3) A terceira operação a ser executada foi “VIEW”, o tempo gasto para executar esta operação foi 1 centésimo de segundo (lembrando que o valor apresentado é um acumulado dos tempos da operações filhas 2.23 + 0.01 = 2.24), as demais colunas estatísticas repetem o valores da operação filha pois são colunas de valores acumulados.
(6) A quarta operação a ser executada foi “INDEX RANGE SCAN” no índice “MY_TABLES_IDX”, neste caso o Otimizador estimou 2 registros (E-Rows) e foram lidos 41 milhões (A-Rows), nessa operação podemos observar que diferente das demais operações, a coluna “Starts” apresenta o valor de 42603 que significa que esta operação foi executada 42603 vezes. Isso explica por que somente esta operação consumiu o tempo de 7 segundos e 76 centésimos de segundos, fez a leitura de 245 mil blocos no “Buffer Cache” e 12 leituras físicas. É importante observar que esta operação não tem operações filhas, logo os valores estatísticas são exclusivos dela.
(2) A quinta operação a ser executada foi “NESTED LOOPS”, na verdade devido a natureza dessa operação, a operação filha (6) é executada em conjunto com essa operação até o fim do “LOOP”, para definição de sequência dizemos que a operação (6) foi executada primeiro pois ela é filha e sempre vai gerar informação para a operação pai (2). No plano observamos que o Otimizador estimou 33945 registros quando na verdade foram lidos 41 milhões, o tempo de duração dessa operação foi de 4 segundos e 45 centésimos de segundo pois os 10 segundos adicionais que aparecem no plano são das operações filhas 3 e 6 (2.24 + 7.76 = 10). O demais valores estatísticos são valores acumulados e são resultado da soma das operações filhas.
(1) A sexta operação a ser executada foi “SORT GROUP BY NOSORT”, nessa operação o Otimizador estimou que seriam tratados 98 registros e após execução foram 73 registros, com um tempo de duração de 22 segundos e cinco centésimos acumulando os tempos de todas as operações descendentes. Demais estatísticas permaneceram inalteradas e como são valores acumulados significa que para essas colunas não houve atividade.
Conclusão
As estatísticas geradas em tempo de execução são uma fonte importante de informação para analise do desempenho da instrução SQL, através dela conseguimos saber se o Otimizador conseguiu estimar corretamente a quantidade de registro para cada operação, conseguimos identificar qual operação esta com duração de tempo maior, conseguimos ver se a ordem de junção das tabelas é a mais adequada e muito mais. Existem muitas técnicas de tuning que podem ser aplicadas para melhoria de desempenho de instruções SQL, mas em quase todas você precisa saber interpretar corretamente as estatísticas que são exibidas no plano de execução para obter sucesso nesse trabalho.
Referências
http://allthingsoracle.com/execution-plans-part-11-actuals/
http://docs.oracle.com/cd/E11882_01/server.112/e40402/dynviews_3057.htm#REFRN30252
