Thursday, December 22, 2011

Small query performance analysis / Pequena análise de performance de querys

This article is written in English and Portuguese
Este artigo está escrito em Inglês e Português

English version:

The need...

The end of the year is typically a critical time for IT people. Following up on last article's I'm still working with performance issues. "Performance issues on Informix?!" I hear you say... Well yes, but to give you an idea of the kind of system I'm talking about I can say that recently we noticed three small tables (between 3 and 60 rows) that between mid-night and 11AM were scanned 33M times. To save you the math, that's around 833 scans/queries for each of these tables per second. And this started to happen recently, on top of the normal load that nearly 3000 sessions can generate...
So, the point is: every bit of performance matters. And in most cases, on this system there are no long running queries. It's mostly very short requests made an incredible number of times. And yes, this makes the DBA life harder... If you have long running queries with bad query plans they're usually easy to spot. But if you have a large number of very quick queries, but with questionable query plans, than it's much more difficult to find.

Just recently I had one of this situations. I've found a query with a questionable query plan. The query plan varies with the arguments and both possible options have immediate response times (fraction of a second). That's not the first time I've found something similar, and most of the times I face the same situation twice I usually decide I need to have some tool to help me on that.

The idea!

The purpose was to see the difference in the work the engine does between two query plans. And when I say "tool" I'm thinking about a script. Last time I remember having this situation, I used a trick in dbaccess to obtain the performance counters for both the session, and the tables involved. Some of you probably know, others may not, but when dbaccess parses an SQL script file it can recognize a line starting with "!" as an instruction to execute the rest of the line as a SHELL command. So basically what I did previously was to customize the SQL script containing the query like this:

!onstat -z
SELECT .... FROM .... WHERE ...
!some_shell_scritpt

where some_shell_script had the ability to find the session and run an onstat -g tpf and also an onstat -g ppf. These two onstat commands show us a lot of performance counters respectively from the threads (tpf) and from the partitions (ppf). The output looks like:


IBM Informix Dynamic Server Version 11.70.UC4 -- On-Line -- Up 7 days 23:42:15 -- 411500 Kbytes

Thread profiles
tid lkreqs lkw dl to lgrs isrd iswr isrw isdl isct isrb lx bfr bfw lsus lsmx seq
24  0      0   0  0  0    0    0    0    0    0    0    0  0   0   0    0    0  
26  0      0   0  0  0    0    0    0    0    0    0    0  95  95  0    0    0  
51  32917  0   0  0  21101 13060 3512 57   532  3795 0    0  91215 29964 0    125008 4226
52  39036  0   0  0  9099 11356 2648 80   1372 265  0    0  45549 9312 0    244900 21 
49  705    0   0  0  574  8938 0    139  0    139  0    0  22252 148 0    5656 541
2444 706    0   0  0  14   344  0    4    0    0    3    0  819 7   136  224  0  

This tells us the thread Id, lock requests, lock waits, deadlocks, timeouts, logical log records, isam calls (read, write, rewrite, delete, commit and rollback), long transactions, buffer reads and writes, logical log space used, logical log space maximum and sequential scans.
And this:

panther@pacman.onlinedomus.com:informix-> onstat -g ppf | grep -v "0     0     0     0     0     0     0     0     0     0     0     0"

IBM Informix Dynamic Server Version 11.70.UC4 -- On-Line -- Up 7 days 23:43:41 -- 411500 Kbytes

Partition profiles
partnum    lkrqs lkwts dlks  touts isrd  iswrt isrwt isdel bfrd  bfwrt seqsc rhitratio
0x100001   0     0     0     0     0     0     0     0     13697 0     0     100
0x100002   993   0     0     0     445   0     0     0     1460  0     2     100
0x10002d   6769  0     0     0     2379  34    340   34    9094  581   2     100
0x10002e   164   0     0     0     166   0     0     0     472   0     2     100
0x10002f   2122  0     0     0     2750  0     0     0     5288  0     0     100
0x100030   0     0     0     0     4     0     0     0     700   0     4     100
0x100034   14192 0     0     0     5922  192   80    192   15566 1274  0     100
0x100035   2260  0     0     0     188   80    0     80    2766  655   4     100
0x100036   1350  0     0     0     548   34    0     34    1872  249   0     100
0x100037   80    0     0     0     16    4     0     4     346   28    0     100
0x100038   4720  0     0     0     738   360   0     360   3734  1557  0     100

which tells us some of the above, but for each partition.
Note that I reset the counters, run the query and then obtain the profile counters. Ideally, nothing else should be running on the instance (better to do it on a test instance)

Sharing it

But I decided to make this a bit easier and I created a script for doing it. I'm also using this article to announce that starting today, I'll try to keep my collection of scripts on a publicly available site:

http://onlinedomus.com/informix/viewvc.cgi

This repository contains a reasonable amount of scripts for several purposes. Ideally I should create proper documentation and use cases for each one of them, but I currently don't have that. It's possible I'll cover some of them here in the blog, but probably only integrated in a wider article (like this one).

These scripts were created by me (with one exception - setinfx was created by Eric Vercelleto when we were colleagues in Informix Portugal and we should thank him for allowing the distribution), during my free time and should all contain license info (GPL 2.0). This means you can use them, copy them, change them etc. Some of them are very old and may not contain this info.
Some fixes and improvements were done during project engagements. Many of them were based on ideas I got from some scripts available in IIUG's software repository or from colleagues ideas, problems and suggestions (Thanks specially to António Lima and Adelino Silva)

