Showing posts with label re-optimization. Show all posts
Showing posts with label re-optimization. Show all posts

Wednesday, November 27, 2024

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:





Friday, March 01, 2024

Rethinking AUTO_REPREPARE

Revisiting AUTO_REPREPARE parameter (original version here)

English version
A recent customer engagement made me analyze the use of this parameter. I have no absolute certain, but what it seems is that the system starts to use a non-optimal query plan (the reason for this is not yet clear, but seems related to the way statistics are updated) for a specific query. The query can be seen running very frequently and taking much longer than it should and the CPU consumption increases. Running statistics doesn't seem to help, but restarting the applications does solve the issue.

A possible explanation is that the query is PREPAREd, and the query plan doesn't change even when we run the statistics. Eventually new sessions will get the correct query plan, and the system returns to normal. This is (up to a point) a normal effect when using prepared statements. Obviously this is highly inconvenient.

That's where the AUTO_REPREPARE parameter can play a fundamental role. This parameter was introduced to avoid the error -710. This used to happen when a table used in a PREPARED statement was changed (new indexes, new columns, dropping columns etc.). The next occurrences of the execution would raise this error and would require an explicit re-preparation of the query, a re-opening of the associated cursor or another activity that would force the calculation of a new plan.

The parameter exists since version 11.10 but it only accepted two values: 0 to turn the feature off and 1 to turn it off. In version 12.10 new values were introduced but apparently they didn't get enough visibility:

  • 0 = Disables the automatic repreparation of prepared objects after the schema of a directly or an indirectly referenced table is modified. Also disables the automatic reoptimization of SPL routines after the schema of an indirectly referenced table is modified.
  • 1 = Enables automatic repreparation.
  • 3 = Enables automatic repreparation in optimistic mode.
  • 5 = Enables automatic repreparation on update statistics.
  • 7 = Enables automatic repreparation in optimistic mode and on update statistics

