New feature? / Nova funcionalidade?

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:

The fun...

Working with Informix has been much fun, but sometimes for strange reasons. One of those is the consequence of not being considered a "mainstream" database. From time to time I see references to features of "mainstream" databases that do amuse me. It surely happens the other way around, but the echoes of that are naturally smaller and could be expected from what bloggers and analysts would consider a non-Tier 1 database. So, when this happens It really makes my day...
This time, while browsing the Net, I noticed several articles or posts talking about a "new fascinating feature" of SQL Server 2014 CTP2 (pre-release) called Delayed Transaction Durability. Well... After reading some of those posts including the "official source" I was a bit surprised that this is just what we call buffered logging! Yes... The ability to delay logical log buffer flush until the logical log buffer is full. And yes, same as us, it means that an application can assume something is committed while if there is a database crash it won't (the fast recovery process will rollback the transaction).
So, as you may expect, most bloggers were careful to note this could lead to data loss. In fact the database integrity is preserved, but because the application receives the commit "ok" message before it was actually written to disk, a crash in the specific interval would mean the transaction would be incomplete so a rollback would happen during recovery.
So why use it? Performance... But in fact most customers don't want to risk and they usually choose unbuffered logging.

What we have

But why am I writing this? Just to make fun of our competitor and the fact that they're announcing and talking about a feature that everybody else (Informix, Oracle, DB2, MySQL, Postgres...) seems to have? Not really... although it is funny to see this situation over and over again (happened recently with SQL Server's high availability options also...).
The fact is that there's more to this than what immediately comes to mind. First, I'd bet most of our customers know about the [BUFFERED] LOG option of the CREATE DATABASE statement, but they possibly don't know about the SET [BUFFERED] LOG statement. Did I catch you? Read on... Secondly, because there are at least two databases that implemented this better than us (and I find it very little ambitious from Microsoft to implement just what I'd call "basic" - if you're doing something new, you may as well aim for the best available). So, let's start by the SQL statement SET [BUFFERED] LOG.
I could track this down to at least version 7.3 of Informix Dynamic Server's (1998) documentation as well as the Online engine. And this matches more or less the functionality that SQL Server is implementing now (16 years later, not bad, right?). It means that even in an unbuffered database, you can ask the server to work with your session as if it was setup for BUFFERED logging. In other words, COMMITs issued by sessions that execute SET BUFFERED LOG won't cause the flush of the logical log buffer to disk. They will behave as if you had created the database with BUFFERED LOG. Consequently you're possibly contributing to the database performance, while you open the window to "data loss" only in your session.
Alternatively you can execute the SET LOG statement and ask the server to flush the logical log buffer on every COMMIT you make. You'll make sure that your commits are persisted to disk even if you're working on a BUFFERED database.
We can see the effect of this statement quite easily. The test case I created is fairly simple:

1. Create a very simple table with an ID (INTEGER) and some other column - VAL (CHAR(1)) - with 1M rows in an UNBUFFERED LOG database
2. Create a procedure that accepts the number of records to update, the commit interval and the new value
3. Reset the engine counters (onstat -z)
4. Set either BUFFERED or UNBUFFERED LOG level for the session
5. Execute the procedure with some values
6. Check the statistics with onstat -l
7. Repeat from 3 using a different logging mode and compare the times and specially the counter values

So let's do it. The table and procedure SQL is this:

castelo@primary:informix-> cat test_buf.sql 
DROP PROCEDURE IF EXISTS test_proc;
DROP TABLE IF EXISTS test_data;
SELECT LEVEL id,"A" val FROM sysmaster:sysdual CONNECT BY LEVEL <= 1000000 INTO RAW test_data IN dbs1 EXTENT SIZE 5000 NEXT SIZE 5000;
ALTER TABLE test_data TYPE(standard);

CREATE PROCEDURE test_proc(total_rec INTEGER, commit_interval INTEGER, new_value CHAR) RETURNING INTEGER;

DEFINE total_counter, commit_counter, v_id, cycle INTEGER;

LET total_counter=0;
LET commit_counter=0;
LET cycle = 0;

BEGIN WORK;
FOREACH c1 WITH HOLD FOR
SELECT
        id