It's important to notice that the scripts are available "as-is", no guarantees are made and I cannot be held responsible for any problem that it's use may cause.
Having said that, I've been using most of them on several customers for years without problems.
Any comments and/or suggestions are very welcome, and if I find the suggestions interesting and they don't break the script's ideas and usage, I'll be glad to incorporate them on future versions.

Many of the scripts have two option switches that provide basic help (-h) and version info (-V).
If by any chance you are using any of these scripts I suggest you check the site periodically to find any updates. I try my best to maintain retro-compatibility and old behavior when I make changes on them.

Back to the problem

So, this article focus on analyzing and comparing the effects of running a query with two (or more) different query plans. The script created for this was ixprofiling. If you run it with -h (help) option it will print:


panther@pacman.onlinedomus.com:fnunes-> ./ixprofiling -h
ixprofiling [ -h | -V ]
            -s SID database
            [-z|-Z|-n] database sql_script
     -h             : Get this help
     -V             : Get script version
     -s SID database: Get stats for session (SID) and database
     -n             : Do NOT reset engine stats
     -z             : Reset engine stats using onstat (default - needs local database)
     -Z             : Reset engine stats using SQL Admin API (can work remotely )

Let's see what the options do:
  • -s SID database
    Shows the info similar to onstat -g tpf (for the specified session id) and onstat -g ppf (for the specified database)
    It will show information for all the partition objects in the specified database for which any of the profile counters is different from zero. Note that when I write partition, it can be a table, a table's partition or a table's index.
  • database sql_script
    Runs the specified SQL script after making some changes that will (by default) reset the engine profile counters (-z option). See more information about the SQL script below
  • -n
    Prevents the reset of profile counters (if you're not a system database administrator you'll need to specify this to avoid errors)
  • -z
    Resets the profile counters using onstat -z. This is the quickest and most simple way to do it but will need local database access.
  • -Z
    Resets the counters using SQL admin API, so it can be used on remote databases


And now let's see an usage example. The script has some particularities that need to be detailed.
First, since the idea is to compare two or more query plans we can put all the variations inside the SQL script, separating them by a line like:

-- QUERY

when the script finds these lines, it will automatically get the stats (from the previous query) and reset the counters to prepare for the next query. If you use just one query you don't need this, since by default it will reset the counters at the beginning and show the stats at the end.
If you put two or more queries on the script don't forget to end each query with ";" or it will break the functionality.
Let's see a practical example. I have a table with the following structure:

create table ibm_test_case 
  (
    col1 integer,
    col2 smallint not null ,
    col3 integer,
    col4 integer,
[... irrelevant bits... ]
    col13 datetime year to second,
[... more irrelevant bits... ]
  );

create index ix_col3_col13 on ibm_test_case (col3,col13) using btree ;
create index ix_col4 on ibm_test_case (col4) using btree ;

and a query like:

select c.col1
from ibm_test_case c
where
        c.col3 = 123456789 and
        c.col4 = 1234567 and
        c.col13 = ( select max ( c2.col13 ) from ibm_test_case c2
                where
                        c2.col3 = c.col3 and
                        c2.col4 = c.col4
                );


The problem is the query plan for the sub-query. It can choose between an index headed by col3 and another on col4. So I create a test_case.sql with:


unload to /dev/null select c.col1
from ibm_test_case c
where
        c.col3 = 123456789 and
        c.col4 = 1234567 and
        c.col13 = ( select max ( c2.col13 ) from ibm_test_case c2
                where
                        c2.col3 = c.col3 and
                        c2.col4 = c.col4
                );

-- QUERY
unload to /dev/null select c.col1
from ibm_test_case c
where
        c.col3 = 123456789 and
        c.col4 = 1234567 and
        c.col13 = ( select --+ INDEX ( c2 ix_col3_col13 )
                max ( c2.col13 ) from ibm_test_case c2
                where
                        c2.col3 = c.col3 and
                        c2.col4 = c.col4
                );

Note that on the second query I'm forcing the use of a particular index.
Then we run:

ixprofiling stores test_case.sql


and we get the following output:


Database selected.

Engine statistics RESETed. Query results:

Explain set.


1 row(s) unloaded.


Thread profiles (SID: 2690)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
5224  0     0     0     0     2611  0     0     0     2646  0     0     0     0     0     0     0     2170  0.051671256 sqlexec     

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
6     0     0     0     0     0     2     0     0     0     10    0     0     systables
2609  0     0     0     1933  0     2607  0     0     0     2609  0     0     ibm_test_case
1     0     0     0     2     0     1     0     0     0     6     0     0     ibm_test_case#ix_col3_col13
2608  0     0     0     3     0     1     0     0     0     21    0     0     ibm_test_case#ix_col4
Engine statistics RESETed. Query results:

1 row(s) unloaded.


Thread profiles (SID: 2690)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
17    0     0     0     0     6     0     0     0     31    0     0     0     0     0     0     0     188   0.003161049 sqlexec     

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
6     0     0     0     0     0     2     0     0     0     10    0     0     systables
4     0     0     0     2     0     1     0     0     0     4     0     0     ibm_test_case
7     0     0     0     0     0     6     0     0     0     17    0     0     ibm_test_case#ix_col3_col13

So, we can now analyze the differences. As you can see the output is more friendly than the output from onstat. On the session section we can see the usual counters, plus the number of times the engine scheduled the thread(s) to run, the CPU time consumed and the name of the threads.
On the tables/partitions section, we can find the partition, table or index name in a friendly nomenclature (instead of the partnum).
As for the comparison, you can spot a big difference. Much more buffer reads and ISAM reads for the first query plan and also a bigger CPU time. Be aware however that for very fast queries the CPU times may show very big variance so don't assume a lower CPU time is always associated with the better query plan. You should repeat the test many times to see the oscillations.
Also note that the meaning of ISAM calls is many times misunderstood. Some people think it's the number of "SELECTs", others the number of rows returned... In reality it's the number of internal functions calls. Some engine settings like BATCHEDREAD_TABLE and BATCHEDREAD_INDEX may influence the number of calls for the same query and query result.

