Thursday, September 04, 2014

PAM revisited / PAM revisitado

This article is written in English and Portuguese (original version here)
Este artigo está escrito em Inglês e Português (versão original aqui)

English version:

Introduction
I covered PAM authentication in Informix a few years ago. I'd say most of what is written in those articles is still true. But I recently had to run some tests due to a customer situation, that may render some previous facts as not true anymore. To be more specific, I believe there is the generalized idea that implicit connections are hard or impossible to setup using PAM. This article will show that's not true. Nevertheless there are a few considerations to keep in mind.
In a recent customer situation we faced the following issue. The customer is implementing a third party product that will act as a proxy for the Informix connections. The product is being installed on the database servers and remote clients connect to a TCP port under control of this software (let's imagine 1500 on external TCP interface). The software will make a connection to the real Informix port (let's assume 1501 on localhost). The customer is using implicit (trusted) and explicit (password) connections. For explicit connections this architecture doesn't raise any issue. But for implicit connections there was (3rd party provider apparently already solved it) a big security issue. Informix checks the trust relation against the socket origin. But now, instead of the remote client, the socket is originating in the database server itself by the 3rd party application. So, every implicit connection was being trusted by Informix, independently of the real origin.
This led me to do some tests with PAM. As you know PAM (Plugin Authentication Modules) is a framework that allows applications to use different authentication modules to accomplish the authentication of a user. Different platforms come with different modules already pre-installed. What I'm going to demonstrate was tested with Linux and AIX. But it should work with any other operation system that implements PAM (HP-UX and Solaris). But the catch is that one of the modules may not be installed by default. In the worst case scenario you'd need to grab the module source code and adapt it to your platform, and compile. That work is outside the scope of this article.

Goal
So, what I was trying to achieve was the simulation of the default Informix authentication but using PAM. By default, and depending on the $INFORMIXSQLHOSTS configuration, Informix accepts both password and trusted connections on the TCP ports. In order to achieve that I need to setup a PAM service that uses two different mechanisms. One for password and the other for trusts. The module for password is easy. I think every OS has one to do that. In Linux it's pam_unix.so, in AIX is pam_aix etc. To get the trusted hosts functionality we need another module, and this one will be pam_rhosts.so (on Linux) and pam_rhosts_auth on AIX. I couldn't find a ready module for HP-UX to do this, but it's possible to adapt the module from Linux. There are some changes that must be done, because Linux-PAM has some extensions over the standard PAM framework.
Once we identify the modules we need to define how to set them up.

Configuration
As mentioned in the goal section, the idea is to configure a PAM listener that will accept both types of connections. If you check on previous articles you'll find that PAM modules can be configured with a module type and a control flag.
The module type can be auth, account, session and password.
I explained also that Informix only uses auth and account. For each type we can specify more than one module. Auth module type will check the user identity (is the password correct, is the host trusted) and account will check if the user can access the service, if the user account and/or password is valid and so on.
The control flag defines the role of the module in the overall module stack. Since each module type can use more than one module, we should specify for each module if it's return is critical or not for the overall result. The options we can use are required, requisite, sufficient and optional. LinuxPAM is more feature reach, but you should be able to get information about all these by checking the pam or pam.conf manual on your system.
So, we already know we'll need two modules, the module type, the control flags and finnaly we'll need a service name. The service name is whatever we choose, and makes the bridge between Informix configuration and the PAM framework.
I'll start the configuration in the Informix level and I'll create a new listener port for this. I'll use the name cheetah_pam as the INFORMIXSERVER (DBSERVERALIAS to be more exact). As such I need a new entry in $INFORMIXSQLHOSTS:

cheetah_pam  onsoctcp     primary 1533 s=4,pam_serv=(pam_informix),pamauth=(password)

So, I'm using "pam_informix" as the service name and I'm defining the PAM Informix option "password" as the pamauth option. The values allowed here are "password" and "challenge".
"password" should be used by services where the clients connect to using a user and password and challenge for anything else. But as we shall see, there's more to it than what's explained in the manual
So, after adding it to the $INFORMIXSQLHOSTS we should also add the new name (cheetah_pam) to $INFORMIXDIR/etc/$ONCONFIG option DBSERVERALIAS.