As we can see, there are options that will trigger automatic statement re-preparation on UPDATE STATISTICS (I'll address the "optimistic mode" later). 5 should be exactly what we want. It will take care of schema changes and also when we UPDATE STATISTICS on the tables used. This way the existing (bad) plans will be updated automatically and we avoid the need to restart the applications. The process will be transparent to the applications.

I've created a simple test to show the effect of this setting. I picked up the "demo1.ec" sample from a Client SDK installation and made some changes to it:

  1. Added a variable "customer_num" and a "count" to obtain the number of full scans executed on the table.
  2. Changed the query WHERE condition to use "WHERE customer_num > ?". Also changed the query to use a table "customer_tst" which will be created for the test purpose.
  3. Repeated the cursor block. I want to execute the query three times. First with value 1 (when plan is calculated it uses a sequential scan), then with value 115 (will choose an INDEX path if the plan is recalculated) and a last time with the original value of 1.
  4. Added a SET EXPLAIN ON that will give us an overview of what's happening
  5. Execute UPDATE STATISTICS LOW after first query execution to see if it triggers the re-optimization of the statement
  6. Find out how many sequential scans were run on the test table and return it as return code of the program

I also created a test SHELL script that will do the following steps for different values of AUTO_REPREPARE (1 and 5):

  1. Create a copy of the customer table in the stores demo database (includes data and the index on the customer_num column
  2. Launch the demo_tst compiled program and obtain the return code (number of sequential scans executed on the table)
  3. Show the explain output for the demo_tst program

The code is at the end of this article, if you want to run the test. To run it follow this steps:

  1. Compile the demo_tst program with: esql -o demo_tst demo_tst.ec
  2. Execute the shell script with: ./test.sh
     

Hopefully what you'll see is:

  •  For execution with AUTO_REPREPARE set to 1:
    • You will get three sequential scans and the explain plan will show only one plan and three similar executions.
  • For execution with AUTO_REPREPARE set to 5:
    • You will get one sequential scan (triggered by the use of "1" in the first query) and two INDEX path (triggered by the use of "115" on the second query, re-optimized because between first and second execution we run UPDATE STATISTICS). Third execution, although it uses the same value as the first execution will follow the plan calculated on the second execution, because there is nothing that triggers the re-optimization between second and third executions.

 

Conclusion

The (not so) new value of 5 allows PREPARED queries to be re-optimized when statistics on the underlying table(s) are refreshed, allowing the queries to benefit from improved query plans without restarting. It will also avoid the -710 error as the usual value of "1" permits.

Note that sometimes customers don't have AUTO_REPREPARE explicitly set to one, but it assumes this value if AUTO_TUNE is set to 1. However to benefit from this extended improvement we need to explicitly set the value to 5.

The value 3 and 7 are similar respectively to values 1 and 5, but the system will not check for schema changes or UPDATE STATISTICS if a query run successfully in the last second. This will of course open the possibility of getting -710 errors if a query is constantly used.

One question pop out: Is there any reason to run Informix with a different value?



Versão Portuguesa
Uma actividade num cliente fez-me revisitar o uso deste parâmetro (AUTO_REPREPARE). De momento não tenho a certeza absoluta, mas parece que ocasionalmente o sistema começa a usar um plano de execução pior para uma query (a razão para isto ainda não é conhecida mas suspeita-se que está relacionado com a forma como se executam as estatísticas). Nestas alturas a query pode facilmente encontrar-se a correr e demora muito mais que o esperado, e o consumo de CPU aumenta. Recalcular as estatísticas não parece resolver, mas um re-inicio das aplicações faz desaparecer o problema.

Uma possível explicação é que a query está "preparada", e assim o plano não se altera quando executamos o UPDATE STATISTICS. Eventualmente novas sessões obtêm o novo e melhorado plano de execução, e depois o sistema volta ao normal. Isto é (até certo ponto) um efeito esperado da utilização de statements preparados. Obviamente é também bastante inconveniente.

É aqui que o parâmetro AUTO_REPREPARE pode ter um papel fundamental. Este parâmetro foi introduzido para evitar o erro -710. Isto acontecia quando uma tabela usada numa instrução preparada sofria alguma modificação (novos índices, novas colunas, remoção de colunas etc.). A execução seguinte da instrução geraria o erro e seria necessário uma nova abertura de cursor associado, a execução do PREPARE novamente ou outra acção que despoletasse a geração de um novo plano de execução.

Este parâmetro existe desde a versão 11.10, mas só aceitava dois valores: 0 para desligar a funcionalidade e 1 para a ligar. Na versão 12.10 foram introduzidos novos valores, mas aparentemente não tiveram visibilidade suficiente:

  • 0 = Desactiva a "repreparação" automática depois de a estrutura de uma tabela directa ou indirectamente usada na query ser mudada. Desliga também a re-optimizção automática para procedimentos SPL.
  • 1 = Activa a re-optimização automática.
  • 3 = Activa a re-optimização automática em modo "optimista".
  • 5 = Activa a re-optimização automática também para UPDATE STATISTICS.
  • 7 = Activa a re-optimização automática também para UPDATE STATISTICS em modo "optimista".

Como se pode verificar há opções para despoletar a re-optimização das instruções quando ocorre um UPDATE STATISTICS (vermos o modo "optimista" depois). O valor 5 será exactamente o que se pretende. Endereça as alterações de estrutura bem como a execução de estatísticas nas tabelas envolvidas. Desta forma os planos existentes (não óptimos) serão actualizados automaticamente e evitamos o re-inicio das aplicações. Este processo é transparente para as aplicações.

Para demonstrar isto criei um teste simples que permite ver o efeito da funcionalidade. Parti do exemplo "demo1.ec" existente numa instalação de Client SDK e fiz-lhe algumas alterações:

  1. Adicionei uma variável "customer_num" para a condição da query e uma "count" para obter o número de sequential scans efectuados.
  2. Mofifiquei a condição WHERE da query para usar "WHERE customer_num > ?". Também alterei a query para usar uma tabela "customer_tst" que será criada para este propósito.
  3. Repeti o bloco de código que abre o cursor. Quero executar a query três vezes. A primeira será com o valor 1 (o motor escolhe um sequential scan para este valor). Depois com o valor 115 (o plano terá um acesso por índice quando recalculado) e novamente com o valor inicial de 1.
  4. Adicionei um SET EXPLAIN ON que nos dará visibilidade sobre o que se passou.
  5. Execução de um UPDATE STATISTICS LOW depois da primeira execução para vermos de dispara a re-optimização na segunda execução
  6. Obter o número de sequential scans executados na tabela de teste. Esse valor é usado como retorno do programa para que o script possa obter a contagem

Criei também um SHELL script que fará os seguintes passos para ambos os valores do  AUTO_REPREPARE (1 e 5):

  1. Cria uma cópia da tabela "customer" na base de dados de demonstração stores (incluí dados e o índice na coluna customer_num.
  2. Lança o programa referido antes (demo_tst) e obtém o seu código de retorno (número de sequential scans executado na tabela).
  3. Mostra o resultado do EXPLAIN contendo as queries feitas pelo programa demo_tst

O código está no fim do artigo, caso pretenda executar o teste. Os passos serão:

  1. Compilar o demo_tst com: esql -o demo_tst demo_tst.ec
  2. Executar o SHELL script com: ./demo.sh

Em princípio o resultado será:

  •  Para a execução com AUTO_REPREPARE = 1:
    • Serão executados três sequential scans e o EXPLAIN terá apenas um plano e três execuções similares.
  • Para a execução com AUTO_REPREPARE = 5:
    • Será executado apenas um sequential scan (da primeira execução pela utilização do valor "1") e dois acessos por índice (este segundo plano obtido pelo uso do valor "115" na segunda execução, re-optimizado porque entre a primeira e segunda execução fizemos um UPDATE STATISTICS). A terceira execução terá sempre o mesmo plano da segunda, pois não há nada entre ambas que cause uma re-optimização.

 

Conclusão

O (relativamente) novo valor 5 permite que queries preparadas possam ser re-optimizadas logo que sejam refrescadas estatísticas nas tabelas envolvidas, permitindo que as queries beneficiem automaticamente de planos melhoradas, sem re-inicio das aplicações. Também evita o erro -710 como o mais habitual valor 1 permite.

Note-se que é frequente que os clientes não tenham o AUTO_REPREPARE explicitamente definido, mas em alguns casos acaba por assumir o valor 1, caso tenham o AUTO_TUNE a 1. Mas para beneficiarmos desta funcionalidade estendida é necessário defini-lo explicitamente a 5.

O valor 3 e 7 são semelhantes respectivamente aos valores 1 e 5, mas no modo "optimista" onde o sistema não vai verificar se é necessário fazer a re-optimização se a query correu com sucesso há menos de um segundo. Isto deixa naturalmente margem para ocorrência do erro -710 se uma query fôr executada constantemente.

Tendo isto em conta há uma questão que salta à vista: Haverá razão para ter outro valor que não o 5 neste parâmetro?


The code

demo_tst.ec:
 
/****************************************************************************

 * Licensed Material - Property Of IBM
 *
 * IBM Informix Client-SDK
 *
 * (c)  Copyright IBM Corporation 1997, 2013. All rights reserved.
 * (c) Copyright HCL Technologies Ltd. 2017.  All Rights Reserved.
 *
 ****************************************************************************
 */


#include <stdio.h>
#include <string.h>
#include <unistd.h>

EXEC SQL define FNAME_LEN       15;
EXEC SQL define LNAME_LEN       15;

int main()
{
EXEC SQL BEGIN DECLARE SECTION;
    char fname[ FNAME_LEN + 1 ];
    char lname[ LNAME_LEN + 1 ];
    integer customer_num = 1, seq_scans;
EXEC SQL END DECLARE SECTION;
    int count;

    printf( "DEMO1 Sample ESQL Program running.\n\n");
    EXEC SQL WHENEVER ERROR STOP;
    EXEC SQL connect to 'stores';

    EXEC SQL SET EXPLAIN ON;

    EXEC SQL PREPARE p1 FROM "select fname, lname from customer_tst where customer_num > ?";
    printf("======== Statment prepared ====================\n");
    EXEC SQL declare democursor cursor for p1;

    printf("== Opening the cursor with value 1 ============\n");
    EXEC SQL open democursor USING :customer_num;
    count=0;
    for (;;)
        {
        EXEC SQL fetch democursor into :fname, :lname;
        if (strncmp(SQLSTATE, "00", 2) != 0)
            break;
        count++;

        if ( count == 1 )
                printf("Frst row: %s %s\n",fname, lname);
        }
    printf("%d rows were returned\n", count);

    if (strncmp(SQLSTATE, "02", 2) != 0)
        printf("SQLSTATE after fetch is %s\n", SQLSTATE);

    EXEC SQL close democursor;

    printf("== Updating statistics for table =====\n");
    EXEC SQL UPDATE STATISTICS LOW FOR TABLE customer_tst;
    printf("======== Reopening the cursor again with 115 ==\n");

    customer_num = 115;
    EXEC SQL open democursor USING :customer_num;
    count=0;
    for (;;)
        {
        EXEC SQL fetch democursor into :fname, :lname;
        if (strncmp(SQLSTATE, "00", 2) != 0)
            break;
        count++;

        if ( count == 1 )
                printf("Frst row: %s %s\n",fname, lname);
        }
    printf("%d rows were returned\n", count);

    if (strncmp(SQLSTATE, "02", 2) != 0)
        printf("SQLSTATE after fetch is %s\n", SQLSTATE);

    EXEC SQL close democursor;

    printf("======== Reopening the cursor again with original 1 ==\n");

    customer_num = 1;
    EXEC SQL open democursor USING :customer_num;
    count=0;
    for (;;)
        {
        EXEC SQL fetch democursor into :fname, :lname;
        if (strncmp(SQLSTATE, "00", 2) != 0)
            break;
        count++;

        if ( count == 1 )
                printf("Frst row: %s %s\n",fname, lname);
        }
    printf("%d rows were returned\n", count);

    if (strncmp(SQLSTATE, "02", 2) != 0)
        printf("SQLSTATE after fetch is %s\n", SQLSTATE);

    EXEC SQL close democursor;
    EXEC SQL free democursor;


    EXEC SQL SET EXPLAIN OFF;
    EXEC SQL SELECT t2.pf_seqscans INTO :seq_scans FROM sysmaster:systabnames t1, sysmaster:sysptntab t2 WHERE t1.partnum = t2.partnum AND t1.dbsname = 'stores' and t1.tabname = 'customer_tst';
    EXEC SQL disconnect current;
    printf("\nDEMO1 Sample Program over.\n\n");


   printf("======== Sequential scans executed on customer_tst table: %d =======\n",seq_scans);
   return(seq_scans);
}

test.sh:
 


#!/bin/bash

run_actions()
{

AUTO_REPREPARE_MODE=$1
onmode -wm AUTO_REPREPARE=$AUTO_REPREPARE_MODE

printf -- "------------------------------------------------------------------------------------------------\nPreparing the table (customer_tst) and launching the program demo1\n------------------------------------------------------------------------------------------------\n"
dbaccess stores <<EOF

DROP TABLE IF EXISTS customer_tst;
CREATE TABLE customer_tst AS SELECT * FROM customer;
CREATE INDEX cust_fis_pk ON customer_tst(customer_num);
EOF

./demo_tst
NUM_SEQSCANS=$?

cat sqexplain.out
case $NUM_SEQSCANS in
        1)
                printf -- "------------------------------------------------------------------------------------------------\nOnly one sequential scan was done. That was the first. The plan changed between executions\n------------------------------------------------------------------------------------------------\n"
                if [ "X${AUTO_REPREPARE_MODE}" = "X5" ]
                then
                        printf -- "------------------------------------------------------------------------------------------------\nThis is expected with AUTO_REPREPARE set to 5\n------------------------------------------------------------------------------------------------\n"
                else
                        printf -- "------------------------------------------------------------------------------------------------\nThis is NOT expected with AUTO_REPREPARE set to 1\n------------------------------------------------------------------------------------------------\n"
                fi
                ;;
        3)
                printf -- "------------------------------------------------------------------------------------------------\nThree sequential scans were done. The plan didn't change between executions\n------------------------------------------------------------------------------------------------\n"
                if [ "X${AUTO_REPREPARE_MODE}" = "X1" ]
                then
                        printf -- "------------------------------------------------------------------------------------------------\nThis is expected with AUTO_REPREPARE set to 1 or unset if AUTO_TUNE is set to 1\n------------------------------------------------------------------------------------------------\n"
                else
                        printf -- "------------------------------------------------------------------------------------------------\nThis is NOT expected with AUTO_REPREPARE set to 5\n------------------------------------------------------------------------------------------------\n"
                fi
                ;;
        *)
                printf -- "------------------------------------------------------------------------------------------------\nUnexpected value for number of sequential scans ($NUM_SEQSCANS) in customer_tst table. No external access to this table should be done during testing\n------------------------------------------------------------------------------------------------\n"
                exit 1
                ;;
esac

printf -- "------------------------------------------------------------------------------------------------\nPlease check query plans. If three sequential scans were executed it should show only one query plan and three executions.\nIf only one sequential scan was executed it should show two plans and an execution for first and two for second\n------------------------------------------------------------------------------------------------\n"

}



printf -- "------------------------------------------------------------------------------------------------\nRunning for AUTO_REPREPARE = 1\n------------------------------------------------------------------------------------------------\n"
rm -f sqexplain.out
run_actions 1


printf "*************************************************************************\nPRESS ENTER TO CONTINUE WITH SECOND PART OF THE TEST\n*************************************************************************\n"
read DUMMY


printf "*************************************************************************\nSTARTING SECOND PART OF TEST\n*************************************************************************\n"

printf -- "------------------------------------------------------------------------------------------------\nRunning for AUTO_REPREPARE = 5\n------------------------------------------------------------------------------------------------\n"
rm -f sqexplain.out

run_actions 5
dbaccess stores <<EOF
DROP TABLE IF EXISTS customer_tst;
EOF