INTO v_id
FROM
        test_data

        UPDATE test_data SET val = new_value WHERE CURRENT OF c1;
        LET total_counter = total_counter + 1;
        LET commit_counter = commit_counter + 1;
        IF commit_counter = commit_interval
        THEN
                LET cycle = cycle + 1;
                COMMIT WORK;
                LET commit_counter = 0;
                BEGIN WORK;
        END IF;
        IF total_counter = total_rec
        THEN
                COMMIT WORK;
                RETURN cycle;
        END IF
END FOREACH;

END PROCEDURE;

Now, let's try it with a COMMIT interval of 100 records and UNBUFFERED LOG. The code and output is this:

castelo@primary:informix-> dbaccess -e stores run_unbuf.sql 

Database selected.

SET LOG;
Log set.


EXECUTE FUNCTION sysadmin:task('onstat', '-z');


(expression)  
              IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09
              :01:52 -- 287720 Kbytes
              
               

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 18:57:09.622

1 row(s) retrieved.


EXECUTE PROCEDURE test_proc(500000,100,'U');

(expression) 

        5000

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 18:57:20.242

1 row(s) retrieved.



Database closed. 

It took around 11-12s but the real important part is this:

castelo@primary:informix-> onstat -l

IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09:02:15 -- 287720 Kbytes

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-2  15       64       14         0          0.00
      phybegin         physize    phypos     phyused    %used   
      2:53             62500      50947      44         0.07    

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-2  0        64       510094     20018      5015       25.5       4.0     
        Subsystem    numrecs    Log Space used
        OLDRSAM      510094     38569892

Note that we've done 5015 write operations to disk. On each of them, on average we were writing four pages of logical log buffer. Each page contains around 25 records, so as we've asked for a COMMIT interval each 100 rows, everything matches what we'd expect.
Let's try with BUFFERED LOG:

castelo@primary:informix-> dbaccess -e stores run_buf.sql 

Database selected.

SET BUFFERED LOG;
Log set.


EXECUTE FUNCTION sysadmin:task('onstat', '-z');


(expression)  
              IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09
              :07:52 -- 287720 Kbytes
              
               

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 19:03:08.698

1 row(s) retrieved.


EXECUTE PROCEDURE test_proc(500000,100,'B');

(expression) 

        5000

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 19:03:17.004

1 row(s) retrieved.



Database closed.

It took 8-9s, so it's a bit faster, but this is a VM, with no more activity... But the more interesting part is the logical log statistics we get from onstat -l:

castelo@primary:informix-> onstat -l

IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09:10:44 -- 287720 Kbytes

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-1  18       64       17         0          0.00
      phybegin         physize    phypos     phyused    %used   
      2:53             62500      50974      29         0.05    

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-2  0        64       510095     19119      313        26.7       61.1    
        Subsystem    numrecs    Log Space used
        OLDRSAM      510095     38570264

Let's compare both outputs:

• The number of records and log space used it roughly the same
• The number of records per page is roughly the same
• The number of writes (313) is much less than for UNBUFFERED mode (5015)
• The number of pages on each write (average) if much higher now (61.1) as opposed to 4 in the previous test (I had a LOGBUFF size of 128KB)

What we're missing

Now, let's look at the other more interesting aspect of this.... I mentioned earlier that at least two databases do this in a smarter way than Informix. I'm thinking about DB2 and Oracle. How can this be done in a smarter way? Well, as you notice, the BUFFERED logging is a trade-off. You exchange security for performance (you give away the first and gain on the second). What if there was a better solution? What if you could gain on I/O performance, by reducing the number of operations while not giving away the durability of your data? It may seem impossible, but it's actually very easy and has been done. Let's assume what we have right now in most customers:

• Lots of sessions and most of them do a commit from time to time
• Many sessions making commits from time to time, usually means a very frequent commit rate
• Very frequent commit rates means that we'll do a lot of logical log flushes per second. This is usually noticeable from the average pages per logical log flush. On busy systems with UNBUFFERED LOG this tends to be 1

The way other RDBMs can be configured is to don't flush on every commit but:

1. Flush when the buffer is full (this always happen)
2. Flush the logical log buffer if an amount of time has elapsed since the last flush, or flush only after a specific number of COMMITS have been issued
3. Only send the ok to the application after you effectively flush the buffer that contains the COMMIT