That's all for now. I leave you with the repository and hopefully future articles will focus on some of these scripts. Feel free to use them and send me you suggestions.

Versão Portuguesa:


A necessidade...

O fina do ano é tipicamente uma altura critica para os informáticos. Continuando no mesmo tema do último artigo, continuo a trabalhar com problemas de performance. "Problemas de performance em Informix?!" poderão estar a pensar... Bem, sim, mas para vos dar uma ideia do sistema sobre o qual estou a falar, posso dizer que recentemente notámos três pequenas tabelas (entre 3 e 60 linhas) que entre a meia-noite e as onze da manhã eram varridas (sequential scan) 33M de vezes. Para poupar nas contas posso já dizer que dá cerca de 833 scans/queries por segundo para cada uma das tabelas. E isto começou a acontecer recentemente sobre a carga "normal" que perto de 3000 sessões podem criar.
Portanto, a ideia é que cada bocadinho de performance tem impacto. Na maioria dos casos, este sistema não tem queries longas. Na maior parte das vezes os problemas são pedidos com curta duração mas feitos um imenso número de vezes. E sim, isto torna a vida dos DBAs mais dicfícil... Se tivermos queries longas com maus planos de execução são normalmente fáceis de identificar. Mas se tivermos um grande número de queries muito curtas, com um plano de execução questionável, isso é muito mais difícil de encontrar.

Ainda recentemente tive uma dessas situações. Detectei uma query com um plano de execução duvidoso. O plano de execução varia com os parâmetros usados e ambas as alternativas têm um tempo de resposta "imediato" (fracção de segundo). Não foi a primeira vez que encontrei algo semelhante, e na maioria dos casos em que enfrento uma situação duas vezes, normalmente decido que preciso de alguma ferramenta que me ajude no futuro.

A ideia!


O objectivo era evidenciar a diferença no trabalho feito pelo motor entre dois planos de execução. E quando refiro "ferramenta" estou a pensar num script. A última vez que me lembro de ter tido uma situação destas  usei um truque no dbaccess para obter os indicadores de performance tanto para a sessão como para as tabelas envolvidas.
Alguns de vós saberão, outros não, mas quando o dbaccess lê um scritpt SQL pode reconhecer uma linha começada com "!" como uma instrução para executar o resto da linha como um comando SHELL. Assim, o que fiz em situações anteriores foi alterar o script SQL que continha a query para algo do género:

!onstat -z
SELECT .... FROM .... WHERE ...
!um_shell_scritpt

onde um_shell_script tem a capacidade de encontrar a sessão e correr um onstat -g tpf e também um onstat -g ppf. Ests dois comandos mostram-nos uma série de contadores de performance respectivamente da sessão/thread (tpf) e das partições (ppf). O output é semelhante a isto:

IBM Informix Dynamic Server Version 11.70.UC4 -- On-Line -- Up 7 days 23:42:15 -- 411500 Kbytes

Thread profiles
tid lkreqs lkw dl to lgrs isrd iswr isrw isdl isct isrb lx bfr bfw lsus lsmx seq
24  0      0   0  0  0    0    0    0    0    0    0    0  0   0   0    0    0  
26  0      0   0  0  0    0    0    0    0    0    0    0  95  95  0    0    0  
51  32917  0   0  0  21101 13060 3512 57   532  3795 0    0  91215 29964 0    125008 4226
52  39036  0   0  0  9099 11356 2648 80   1372 265  0    0  45549 9312 0    244900 21 
49  705    0   0  0  574  8938 0    139  0    139  0    0  22252 148 0    5656 541
2444 706    0   0  0  14   344  0    4    0    0    3    0  819 7   136  224  0  

É-nos mostrado o ID da thread, número de pedidos de lock, esperas em locks, deadlocks, lock timeouts, chamadas ISAM (leitura, escrita, re-escrita, apagar, commit e rollback), transacções longas, leituras e escritas de buffers, espaço usado em logical logs e máximo espaço usado em logical logs e número de sequential scans. E isto:

panther@pacman.onlinedomus.com:informix-> onstat -g ppf | grep -v "0     0     0     0     0     0     0     0     0     0     0     0"

IBM Informix Dynamic Server Version 11.70.UC4 -- On-Line -- Up 7 days 23:43:41 -- 411500 Kbytes

Partition profiles
partnum    lkrqs lkwts dlks  touts isrd  iswrt isrwt isdel bfrd  bfwrt seqsc rhitratio
0x100001   0     0     0     0     0     0     0     0     13697 0     0     100
0x100002   993   0     0     0     445   0     0     0     1460  0     2     100
0x10002d   6769  0     0     0     2379  34    340   34    9094  581   2     100
0x10002e   164   0     0     0     166   0     0     0     472   0     2     100
0x10002f   2122  0     0     0     2750  0     0     0     5288  0     0     100
0x100030   0     0     0     0     4     0     0     0     700   0     4     100
0x100034   14192 0     0     0     5922  192   80    192   15566 1274  0     100
0x100035   2260  0     0     0     188   80    0     80    2766  655   4     100
0x100036   1350  0     0     0     548   34    0     34    1872  249   0     100
0x100037   80    0     0     0     16    4     0     4     346   28    0     100
0x100038   4720  0     0     0     738   360   0     360   3734  1557  0     100

