Creando 30.000 tablas con PostgreSQL


Esta mañana leyendo los mensajes de Twitter que me llegaron por la noche, me encontre con uno que me llamó la atención, “Steward Smith blogs on Optimazing InnoDB for creating 30.000 tables (and nothing else)".

Empece a leerlo y estuvo entretenido. Trataba de lo que se podia hacer para acelerar la creación de muchos objetos en MySQL usando InnoDB, esto es especialmente importante cuando se vaya a importar una nueva base de datos que sea grande.

Una de las cosas que decia, con la que estoy de acuerdo, es que en estos casos la durabilidad de los datos no es importante hasta que terminemos con la creación de todos los objetos, por lo que podemos apagar todos los mecanismos implementados en la base de datos para garantizar esta durabilidad mientras que estemos importando.

El test del que hablaba este artículo consistía en crear 30.000 tablas, insertar una fila en cada tabla y destruir las 30.000 tablas. Como me pico la curiosidad, me puse manos a la obra para ver como PostgreSQL funcionaba ejecutando un test similar.

Primero ejecuté el test con todos los parametros que garantizan la durabilidad de los datos activados.

Estos son los valores de los parametros relevantes para este test en una máquina con 8GB de memoria y postgreSQL 9.1.1 (especialmente importante es max_locks_per_transaction si no quereis que el test falle estrepitosamente):

max_connections = 100
shared_buffers = 2GB
work_mem = 16MB
maintenance_work_mem = 256MB
max_stack_depth = 4MB 
wal_level = archive
fsync = on                    
synchronous_commit = on                                                                             
wal_sync_method = fdatasync
checkpoint_segments = 128
max_locks_per_transaction = 1000

Y esto lo ejecutado para realizar el test:

CREATE DATABASE pgtest2;
\c pgtest2 
\timing 

DO
$$
BEGIN
 FOR i IN 1..30000 LOOP
  EXECUTE 'CREATE TABLE table' || i || '(id INT, PRIMARY KEY (id))';
 END LOOP;
END$$;

DO
$$
BEGIN
 FOR i IN 1..30000 LOOP
  EXECUTE 'INSERT INTO table' || i || ' VALUES (' || i || ')';
 END LOOP;
END$$;

DO
$$
BEGIN
 FOR i IN 1..30000 LOOP
  EXECUTE 'DROP TABLE table' || i;
 END LOOP;
END$$;

La creación de todas las tablas duró 49818.792 ms, la inserción de una fila en cada una de ellas 37681.864 ms y la destrucción de las 30.000 tablas 548185.154 ms. Bueno, la creación e inserción de datos en 87.5 segundos no esta nada mal, me dejo un poco sorprendido que la destrucción de todas las tablas durase 9.1 minutos. En total 10.5 minutos, no estaba nada mal para tener todo lo referente a durabilidad activado.

Si lo comparamos con los números conseguidos con MySQL usando InnoDB con las opciones por defecto de “MySQL test suite”, está pero que muy bien, ya que en el mejor de los casos estaban consiguiendo unas 20-25 tablas por segundo, con lo cual hubieran tardado unos 20 minutos en terminar.

Era hora de empezar a apagar parámetros relacionados con la durabilidad de los datos. El primero synchronous_commit, lo apagamos y volvemos a ejecutar el test.

Para este test en concreto, el apagado de este parámetro no afecta prácticamente en nada al resultado final, (47834.357 ms, 37889.342 ms y 546201.158 ms respectivamente). La explicación que yo le encuentro a esto es que todo lo ejecutado en un bloque DO se ejecuta dentro de una misma transacción, con lo que en realidad estamos ejecutando solamente 3 transacciones.

Seguimos, definimos wal_level = minimal, fsync = off y vamos a ver si conseguimos una mejora en la velocidad.

Con este cambio si que obtenemos una importante mejora en la creación y la inserción (31823.101 ms y 35474.310 ms respectivamente), en total 67.2 segundos, que supone una reducción de 20.3 segundos o lo que es lo mismo un 23.2% menos de tiempo con respecto a la primera vez. La destrucción de las tablas no mejora en absoluto (547486.861 ms)

En una situación real en la que estemos importando una base de datos grande no vamos a destruir seguidamente los datos importados, asi que el uso de wal_level = minimal, fsync = off y synchronous_commit = off nos puede ahorrar en general una gran cantidad de tiempo. No olvidar volver a cambiar estos parámetros al terminar para asegurar la durabilidad de los datos.

