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.
Posts