que nos mostra alguns dos contadores anteriores, mas por partição.
Note-se que re-inicializo os contadores, corro a query e depois obtenho os outputs. Idealmente não deverá estar mais nada a correr na instância (é preferível usar uma instância de teste).

Partilha


Mas decidi tornar isto um pouco mais fácil e criei um script para o fazer. Estou também a usar este artigo para anunciar que a partir de hoje, tentarei manter a minha colecção de scripts disponível num site público:

http://onlinedomus.com/informix/viewvc.cgi

Este repositório contém uma quantidade razoável de scripts e outras ferramentas úteis para várias tareafas. Idealmente eu deveria criar documentação e casos de uso para cada um deles, mas de momento isso não está feito. É possível que vá descrevendo alguns destes scripts em futuros artigos, mas sempre integrados em assuntos mais vastos (como este)

Estes scripts foram criados por mim (com uma excepção - setinfx foi criado por Eric Vercelletto quando éramos colegas na Informix Portugal e devemos agradecer-lhe por permitir a distribuição), durante os meus tempos livres e devem conter informação de licenciamento (GPL 2.0). Isto quer dizer que podem ser usados, distribuidos, alterados etc.). Alguns podem não ter esta informação por serem muito antigos.
Naturalmente algumas correcções e melhorias foram feitas durante projectos em clientes, sempre que detecto algum erro ou hipótese de melhoria no seu uso. Muitos deles foram baseados em ideias que obtive de scripts existents no repositório do IIUG, ou de ideias, problemas e sugestões de colegas (agradecimento especial ao António Lima e ao Adelino Silva)

É importante avisar que os scripts são disponiblizados "como são", sem qualquer tipo de garantia implicita ou explicita e eu não posso ser responsabilizado por qualquer problema que advenha do seu uso. Posto isto, convém também dizer que a maioria dos scripts têm sido usados por mim em clientes ao longo de anos, sem problemas.

Quaisquer comentários e/ou sugestões são bem vindas, e se os achar interessantes terei todo o prazer em os incorportar em futuras versões (desde que não fujam à lógica e utilização do script)
Muitos destes scripts disponibilizam duas opções que fornecem ajuda básica (-h) e informação sobre a versão (-V).
Se utilizar algum destes scripts no seu ambiente, sugiro que verifique periodicamente se houve correcções ou melhorias, consultando o site com alguma regularidade. Sempre que possível evito que novas funcionalidades alterem o comportamento do script.

De volta ao problema

Este artigo foca a análise e comparação dos efeitos de executar uma query com dois (ou mais) planos de execução. O script criado para isso chama-se ixprofiling. Se corrido com a opção -h (help) mostra-nos:

panther@pacman.onlinedomus.com:fnunes-> ./ixprofiling -h
ixprofiling [ -h | -V ]
            -s SID database
            [-z|-Z|-n] database sql_script
     -h             : Get this help
     -V             : Get script version
     -s SID database: Get stats for session (SID) and database
     -n             : Do NOT reset engine stats
     -z             : Reset engine stats using onstat (default - needs local database)
     -Z             : Reset engine stats using SQL Admin API (can work remotely )

Vejamos o que fazem as opções:
  • -s SID base_dados
    Mostra informação semelhante ao onstat -g tpf (para a sessão indicada por SID) e onstat -g ppf (para a base de dados indicada)
    Irá mostrar informação para todas as partições na base de dados escolhida, para as quais exista pelo menos um dos contadores com valor diferente de zero. Note-se que quando refiro partição estou a referir-me a uma tabela, a um fragmento de tabela fragmentada (ou se preferir particionada) ou a um indíce.
  • base_dados script_sql
    Corre o script SQL indicado, fazendo alterações que irão (por omissão), re-inicializar os contadores de performance do motor (opção -z). Veja mais informação sobre o script SQL abaixo
  • -n
    Evita a re-inicialização dos contadores de performance (se não fôr administrador do sistema de base de dados terá de usar esta opção para evitar erros)
  • -z
    Faz a re-inicialização dos contadores do motor usando o comando onstat -z. Esta é a forma mais simples e rápida de o fazer, mas requer que a base de dados seja local
  • -Z
    Faz a re-inicialização dos contadores utilizando a SQL Admin API, de forma que possa ser feito com bases de dados remotas

E agora vejamos um exemplo de uso. O script tem algumas particularidades que merecem ser datalhadas.
Primeiro e porque a ideia é comparar dois ou mais planos de execução, podemos colocar todas as variantes de plano de execução  dentro do mesmo script SQL usando uma linha como esta para separar as queries:

-- QUERY

Estas linhas são automaticamente substituídas por comandos que obtêm os contadores actuais (da query anterior) e que re-inicializam os mesmos contadores preparando a execução seguinte. Se usar apenas uma query não é necessário isto, pois por omissão a re-inicialização dos contadores é feita no início, e após a última query são automaticamente mostrados os contadores.
Se colocar duas ou mais queries no script não se esqueça de terminar cada uma com ";" ou o script não funcionará como esperado.
Vamos ver um exemplo prático. Tenho uma tabela com a seguinte estrutura:

create table ibm_test_case 
  (
    col1 integer,
    col2 smallint not null ,
    col3 integer,
    col4 integer,
[... parte irrelevante ... ]
    col13 datetime year to second,
[... mais colunas irrelevantes ... ]
  );

create index ix_col3_col13 on ibm_test_case (col3,col13) using btree ;
create index ix_col4 on ibm_test_case (col4) using btree ;

e uma query com:

select c.col1
from ibm_test_case c
where
        c.col3 = 123456789 and
        c.col4 = 1234567 and
        c.col13 = ( select max ( c2.col13 ) from ibm_test_case c2
                where
                        c2.col3 = c.col3 and
                        c2.col4 = c.col4
                );


O problem é o plano de execução da sub-query. Pode  escolher entre um índice começado pela coluna col3 e outro pela coluna col4. Por isso crio um ficheiro, caso_teste.sql com:


unload to /dev/null select c.col1
from ibm_test_case c
where
        c.col3 = 123456789 and
        c.col4 = 1234567 and
        c.col13 = ( select max ( c2.col13 ) from ibm_test_case c2
                where
                        c2.col3 = c.col3 and
                        c2.col4 = c.col4
                );

-- QUERY
unload to /dev/null select c.col1
from ibm_test_case c
where
        c.col3 = 123456789 and
        c.col4 = 1234567 and
        c.col13 = ( select --+ INDEX ( c2 ix_col3_col13 )
                max ( c2.col13 ) from ibm_test_case c2
                where
                        c2.col3 = c.col3 and
                        c2.col4 = c.col4
                );

Repare  que na segunda query estou a forçar o uso de um determinado índice:
Depois corro:

ixprofiling stores caso_teste.sql


e obtemos o seguinte:


Database selected.

Engine statistics RESETed. Query results:

Explain set.


1 row(s) unloaded.


Thread profiles (SID: 2690)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
5224  0     0     0     0     2611  0     0     0     2646  0     0     0     0     0     0     0     2170  0.051671256 sqlexec     

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
6     0     0     0     0     0     2     0     0     0     10    0     0     systables
2609  0     0     0     1933  0     2607  0     0     0     2609  0     0     ibm_test_case
1     0     0     0     2     0     1     0     0     0     6     0     0     ibm_test_case#ix_col3_col13
2608  0     0     0     3     0     1     0     0     0     21    0     0     ibm_test_case#ix_col4
Engine statistics RESETed. Query results:

1 row(s) unloaded.


Thread profiles (SID: 2690)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
17    0     0     0     0     6     0     0     0     31    0     0     0     0     0     0     0     188   0.003161049 sqlexec     

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
6     0     0     0     0     0     2     0     0     0     10    0     0     systables
4     0     0     0     2     0     1     0     0     0     4     0     0     ibm_test_case
7     0     0     0     0     0     6     0     0     0     17    0     0     ibm_test_case#ix_col3_col13

Então, podemos agora analisar as diferenças. Como se pode ver o resultado é mais simpático que o do onstat. Na secção relativa à sessão, podemos ver os contadores habituais, mais o número de vezes que o motor escalonou a thread para correr, e o tempo de CPU consumido, bem como o nome das threads
Na secção destinada às partições podemos encontrar os nomes das tabelas, partições ou indíces numa nomenclatura fácil de entender (em vez do partnum).
Sobre a comparação, podemos ver uma grande diferença. Muitos mais leituras de buffers e chamadas ISAM para o primeiro plano de execução e também mais consumo de CPU. Mas atenção que para queries muito rápidas os tempos de CPU podem apresentar uma variação muito grande. Por isso convém não assumir imediatamente que um plano de execução é melhor porque se vê um tempo de CPU menor na primeira interação. Deve repetir-se o teste muitas vezes para se verificar as oscilações.
Chamo também a atenção para o significado das chamadas ISAM. Muitas vezes vejo confusões sobre este tema. Algumas pessoas pensam que são o número de SELECTs (para os ISAM reads), ou que serão o número de linhas retornadas... Na realidade é o número de chamadas a funções internas. Algumas configurações do motor como BATCHEDREAD_TABLE e BATCHEDREAD_INDEX podem influenciar o número destas chamadas, para a mesma query e mesmo conjunto de resultados.


É tudo por agora. Deixo-lhe o repositório e a esperança que artigos futuros se foquem em alguns destes scripts. Use-os à vontade e envie quaisquer sugestões.

Saturday, December 10, 2011

Optimizer secrets / segredos do optimizador

This article is written in English and Portuguese
Este artigo está escrito em Inglês e Português

English version:

Spending a lot of time with customers is great. It gives me time to go beyond the strict task execution that short projects allow. We actually have time to dive deep into what sometimes looks only as a curiosity. I'll describe one of this situations in this post. It started out as a normal performance issue. A query involving a join was causing an hash join and apparently there was an index that could be used. Some quick investigation showed that the datatypes didn't match on the join columns, and as such the index was not being used.
The situation was fixed (using an explicit cast since changing the datatypes would require more deep analysis) and the programmer(s) received an explanation about the issue so that future situations would be avoided. Simple right? Yes... But when you have inquiring minds and programmers with a few minutes to spare you may be surprised. And this was the case. A few weeks later the DBA team received a request to explain why we recommended that the columns used in joins should have the same datatype. A programmer had produced a testcase where the engine was able to convert the parameter sent and use the index. In other words, if the engine is smart enough why should we care?!

Although this could be considered a waste of time (using the same datatypes or explicit cast is a good practice, right?!) the question was interesting enough to make us spend some time with it. In fact I had seen situations in the past where apparently sometimes the engine was smart, and others not. I never thought too much about it, since I always recommended to follow the best practices (which clearly saves us some troubles). So, personally I also had this doubt, and together with the customer DBAs we started to do some tests. We came up with a very simple test case that we though would show the problem:

DATABASE stores;

DROP TABLE IF EXISTS tst_int;
DROP TABLE IF EXISTS tst_char;

