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:
- Create a very simple table with an ID (INTEGER) and some other column - VAL (CHAR(1)) - with 1M rows in an UNBUFFERED LOG database
- Create a procedure that accepts the number of records to update, the commit interval and the new value
- Reset the engine counters (onstat -z)
- Set either BUFFERED or UNBUFFERED LOG level for the session
- Execute the procedure with some values
- Check the statistics with onstat -l
- 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:
- Flush when the buffer is full (this always happen)
- 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
- 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:
- 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
- Criar um procedimento que aceita o número de registos a alterar, o intervalo de COMMIT e um novo valor para a coluna VAL
- Fazer o reset dos contadores do motor (com onstat -z)
- Estabelecer o modo BUFFERED ou UNBUFFERED LOG na nossa sessão
- Executar o procedimento com certos valores
- Verificar as estatísticas com onstat -l
- 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:
- Fazer o flush quando o bufer enche (isto acontece sempre)
- 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
- 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.
Posts
