V15: Obtain the query plan of a running query

New feature that allows retrieving a query plan of a running query (original version here)

English version
For anyone involved with RDBMS, the concept of a query plan and its importance is not new. Most performance issues are probably related to bad query plans. So, the ability to obtain the query plan of a query is a base stone of the DBA work. And informix allows it for as long as I can remember. The only "slight" issue is that it only works for a query that we run or simulate to run. Why is this an issue? For three main reasons:

1. It's an hassle to have to capture a query and it's parameters (if the query is prepared), run it in a tool and obtain the query plan. Specially for short lived queries
2. The fact that a prepared query may have a different query plan than the one we get in a tool with a query written with values (more on this later)
3. A long running query may be using a different query plan than the one we get, because some of the conditions may be different (update statistics may have been run, parameters or context may have changed)
   

So, we could overcome the first point with some work, but we cannot overcome the last points. And in order to understand what is happening with a running query we MUST be able to capture the existing plan of a query that is being run. This is why it was so difficult for me to understand why it took so long to fix this. The only explanation I have is an enormous "distance" between developers and people who use the products. This is not exclusive to Informix. I've personally felt this with other products.
This is just to explain that this was a "since ever" requested feature. I personally officially registered it at

https://ideas.ibm.com/ideas/INFX-I-249

on April 2013. But this was not the first time I pushed for it. I even made some attempts do dig into the memory structures that would show this, but the lack of internal documentation made it a nightmare and a dead end. Anyway, enough with the history. The feature was implemented in version 15, and for me personally this would be the top priority. Let's see how we can use it. There are two interfaces to access the query plan:

• onstat -g qplan <0 | session_id>
• query the sysmaster:syssqexplain

 Let's start by opening a session an run a simple query:

 SELECT * FROM customer WHERE customer_num > 110;

 On another session let's identify the session and run the onstat command on that session:

asterix@myhost.onlinedomus.local:informix-> onstat -g qplan 91

IBM Informix Dynamic Server Version 15.0.0.0AEE -- On-Line -- Up 2 days 00:23:07 -- 2193704 Kbytes
2024-11-25 22:34:02 -- Infrastructure Version: 1

Session [91]
QUERY:
------
SELECT * FROM customer WHERE customer_num > 110

QUERY: (OPTIMIZATION TIMESTAMP: 11-25-2024 22:34:03)Estimated Cost: 3
Estimated # of Rows Returned: 18

  1) informix.customer: INDEX PATH

    (1) Index Name: informix. 100_1
        Index Keys: customer_num   (Serial, fragments: ALL)
        Lower Index Filter: informix.customer.customer_num > 110



asterix@myhost.onlinedomus.local:informix->

Very simple. If a session has no active query (or if we issue the command too late) we'll get:

asterix@myhost.onlinedomus.local:informix-> onstat -g qplan 91

IBM Informix Dynamic Server Version 15.0.0.0AEE -- On-Line -- Up 2 days 00:25:14 -- 2193704 Kbytes
2024-11-25 22:36:10 -- Infrastructure Version: 1

Session [91]: No running query to generate the plan.

asterix@myhost.onlinedomus.local:informix->

Again very simple. Now let's check how this can be done through SQL The feature introduced a new column on the sysmaster:syssqexplain, called sqx_sqlstatementplan. So we simply need to query this with a filter on sqx_session_id. An example:

asterix@myhost.onlinedomus.local:informix-> dbaccess -e sysmaster qplan.sql

Database selected.

SELECT
        sqx_sqlstatementplan
FROM
        sysmaster:syssqexplain
WHERE
        sqx_sessionid = 91



sqx_sqlstatementp+
                    QUERY: (OPTIMIZATION TIMESTAMP: 11-25-2024 22:41:12)Estimat
                    ed Cost: 3
                    Estimated # of Rows Returned: 18

                      1) stores:informix.customer: INDEX PATH

                        (1) Index Name: informix. 100_1
                            Index Keys: customer_num   (Serial, fragments: ALL)

                            Lower Index Filter: stores:informix.customer.custom
                    er_num > 110


1 row(s) retrieved.


Database closed.