CREATE TABLE tst_int
(
    c1 INTEGER,
    c2 INTEGER
);
CREATE TABLE tst_char
(
    c1 CHAR(15),
    c2 INTEGER
);

INSERT INTO tst_int
SELECT FIRST 2000 pg_pagenum, pg_partnum FROM sysmaster:syspaghdr;

INSERT INTO tst_char
SELECT FIRST 2000 pg_pagenum, pg_partnum FROM sysmaster:syspaghdr;

CREATE INDEX i_tst_int ON tst_int(c1);
CREATE INDEX i_tst_char ON tst_char(c1);

SET EXPLAIN ON;
SELECT "tst_int with char parameter:", * FROM tst_int WHERE c1 = '12345678';
SELECT "tst_char whth int parameter",* FROM tst_char WHERE c1 = 12345678;

--- demonstrates that each index key is being casted
INSERT INTO tst_char VALUES("a1", 12345678);
SELECT * FROM tst_char WHERE c1 = 12345678;

If we take a look at the query plan we see:

QUERY: (OPTIMIZATION TIMESTAMP: 12-10-2011 23:25:19)
------
SELECT "tst_int with char parameter:", * FROM tst_int WHERE c1 = '12345678'

Estimated Cost: 1
Estimated # of Rows Returned: 1

  1) informix.tst_int: INDEX PATH

    (1) Index Name: informix.i_tst_int
        Index Keys: c1   (Serial, fragments: ALL)
        Lower Index Filter: informix.tst_int.c1 = 12345678

So here the engine was "smart". Meaning it converted the CHAR to an INTEGER and that allowed it to use the index. Nice.


But here:

QUERY: (OPTIMIZATION TIMESTAMP: 12-10-2011 23:25:19)
------
SELECT "tst_char whth int parameter",* FROM tst_char WHERE c1 = 12345678

Estimated Cost: 84
Estimated # of Rows Returned: 1

  1) informix.tst_char: SEQUENTIAL SCAN

        Filters: informix.tst_char.c1 = 12345678

It looks as it's not that smart... Instead of converting the INTEGER parameter to a CHAR and use the index it decides to do the opposite: Converts all the CHARs in that column into INTEGERs and makes a SEQUENTIAL SCAN.
Since I didn't have a good explanation for this we decided to open a PMR to get an official technical support explanation.


Technical support reported that we had something in the documentation that tries to explain this:

http://publib.boulder.ibm.com/infocenter/idshelp/v117/topic/com.ibm.sqls.doc/ids_sqs_1620.htm

This documentation is highly confusing but it tells us something important: If we use a numeric filter against a CHAR column, the database server will convert all the CHAR values to numbers. This is precisely what we saw in the example above. But it still does not explain why. Let me show why with a few examples:
  1. If we have "00123" in the table and we give 123 as the parameter, if we convert the number to CHAR and try to match it, ir would fail. Bad results...
  2. If we have "234" in the column and we give 9 as the parameter for a "less or equal" (col <= 9), if we convert the number to CHAR, and apply the filter to the CHAR type, it would match ("9" >= "234"). Again it would return an incorrect result because by using an INTEGER as a parameter we're assuming INTEGER comparison
So, after this, the rule would seem pretty simple. Something like: "If you use a numeric parameter against a CHAR column, all the values in the column will be converted to numeric.  On the other hand, using a CHAR parameter against a numeric column allows the engine to convert the numeric to CHAR and if there is an index on the column it can be used".

But life's not that simple... If it was so simple why couldn't we find it in the documentation? I tried to search for other RDBMS (Oracle and MS SQL) documentation, and in those cases they're very clear about the issue. Something like "whenever an implicit CAST is needed we follow a precedence table of datatypes. The datatype with lower precedence will be converted into the datatype with higher precedence". Sincerely I thought this was a good way to put it, and if we did the same, why not document it properly? So the PMR already opened started to look like a documentation bug.
But again, life sometimes is not simple... And while this was being analyzed and discussed, the customer team discovered an interesting scenario: If you give an integer value as a filter against a CHAR column, AND the length of the integer value (excluding any leading zeros) is equal to the size of the column, than Informix will convert the number to CHAR and eventually will use an index on the specified column.
This is the optimizer being smart. If you think about it, if the number has the same number of digits as the length of the CHAR column, you can convert the number to CHAR and compare it. The result set will be correct no matter the values in question or the operator.

To end the story, while browsing the documentation in search for other topics we came across this:

http://publib.boulder.ibm.com/infocenter/idshelp/v117/topic/com.ibm.perf.doc/ids_prf_536.htm

It's clear and well explained. Informix makes the necessary casts but that can have a real impact on the performance, specially if exists an index on the column. And the optimizer is smart enough to use a better query plan in the only situation where it can be done. Really nice and at least here (Performance Guide) it's well explained. I really don't mind when a PMR generates a bug because that's a product improvement, but I must admit I prefer to be proven wrong and see that the product really works well!


Versão Portuguesa:

É ótimo passar muito tempo com clientes. Dá-me tempo para ir para além da estrita execução de tarefas que os projetos curtos permitem. Temos tempo para aprofundar o que por vezes não parece ser mais que uma curiosidade. Nesta entrada vou descrever uma dessas situações. Começou como um banal problema de performance. Uma query que envolvia um join estava a gerar um hash join havendo um índice que aparentemente podia ser usado. Após uma rápida investigação percebeu-se que os tipos de dados das colunas envolvidas no join não eram iguais e por isso o índice não era usado.
A situação foi corrigida (usando um CAST explícito pois mudar os tipos de dados teria necessitado de uma análise mais profunda e poderia ter outras implicações) e o programador(es) recebeu uma explicação sobre o problema para que situações semelhantes fossem evitadas no futuro. Simples, certo? Sim... Mas quando temos mentes curiosas e programadores com alguns minutos para dispensar podemos ser surpreendidos. E este foi um desses casos. Umas semanas mais tarde a equipa de DBAs do cliente recebeu um pedido para explicar o porquê da recomendação, acompanhado de um caso de teste que demonstrava que o motor conseguia usar um índice mesmo quando os tipos de dados não batiam certo. Por outras palavras, se o motor tem inteligência para o fazer, porque nos devemos nós preocupar?!