This may seem a bit strange, because you're effectively "holding back" the applications. But keep in mind that this delay can be very small and is optional. The difference between this and the BUFFERED LOG is that the application will probably get only a slight delay, but more importantly, it won't receive an OK of an "uncommitted" COMMIT. When it gets the "ok", the data is securely flushed to the logical logs. Assuming this can be configure at the session level, we can get the best of both worlds (as there  is no gain without loss, the loss here is the probably slight delay, which for interactive applications at least would be unnoticeable)

I've seen situations where the I/O rate on the logical logs can be a bottleneck. As such I've created an RFE (Request For Enhancement) 45166 . If you like the idea and you've seen this happen on your system, vote for it


Versão Portuguesa:

A parte engraçada...

Trabalhar com Informix tem sido bastante engraçado, mas por vezes é por razões estranhas. Uma delas é a consequência de não ser considerada uma base de dados mainstream. De tempos a tempos vejo referências a "novas" funcionalidades nas bases de dados mais populares que me fazem sorrir. Certamente que o contrário também acontece, mas os ecos dessas "novas" funcionalidades no Informix são sempre menores que nos outros,  e seria algo normal numa base de dados que muitos bloggers e analistas não consideram Tier-1. Portanto quando tal acontece, ganho o dia...
Desta feita, ao navegar pela Internet, reparei em vários artigos referindo-se a (minha tradução) "funcionalidade nova e fascinante" do SQL Server 2014 CTP2 (ante-visão) chamada Delayed Transaction Durability. Bom... Depois de ler alguns destes artigos, incluindo o "oficial" fiquei um pouco surpreendido que isto seja apenas aquilo a que chamamos buffered logging! Sim... A possibilidade de atrasar o flush do buffer do logical log até que o mesmo buffer se encontre cheio, em vez de o fazer a cada COMMIT. E sim, tal como nós, isto significa que a aplicação assume que algo foi efetivamente "COMMITed", ao passo que se houver uma queda inesperada da base de dados na verdade não foi (o processo de fast recovery irá fazer rollback da transação).
Portanto, como seria de esperar, muitos autores de blogs foram cautelosos e referiram que isto pode levar à perda de dados. Na verdade a integridade da base de dados é mantida, mas como a aplicação recebe o "ok" antes de os dados estarem efetivamente escritos em disco, uma queda num intervalo específico, significaria que a transação estaria incompleta , levando portanto a um rollback durante o processo de recovery.
Então para quê usar isto? Rapidez... Mas na realidade a maioria dos clientes não quer arriscar, e habitualmente escolhem unbuffered logging.

A parte que temos

Mas porque estou a escrever isto? Apenas para brincar com a concorrência, realçando o facto de estarem a anunciar uma funcionalidade que todas a bases de dados (Informix, DB2, Oracle, MySQL, Postgres...) já têm? Não... não é por isso. Apesar de ser divertido verificar este tipo de situações com frequência (aconteceu recentemente com as suas funcionalidades de alta disponibilidade...).
O ponto é que este assunto tem outros aspetos interessantes para além do óbvio. Primeiro, apostaria que a maioria dos nossos clientes conhecem a opção [BUFFERED] LOG da instrução CREATE DATABASE. mas possivelmente desconhecem a instrução SET [BUFFERED] LOG. Apanhei-o? Continue a ler... Em segundo, existem pelo menos duas bases de dados que implementaram isto de forma mais "inteligente" que o Informix (e parece-me pouco ambicioso da parte da Microsoft fazer a implementação "básica" - se vamos criar algo de novo, porque não apontar para o melhor possível?). Veremos como isso pode ser feito e quais as diferenças. Comecemos então pela instrução SET [BUFFERED] LOG.
Consegui encontrar referências a esta instrução pelo menos tão antigas quanto a versão 7.3 do Informix Dynamic Server (1998), e também na documentação do motor Online. E isto mapeia mais ou menos diretamente com a funcionalidade que o SQL Server está a receber agora (16 anos depois não é mau, certo?). Significa que mesmo numa base de dados criada com unbuffered logging, podemos pedir ao servidor que trabalhe na nossa sessão como se estivesse em BUFFERED LOG. Por outras palavras, o COMMIT efetuado por sessões que executem o SET BUFFERED LOG, não força o flush do buffer do logical log. As sessões comportam-se como se tivéssemos criado a base de dados com BUFFERED LOG. Assim estaremos a contribuir para o aumento da performance da base de dados, ao mesmo tempo que limitamos a possibilidade de "perda de dados" apenas à(s) sessão que executou esta instrução.
Noutro cenário podemos executar a instrução SET LOG e pedir ao servidor que faça o flush do logical log buffer em cada COMMIT que façamos. Garantiremos que todos os nossos COMMITs são escritos em disco, antes de recebermos o "ok", mesmo que a base de dados esteja em modo BUFFERED.
Podemos ver o efeito desta instrução de forma bastante fácil. O caso de teste que criei é bastante simples:

1. Criar uma tabela muito simples com um ID (INTEGER) e uma outra coluna - VAL (CHAR(1)) - com 1M de registos numa base de dados criada com UNBUFFERED LOG
2. Criar um procedimento que aceita o número de registos a alterar, o intervalo de COMMIT e um novo valor para a coluna VAL
3. Fazer o reset dos contadores do motor (com onstat -z)
4. Estabelecer o modo BUFFERED ou UNBUFFERED LOG na nossa sessão
5. Executar o procedimento com certos valores
6. Verificar as estatísticas com onstat -l
7. Repetir a partir do ponto 3 usando um modo de LOG diferente e comparar os tempos e mais importante os valores dos contadores

Vamos lá então fazê-lo. A tabela e o procedimento são os seguintes:

castelo@primary:informix-> cat test_buf.sql 
DROP PROCEDURE IF EXISTS test_proc;
DROP TABLE IF EXISTS test_data;
SELECT LEVEL id,"A" val FROM sysmaster:sysdual CONNECT BY LEVEL <= 1000000 INTO RAW test_data IN dbs1 EXTENT SIZE 5000 NEXT SIZE 5000;
ALTER TABLE test_data TYPE(standard);

CREATE PROCEDURE test_proc(total_rec INTEGER, commit_interval INTEGER, new_value CHAR) RETURNING INTEGER;

DEFINE total_counter, commit_counter, v_id, cycle INTEGER;

LET total_counter=0;
LET commit_counter=0;
LET cycle = 0;

BEGIN WORK;
FOREACH c1 WITH HOLD FOR
SELECT
        id
INTO v_id
FROM
        test_data

        UPDATE test_data SET val = new_value WHERE CURRENT OF c1;
        LET total_counter = total_counter + 1;
        LET commit_counter = commit_counter + 1;
        IF commit_counter = commit_interval
        THEN
                LET cycle = cycle + 1;
                COMMIT WORK;
                LET commit_counter = 0;
                BEGIN WORK;
        END IF;
        IF total_counter = total_rec
        THEN
                COMMIT WORK;
                RETURN cycle;
        END IF
END FOREACH;

END PROCEDURE;

Vamos tentar com um intervalo de de COMMIT e UNBUFFERED LOG. O código e o resultado é o seguinte:

castelo@primary:informix-> dbaccess -e stores run_unbuf.sql 

Database selected.

SET LOG;
Log set.


EXECUTE FUNCTION sysadmin:task('onstat', '-z');


(expression)  
              IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09
              :01:52 -- 287720 Kbytes
              
               

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 18:57:09.622

1 row(s) retrieved.


EXECUTE PROCEDURE test_proc(500000,100,'U');

(expression) 

        5000

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 18:57:20.242

1 row(s) retrieved.



Database closed. 

Demorou à volta de 11-12s, mas a parte mais importante é esta:

castelo@primary:informix-> onstat -l

IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09:02:15 -- 287720 Kbytes

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-2  15       64       14         0          0.00
      phybegin         physize    phypos     phyused    %used   
      2:53             62500      50947      44         0.07    

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-2  0        64       510094     20018      5015       25.5       4.0     
        Subsystem    numrecs    Log Space used
        OLDRSAM      510094     38569892

Repare que fizemos 5015 operações de escrita em disco. Em cada uma delas, em média, escrevemos 4 páginas do logical log buffer. Cada página contém em média 25 registos (de log), portanto como pedimos COMMITs de 100 em 100 registos os valores batem certo com o que seria expectável.
Vamos tentar com BUFFERED LOG:

castelo@primary:informix-> dbaccess -e stores run_buf.sql 

Database selected.

SET BUFFERED LOG;
Log set.


EXECUTE FUNCTION sysadmin:task('onstat', '-z');


(expression)  
              IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09
              :07:52 -- 287720 Kbytes
              
               

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 19:03:08.698

