plpgsql profiling

Um profiler é uma ferramenta para análise de performance de chamadas e procedures internas de sua aplicação.

Desde a versão 8.2 do postgres está disponível no pgfoundry o pldebugger, uma ferramenta de análise de plpgsql e depuração desenvolvida pela enterprisedb.

O modo de instalação é semelhante a qualquer outro módulo do contrib:

- colocar o pldebugger.tgz na raiz do código fonte do postgres;
- tar -zxvf pldebugger.tgz;
- cd pldebugger && make && make install;
- psql -c “LOAD ‘`pg_config –pkglibdir`/plugins/plugin_profiler’”; // ou adicione no postgresql.conf

Após carregar a biblioteca do profiler no banco são criadas novas variáveis de configuração runtime no postgres: plpgsql.profiler_tablename e profiler_filename.

O pldebugger possibilita encaminhar os resultados de uma sessão do profiler em arquivos no formato XML ou armazenar em uma tabela do banco.

Inicialmente vamos verificar como ficam os resultados em uma tabela.

Criar uma função para analisar (espero que tenham problemas mais complexos para profiling…):

-- Comment: Sem inspiração: Desculpe mas não estava inspirado pra arrumar outra forma de gravar no disco ...
  1 CREATE OR REPLACE FUNCTION itera(OUT x NAME, OUT y OID)
  2 RETURNS SETOF record
  3 LANGUAGE 'plpgsql' VOLATILE
  4 COST 100
  5 ROWS 240
  6 SET plpgsql.profiler_tablename TO profiler_itera
  7 AS
  8 $_$
  9 DECLARE
 10   i RECORD;
 11   j RECORD;
 12 BEGIN
 13   DROP TABLE IF EXISTS foobar;
 14   CREATE TEMP TABLE foobar(a OID,b NAME);
 15   FOR i IN SELECT OID,relname
 16                   FROM pg_class
 17            GROUP BY 1,2
 18            ORDER BY 2,1
 19   LOOP
 20     FOR j IN SELECT attrelid,attname FROM pg_attribute
 21               WHERE attrelid = i.OID
 22            GROUP BY 2,1
 23            ORDER BY 1,2
 24     LOOP
 25         x := j.attname;
 26         y := j.attrelid;
 27         INSERT INTO foobar VALUES (y,x);
 28     END LOOP;
 29     RETURN NEXT;
 30   END LOOP;
 31   RETURN;
 32 END;
 33 $_$;

De acordo com a definição de nossa funcão, na linha seis, configuramos a variável profiler_tablename com o valor profilter_itera. Isto quer dizer que os resultados serão armazenados em uma tabela dentro da base atual com a seguinte definição:

          Table "public.profiler_itera"
+-----------------+------------------+-----------+
|     Column      |       Type       | Modifiers |
+-----------------+------------------+-----------+
| sourcecode      | text             |           |
| func_oid        | oid              |           |
| line_number     | integer          |           |
| exec_count      | bigint           |           |
| tuples_returned | bigint           |           |
| time_total      | double precision |           |
| time_longest    | double precision |           |
| num_scans       | bigint           |           |
| tuples_fetched  | bigint           |           |
| tuples_inserted | bigint           |           |
| tuples_updated  | bigint           |           |
| tuples_deleted  | bigint           |           |
| blocks_fetched  | bigint           |           |
| blocks_hit      | bigint           |           |
+-----------------+------------------+-----------+

Cada linha desta tabela traz a informação relevante a um deteminado ponto de execução da função. Então para esta função que possue dezessete linhas de código fonte (contando quebras e identação), essa tabela possuirá 17 tuplas (registros/linhas) com informações pertencentes a execução da função itera() óbviamente não estimando o custo computacional de uma quebra de linha.

A saída é algo parecido com:

                                        "Saida de profiling"
+----------------------------------------------------------+------------+------------+--------------+
|                        sourcecode                        | exec_count | time_total | time_longest |
+----------------------------------------------------------+------------+------------+--------------+
|                                                          |          0 |          0 |            0 |
|    DECLARE                                               |          0 |          0 |            0 |
|     i RECORD;                                            |          0 |          0 |            0 |
|     j RECORD;                                            |          0 |          0 |            0 |
|   BEGIN                                                  |          0 |          0 |            0 |
|     DROP TABLE IF EXISTS foobar;                         |          2 |   0.004682 |     0.004682 |
|     CREATE TEMP TABLE foobar(a OID,b NAME);              |          2 |   0.041431 |     0.041431 |
|     FOR i IN SELECT OID,relname                          |          2 |   0.521529 |     0.521529 |
|                     FROM pg_class                        |          0 |          0 |            0 |
|              GROUP BY 2,1                                |          0 |          0 |            0 |
|              ORDER BY 1,2                                |          0 |          0 |            0 |
|     LOOP                                                 |          0 |          0 |            0 |
|       FOR j IN SELECT attrelid,attname FROM pg_attribute |        468 |   0.348036 |     0.054492 |
|                 WHERE attrelid = i.OID                   |          0 |          0 |            0 |
|              GROUP BY 1,2                                |          0 |          0 |            0 |
|              ORDER BY 2,1                                |          0 |          0 |            0 |
|       LOOP                                               |          0 |          0 |            0 |
|           x := j.attname;                                |       3659 |   0.058126 |     0.017285 |
|           y := j.attrelid;                               |       3659 |   0.005371 |     0.000207 |
|           INSERT INTO foobar VALUES (y,x);               |       3659 |   0.143374 |         0.03 |
|       END LOOP;                                          |          0 |          0 |            0 |
|       RETURN NEXT;                                       |        468 |   0.011699 |     0.010148 |
|     END LOOP;                                            |          0 |          0 |            0 |
|     RETURN;                                              |          2 |   0.000002 |     0.000002 |
|   END;                                                   |          0 |          0 |            0 |
+----------------------------------------------------------+------------+------------+--------------+

Para os usuários de versões < 8.3, é possível utilizar um arquivo externo no formato de XML com o profiler. Basta configurar a diretira plpgsql.profiler_filename para um arquivo: SET plpgsql.profiler_filename TO ‘/home/leo/path_to_xml.xml’

O plugin traz ainda estatísticas mais detalhadas utilizando-se do módulo pgstattuple e um depurador de stored procedures que veremos no próximo blog.

Abraço!

-Leo