Apesar de isto poder ser considerado uma perda de tempo (usar os mesmos tipos de dados ou um CAST explícito é uma boa prática, não é?!) a questão era suficientemente interessante para nos fazer gastar algum tempo com ela. Na realidade já tinha tido situações no passado onde aparentemente o motor parecia inteligente, e outras onde tal não acontecia. Nunca pensei muito no assunto, dado que recomendo sempre que seja seguida as boas práticas (que claramente nos evitam problemas). Portanto, pessoalmente também tinha esta dúvida e em conjunto com os DBAs do cliente iniciámos alguns testes. Criámos um exemplo muito simples que pensamos que demonstra o problema:

DATABASE stores;

DROP TABLE IF EXISTS tst_int;
DROP TABLE IF EXISTS tst_char;

CREATE TABLE tst_int
(
    c1 INTEGER,
    c2 INTEGER
);
CREATE TABLE tst_char
(
    c1 CHAR(15),
    c2 INTEGER
);

INSERT INTO tst_int
SELECT FIRST 2000 pg_pagenum, pg_partnum FROM sysmaster:syspaghdr;

INSERT INTO tst_char
SELECT FIRST 2000 pg_pagenum, pg_partnum FROM sysmaster:syspaghdr;

CREATE INDEX i_tst_int ON tst_int(c1);
CREATE INDEX i_tst_char ON tst_char(c1);

SET EXPLAIN ON;
SELECT "tst_int with char parameter:", * FROM tst_int WHERE c1 = '12345678';
SELECT "tst_char whth int parameter",* FROM tst_char WHERE c1 = 12345678;

--- demonstrates that each index key is being casted
INSERT INTO tst_char VALUES("a1", 12345678);
SELECT * FROM tst_char WHERE c1 = 12345678;

Se olharmos para o plano de execução vemos:

QUERY: (OPTIMIZATION TIMESTAMP: 12-10-2011 23:25:19)
------
SELECT "tst_int with char parameter:", * FROM tst_int WHERE c1 = '12345678'

Estimated Cost: 1
Estimated # of Rows Returned: 1

  1) informix.tst_int: INDEX PATH

    (1) Index Name: informix.i_tst_int
        Index Keys: c1   (Serial, fragments: ALL)
        Lower Index Filter: informix.tst_int.c1 = 12345678

Ou seja, aqui o motor era "esperto". Convertia o CHAR para INTEGER e isso permitia usar o índice. Boa.

Mas aqui:

QUERY: (OPTIMIZATION TIMESTAMP: 12-10-2011 23:25:19)
------
SELECT "tst_char whth int parameter",* FROM tst_char WHERE c1 = 12345678

Estimated Cost: 84
Estimated # of Rows Returned: 1

  1) informix.tst_char: SEQUENTIAL SCAN

        Filters: informix.tst_char.c1 = 12345678

Parece que não é assim tão esperto.... Em vez de converter o parâmetro INTEGER para um CHAR e usar o índice, decide fazer o oposto: Converte todos os CHARs daquela coluna para INTEGERs e executa um SEQUENTIAL SCAN.
Como não tinha uma boa explicação para isto decidi abrir um PMR para obter uma explicação oficial do suporte técnico.


O suporte técnico informou que nós tínhamos algo na documentação que tenta explicar isto:

http://publib.boulder.ibm.com/infocenter/idshelp/v117/topic/com.ibm.sqls.doc/ids_sqs_1620.htm

Esta documentação é altamente confusa, mas diz-nos algo importante: Se usarmos um filtro numérico contra uma coluna do tipo CHAR, o servidor de base de dados irá converter todos os valores CHAR da coluna em números. Isto é exatamente o que encontrámos no exemplo acima. Mas ainda não explica porquê. Deixe-me explicar o porquê com alguns exemplos:
  1. Se tivermos o valor "00123" na tabela e usarmos 123 como parâmetro/filtro, se convertermos o número para CHAR e tentarmos fazer a comparação não vamos retornar nada ('123' != '00123') . Resultados errados...
  2. Se tivermos o valor "234" na coluna e dermos 9 como parâmetro/filtro para uma condição de menor ou igual (col <= 9), se convertermos o número para CHAR isso implicaria que a linha era retornada  ("9" >= "234"). Mais uma vez iria retornar um resultado "errado", pois ao usarmos um parâmetro numérico estamos a assumir comparação numérica (onde 9 < 234)
Assim, depois disto a regra parecia muito simples. Algo como "Se usarmos um parâmetro numérico contra uma coluna do tipo CHAR, todos os valores da coluna serão convertidos para numérico. Por outro lado, usar um parâmetro CHAR contra uma coluna numérica permite que o motor converta o parâmetro para número e use um índice caso exista".