1 row(s) retrieved.


EXECUTE PROCEDURE test_proc(500000,100,'B');

(expression) 

        5000

1 row(s) retrieved.


SELECT CURRENT YEAR TO FRACTION FROM systables WHERE tabid = 1;

(expression)            

2014-02-17 19:03:17.004

1 row(s) retrieved.



Database closed.

Demorou 8-9s, por isso foi um pouco mais rápido, mas isto é uma máquina virtual sem mais actividade... Mas a parte mais interessante são as estatísticas do logical log que obtemos com o onstat -l:

castelo@primary:informix-> onstat -l

IBM Informix Dynamic Server Version 12.10.FC2 -- On-Line -- Up 09:10:44 -- 287720 Kbytes

Physical Logging
Buffer bufused  bufsize  numpages   numwrits   pages/io
  P-1  18       64       17         0          0.00
      phybegin         physize    phypos     phyused    %used   
      2:53             62500      50974      29         0.05    

Logical Logging
Buffer bufused  bufsize  numrecs    numpages   numwrits   recs/pages pages/io
  L-2  0        64       510095     19119      313        26.7       61.1    
        Subsystem    numrecs    Log Space used
        OLDRSAM      510095     38570264

Vamos comparar ambos os outputs:

• O número de registos e o espaço em log é praticamente o mesmo
• O número de registos por página é praticamente o mesmo
• O número de escritas (313) é muito menos que o efetuado em modo UNBUFFERED  (5015)
• O número de páginas escritas em cada operação (média) é muito maior (61.1) do que o teste anterior que deu 4 páginas por escrita (tinha o LOGBUFF definido como 128KB)

O que nos falta

Bom, vamos agora ver outro aspecto importante deste assunto... Como referi, existem pelo menos duas bases de dados que fazem isto de forma mais eficiente e interessante que o Informix. Estou a pensar no DB2 e no Oracle. Como é que isto pode ser feito de forma mais inteligente? Bom, como terá reparado, o BUFFERED logging é uma troca. Trocamos segurança por rapidez (damos a primeira e recebemos a segunda). Mas e se houver uma melhor solução? E se conseguissemos ganhar rapidez (fazendo menos I/O) e ao mesmo tempo não abdicar da segurança que a escrita prévia nos dá? Pode parecer impossível, mas na verdade pode ser muito fácil e já foi feito. Vamos assumir o cenário que encontro em muitos clientes atualmente:

• Muitas sessões e a maioria delas fazem um COMMIT de vez em quando
• Muitas sessões a fazerem COMMIT "de vez em quando", traduz-se normalmente num ritmo bastante alto de COMMITs
• Um ritmo de COMMITs muito alto implica que façamos muitos flushes do logical log buffer por segundo. Isto é normalmente visível pelo número médio de páginas escritas em cada operação de I/O (flush), que em sistemas configurados em UNBUFFERED e com bastante actividade tende a ser 1

A forma como outras RDBMS podem ser configuradas é não fazer flush em cada COMMIT, mas:

1. Fazer o flush quando o bufer enche (isto acontece sempre)
2. Fazer o flush do logical log biffer se passou um determinado tempo desde o último flush, ou fazer o flush após um certo número de COMMITS terem sido executados
3. Apenas enviar o "ok" às aplicacções quando fazemos efectivamente o flush do biuffer que contém o COMMIT por elas executado

Isto pode parecer um pouco estranho, porque estamos efetivamente a "atrasar" as aplicações. Mas considere que este atraso é muito pequeno e opcional. A diferença entre isto e o BUFFERED LOG é que a aplicação apenas sofre um ligeiro atraso, mas mais importante não recebe "ok" de um COMMIT que efectuou mas que ainda não foi garantido em disco. Quando recebe o "ok" é certo que os registos do log já foram escritos e persistidos em disco. Tendo em conta que isto pode ser configurado ao nível da sessão, podemos obter o melhor dos dois mundos (embora como não haja ganhos sem perdas, a perda aqui será o pequeno atraso, mas este para aplicações interativas é provavelmente negligenciável)

Já vi situações onde o ritmo de operações de I/O nos logical logs pode ser um "fúnil". Dái ter registado um RFE (Request For Enhancement) 45166 . Se gosta da ideia e já viu o mesmo acontecer no seu sistema vote neste pedido.