Next step it to configure the PAM stack for this service. This is a bit different depending if you're on Linux, AIX or others. Basically Linux uses a file for each service in /etc/pam.d. So we would create a file named /etc/pam.d/pam_informix. This file would contain several lines specifying the module type, the control flag, the module location and the module flags.
On other systems like AIX, there is only one file, called /etc/pam.conf and the service name is added as the first column in the file. Although these two ways are very similar, I tend to like better the way Linux works. Why? Because either /etc/pam.conf or /etc/pam.d/* are controlled by root and a sysadmin will not grant you, the Informix DBA, control over the /etc/pam.conf file. But he may allow you to control a single file (called pam_informix) inside the /etc/pam.d folder.
Anyway.... Given what I mentioned above, this is the service configuration:
auth        sufficient  pam_rhosts.so debug
auth        sufficient  pam_unix.so
account     required    pam_unix.so

What am I saying here? As you can see, the "auth" module type included two modules, with the control flag "sufficient". This means that either of them is enough to make the stack accept the identity. If one fails and the other is ok that's enough. If both fail than the auth type will fail.
As for the account, we're using the module pam_unix.so which validates if the account is valid (not blocked etc.). For AIX the following lines would have to be added for /etc/pam.conf
pam_informix auth      sufficient /usr/lib/security/pam_rhosts_auth debug
pam_informix auth      sufficient /usr/lib/security/pam_aix
pam_informix account   sufficient /usr/lib/security/pam_aix

The differences are that we added the service name as the first column, and the modules names are slightly different.

Testing
I have run several tests to check this implementation. I used a virtual machine where I'm running the cheetah_pam service and used the native OS as a client. My client hostname is "PTxxxx" and I created a user with the same name on the Linux box. I also setup an Informix instance on an AIX machine and  used the Linux server as a client in order to test 4GL connectivity.
First scenario is Informix instance on Linux and client on PC (windows). I have two SQL files:
C:\Programas\InformixClientSDK_370_tc7_c86>type *.sql

test_explicit.sql

CONNECT TO 'stores' USER 'PTxxxxxx' USING 'mypassword';
SELECT USER FROM sysmaster:sysdual;

test_implicit.sql

CONNECT TO 'stores';
SELECT USER FROM sysmaster:sysdual;

C:\Programas\InformixClientSDK_370_tc7_c86>

Let's see what happens when I run these both tests:
C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_implicit.sql

 1809: Server rejected the connection.
Error in line 1
Near character position 1

C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_explicit.sql

Connected.

(expression)

PTxxxxxx
1 row(s) retrieved.

Disconnected.

C:\Programas\InformixClientSDK_370_tc7_c86>

Ok. Implicit connections are failing, but user and password are working. This is expected because I didn't create the trusted relation on the Linux machine. Let's check the syslog on that machine:
tail -20 /var/log/secure
[...]
Sep  4 06:52:07 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:07 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:09 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:09 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:12 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:12 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:14 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:14 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:17 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:17 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:32 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx

These lines belong to the implicit attempt and the explicit one (last line). As you can see, for the implicit attempt both modules report failure, but for the explicit attempt only the pam_rhosts reports a failure, because the pam_unix succeeded (and since we used "sufficient", that's enough to accept the connection.
Now, let's configure the trust relation. For that I'll try to add "PTxxxxxx   PTxxxxxx" to /etc/hosts.equiv. Let's repeat the test:
C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_implicit.sql

Connected.

(expression)

PTxxxxxx

1 row(s) retrieved.

Disconnected.

C:\Programas\InformixClientSDK_370_tc7_c86>

and now, I'll remove that line from /etc/hosts.equiv and I'll add it to ~PCxxxxxx/.rhosts
As expected:
C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_implicit.sql

Connected.

(expression)

PCxxxxxx

1 row(s) retrieved.

Disconnected.

C:\Programas\InformixClientSDK_370_tc7_c86>

A final test with this setup: Let's remove the trust and try with a wrong password (changed the test_explicit.sql file):
C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_explicit.sql

 1809: Server rejected the connection.
Error in line 1
Near character position 1

C:\Programas\InformixClientSDK_370_tc7_c86>

So, this proves that with dbaccess we can emulate the native behavior but using PAM. But how about for other connectivity layers, like ODBC, .NET, 4GL etc.?
Well... I tried everything I could think off and only OleDB failed:

  • ConnectTestDemo (ok)
    (connectivity test bundled with ClientSDK for windows
  • ODBC (ok)
    (normal ODBC manager bundled with Windows)
  • VBScript that uses ODBC data source (ok)
  • VBScript that uses OleDB (failed!)
  • C# client that uses .NET (ok)
  • Native 4GL 7.50.UC4 (ok)
As mentioned above, OleDB client failed, because it explicitly does not support PAM. In fact when I try to use it I get the following message in the online.log:

10:35:24  listener-thread: err = -1809: oserr = 0: errstr = Client without PAM support connecting to PAM port: Server rejected the connection.

So this is a known product limitation. I believe this could be removed if we just assumed it would work just for password, and not for challenge. We did that very recently for DRDA and PAM. I suspect, but I cannot be sure, that the limitation comes from the fact that in OleDB clients we can't specify a callback function as we do in JDBC or ESQL/C for example. And that may be the source of this limitation. It would be better to support just the use of password if that's the case.

Conclusions and caveats
This little exercise proves that we can simulate (with some differences mentioned below) that we can simulate the engine native behavior while using PAM. But why would we want to do that? Well, I can list a few different motives:
  1. We may want the user/password to validate against a repository different than the native OS (or simply change the encryption mechanism and Informix may be sensitive to that)
  2. We may setup the OS to work with LDAP, and although it may work for OS native utilities, it may turn the way Informix validates the users in the OS unusable. Informix uses getpwnam() and crypt(). If these two functions don't work exactly the same way after LDAP configuration, the Informix native authentication will fail.
  3. We may want to take advantage of the flexibility of PAM. After setting up these two modules in the PAM configuration there is nothing that prevents us from introducing other modules that implement extra functionality. The only thing to consider is that we can't send challenges to the application from those modules because we setup the pamauth to "password" instead of "challenge"

But as mentioned above, there are a few issues:
  1. When using native authentication, if we provide a password, it will validate the password or refuse the connection. In this example, if the password fails, it will try to validate the trust relation. I don't think this is a big issue... typically trust relations are created for users/servers that don't use passwords. And passwords are created for scenarios where the trust relation is not created
  2. By configuring the port with pamauth=(password) we give up the ability to use any module that sends a challenge that we would reply with a function setup with the callback mechanism
  3. The pam_rhosts module checks the trusts in the files /etc/hosts.equiv and ~utilizador/.rhosts
    As we know, starting with version 11.70, Informix can (and should) use it's own files. It would be possible, and not too complex I believe, to get the source code and change the references to these files (accepting the new ones as module parameters for example) to adapt it to version 11.7
  4. On Linux (and this didn't happen on AIX and may not happen on other Linux versions), the name passed by PAM_RHOST to the module pam_rhosts must be resolvable to an IP address. Otherwise the authentication in this module will fail


Versão Portuguesa:
Introdução
Eu abordei a a autenticação via PAM no Informix há uns anos atrás. Diria que a maioria do que está nesses artigos ainda se aplica. Mas recentemente tive de efetuar alguns testes, devido a uma situação num cliente, que podem tornar falsas algumas assunções anteriores. Para ser mais específico, acredito que exista a ideia generalizada que é impossível efetuar ligações implícitas usando PAM (por exemplo em 4GL). Este artigo irá mostrar que isso é falso. Há no entanto algumas considerações a ter em conta.
Numa situação recente ocorrida num cliente enfrentámos a seguinte situação: O cliente está a implementar um produto de terceiros que irá atuar como proxy para as ligações Informix. O produto está a ser instalado nos servidores de bases de dados e os clientes ligam-se a um porto TCP controlado por esse software (imagine o porto 1500 numa interface "externa"). O referido software irá fazer a conexão ao porto real do Informix (imagine 1501 na interface localhost). O cliente está a usar ligações implícitas (trusted connections) e explícitas (utilizador/password). Para ligações explícitas esta arquitetura não levanta qualquer questão. Mas para conexões implícitas existia (aparentemente já terá sido resolvido pelo fornecedor) um grave problema de segurança. O Informix verifica as relações de confiança (trusts) com base na origem do socket estabelecido pelo cliente. Mas agora, em vez de a origem ser a máquina clientes, a origem era a própria máquina da base de dados, feita pelo software que atua como proxy. Assim, todas as tentativas de conexão implícita estavam a ser consideradas como trusted independentemente da origem real.
Isto levou-me  a fazer alguns testes com PAM. Como saberá, o PAM é uma framework que permite às aplicações usar diferentes módulos de autenticação para efetuar a autenticação dos utilizadores. Plataformas diferentes trazem já módulos pré-instalados diferentes. O que vou demonstrar foi testado em Linux e AIX. Mas deverá funcionar com outros sistemas operativos que suportam PAM (HP-UX e Solaris). O problema é que um dos módulos poderá não estar instalado nas configurações base, ou no pior cenário pode não estar disponível para instalação. Nessa situação poderá ser necessário portar o módulo de Linux e adaptar o código fonte. Esse processo está fora do âmbito deste artigo.

Objectivo
Bem, o que se pretende alcançar é a emulação da autenticação nativa do Informix, mas usando PAM. Por omissão, mas dependendo da configuração das opções no $INFORMIXSQLHOSTS, o Informix aceita tanto ligações com utilizador e password como ligações implícitas. Para conseguir o que pretendo com PAM, necessito de configurar um serviço PAM que utilize dois mecanismos diferentes. Um para as relações de confiança e outro para a autenticação mais clássica com utilizador e password. O módulo PAM para utilizador e password é o mais fácil pois existe em todos os sistemas. Em Linux será o pam_unix e em AIX será o pam_aix. Para conseguir a funcionalidade das relações de confiança será o pam_rhosts (Linux) e pam_rhosts_auth (AIX). Não consegui encontrar este módulo para HP-UX, mas é possível adaptar a partir da versão para Linux. Existem algumas alterações que têm de ser feitas, pois o PAM em Linux tem algumas extensões ao PAM standard.
Após identificarmos os módulos temos de definir a sua configuração.

Configuração
Conforme mencionado na secção anterior, a ideia é configurar um listener usando PAM que aceite ambos os tipos de conexões. Se verificar os artigos anteriores, verifica que os módulos PAM podem ser configurados com um tipo e flag de controlo. O tipo pode ser auth, account, session ou password.
Foi também explicado que o Informix só utiliza o account e auth. Para cada tipo podemos especificar mais que um módulo. O tipo auth irá servir para verificar a identidade do utilizador (se a password está correta, se o par máquina/utilizar está trusted etc.) e o tipo account irá validar se a conta está válida etc.
A flag de controlo define o papel de cada módulo no resultado final da pilha de módulos para o mesmo tipo. Como cada tipo pode conter mais que um módulo, conseguimos assim definir por módulo de que forma o seu resultado afeta o resultado final. As opções que podemos usar são requisite, required, sufficient e optional. LinuxPAM é mais rico nas opções, mas irei manter-me no standard. Pode obter mais informações sobre tudo isto consultando as páginas do manual referentes a "pam" e "pam.conf" no seu sistema.
Portanto, já sabemos que necessitamos de módulos, tipo de módulos, flag de controlo e finalmente vamos precisar de um nome de serviço. O nome de serviço é o que quisermos usar e serve como ponte entre a configuração no Informix e no sistema de PAM.
Vou começar com a configuração de Informix e para tal vamos criar um novo porto para um listener. Vou usar o nome "cheetah_pam" como INFORMIXSERVER (ou para ser mais exato como DBSERVERALIAS). Nestes termos, necessitamos de uma nova entrada em $INFORMIXSQLHOSTS:
cheetah_pam  onsoctcp     primary 1533 s=4,pam_serv=(pam_informix),pamauth=(password)

Estou a usar "pam_informix" como nome de serviço e estou a utilizar o tipo de autenticação "password" na opção "pamauth". Os valores possíveis são "password" e "challenge".
"password" deveria ser usado em situações onde os clientes estão preparados para enviar a password e "challenge" para as outras situações (que implicariam a configuração de uma função de callback).
Mas como veremos, há algo mais sobre isto que aquilo que está explicado no manual.
Depois de adicionar o novo listener à configuração no $INFORMIXSQLHOSTS é necessário incluir isto também no $INFORMIXDIR/etc/$ONCONFIG, no parâmetro DBSERVERALIAS.

O próximo passo é configurar o stack PAM para este serviço. Isto é feito de forma ligeiramente diferente conforme estamos em Linux, AIX ou outros. Basicamente em Linux é usado um ficheiro com o nome do serviço criado em /etc/pam.d. Assim criaremos um ficheiro /etc/pam.d/pam_informix. Este ficheiro deverá conter várias linhas indicando o tipo, a flag de controlo, o nome do módulo e respetivos argumentos.
Em outros sistemas como AIX, existe apenas um ficheiro com o nome /etc/pam.conf e o nome de serviço é adicionado como primeira coluna desse ficheiro. Apesar de ambas as formas serem bastante semelhantes, julgo preferir a forma usada em Linux. Porquê? Porque tanto o /etc/pam.conf como os /etc/pam.d/* são controlados por root e um administrador se sistema não irá conceder-lhe a si, administrador de Informix, controlo sobre o ficheiro /etc/pam.conf. Mas poderá conceder controlo sobre um serviço (ficheiro - pam_informix) dentro do diretório /etc/pam.d
Enfim... Dado o que referi acima, esta será a configuração do serviço:
auth      sufficient  pam_rhosts.so debug
auth      sufficient  pam_unix.so
account   required    pam_unix.so

O que estou aqui a dizer? Como se pode ver, o tipo auth incluí dois módulos, ambos usando a flag de controlo sufficient. Isto significa que qualquer deles são suficientes para fazer o stack aceitar a autenticação. Se um falhar e o outro validar será suficiente. Se ambos falharem, então a autenticação falha.
Em relação ao account, estamos a usar o módulo pam_unix que valida se a conta é válida (não está bloqueada etc.). Para AIX as linhas seguintes teriam de ser adicionadas ao /etc/pam.conf:
pam_informix auth    sufficient /usr/lib/security/pam_rhosts_auth debug
pam_informix auth    sufficient /usr/lib/security/pam_aix
pam_informix account sufficient /usr/lib/security/pam_aix

TA diferença é que adicionámos o nome do serviço como primeira coluna do ficheiro, e os módulos são ligeiramente diferentes no nome.

Testes
Executei vários testes para validar esta implementação. Utilizei uma máquina virtual onde estou a correr a instância onde adicionei o listener cheetah_pam, e utilizei o SO nativo como cliente. O nome do meu cliente é "PTxxxxxx" e criei um utilizador com o mesmo nome no ambiente Linux. Também configurei uma instância numa máquina AIX e usei o Linux como cliente para executar alguns testes com conectividade 4GL.
O primeiro cenário é a instância Informix no Linux e o cliente no PC (Windows). Tenho dois ficheiros SQL:
C:\Programas\InformixClientSDK_370_tc7_c86>type *.sql

test_explicit.sql

CONNECT TO 'stores' USER 'PCxxxxxx' USING 'mypassword';
SELECT USER FROM sysmaster:sysdual;

test_implicit.sql

CONNECT TO 'stores';
SELECT USER FROM sysmaster:sysdual;

C:\Programas\InformixClientSDK_370_tc7_c86>

Vejamos o que acontece quando executo ambos os scripts:
C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_implicit.sql

 1809: Server rejected the connection.
Error in line 1
Near character position 1

C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_explicit.sql

Connected.

(expression)

PTxxxxxx
1 row(s) retrieved.

Disconnected.

C:\Programas\InformixClientSDK_370_tc7_c86>

Ok.As ligações implícitas estão a falhar, mas as que usam utilizador e password estão a funcionar. Isto é esperado porque não criei as relações de confiança na máquina Linux. Verifiquemos o syslog dessa máquina:
tail -20 /var/log/secure

[...]
Sep  4 06:52:07 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:07 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:09 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:09 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:12 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:12 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:14 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:14 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:17 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
Sep  4 06:52:17 primary oninit: pam_unix(pam_informix:auth): authentication failure; logname= uid=1002 euid=0 tty= ruser=PTxxxxxx rhost=192.168.142.1  user=PTxxxxxx
Sep  4 06:52:32 primary oninit: pam_rhosts(pam_informix:auth): denied access to PTxxxxxx@192.168.142.1 as PTxxxxxx
As primeiras pertencem à tentativa implícita e a última à explícita. Como pode ver, para a ligação implícita ambos os módulos reportam falha na autenticação, mas para a explícita apenas o pam_rhosts reporta falha. O pam_unix teve sucesso e como usamos sufficient isso basta para aceitar a conexão.
Agora vamos configurar a relação de confiânça. Para tal vou adicionar"PTxxxxxx   PTxxxxxx" ao ficheiro /etc/hosts.equiv.Vamos repetir o teste:

C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_implicit.sql

Connected.

(expression)

PCxxxxxx

1 row(s) retrieved.

Disconnected.

C:\Programas\InformixClientSDK_370_tc7_c86>

e agora vamos remover essa linha do /etc/hosts.equiv e adicioná-la ao ~PTxxxxxx/.rhosts
Conforme esperado:

C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_implicit.sql

Connected.

(expression)

PTxxxxxx

1 row(s) retrieved.

Disconnected.

C:\Programas\InformixClientSDK_370_tc7_c86>

Um teste final com este ambiente: Vamos remover a relação de confiança e tentar com uma password errada (modificando o ficheiro test_explicit.sql file):

C:\Programas\InformixClientSDK_370_tc7_c86>dbaccess - test_explicit.sql

 1809: Server rejected the connection.
Error in line 1
Near character position 1

C:\Programas\InformixClientSDK_370_tc7_c86>

Portanto, isto prova que no dbaccess podemos emular o comportamento nativo usando PAM. Mas e em relação às outras camadas de conectividade, como ODBC, .NET, 4GL etc.?
Bom... Tentei com tudo o que me ocorreu e só o OleDB falhou:
  • ConnectTestDemo (ok)
    (ferramenta de conectividade fornecida com o ClientSDK para Windows
  • ODBC (ok)
    (o habitual gestor de ODBC fornecido com o Windows)
  • VBScript que usa um data source ODBC (ok)
  • VBScript que usa OleDB (failhou!)
  • Ferramenta Java que usa JDBC (ok)
  • Cliente C# que usa  .NET (ok)
  • 4GL 7.50.UC4 nativo (ok)
Como referido acima, o cliente OleDB falhou, porque explicitamente não suporta PAM. Na verdade quando se tenta usar obtemos a seguinte mensagem no online.log:

10:35:24  listener-thread: err = -1809: oserr = 0: errstr = Client without PAM support connecting to PAM port: Server rejected the connection.

Portanto isto é declaradamente uma limitação no produto (atualmente). Acredito que isto poderia ser removido se assumirmos que passa a funcionar em modo de password e não em challenge. Fizémos isso muito recentemente para DRDA com PAM. Suspeito, mas não consigo ter a certeza, que a limitação deriva do facto de os clientes OleDB não podere especificar uma função de callback como fazemos em JDBC ou ESQL/C. E isso pode ser a fonte desta limitação. Seria melhor limitar o uso de PAM com OleDB a configurações exclusivamente com password.

Conclusões e problemas
Este pequeno exercício prova que podemos simular (com algumas diferenças mencionadas abaixo) o comportamento nativo usando PAM. Mas porque quereríamos fazer isso? Bom, consigo listar alguns motivos:
  1. Podemos querer validar o utilizador/password contra um repositório diferente do SO nativo (ou mais simplesmente mudar o mecanismo de encriptação e o Informix pode ser sensível a isso)
  2. Podemos configurar o SO para trabalhar com LDAP, e ainda que isso possa funcionar bem com utilitários nativos, pode quebrar a forma como o Informix valida os utilizadores no SO. O Informix utiliza as funções getpwnam() e crypt(). Se estas funções não funcionarem exatamente da mesma forma que antes da configuração para LDAP a autenticação Informix pode falhar
  3. Podemos querer aproveitar a flexibilidade do PAM. Depois de configurar estes dois módulos PAM, não há nada que nos impeça de introduzir outros módulos que forneçam outras funcionalidades. A única coisa que temos de manter em mente é que não podemos aceitar "challenges" desses módulos, dado que configurámos o serviço com a opção pamauth=(password) em vez de "challenge"
Mas como escrevi antes, existem alguns problemas:
  1. Ao usar a autenticação nativa, se fornecermos uma password, ira validar a password ou recusar a conexão. Neste exemplo, se a validação cotnra a password falhar vai tentar verificar a relação de confiança. Não me parece que isto seja um grande problema... Normalmente as relações de confiança são criadas para utilizadores que não têm password. E vice-versa, os utilizadores que usam passwords não costumam ter relações de confiança criadas
  2. Ao configurar o porto com pamauth=(password) abdicamos da possibilidade de usar algum módulo que envie um challenge, ao qual poderíamos responder com uma função configurada com o mecanismo de callback
  3. O módulo pam_rhosts valida as relações de confiança nos ficheiros /etc/hosts.equiv e ~utilizador/.rhosts
    Como sabemos, a partir da versão 11.70 o Informix pode (e deve) usar os seus próprios ficheiros. Seria possível e não demasiado complicado obter o código fonte do módulo, alterar estes ficheiros (aceitando-os como parâmetro do módulo por exemplo) para o adaptar à versão 11.7
  4. Em Linux (e isto não aconteceu em AIX e pode não acontecer noutras versões de Linux), o nome que é passado no PAM_RHOST ao módulo pam_rhosts tem de ser passível de resolução para endereço IP ou a autenticação neste módulo falhará

Wednesday, September 03, 2014

INDEX SKIP SCAN

This article is written in Englsih and Portuguese (original version here)
Este artigo está escrito em Inglês e Português (versão original aqui)


English version
What I'm writing about is not really a new feature... It was introduced in 11.70.xC1 and even then it was a port from Informix XPS and I suppose other RDBMs may have something like this. The reason why I'm writing about this now is that I recently went through some situations that made evident the reason why it was introduced

Problem description

It may not be evident to most people working in databases, but the way the data is physically distributed on disk will have a serious impact on the query resolution time. Imagine a simple scenario where we're joining two tables by customer_num for example. One of the tables is relatively large (200M rows) and for each customer_num it contains several records (tens). Let's call it the events table. We're joining it with another table (let's just call it a temp table) where we also have the customer_num and some other fields to which we apply some conditions.
The query plan is pretty obvious. Filters on the temp table and a nested loop with an index lookup on the events table.
This description mimics a real customer situation where they were complaining that the same query, roughly with the same amount of data and similar distribution jumped from around 1H to several hours. Apparently nothing relevant was changed. So why would the query take so much longer now?!

After examining the situation the conclusion was pretty obvious, although the root cause was still unknown: The query plan was the same, but the query now was "always" waiting for I/O. Assuming no problems were happening on the I/O system, what could explain this?

The explanation

After some discussion we figured out what changed. In previous situations, the events table was loaded by a process that worked as a single thread, and the way it compiled the information made the INSERTs in "batch mode". In practice, all the records from a single customer were inserted sequentially, so they were physically near on the disk. Due to some other changes, now the table was loaded using parallel threads, each working on a group of customers. So in practice each customer's records were split across several (sometimes far) physical disk pages.
It's important to note that from the informix perspective we were doing exactly the same steps:
  1. Filter the records on the temp table, extracting a stream of customer_num
  2. For each customer_num (NESTED LOOP), do an index lookup on the events table. This returns a set of rowids (physical page pointers on the data structure)
  3. For each rowid extracted before, access the physical page that contains the matching data.
Why would it take longer then?:
  • In the previous situation, with a single access to a page we would retrieve several rows of data
  • Even when the number of records for a customer_num would require more than one page, it was very likely the pages were physical contiguous. Due to several layers of caches (physical disks, controllers, arrays etc.) the second page access was probably already in cache (the Informix page size is small and no disk will transfer "only" 2 or 4KB on each operation). So the sub-sequent disk I/Os for the same customer would probably not require a real physical I/O 
Is this enough to explain the performance difference? Yes! Definitely. We tested to load ordered data into the table and got the expected results.
This is a good reason for the existence of CLUSTERED INDEXES.

INDEX SKIP SCAN

So, how is the above problem related to the feature called INDEX SKIP SCAN? To be honest it isn't... INDEX SKIP SCAN will not be used in the above situation. But I'm not (yet) completely crazy. In practice this feature tries to solve the same problem. How does it work? The skip scan was introduced when we released the multi index scan. When we use more than one index on the same table for a query, we gather several sets of ROWIDs. And it's highly likely that some of these ROWIDs are repeated among different sets. So it makes sense that we eliminate (skip) some ROWIDs from the scan (to avoid fetching the same rows several times). That's where the name comes from. In order to do this, each set of ROWIDs must be ordered and then merged.
Although it was designed for multi index access, the process can be useful for a single index also. Before the feature, Informix would fetch the page for each rowid retrieved from the index. With the feature it will try to buffer the rowids, sort them, and access the pages after. The result of this is that we increase the probability of fetching sequential (or at least close enough) pages, so that we take advantage of the underlying caches.

Testing

In order to show the effect of this physical layout, I prepared a relatively simple test case. I generated 2M rows of a table using an AWK script. This table has just two columns:
  • col1 INTEGER
  • col2 CHAR(75)
The data was created in a way that the values for column col1 vary between 1 and 40000. On average each value in col1 has 50 rows with that value. Maximum repetition is 82:

castelo@primary:informix-> dbaccess stores -

Database selected.

> select first 3 col1 c1, count(*) c2 from test_data group by 1 order by 2 desc;
select first 3 col1 c1, count(*) c2 from test_data group by 1 order by 2;
select avg(c2) from (select col1 c1, count(*) c2 from test_data group by 1 );

         c1               c2 
      38137               82
      30478               79
      29224               79
3 row(s) retrieved.

> 
         c1               c2 
      33710               24
      39038               26
      32313               26
3 row(s) retrieved.
> 
           (avg) 
50.0000000000000
1 row(s) retrieved.

> 


I then created a few SQL scripts:
  1. test_query_count
    Does a simple count WHERE col1 BETWEEN 1000 and 1400
  2. test_query_data_full
    Does a SELECT * of the same records, forcing a SEQUENTIAL SCAN
  3. test_query_data_index_skip_scan
    Does a SELECT * of the same records forcing the new feature
  4. test_query_data_index
    Does a SELECT * of the same records using the normal INDEX PATH
  5. test_query_force_sort
    This is the trickiest one. I do a SELECT * using the ROWIDs gathered from an inline view that uses the same criteria and ORDERs the ROWIDs. The goal here is to emulate the feature in a way that it's compatible with older versions
All the scripts write the query plan to a file and insert a record into a control table that has the identifier for the query and the start and stop time.
castelo@primary:informix-> for script in test_query*.sql
do
  printf '===============================================\n%s\n===============================================\n' $script
  cat $script
  printf "\n\n\n"
done
 ===============================================
test_query_count.sql
===============================================
!rm sqexplain_query_count.out
SET EXPLAIN FILE TO 'sqexplain_query_count.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Simple count', CURRENT YEAR TO FRACTION(3));
SELECT --+ EXPLAIN
COUNT(*) FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Simple count';



===============================================
test_query_data_full.sql
===============================================
!rm sqexplain_data_full.out
SET EXPLAIN FILE TO 'sqexplain_data_full.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Sequential scan (force)', CURRENT YEAR TO FRACTION(3));
UNLOAD TO /dev/null
SELECT --+ EXPLAIN, FULL (test_data)
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Sequential scan (force)';



===============================================
test_query_data_index_skip_scan.sql
===============================================
!rm sqexplain_data_index_skip_scan.out
SET EXPLAIN FILE TO 'sqexplain_data_index_skip_scan.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Data with index skip scan (force)', CURRENT YEAR TO FRACTION(3));
UNLOAD TO /dev/null SELECT --+ EXPLAIN, MULTI_INDEX(test_data)
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Data with index skip scan (force)';



===============================================
test_query_data_index.sql
===============================================
!rm sqexplain_data_index.out
SET EXPLAIN FILE TO 'sqexplain_data_index.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Data with index', CURRENT YEAR TO FRACTION(5));
UNLOAD TO /dev/null SELECT --+ EXPLAIN
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Data with index';



===============================================
test_query_force_sort.sql
===============================================
!rm sqexplain_force_sort.out
SET EXPLAIN FILE TO 'sqexplain_force_sort.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Data with index and sorted rowIDs', CURRENT YEAR TO FRACTION(3));
UNLOAD TO /dev/null SELECT --+ EXPLAIN
a.* FROM test_data a, (SELECT rowid r FROM test_data c WHERE col1 BETWEEN 1000 AND 1400 ORDER BY 1) b
WHERE a.rowid = b.r;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Data with index and sorted rowIDs';


Finally I created a SHELL script that recreates and loads the data table and the control table and then executes each of these scripts. It restarts the engine between each script to clean up the caches Let's see the results:

castelo@primary:informix-> cat test_script.sh;printf "\n\n";./test_script.sh 2>&1| grep -v "^$"
#!/bin/bash

printf "Recreating and loading table...\n"
dbaccess stores <<EOF
DROP TABLE IF EXISTS test_data;
DROP TABLE IF EXISTS test_data_results;

CREATE RAW TABLE test_data
(
        col1 INTEGER,
        col2 CHAR(75)
) IN dbs1 EXTENT SIZE 5000 NEXT SIZE 5000;


BEGIN WORK;
LOCK TABLE test_data IN EXCLUSIVE MODE;
LOAD FROM test_data.unl INSERT INTO test_data;
COMMIT WORK;

ALTER TABLE test_data TYPE (standard);

CREATE INDEX ix_test_data_1 ON test_data(col1) IN dbs2;

CREATE TABLE test_data_results
(
        access_type VARCHAR(255),
        query_start DATETIME YEAR TO FRACTION(3),
        query_end DATETIME YEAR TO FRACTION(3)
);

EOF
printf "Done...\n"
for SCRIPT in test_query_count.sql test_query_data_full.sql test_query_data_index_skip_scan.sql test_query_data_index.sql test_query_force_sort.sql
do
        printf "Stopping informix...\n"
        onmode -ky
        printf "Starting informix...\n"
        oninit -w
        printf "Running script $SCRIPT\n"
        dbaccess stores $SCRIPT
        printf "\nDone...\n"
done

dbaccess stores <<EOF
SELECT
        access_type, query_start, query_end, query_end - query_start elapsed_time
FROM
        test_data_results;
EOF


Recreating and loading table...
Database selected.
Table dropped.
Table dropped.
Table created.
Started transaction.
Table locked.
2000000 row(s) loaded.
Data committed.
Table altered.
Index created.
Table created.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_count.sql
Database selected.
Explain set.
1 row(s) inserted.
      (count(*)) 
           20267
1 row(s) retrieved.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_data_full.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_data_index_skip_scan.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_data_index.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_force_sort.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Database selected.
access_type   Simple count
query_start   2014-09-02 13:08:12.141
query_end     2014-09-02 13:08:12.259
elapsed_time          0 00:00:00.118
access_type   Sequential scan (force)
query_start   2014-09-02 13:08:29.215
query_end     2014-09-02 13:08:36.838
elapsed_time          0 00:00:07.623
access_type   Data with index skip scan (force)
query_start   2014-09-02 13:08:54.250
query_end     2014-09-02 13:09:03.403
elapsed_time          0 00:00:09.153
access_type   Data with index
query_start   2014-09-02 13:09:21.684
query_end     2014-09-02 13:10:53.474
elapsed_time          0 00:01:31.790
access_type   Data with index and sorted rowIDs
query_start   2014-09-02 13:11:12.682
query_end     2014-09-02 13:11:22.874
elapsed_time          0 00:00:10.192
5 row(s) retrieved.
Database closed.
castelo@primary:informix->

We can see the results in a table:

Query
Start
Stop
Elapsed
Simple count
13:08:12.141
13:08:12.259
00:00:00.118 (0s)
Sequential scan (force)
13:08:29.215
13:08:36.838
00:00:07.623 (7.6s)
Data with index skip scan (force)
13:08:54.250
13:09:03.403
00:00:09.153 (9.1s)
Data with index
13:09:21.684
13:10:53.474
00:01:31.790 (1m31s)
Data with index and sorted rowIDs
13:11:12.682
13:11:22.874
00:00:10.192 (10.1s)
So, here are the important points:
  1. SELECT COUNT(*) is extremely fast. Just count the index entries that match the criteria
  2. A sequential scan takes around 8s. The table size is small.
  3. Forcing the MULTINDEX path allows the INDEX SKIP SCAN feature and it's around the same as a full sequential scan
  4. Going through the normal index PATH is extremely slow. 1.5 minutes compared to ~10s for the other options. That's the price we pay for scattered reads.
  5. By simulating the feature we get a time very close to the feature itself
I also used a script I mentioned before, called ixprofiling, to show the real work being done do solve each query. For the query that uses INDEX SKIP SCAN:

castelo@primary:informix-> onmode -ky;oninit -w;ixprofiling -z -i stores test1.sql

Database selected.

Engine statistics RESETed. Query results:
Query start time: 17:31:06.017924000

UNLOAD TO /dev/null SELECT --+ EXPLAIN, MULTI_INDEX(test_data)
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
20267 row(s) unloaded.

Query stop time: 17:31:15.806221000

Thread profiles (SID: 6)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
40641 0     0     0     0     526   0     0     0     18335 0     0     0     2     1     0     0     36962 0.340086802 sqlexec     
LkWs         IOWs         nIOW         IdxBR        Name                               
------------ ------------ ------------ ------------ -----------------------------------
0.0          9.3030077117 18157        0            sqlexec                            

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
20267 0     0     0     18018 0     495   0     0     0     18076 0     1     test_data
20307 0     0     0     109   0     0     0     0     0     365   0     0     test_data#ix_test_data_1

Database closed.

real    0m11.807s
user    0m0.000s
sys     0m0.090s
castelo@primary:informix->

For the normal query:

castelo@primary:informix-> onmode -ky;oninit -w;ixprofiling -z -i stores test2.sql

Database selected.

Engine statistics RESETed. Query results:
Query start time: 17:45:39.873507000

UNLOAD TO /dev/null SELECT --+ EXPLAIN
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
20267 row(s) unloaded.

Query stop time: 17:47:11.803271000

Thread profiles (SID: 6)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
40720 0     0     0     0     31    0     0     0     20608 0     0     0     1     0     0     0     950   0.261092628 sqlexec     
LkWs         IOWs         nIOW         IdxBR        Name                               
------------ ------------ ------------ ------------ -----------------------------------
0.0          6.2963172635 320          0            sqlexec                            

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
20267 0     0     0     17921 0     0     0     0     0     39562 0     0     test_data
20386 0     0     0     206   0     0     0     0     0     587   0     0     test_data#ix_test_data_1

Database closed.

real    1m35.757s
user    0m0.050s
sys     0m0.080s
castelo@primary:informix->


Things to note:
  1. The number of disk reads is roughly the same.
  2. The number of buffer reads on the partitions is significantly higher in the second case
  3. The CPU time is actually higher (slightly) on the first query
If we compare sections of onstat -g ioa we confirm the work done in terms of I/O was similar, but we know one of them took much longer:

I/O queues:
AIO I/O queues with INDEX SKIP SCAN:
q name/id    len maxlen totalops  dskread dskwrite  dskcopy
 fifo   0      0      0        0        0        0        0
drda_dbg   0      0      0        0        0        0        0
sqli_dbg   0      0      0        0        0        0        0
  kio   0      0     32      725      408      317        0
  kio   1      0     33    20342    20274       68        0
  adt   0      0      0        0        0        0        0
  msc   0      0      1        4        0        0        0


AIO I/O queues for normal query:
q name/id    len maxlen totalops  dskread dskwrite  dskcopy
 fifo   0      0      0        0        0        0        0
drda_dbg   0      0      0        0        0        0        0
sqli_dbg   0      0      0        0        0        0        0
  kio   0      0     33     9667     9653       14        0
  kio   1      0     33    11051    11035       16        0
  adt   0      0      0        0        0        0        0
  msc   0      0      1        4        0        0        0


Apparently the slower one did less work! Some more writes for the first. Hard to tell if significant.


AIO I/O vps with INDEX SKIP SCAN:
class/vp/id s  io/s totalops  dskread dskwrite  dskcopy  wakeups  io/wup  errors tempops
 fifo  7  0 i   0.0        0        0        0        0        0   0.0       0        0
  kio -1  0 i   0.5      379      210      169        0      579   0.7       0        0
  kio -1  1 i  25.4    19839    19792       47        0    33783   0.6       0        0
  msc  6  0 i   0.0        4        0        0        0        4   1.0       0        9
  aio  5  0 i   0.6      469      195       84        0      469   1.0       0        0
 [...]


AIO I/O vps for normal query:
class/vp/id s  io/s totalops  dskread dskwrite  dskcopy  wakeups  io/wup  errors tempops
 fifo  7  0 i   0.0        0        0        0        0        0   0.0       0        0
  kio -1  0 i  56.2     9506     9492       14        0    15327   0.6       0        0
  kio -1  1 i  61.5    10395    10379       16        0    14895   0.7       0        0
  msc  6  0 i   0.0        4        0        0        0        4   1.0       0        9
  aio  5  0 i   2.7      459      195       74        0      459   1.0       0      460
  [...]

Roughly the same work, but more evely split across the two kio threads for the slower query. Possibly an indication that the I/Os are slower.


AIO big buffer usage summary with INDEX SKIP SCAN:
class                 reads                                   writes
       pages    ops  pgs/op  holes  hl-ops hls/op      pages    ops  pgs/op
fifo      0       0   0.00      0       0   0.00           0      0   0.00
drda_dbg  0       0   0.00      0       0   0.00           0      0   0.00
sqli_dbg  0       0   0.00      0       0   0.00           0      0   0.00
 kio  21665   20002   1.08    983     151   6.51         871    216   4.03


AIO big buffer usage summary for normal query:

class                 reads                                   writes
       pages    ops  pgs/op  holes  hl-ops hls/op      pages    ops  pgs/op
fifo      0       0   0.00      0       0   0.00           0      0   0.00
drda_dbg  0       0   0.00      0       0   0.00           0      0   0.00
sqli_dbg  0       0   0.00      0       0   0.00           0      0   0.00
 kio  22576   19871   1.14   1888     279   6.77         498     30  16.60 
 
Not a huge difference for the number of operations.

Conclusion

Don't underestimate the real effect of data dispersion on disk. This situation shows clearly the impact. On another customer situation I had very recently I saw around 4 times performance degradation when comparing the sorted rowids method to the natural method.
I'd like to see this feature being more naturally used in Informix (outside the scenario of MULTI_INDEX path).

Versão Portuguesa
O assunto sobre o qual vou escrever não é propriamente novidade. Foi introduzido na versão 11.70.xC1 e mesmo aí foi um port de uma funcionalidade que já existia no Informix XPS e penso que em outras bases de dados do mercado. A razão porque decidi descrever esta funcionalidade prende.se com o facto de ter estado envolvido em situações recentemente onde ficou evidente a razão para a sua criação.

Descrição do problema

Pode não ser evidente para todas as pessoas que trabalham com bases de dados, mas a forma como os dados estão físicamente dispostos nos discos terá um impacto significativo na resolução das queries. Imagine um cenário simples onde façamos um JOIN entre duas tabelas por customer_num por exemplo. Uma dessas tabelas é relativamente grande (200M registos) e para cada customer_num contém vários registos (dezenas). Vamos chamar a esta tabela "eventos". Estamos a fazer o JOIN com outra tabela (chamemos-lhe apenas uma tabela temporária) onde temos o campo customer_num e outros campos aos quais aplicamos uma ou mais condições. O plano de execução será bastante óbvio. Filtros aplicados na tabela temporária e um NESTED LOOP JOIN com procura por índice na tabela de eventos.
Esta descrição é uma réplica de uma situação real num cliente onde se estavam a queixar que para o mesmo processo, grosseiramente com o mesmo volume de dados e distribuições semelhantes o processo tinha passado de 1H para várias. Aparentemente nada tinha mudado. Sendo assim de onde vinha a lentidão?!


Depois de analizar a situação a conclusão foi bastante óbvia, apesar se a causa original ser ainda desconhecida: O plano de execução não se tinha alterado, mas agora a query estava "sempre" à espera de I/O. Assumindo que não havia problemas no sistema de I/O o que poderia causar isto?

A explicação

Após alguma discussão, descobrimos o que tinha mudado. Na situação anterior, a tabela de eventos era carregada por um único processo e a forma de processamento resultava em INSERTs em "batch". Na prática, todos os registos de um mesmo customer_num eram inseridos sequencialmente, pelo que resultava numa ordenação física no disco. Devido a algumas mudanças nos processos, agora a tabela era carregada usando processos paralelos, cada um trabalhando num conjunto distinto de clientes. Por isso na prática,  os registos para um mesmo customer_num acabavam dispersos (por vezes muito afastadas) em várias páginas em disco.
É importante salientar que do ponto de vista do Informix estávamos a fazer exactamente os mesmos passos:

  1. Filtrar os registos na tabela temporária, obtendo uma lista de valores de customer_num
  2. Para cada customer_num (NESTED LOOP), fazer uma pesquisa no índice da tabela de eventos. Isto retorna uma lista de rowIDs (ponteiros para as páginas físicas dos dados)
  3. Para cada rowID obtido anteriromente, aceder à página de dados e obter os dados correspondentes
Porque demoraria mais então?
  • Na situação anterior, com um único acesso a uma página obtinhamos normalmente mais que um registo de dados (os acessos futuros já estavam em cache
  • Mesmo quando o número de registos para um customer_num precisasse de mais de uma página, as páginas sub-sequentes estavam contíguas em disco. E devido a vários níveis de caches (discos físicos, controladores, arrays etc.) o acesso às segundas páginas já seria resolvido em cache (o tamanho de página do Informix é pequeno e nenhum sistema de armazenamento faz transferências de "apenas" 2 ou 4KB em cada operação). Ou seja, os segundos acessos raramente necessitariam de uma operação física em disco
Será isto suficiente para explicar a diferença de performance? Sim! Sem sombra para dúvidas. Testámos carregar a tabela de eventos de forma "ordenada" e os tempos de execução voltaram a rondar 1H.
Eis uma boa razão para a existência de CLUSTERED INDEXES.

INDEX SKIP SCAN

Bom, então como está relacionado o problema acima com a funcionalidade chamada INDEX SKIP SCAN? Para ser honesto não está... INDEX SKIP SCAN não seria utilizado na situação acima. Mas (ainda) não estou completamente louco. Na prática esta funcionalidade  resolve o mesmo problema. Como funciona? O INDEX SKIP SCAN foi introduzido juntamente com o MULTI INDEX SCAN. Quando usamos mais que um índice numa mesma tabela, obtemos tantos conjuntos de rowIDs quanto os índices que estamos a utilizar. E é muito provável que haja duplicações entre estes conjuntos. Por isso faz todo o sentido que eliminemos (SKIP) os duplicados para evitar tentar obter a mesma linha duas vezes. É daí que vem o nome. Cada conjunto de rowIDs têm de ser ordenado e depois é feito o merge dos mesmos.
Apesar de ter sido desenhado para o MULTI INDEX ACCESS, o processo pode ser útil para um único indíce também. Antes desta funcionalidade  o acesso às páginas de dados era directo e pela ordem que os rowIDs eram encontrados. Com a funcionalidade activa é feita uma ordenação dos valores de rowID e depois então é feito o acesso aos dados. Daqui resulta uma probabilidade muito maior de que se façam I/Os de páginas consecutivas ou pelo menos mais próximas. Isto permite aproveitar melhor as caches que estejam envolvidas.

Testando

Com o objectivo de mostrar os efeitos da distribuição fisica dos dados, preparei um caso de teste relativamente simples. Gerei 2M de linhas para uma tableam usando um script AWK. Esta tabela tem apenas duas colunas:
  • col1 INTEGER
  • col2 CHAR(75)
Os dados foram criados de uma forma em que os valores da col1 variam entre 1 e 40000. Em média, cada um destes valores corresponde a 50 registos na tabela. O valor mais repeitdo tem 82 ocorrências:

castelo@primary:informix-> dbaccess stores -

Database selected.

> select first 3 col1 c1, count(*) c2 from test_data group by 1 order by 2 desc;
select first 3 col1 c1, count(*) c2 from test_data group by 1 order by 2;
select avg(c2) from (select col1 c1, count(*) c2 from test_data group by 1 );

         c1               c2 
      38137               82
      30478               79
      29224               79
3 row(s) retrieved.

> 
         c1               c2 
      33710               24
      39038               26
      32313               26
3 row(s) retrieved.
> 
           (avg) 
50.0000000000000
1 row(s) retrieved.

> 

Depois criei alguns scripts SQL:
  1. test_query_count
    Faz um COUNT(*) simples WHERE col1 BETWEEN 1000 and 1400
  2. test_query_data_full
    Faz um SELECT * dos mesmos registos, forçando um SEQUENTIAL SCAN
  3. test_query_data_index_skip_scan
    Faz um SELECT * dos mesmos registos forçando a nova funcionalidade
  4. test_query_data_index
    Faz um SELECT * dos mesmos registos, usando o normal INDEX PATH
  5. test_query_force_sort
    Este é o mais rebuscado. Faz um SELECT * usando ROWIDs obtidos numa inline view que usa o mesmo critério e um ORDERs dos ROWIDs. O objectivo é simular a funcionalidade, numa forma que seja compatível com versões anteriores
Todos os scripts escrevem o plano de execução num ficheiro e inserem numa tabela de controlo um registo que tem o identificador da query e o tempo de início e fim da mesma..
castelo@primary:informix-> for script in test_query*.sql
do
  printf '===============================================\n%s\n===============================================\n' $script
  cat $script
  printf "\n\n\n"
done
 ===============================================
test_query_count.sql
===============================================
!rm sqexplain_query_count.out
SET EXPLAIN FILE TO 'sqexplain_query_count.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Simple count', CURRENT YEAR TO FRACTION(3));
SELECT --+ EXPLAIN
COUNT(*) FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Simple count';



===============================================
test_query_data_full.sql
===============================================
!rm sqexplain_data_full.out
SET EXPLAIN FILE TO 'sqexplain_data_full.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Sequential scan (force)', CURRENT YEAR TO FRACTION(3));
UNLOAD TO /dev/null
SELECT --+ EXPLAIN, FULL (test_data)
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Sequential scan (force)';



===============================================
test_query_data_index_skip_scan.sql
===============================================
!rm sqexplain_data_index_skip_scan.out
SET EXPLAIN FILE TO 'sqexplain_data_index_skip_scan.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Data with index skip scan (force)', CURRENT YEAR TO FRACTION(3));
UNLOAD TO /dev/null SELECT --+ EXPLAIN, MULTI_INDEX(test_data)
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Data with index skip scan (force)';



===============================================
test_query_data_index.sql
===============================================
!rm sqexplain_data_index.out
SET EXPLAIN FILE TO 'sqexplain_data_index.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Data with index', CURRENT YEAR TO FRACTION(5));
UNLOAD TO /dev/null SELECT --+ EXPLAIN
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Data with index';



===============================================
test_query_force_sort.sql
===============================================
!rm sqexplain_force_sort.out
SET EXPLAIN FILE TO 'sqexplain_force_sort.out';
INSERT INTO test_data_results (access_type, query_start) VALUES ('Data with index and sorted rowIDs', CURRENT YEAR TO FRACTION(3));
UNLOAD TO /dev/null SELECT --+ EXPLAIN
a.* FROM test_data a, (SELECT rowid r FROM test_data c WHERE col1 BETWEEN 1000 AND 1400 ORDER BY 1) b
WHERE a.rowid = b.r;
UPDATE test_data_results SET query_end = CURRENT YEAR TO FRACTION(3) WHERE access_type = 'Data with index and sorted rowIDs';


Por último criei um script SHELL que recria e carrega a tabela de dados e a tabela de controlo. Depois executa cada um destes scripts, fazendo um reinício do motor para limpar caches. Vejamos os resultados:

castelo@primary:informix-> cat test_script.sh;printf "\n\n";./test_script.sh 2>&1| grep -v "^$"
#!/bin/bash

printf "Recreating and loading table...\n"
dbaccess stores <<EOF
DROP TABLE IF EXISTS test_data;
DROP TABLE IF EXISTS test_data_results;

CREATE RAW TABLE test_data
(
        col1 INTEGER,
        col2 CHAR(75)
) IN dbs1 EXTENT SIZE 5000 NEXT SIZE 5000;


BEGIN WORK;
LOCK TABLE test_data IN EXCLUSIVE MODE;
LOAD FROM test_data.unl INSERT INTO test_data;
COMMIT WORK;

ALTER TABLE test_data TYPE (standard);

CREATE INDEX ix_test_data_1 ON test_data(col1) IN dbs2;

CREATE TABLE test_data_results
(
        access_type VARCHAR(255),
        query_start DATETIME YEAR TO FRACTION(3),
        query_end DATETIME YEAR TO FRACTION(3)
);

EOF
printf "Done...\n"
for SCRIPT in test_query_count.sql test_query_data_full.sql test_query_data_index_skip_scan.sql test_query_data_index.sql test_query_force_sort.sql
do
        printf "Stopping informix...\n"
        onmode -ky
        printf "Starting informix...\n"
        oninit -w
        printf "Running script $SCRIPT\n"
        dbaccess stores $SCRIPT
        printf "\nDone...\n"
done

dbaccess stores <<EOF
SELECT
        access_type, query_start, query_end, query_end - query_start elapsed_time
FROM
        test_data_results;
EOF


Recreating and loading table...
Database selected.
Table dropped.
Table dropped.
Table created.
Started transaction.
Table locked.
2000000 row(s) loaded.
Data committed.
Table altered.
Index created.
Table created.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_count.sql
Database selected.
Explain set.
1 row(s) inserted.
      (count(*)) 
           20267
1 row(s) retrieved.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_data_full.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_data_index_skip_scan.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_data_index.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Stopping informix...
Starting informix...
Running script test_query_force_sort.sql
Database selected.
Explain set.
1 row(s) inserted.
20267 row(s) unloaded.
1 row(s) updated.
Database closed.
Done...
Database selected.
access_type   Simple count
query_start   2014-09-02 13:08:12.141
query_end     2014-09-02 13:08:12.259
elapsed_time          0 00:00:00.118
access_type   Sequential scan (force)
query_start   2014-09-02 13:08:29.215
query_end     2014-09-02 13:08:36.838
elapsed_time          0 00:00:07.623
access_type   Data with index skip scan (force)
query_start   2014-09-02 13:08:54.250
query_end     2014-09-02 13:09:03.403
elapsed_time          0 00:00:09.153
access_type   Data with index
query_start   2014-09-02 13:09:21.684
query_end     2014-09-02 13:10:53.474
elapsed_time          0 00:01:31.790
access_type   Data with index and sorted rowIDs
query_start   2014-09-02 13:11:12.682
query_end     2014-09-02 13:11:22.874
elapsed_time          0 00:00:10.192
5 row(s) retrieved.
Database closed.
castelo@primary:informix->

Podemos ver os resultados numa tabela:

Query
Start
Stop
Elapsed
Simple count
13:08:12.141
13:08:12.259
00:00:00.118 (0s)
Sequential scan (force)
13:08:29.215
13:08:36.838
00:00:07.623 (7.6s)
Data with index skip scan (force)
13:08:54.250
13:09:03.403
00:00:09.153 (9.1s)
Data with index
13:09:21.684
13:10:53.474
00:01:31.790 (1m31s)
Data with index and sorted rowIDs
13:11:12.682
13:11:22.874
00:00:10.192 (10.1s)
Aqui ficam os pontos importantes:
  1. SELECT COUNT(*) é extremamente rápido. Apenas conta o número de entradas no índice que verificam o critério
  2. Uma leitura sequencial e integral da tabela demora cerca de 10s. O tamanho da tabela é pequeno.
  3. Forçando o acesso com o MULTI_INDEX permitimos o INDEX SKIP SCAN e demora aproximadamente o mesmo que o sequential scan neste caso.
  4. Através do normal INDEX PATH, é extremamente lento. 1.5 minutos comparado com cerca de 10s das outras alternativas. É este o preço que pagamos por leituras dispersas
  5. Simulando a funcionalidade, com o truque de ordenar os rowids, conseguimos um valor parecido com o obtido usando a própria funcionalidade
Também usei um script que já referi noutr(s) artigos, chamado ixprofiling, para demonstrar o trabalho real feito por cada query. Para a query que usa o INDEX SKIP SCAN:
castelo@primary:informix-> onmode -ky;oninit -w;ixprofiling -z -i stores test1.sql

Database selected.

Engine statistics RESETed. Query results:
Query start time: 17:31:06.017924000

UNLOAD TO /dev/null SELECT --+ EXPLAIN, MULTI_INDEX(test_data)
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
20267 row(s) unloaded.

Query stop time: 17:31:15.806221000

Thread profiles (SID: 6)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
40641 0     0     0     0     526   0     0     0     18335 0     0     0     2     1     0     0     36962 0.340086802 sqlexec     
LkWs         IOWs         nIOW         IdxBR        Name                               
------------ ------------ ------------ ------------ -----------------------------------
0.0          9.3030077117 18157        0            sqlexec                            

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
20267 0     0     0     18018 0     495   0     0     0     18076 0     1     test_data
20307 0     0     0     109   0     0     0     0     0     365   0     0     test_data#ix_test_data_1

Database closed.

real    0m11.807s
user    0m0.000s
sys     0m0.090s
castelo@primary:informix->
Para a query normal:
castelo@primary:informix-> onmode -ky;oninit -w;ixprofiling -z -i stores test2.sql

Database selected.

Engine statistics RESETed. Query results:
Query start time: 17:45:39.873507000

UNLOAD TO /dev/null SELECT --+ EXPLAIN
* FROM test_data WHERE col1 BETWEEN 1000 AND 1400;
20267 row(s) unloaded.

Query stop time: 17:47:11.803271000

Thread profiles (SID: 6)
LkReq LkWai DLks  TOuts LgRec IsRd  IsWrt IsRWr IsDel BfRd  BfWrt LgUse LgMax SeqSc Srts  DskSr SrtMx Sched CPU Time    Name        
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----------- ------------ 
40720 0     0     0     0     31    0     0     0     20608 0     0     0     1     0     0     0     950   0.261092628 sqlexec     
LkWs         IOWs         nIOW         IdxBR        Name                               
------------ ------------ ------------ ------------ -----------------------------------
0.0          6.2963172635 320          0            sqlexec                            

Partitions profiles (Database: stores)
LkReq LkWai DLks  TOuts DskRd DskWr IsRd  IsWrt IsRWr IsDel BfRd  BfWrt SeqSc Object name                                           
----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ------------------------------------------------------
20267 0     0     0     17921 0     0     0     0     0     39562 0     0     test_data
20386 0     0     0     206   0     0     0     0     0     587   0     0     test_data#ix_test_data_1

Database closed.

real    1m35.757s
user    0m0.050s
sys     0m0.080s
castelo@primary:informix->
Notas:
  1. O número de leituras em disco é aproximadamente o mesmo
  2. O número de leituras de buffers por partição na segunda query é sinificativamente mais alto
  3. O tempo de CPU na verdade é mais alto (pouco) na primeira opção
Se compararmos algumas secções de um onstat -g ioa podemos confirmar as semlhanças entre o trabalho feito de uma forma e de outra:

I/O queues:
AIO I/O queues com INDEX SKIP SCAN:
q name/id    len maxlen totalops  dskread dskwrite  dskcopy
 fifo   0      0      0        0        0        0        0
drda_dbg   0      0      0        0        0        0        0
sqli_dbg   0      0      0        0        0        0        0
  kio   0      0     32      725      408      317        0
  kio   1      0     33    20342    20274       68        0
  adt   0      0      0        0        0        0        0
  msc   0      0      1        4        0        0        0

AIO I/O queues para a query  normal:
q name/id    len maxlen totalops  dskread dskwrite  dskcopy
 fifo   0      0      0        0        0        0        0
drda_dbg   0      0      0        0        0        0        0
sqli_dbg   0      0      0        0        0        0        0
  kio   0      0     33     9667     9653       14        0
  kio   1      0     33    11051    11035       16        0
  adt   0      0      0        0        0        0        0
  msc   0      0      1        4        0        0        0

Aparentemente o mais lento até fez menos trabalho. Mais algumas escritas para o primeiro. É difícil extrair o significado disto

AIO I/O vps com INDEX SKIP SCAN:
class/vp/id s  io/s totalops  dskread dskwrite  dskcopy  wakeups  io/wup  errors tempops
 fifo  7  0 i   0.0        0        0        0        0        0   0.0       0        0
  kio -1  0 i   0.5      379      210      169        0      579   0.7       0        0
  kio -1  1 i  25.4    19839    19792       47        0    33783   0.6       0        0
  msc  6  0 i   0.0        4        0        0        0        4   1.0       0        9
  aio  5  0 i   0.6      469      195       84        0      469   1.0       0        0
 [...]

AIO I/O vps para a query normal:
class/vp/id s  io/s totalops  dskread dskwrite  dskcopy  wakeups  io/wup  errors tempops
 fifo  7  0 i   0.0        0        0        0        0        0   0.0       0        0
  kio -1  0 i  56.2     9506     9492       14        0    15327   0.6       0        0
  kio -1  1 i  61.5    10395    10379       16        0    14895   0.7       0        0
  msc  6  0 i   0.0        4        0        0        0        4   1.0       0        9
  aio  5  0 i   2.7      459      195       74        0      459   1.0       0      460
  [...]

Grosso modo o mesmo trabalho, mas mais distribuído entre as threads kio no caso da query mais lenta. Possivelmente uma indicação de que as operações estão a demorar mais.

AIO big buffer usage summary com INDEX SKIP SCAN:
class                 reads                                   writes
       pages    ops  pgs/op  holes  hl-ops hls/op      pages    ops  pgs/op
fifo      0       0   0.00      0       0   0.00           0      0   0.00
drda_dbg  0       0   0.00      0       0   0.00           0      0   0.00
sqli_dbg  0       0   0.00      0       0   0.00           0      0   0.00
 kio  21665   20002   1.08    983     151   6.51         871    216   4.03


AIO big buffer usage summary para a query normal:
class                 reads                                   writes
       pages    ops  pgs/op  holes  hl-ops hls/op      pages    ops  pgs/op
fifo      0       0   0.00      0       0   0.00           0      0   0.00
drda_dbg  0       0   0.00      0       0   0.00           0      0   0.00
sqli_dbg  0       0   0.00      0       0   0.00           0      0   0.00
 kio  22576   19871   1.14   1888     279   6.77         498     30  16.60 
 
Não existe uma grande diferença no número de operações

Conclusão

Nunca subestime o efeito real da dispersão de dados em disco. Esta situação demonstra o potencial impacto com clareza. Numa outra situação num cliente, que tive muito recentemente, verifiquei uma degradação de performance de 4 vezes quando comparava o método de ordenar os ROWIDs com o método "natural". Gostaria de ver esta funcionalidade ser usada mais naturalmente no Informix (fora dos cenários de utilização do MULTI_INDEX path).