Mas a vida não é assim tão simples... Se era assim tão direto porque razão não estava documentado (ou pelo menos nós não tínhamos encontrado)? Tentei procurar na documentação de outros sistemas de gestão de bases de dados (Oracle e MS SQL) , e nestes casos eram bastante claros sobre o assunto. Um resumo livre seria "sempre que um CAST implícito seja necessário, seguimos uma tabela de precedências de tipos de dados. O tipo de dado com menor precedência será convertido para o que tem mais precedência". Sinceramente isto pareceu-me uma forma correta de colocar a questão, e se fazíamos o mesmo porque não ter isto claro na documentaçã? Assim o PMR já aberto parecia encaminhar-se para um bug de documentação.

Mas novamente, a vida por vezes não é simples... E enquanto isto estava a ser analisado e discutido , a equipa do cliente descobriu um cenário interessante: Se usarmos um numero como filtro contra uma coluna do tipo CHAR, e o numero de dígitos desse inteiro (excluindo quaisquer zeros à esquerda) for igual ao número de caracteres definido na coluna, então o número será convertido para CHAR e um eventual índice na coluna será usado.
Isto é o optimizador a ser "esperto". Se pensarmos sobre o assunto, se o número de dígitos do número for igual ao número de caracteres da coluna, podemos convertê-lo para CHAR e compará-lo com a coluna. O resultado será o correto independentemente dos valores em questão e do operador.


Para terminar a história, enquanto consultáva-mos a documentação devido a outro assunto, demos com o seguinte:

http://publib.boulder.ibm.com/infocenter/idshelp/v117/topic/com.ibm.perf.doc/ids_prf_536.htm

Está claro e bem explicado. O Informix efetua os CASTS necessários para resolver queries onde existam inconsistências entre os tipos de dados. Mas isso pode ter um impacto significativo na performance, especialmente se existir um índice na coluna. E o optimizador é suficientemente inteligente para obter um melhor plano de execução na única situação onde isso pode ser feito. Muito correto e pelo menos aqui (Guia de Performance) está bem explicado.
Sinceramente não me importo muito quando um PMR dá origem a um bug, pois isso traduz-se numa melhoria do produto, mas tenho de admitir que prefiro que resulte que estava enganado e ser-me mostrado que o produto está a funcionar bem!

Short notes / Notas curtas

This article is written in English and Portuguese
Este artigo está escrito em Inglês e Português

English version:


This is a very short article that consists of a few short notes.
First, as you can notice from the banner above, IIUG is going to organize the 2012 International User Conference in San Diego on April 22-25 2012. Next year's conference will move from the traditional Kansas City location to San Diego, California. As usual, you can get a lot of value for money. I will probably skip this one, but Ill surely miss it. Please consult the conference URL for all the details.

Some time ago I added a blog to my list, mas to be honest at the time I didn't review the content that it already had. Recently, during some investigation I ended up there and I had the opportunity to browse over it's content and it's really interesting. I'm talking about http://www.jfmiii/informix/ . The URL shows that it's author is John Miller, one of the most well known elements of the Informix community. John is the author of a lot of Informix material, specially about update statistics and backup and restore. In the last years is has been involved with Open Admin Tool (OAT). He's also a usual presence in conferences and presentations done or sponsored by IBM. I highly recommend this blog. The blog also includes contributions from other well known members of the community


Still related to blogs, I just added one more to the list: http://informixdba.wordpress.com/ . It's author is Ben Thompson, an UK based Informix and Oralce DBA. Not many articles yet, but it looks promising.


Philip Howard, from Bloor Research talks about the Informix revive and also mentions it in the article "Breakthrough and instrumented applications".



TatukGIS a Polish based GIS software and solution provider recently extended it's products support to Informix and DB2

In a blog hosted by Microsoft, there is a reference to future support for Informix 11 on their BizTalk ESB software in the next release of the product


Versão Portuguesa:

Este é um artigo muito curto e consistirá em algumas notas sobre vários temas.
Primeiro, como pode ver pelo cabeçalho acima, o IIUG vai organizar a conferência internacional de utilizadores de 2012 em San Diego entre 22 e 25 de Abril de 2012. A conferência do ano que vem deixará a localização tradicional em Kansas City e irá para San Diego na California. Como é hábito pode obter bastante valor pelo investimento. Em princípio não irei estar presente, mas irei sem dúvida sentir a falta. Consulte o endereço da conferência para mais detalhes.

Há uns tempos adicionei um blog à lista, mas sinceramente na altura não revi todo o conteúdo que já existia. Recentemente durante alguma investigação que efectuei acabei por lá ir parar e tive oportunidade de verificar que tem conteúdo bastante interessante. Estou a falar de http://www.jfmiii/informix/ . Pelo endereço e conteúdo é fácil perceber que se trata do John Miller um dos mais conhecidos elementos da comunidade Informix. O John tem estado ligado a imenso material sobre Informix, em particular artigos sobre update statistics, backup e restore e outros. Nos últimos anos tem estado por detrás do Open Admin Tool. É também presença habitual em conferências e apresentações da IBM. Recomendo vivamente. O blog contém também contribuições de outros elementos bem conhecidos da comunidade

Ainda relacionado com blogs, acabei de adicionar um à lista: http://informixdba.wordpress.com/ . O seu autor é Ben Thompson, um DBA Informix e Oracle baseado no Reino Unido. Ainda não tem muitos artigos, mas parece promissor.

Philip Howard, da Bloor Research fala sobre o Informix revive e também o refere noutro artigo: "Breakthrough and instrumented applications".

TatukGIS, um fornecedre de software e soluções GIS, baseado na Polónia anunciou recentemente a extensão do suporte nos seus produtos para Informix e DB2


Num blog hospedado na Microsoft, existe uma referencia ao futuro suporte ao Informix 11 na próxima release do seu BizTalk ESB.