asterix@myhost.onlinedomus.local:informix->

Before I end this article, I'd like to get back to point 2) above. The fact that a prepared statement may have a different query plan from what we can reproduce by writing the same statement and using the same values as in it's parameters. This is usually hard to explain to customers who usually don't understand why I don't trust in the query plan obtained in dbaccess when we're trying to analyze a performance issue where prepared statements are involved. The reason why this happens is one of the main reasons why this feature is so important, so I think it's worth the effort to dive a bit into this subject. The first important thing we need to clarify is what is a prepared statement? A prepared statement is a statement sent to the engine with the conditions in the WHERE clause, but where the values used in those conditions CAN be replaced by questions marks. If we wanted to prepared the statement above used as an example, the query text would be: SELECT * FROM customer WHERE customer_num > ?
When the statement is prepared, it is sent to the engine, and the engine validates the syntax. The statement executions will pass the parameters. On the first execution, the engine will calculate the query plan. And this is the crucial point around this discussion. The plan will depend on the first execution values, and in normal circumstances will not change until the statement is re-prepared or re-optimized. I'll try to show this with an example, created in JAVA. Let's start with a snippet of the program code:

1   import java.sql.*;
2   import java.util.*;
3   import java.text.*;
4   import com.informix.jdbc.*;
5   import java.util.Scanner;
6
7
8   public class cursor_iter
9   {
10      public static void main( String [] args ) {
11
12              Connection conn = null;
13              int count=0;
14              ResultSet dbRes = null;
15              IfxStatement is = null;
16              Statement is1 = null;
17              String timeStamp;
18              SimpleDateFormat dateFormat;
19              com.informix.jdbc.IfmxPreparedStatement ps = null;
20              Statement st = null;
21              Scanner scan = new Scanner(System.in);
22
23              try {
24
25                      Class.forName("com.informix.jdbc.IfxDriver");
26                      conn = DriverManager.getConnection("jdbc:informix-sqli://myhost:10010/example_db:INFORMIXSERVER=goscinny;USER=informix;PASSWORD=MASKEDPWD;");
27
28              } catch (Exception sqle1) {
29                      System.out.println("Database connection has failed.");
30                      System.out.println("Reason: " + sqle1.getMessage());
31              }
32
33
34
35              try {
36                      st = conn.createStatement();
37                      st.executeUpdate("SET EXPLAIN ON");
38
39                      ps = (com.informix.jdbc.IfmxPreparedStatement) conn.prepareStatement("SELECT * FROM example_table WHERE id >= ?");
40                      System.out.println("STEP 1: Statement prepared. Press ENTER to set parameter\n");scan.nextLine();
41
42                      ps.setInt(1, 1);
43                      System.out.println("STEP 2: Parameter set to 1. Press ENTER to execute\n");scan.nextLine();
44                      ResultSet rs = ps.executeQuery();
45                      System.out.println("STEP 3: Query executed with 1. Press ENTER to position in result set\n");scan.nextLine();
46                      rs.next();
47                      System.out.println("STEP 4: Next() executed with 1. Value: " + rs.getString(1) + ". Press ENTER to close result set\n");scan.nextLine();
48                      rs.close();
49                      System.out.println("STEP 5: ResultSet closed. Press ENTER to set parameter\n");scan.nextLine();
50
51                      ps.setInt(1, 2);
52                      System.out.println("STEP 6: Parameter set to 2. Press ENTER to execute query\n");scan.nextLine();
53                      rs = ps.executeQuery();
54                      System.out.println("STEP 7: Query executed with 2. Press ENTER to position in result set\n");scan.nextLine();
55                      rs.next();
56                      System.out.println("STEP 8: Next() executed with 2. Value: " + rs.getString(1) + ". Press ENTER to close result set\n");scan.nextLine();
57                      rs.close();
58                      System.out.println("STEP 9: ResultSet closed. Press ENTER to set parameter\n");scan.nextLine();
59
60                      ps.setInt(1, 7);
61                      System.out.println("STEP 10: Parameter set to 7. Press ENTER to execute with reoptimization\n");scan.nextLine();
62                      rs = ps.executeQuery(false,true);
63                      System.out.println("STEP 11: Query executed with 7 with re-optimization. Press ENTER to position in result set\n");scan.nextLine();
64                      rs.next();
65                      System.out.println("STEP 12: Next() executed with 7. Value: " + rs.getString(1) + ". Press ENTER to close\n");scan.nextLine();
66                      rs.close();
67                      System.out.println("STEP 13: ResultSet closed. Press ENTER to set parameter\n");scan.nextLine();
68
69                      ps.setInt(1, 1);
70                      System.out.println("STEP 14: Parameter set to 1. Press ENTER to execute query\n");scan.nextLine();
71                      rs = ps.executeQuery();
72                      System.out.println("STEP 15: Query executed with 1. Press ENTER to position in result set\n");scan.nextLine();
73                      rs.next();
74                      System.out.println("STEP 16: Next() executed with 1. Value: " + rs.getString(1) + ". Press ENTER to close result set\n");scan.nextLine();
75                      rs.close();
76                      System.out.println("STEP 17: ResultSet closed. Press ENTER to finish\n");scan.nextLine();
77              } catch (SQLException sqle) {

The code is fairly simple (disclaimer: it may contain some errors or bad practices). The list of actions is:

• Lines 23-31: It connects to the DB
• Lines 36,37: Activates the explain
• Line 39: Prepares a statement with one host variable
• Lines 42-49: Sets the host variable to "1" and executes the query, fetches a row and closes the result set
• Lines 51-58: Repeats the execution for value "2"
• Lines 60-67: Repeats the execution for value "7", but with re-optimization
• Lines 69-76: Repeats the execution for value 1 again

Each step will wait for user input. The purpose of the code is to show the following:

1. The first query plan calculation happens on the first execution and the plan uses a sequencial scan (because the query has a filter >= 1 and "1" is the lowest table value, so statistically the query will return the whole table
2. The second execution does not recalculate the plan
3. The third execution uses a very selective value (7), and is executed with the option to re-optimize the plan. And because we have a different value (with much higher selectivity) it will choose an index
4. The last execution doesn't request re-optimization, and although it uses the first value (1) it will use the index

Hopefully when you analyze the behavior you'll understand:

1. Prepared statements calculate the query plan for the value(s) passed in the first execution, unless we request a re-optimization (which will recalculate the plan and from then on) this one will be used until a new re-optimization is requested
2. New simple execution will re-use the latest calculated plan
3. A plan calculated once can be good for certain values and bad for others. Prepared statements don't care about this
4. This "issue" is only meaningful if for a certain plan you have values that are good and others that would benefit from a different plan. In other words, if your table distribution is not relatively uniform across values
5. Most important conclusion: Given the previous points it should become clear why the need for this feature should be so obvious for anyone using Informix.
    

To make it a bit more clear why we get two different plans here is the column distributions:

goscinny@myhost.onlinedomus.local:informix-> dbschema -d example_db -hd example_table | head -33

DBSCHEMA Schema Utility       INFORMIX-SQL Version 12.10.FC15

{

Distribution for idt.example_table.id
Constructed on 2024-10-19 01:13:30.77780
High Mode, 0.500000 Resolution

--- DISTRIBUTION ---
    (                                   1)
 1: (        10,          1,            7)

--- OVERFLOW ---

 1: (  16670876,                        1)
 2: (  16664127,                        2)
 3: (  16659895,                        3)
 4: (  16664556,                        4)
 5: (  16670374,                        5)
 6: (  16670185,                        6)

goscinny@myhost.onlinedomus.local:informix->

So, the values 1,2,3,4,5 and 6 are considered overflows meaning they have many rows (~16.6M each). Value 7 has only 10 rows. So, if we start the executions with value 1, it will choose a sequential scan which is the best option because we're expecting to read the whole table. But once we have that query plan, an execution with "7" would take a long time (which is why I used "2" in the second execution).
On the other hand, if we use "7" on the first execution, the engine chooses the index path, which again is the best option for this value, but would not be a good option for "1" (and most probably the others).

This is the nature of prepared statements with tables with uneven distributions. The workarounds for these cases are not in the scope for this article (it could be a good idea to cover this in another article), but I hope this makes it very clear why we need to get the effective plan of a running query and not a plan we get on dbaccess by writing the query with values.

And here is video capture of the above code. On the left side you can see what is being written to the sqexplain.out file where it becomes evident when the query plans are calculated and re-used. On the right side there's the code running and pausing for user input.

One final note: When we re-optimize we seem to get a "phantom" execution of the query with the previous plan and the new value. If you check it, you'll see the statistics of the execution are equal to the last one  used (for value 2). I believe this is a glitch or bug in the SET EXPLAIN code. A sequential scan for value 7 would take a long time to return (I tested it). And it would not return the same stats as for the value 2

Here's the video to make this more clear:

Versão Portuguesa

Para qualquer pessoa envolvida com RDBMS, o conceito de plano de execução e a sua importância não será novidade. A maioria dos problemas de performance estão provavelmente relacionados com maus planos de execução. Assim, a capacidade de obter um plano de execução de uma query, é como uma pedra de fundação do trabalho de DBA. E o Informix permite isso desde que me recordo. O único "ligeiro" problema é que isso só funciona para uma query que vamos executar ou simular a execução. Porque é que isto é um problema? Por três razões principais:

1. É trabalhoso ter de obter uma query e os seus parâmetros (se a query fôr "PREPAREd"), executá-la numa ferramenta e daí obter o plano se execução. Em especial se a query fôr de curta duração
2. O facto de que uma query "PREPAREd" pode ter um plano de execução diferente daquele que obtemos correndo a query directamente com valores numa ferramenta (mais sobre isto mais adiante)
3. Uma query com uma execução muito longa, pode estar a usar um plano de execução diferente daquele que obtemos, porque as condições podem ter-se alterado (as estatísticas podem ter sido refeitas, parâmetros ou contexto pode ser diferente...)
   

Portanto, podemos contornar ou ignorar o primeiro ponto, com mais ou menos trabalho, mas não conseguimos resolver os últimos pontos. E para entendermos o que se passa com uma query em execução TEMOS mesmo de ser capazes de capturar o seu efectivo plano de execução. É por isto que sempre me foi muito difícil entender porque demorou tanto tempo a corrigir isto. A única explicação que encontro é uma grande "distância" entre quem desenvolve e quem usa os produtos. Isto não se passa apenas no Informix. Tenho-o sentido com outros produtos também.
Serve tudo isto para explicar que esta funcionalidade era um pedido "desde sempre". Registei-o oficialmente aqui

https://ideas.ibm.com/ideas/INFX-I-249

em Abril de 2013. Mas este não foi o primeiro momento em que batalhei por isto. Cheguei mesmo a fazer algumas tentativas para vasculhar estruturas de memória que poderiam conter esta informação. Mas a falta de documentação sobre essas estruturas tornou a tarefa num pesadelo e beco sem saída.

Bom, mas chega de história. A funcionalidade foi implementada na versão 15, e para mim sempre seria uma prioridade absoluta. Vejamos como a podemos utilizar. Existem duas interfaces para aceder ao plano de execução:

• onstat -g qplan <0 | id_sessao>
• consultar a sysmaster:syssqexplain

 Comecemos por abrir uma sessão e executar uma query simples::

 SELECT * FROM customer WHERE customer_num > 110;

Noutra sessão vamos identificar a sessão de base de dados onde a query está a correr e executar o comando onstat contra essa sessão:

asterix@myhost.onlinedomus.local:informix-> onstat -g qplan 91

IBM Informix Dynamic Server Version 15.0.0.0AEE -- On-Line -- Up 2 days 00:23:07 -- 2193704 Kbytes
2024-11-25 22:34:02 -- Infrastructure Version: 1

Session [91]
QUERY:
------
SELECT * FROM customer WHERE customer_num > 110

QUERY: (OPTIMIZATION TIMESTAMP: 11-25-2024 22:34:03)Estimated Cost: 3
Estimated # of Rows Returned: 18

  1) informix.customer: INDEX PATH

    (1) Index Name: informix. 100_1
        Index Keys: customer_num   (Serial, fragments: ALL)
        Lower Index Filter: informix.customer.customer_num > 110



asterix@myhost.onlinedomus.local:informix->

Muito simples. Se a sessão não tiver nenhuma query activa (ou se dermos o comando demasiado tarde) é isto que obtemos:

asterix@myhost.onlinedomus.local:informix-> onstat -g qplan 91

IBM Informix Dynamic Server Version 15.0.0.0AEE -- On-Line -- Up 2 days 00:25:14 -- 2193704 Kbytes
2024-11-25 22:36:10 -- Infrastructure Version: 1

Session [91]: No running query to generate the plan.

asterix@myhost.onlinedomus.local:informix->

Novamente muito simples. Agora vejamos como podemos aceder a esta informação via SQL. A funcionalidade introduziu uma nova coluna na sysmaster:syssqexplain, chamada sqx_sqlstatementplan. Portanto só temos de interrogar esta view seleccionando esta coluna e filtrando pela coluna  sqx_session_id. Um exemplo:

asterix@myhost.onlinedomus.local:informix-> dbaccess -e sysmaster qplan.sql

Database selected.

SELECT
        sqx_sqlstatementplan
FROM
        sysmaster:syssqexplain
WHERE
        sqx_sessionid = 91



sqx_sqlstatementp+
                    QUERY: (OPTIMIZATION TIMESTAMP: 11-25-2024 22:41:12)Estimat
                    ed Cost: 3
                    Estimated # of Rows Returned: 18

                      1) stores:informix.customer: INDEX PATH

                        (1) Index Name: informix. 100_1
                            Index Keys: customer_num   (Serial, fragments: ALL)

                            Lower Index Filter: stores:informix.customer.custom
                    er_num > 110


1 row(s) retrieved.


Database closed.

asterix@myhost.onlinedomus.local:informix->

Antes de terminar este artigo, gostaria de voltar ao ponto 2) acima. É um facto que uma query PREPAREd pode usar um plano de execução diferente do que conseguimos reproduzir, usando o mesmo SQL e parâmetros. É habitual ter alguma dificuldade em explicar isto a clientes, que geralmente não entendem porque não confio nos planos de execução obtidos por exemplo no dbaccess, quando tentamos analisar problemas de performance que envolvam este tipo de instruções.

A razão porque isto acontece é uma das principais razões porque esta funcionalidade é tão importante, e assim penso que vale o esforço de aprofundar mais o tema. Temos de começar por clarificar o que é uma instrução "PREPAREd". É uma instrução enviada ao motor de base de dados, em que os valores das condições da cláusula WHERE podem ser substituídos por pontos de interrogação. Caso quiséssemos fazer o PREPARE do exemplo acima usaríamos: SELECT * FROM customer WHERE customer_num > ?

Quando a instrução é "PREPAREd", é enviada ao motor, e o motor irá validá-la sintacticamente. Depois as várias execuções da instrução irão passar parâmetros. Na primeira execução o motor irá calcular o plano de execução. E este é o ponto crucial para a discussão. O plano irá depender dos valores passados para a primeira execução, e em circunstâncias normais não irá mudar até que a instrução seja novamente PREPAREd ou re-optimizada. Vou tentar evidenciar isto com um exemplo, criado em JAVA. Comecemos por ver um excerto desse programa:

1   import java.sql.*;
2   import java.util.*;
3   import java.text.*;
4   import com.informix.jdbc.*;
5   import java.util.Scanner;
6
7
8   public class cursor_iter
9   {
10      public static void main( String [] args ) {
11
12              Connection conn = null;
13              int count=0;
14              ResultSet dbRes = null;
15              IfxStatement is = null;
16              Statement is1 = null;
17              String timeStamp;
18              SimpleDateFormat dateFormat;
19              com.informix.jdbc.IfmxPreparedStatement ps = null;
20              Statement st = null;
21              Scanner scan = new Scanner(System.in);
22
23              try {
24
25                      Class.forName("com.informix.jdbc.IfxDriver");
26                      conn = DriverManager.getConnection("jdbc:informix-sqli://myhost:10010/example_db:INFORMIXSERVER=goscinny;USER=informix;PASSWORD=MASKEDPWD;");
27
28              } catch (Exception sqle1) {
29                      System.out.println("Database connection has failed.");
30                      System.out.println("Reason: " + sqle1.getMessage());
31              }
32
33
34
35              try {
36                      st = conn.createStatement();
37                      st.executeUpdate("SET EXPLAIN ON");
38
39                      ps = (com.informix.jdbc.IfmxPreparedStatement) conn.prepareStatement("SELECT * FROM example_table WHERE id >= ?");
40                      System.out.println("STEP 1: Statement prepared. Press ENTER to set parameter\n");scan.nextLine();
41
42                      ps.setInt(1, 1);
43                      System.out.println("STEP 2: Parameter set to 1. Press ENTER to execute\n");scan.nextLine();
44                      ResultSet rs = ps.executeQuery();
45                      System.out.println("STEP 3: Query executed with 1. Press ENTER to position in result set\n");scan.nextLine();
46                      rs.next();
47                      System.out.println("STEP 4: Next() executed with 1. Value: " + rs.getString(1) + ". Press ENTER to close result set\n");scan.nextLine();
48                      rs.close();
49                      System.out.println("STEP 5: ResultSet closed. Press ENTER to set parameter\n");scan.nextLine();
50
51                      ps.setInt(1, 2);
52                      System.out.println("STEP 6: Parameter set to 2. Press ENTER to execute query\n");scan.nextLine();
53                      rs = ps.executeQuery();
54                      System.out.println("STEP 7: Query executed with 2. Press ENTER to position in result set\n");scan.nextLine();
55                      rs.next();
56                      System.out.println("STEP 8: Next() executed with 2. Value: " + rs.getString(1) + ". Press ENTER to close result set\n");scan.nextLine();
57                      rs.close();
58                      System.out.println("STEP 9: ResultSet closed. Press ENTER to set parameter\n");scan.nextLine();
59
60                      ps.setInt(1, 7);
61                      System.out.println("STEP 10: Parameter set to 7. Press ENTER to execute with reoptimization\n");scan.nextLine();
62                      rs = ps.executeQuery(false,true);
63                      System.out.println("STEP 11: Query executed with 7 with re-optimization. Press ENTER to position in result set\n");scan.nextLine();
64                      rs.next();
65                      System.out.println("STEP 12: Next() executed with 7. Value: " + rs.getString(1) + ". Press ENTER to close\n");scan.nextLine();
66                      rs.close();
67                      System.out.println("STEP 13: ResultSet closed. Press ENTER to set parameter\n");scan.nextLine();
68
69                      ps.setInt(1, 1);
70                      System.out.println("STEP 14: Parameter set to 1. Press ENTER to execute query\n");scan.nextLine();
71                      rs = ps.executeQuery();
72                      System.out.println("STEP 15: Query executed with 1. Press ENTER to position in result set\n");scan.nextLine();
73                      rs.next();
74                      System.out.println("STEP 16: Next() executed with 1. Value: " + rs.getString(1) + ". Press ENTER to close result set\n");scan.nextLine();
75                      rs.close();
76                      System.out.println("STEP 17: ResultSet closed. Press ENTER to finish\n");scan.nextLine();
77              } catch (SQLException sqle) {

O código é bastante simples (salvaguarda: o código pode conter erros ou más práticas). A lista de acções é:

• Linhas 23-31: Abre a conexão à BD
• Linhas 36,37: Activa a escrita do plano de execução para ficheiro
  
• Linhas 39: Faz o PREPARE com uma variável "host"
  
• Linhas 42-49: Define a variável "host" a "1", executa a query, posiciona-se numa linha e fecha o "result set"
• Linhas 51-58: Repete a execução para o valor "2"
• Linhas 60-67: Repete a execução para o valor "7", mas desta feita com re-optimização
• Linhas 69-76: Repete a execução para o valor "1" novamente

Em cada passo espera pelo input do utilizador. Os objectivos deste código são mostrar o seguinte:

1. O cálculo do primeiro plano de execução acontece na primeira execução, e usa uma busca sequencial na tabela (pois tem um filtro ">= 1" e "1" é o menor valor da tabela, portanto estatisticamente deveremos ler a tabela toda)
2. A segunda execução não recalcula o plano
3. A terceira execução usa um valor muito selectivo (7), e é efectuada com a opção de re-optimização. Sendo um valor muito mais selectivo o plano vai escolher acesso por índice
4. A última execução não pede re-optimização, e embora use o primeiro valor (1) que despoletou um acesso sequencial vai usar o plano com acesso por índice calculado na interação anterior.

Espero que depois de analisado este comportamento possa entender o seguinte:

1. Instruções PREPAREd calculam o plano para o(s) valor(es) passado(s) na primeira execução, e a menos que seja pedida uma re-optimização (que irá recalcular o plano a usar daí em diante), irá usar sempre o mesmo plano calculado na primeira execução.
2. Novas execuções "simples" irão utilizar o último plano calculado
3. Um plano calculado uma vez pode ser bom para certos valores e mau para outros. Instruções PRERAREd trabalham mesmo assim
4. Este "problema" só tem impacto se para determinado plano há valores "bons" e outros "maus". Por outras palavras, só tem impacto quando a tabela tem distribuições não uniformes entre os diferentes valores possíveis.
5. A conclusão mais importante: Dados os pontos anteriores, deverá estar muito claro para quem usa Informix porque necessitamos tanto desta nova funcionalidade.
    

Para tornar o exemplo um pouco mais claro, e explicar porque obtemos diferentes planos, aqui fica a distribuição de valores na coluna usada na cndição:

goscinny@myhost.onlinedomus.local:informix-> dbschema -d example_db -hd example_table | head -33

DBSCHEMA Schema Utility       INFORMIX-SQL Version 12.10.FC15

{

Distribution for idt.example_table.id
Constructed on 2024-10-19 01:13:30.77780
High Mode, 0.500000 Resolution

--- DISTRIBUTION ---
    (                                   1)
 1: (        10,          1,            7)

--- OVERFLOW ---

 1: (  16670876,                        1)
 2: (  16664127,                        2)
 3: (  16659895,                        3)
 4: (  16664556,                        4)
 5: (  16670374,                        5)
 6: (  16670185,                        6)

goscinny@myhost.onlinedomus.local:informix->

Portanto, os valores 1,2,3,4,5 e 6 são considerados "overflows", o que significa que têm muitas linhas (~16.6M cada). O valor 7 só tem 10 linhas. Assim se iniciamos as execuções com o valor "1", irá escolher uma busca sequencial, dado que espera ler toda a tabela, e assim é o método mais eficiente. Mas uma vez que tenhamos esse plano, uma execução para o valor "7" demoraria muito tempo (daí ter usado "2" na segunda execução). Por outro lado, se usamos o "7" na primeira execução ficaremos com um plano de acesso por índice, pois é a melhor opção para este valor. Mas não será a melhor opção para o valor "1" (e provavelmente para os outros).

Esta é a natureza das instruções PREPAREd com tabelas com distribuições "irregulares". As formas de contornar estes casos não estão no âmbito deste artigo (poderia ser uma boa ideia fazer um artigo dedicado ao tema), mas espero que isto torne claro porque necessitamos mesmo de conseguir obter o plano efectivo de uma query em execução, e não o plano que é gerado pela query escrita com os valores.

E abaixo está uma captura de video da execução do código explicado acima. Do lado esquerdo pode seguir o que vai sendo escrito no ficheiro de saída do SET EXPLAIN. o que evidencia quando é que os planos são calculados e re-utilizados. Do lado direito tem a execução do código com as pausas para input do utilizador.

Uma nota final: Quando se efectua a re-optimização, aparentemente obtemos uma execução "fantasma" da query com o plano anterior e o valor novo. Se atentar nos dados, verá que as estatísticas e execução são iguais às mostradas no passo anterior (para o valor "2"). Suponho que isto seja um bug do SET EXPLAIN. Uma pesquisa sequencial para o valor "7" demoraria muito mais tempo a retornar (eu tentei). E naturalmente não retornaria as mesmas estatísticas que foram retornadas pelo valor "2".

Aqui fica o vídeo:

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.