Me quedo con la duda de porque la destrucción de todas las tablas dura tanto, especialmente cuando la creación de las mismas ha tardado solamente 31 segundos. Haciendo un strace al proceso que está ejecutando las ordenes, podemos ver que una serie de operaciones de este tipo se repiten durante todo el tiempo que el proceso se está ejecutando:

open("base/42616854/42941855", O_RDWR)  = 10
close(10)                               = 0
open("base/42616854/42941855", O_RDWR)  = 10
ftruncate(10, 0)                        = 0
close(10)                               = 0
unlink("base/42616854/42941855.1")      = -1 ENOENT (No such file or directory)
open("base/42616854/42941855_fsm", O_RDWR) = -1 ENOENT (No such file or directory)
open("base/42616854/42941855_vm", O_RDWR) = -1 ENOENT (No such file or directory)
open("base/42616854/42941855_init", O_RDWR) = -1 ENOENT (No such file or directory)

Parece ser que está intentando limpiar y encontrar una serie de ficheros asociados a cada tabla que está destruyendo y esto es lo que consume todo el tiempo, especialmente cuando estos ficheros todavía no se encuentran en el sistema. ¿Quizás alguien tenga alguna información de porque esto es así y si se puede hacer algo para mejorar los tiempos de destrucción de tablas?

Los tiempos totales conseguidos con strace -c -p son:

CREACION de tablas:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 61.12    0.087196           0    184077     64014 open
 18.07    0.025772           1     44762           write
 12.43    0.017730         633        28           munmap
  3.20    0.004565           0    120074           close
  2.41    0.003438           0    164859           lseek
  1.97    0.002811           0     60003         1 stat
  0.46    0.000655           0      3340           sendto
  0.29    0.000419           0      4652           brk
  0.03    0.000042           0       139           read
  0.01    0.000019           0       820           semop
  0.01    0.000012           0       430           kill
  0.00    0.000000           0         1           fstat
  0.00    0.000000           0        59           mmap
  0.00    0.000000           0         1           mprotect
  0.00    0.000000           0         1           rt_sigreturn
  0.00    0.000000           0         1           select
  0.00    0.000000           0         2           setitimer
  0.00    0.000000           0         4           recvfrom
  0.00    0.000000           0         1           unlink
  0.00    0.000000           0         1           futex
------ ----------- ----------- --------- --------- ----------------
100.00    0.142659                583255     64015 total
INSERCION de filas:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 40.93    0.047498           1     60000           write
 39.83    0.046216           0    120004     60000 open
 12.85    0.014908           0     30002           read
  3.06    0.003555           0    119021           lseek
  2.38    0.002763           0     60005           close
  0.95    0.001103           0      6671           sendto
  0.00    0.000000           0        22           brk
  0.00    0.000000           0         1           rt_sigreturn
  0.00    0.000000           0         2           setitimer
  0.00    0.000000           0         4           recvfrom
  0.00    0.000000           0        13           kill
  0.00    0.000000           0        20           semop
------ ----------- ----------- --------- --------- ----------------
100.00    0.116043                395765     60000 total
DESTRUCCION de tablas:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 69.45    0.330171           6     60000           ftruncate
 17.79    0.084591           0    300009    180000 open
  8.29    0.039411           1     60000     60000 unlink
  2.81    0.013347         404        33           brk
  1.65    0.007838           0    120008           close
  0.00    0.000011           0       369           kill
  0.00    0.000010           0       707           semop
  0.00    0.000000           0         8           read
  0.00    0.000000           0         1           write
  0.00    0.000000           0         6           lseek
  0.00    0.000000           0         1           rt_sigreturn
  0.00    0.000000           0         2           setitimer
  0.00    0.000000           0         6           sendto
  0.00    0.000000           0         4           recvfrom
------ ----------- ----------- --------- --------- ----------------
100.00    0.475379                541154    240000 total

Casi un 70% del tiempo es consumido por ftruncate

Queda decir que en este pequeño test realizado con MySQL usando InnoDB, consiguieron reducir los tiempos de ejecución a 180 segundos. PostgreSQL consigue ejecutar las dos partes relevantes del test en 67 segundos, pero tarda mucho en la destrucción de los datos.

También hay que decir que esta comparación entre los tiempos conseguidos con MySQL y PostgreSQL es totalmente inútil al haberse realizado en máquinas diferentes, y al no saber la definición de la tabla que utilizaron, con lo que no podemos comparar los resultados. De todas maneras ahí quedan los datos para el que le interese estas cosas.