Durée d'établissement d'une connexion

Ce billet fait partie d'une série sur l'écriture de mon livre, « PostgreSQL - Architecture et notions avancées ».

J'ai toujours eu en tête qu'une connexion mettait du temps à s'établir entre un client et PostgreSQL. J'avais en tête un nombre qui me semblait plausible mais j'avoue que je n'avais jamais fait réellement le test.

Ce week-end, travaillant sur le chapitre sur la gestion des connexions, je me suis demandé si on pouvait calculer ce temps. J'ai donc regardé le code des processus postmaster/postgres pour ajouter quelques traces, histoire d'en savoir plus. Voici le patch que j'ai réalisé :

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index f05114d..9d8fb8a 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -2198,6 +2198,8 @@ ConnCreate(int serverFd)
 {
        Port       *port;
 
+       elog(LOG, "patch - ConnCreate(%d)", serverFd);
+
        if (!(port = (Port *) calloc(1, sizeof(Port))))
        {
                ereport(LOG,
@@ -3760,6 +3762,8 @@ BackendStartup(Port *port)
        Backend    *bn;                         /* for backend cleanup */
        pid_t           pid;
 
+       elog(LOG, "patch - BackendStart()");
+
        /*
         * Create backend data structure.  Better before the fork() so we can
         * handle failure cleanly.
@@ -3814,6 +3818,8 @@ BackendStartup(Port *port)
 
                MyProcPid = getpid();   /* reset MyProcPid */
 
+               elog(LOG, "patch - new pid is %d", MyProcPid);
+
                MyStartTime = time(NULL);
 
                /* We don't want the postmaster's proc_exit() handlers */
@@ -3916,6 +3922,8 @@ BackendInitialize(Port *port)
        char            remote_port[NI_MAXSERV];
        char            remote_ps_data[NI_MAXHOST];
 
+       elog(LOG, "patch - BackendInitialize()");
+
        /* Save port etc. for ps status */
        MyProcPort = port;
 
@@ -4096,6 +4104,8 @@ BackendRun(Port *port)
        int                     usecs;
        int                     i;
 
+       elog(LOG, "patch - BackendRun()");
+
        /*
         * Don't want backend to be able to see the postmaster random number
         * generator state.  We have to clobber the static random_seed *and* start
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index bc4eb33..4e1a3f7 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -3578,6 +3578,7 @@ PostgresMain(int argc, char *argv[],
        sigjmp_buf      local_sigjmp_buf;
        volatile bool send_ready_for_query = true;
 
+       elog(LOG, "patch - PostgresMain()");
        /*
         * Initialize globals (already done if under postmaster, but not if
         * standalone).
@@ -3845,6 +3846,8 @@ PostgresMain(int argc, char *argv[],
         * were inside a transaction.
         */
 
+       elog(LOG, "patch - PostgresMain() - ready to execute command");
+
        if (sigsetjmp(local_sigjmp_buf, 1) != 0)
        {
                /*
@@ -4056,12 +4059,16 @@ PostgresMain(int argc, char *argv[],
                if (ignore_till_sync && firstchar != EOF)
                        continue;
 
+               elog(LOG, "patch - PostgresMain() - processing command");
+
                switch (firstchar)
                {
                        case 'Q':                       /* simple query */
                                {
                                        const char *query_string;
 
+                                       elog(LOG, "patch - PostgresMain() - executing simple query");
+
                                        /* Set statement_timestamp() */
                                        SetCurrentStatementStartTimestamp();
 
@@ -4279,6 +4286,8 @@ PostgresMain(int argc, char *argv[],
                        case 'X':
                        case EOF:
 
+                               elog(LOG, "patch - PostgresMain() - exiting");
+
                                /*
                                 * Reset whereToSendOutput to prevent ereport from attempting
                                 * to send any more messages to client.

En configurant PostgreSQL pour qu'il ajoute la date (à la milliseconde près) et le PID, et en configurant la trace des connexions et déconnexions :

log_min_duration_statement = 0
log_connections = on
log_disconnections = on
log_line_prefix = '%m [%p] '

et en exécutant la commande suivante :

$ psql -c "select * from t1 limit 200" b1

nous obtenons les traces suivantes :

2015-02-22 22:47:23.022 CET [6087] LOG:  patch - ConnCreate(5)
2015-02-22 22:47:23.022 CET [6087] LOG:  patch - BackendStart()
2015-02-22 22:47:23.023 CET [6283] LOG:  patch - new pid is 6283
2015-02-22 22:47:23.023 CET [6283] LOG:  patch - BackendInitialize()
2015-02-22 22:47:23.023 CET [6283] LOG:  connection received: host=[local]
2015-02-22 22:47:23.023 CET [6283] LOG:  patch - BackendRun()
2015-02-22 22:47:23.023 CET [6283] LOG:  patch - PostgresMain()
2015-02-22 22:47:23.025 CET [6283] LOG:  connection authorized: user=postgres database=b1
2015-02-22 22:47:23.027 CET [6283] LOG:  patch - PostgresMain() - ready to execute command
2015-02-22 22:47:23.027 CET [6283] LOG:  patch - PostgresMain() - processing command
2015-02-22 22:47:23.028 CET [6283] LOG:  patch - PostgresMain() - executing simple query
2015-02-22 22:47:23.028 CET [6283] LOG:  duration: 0.691 ms  statement: select * from t1 limit 200
2015-02-22 22:47:23.736 CET [6283] LOG:  patch - PostgresMain() - processing command
2015-02-22 22:47:23.736 CET [6283] LOG:  patch - PostgresMain() - exiting
2015-02-22 22:47:23.737 CET [6283] LOG:  disconnection: session time: 0:00:00.913 user=postgres database=b1 host=[local]

Autrement dit, il faut compter quelques millisecondes pour établir une connexion sans pooler. Après différents tests (impliquant notamment pgbench), le pire que j'ai vu est 10 millisecondes. Pas bien méchant quand on y pense. J'ai aussi noté que la toute première connexion était bien plus lente (dans les 40 millisecondes), ce qui reste encore bien loin de ce que j'imaginais.

J'ai aussi testé avec différentes valeurs du shared_buffers car il semblerait que la taille mémoire d'un processus a une importance dans la durée d'exécution de l'appel système fork().

Comme quoi il est vraiment préférable de tout tester pour ne pas avoir d'idées préconçues.

Commentaires

1. Le mercredi, mars 11 2015, 11:32 par Rodolphe

Coté client il est également possible de mesurer cela avec Tsung, qui remonte le temps de CONNECT, utile pour valider par exemple l'utilisation ou non d'un pooler.

2. Le mercredi, mars 11 2015, 13:53 par Guillaume Lelarge

Tout à fait possible. Je connais très peu Tsung, et ne pourrais pas en dire beaucoup sur son utilisation.

Ajouter un commentaire

Les commentaires peuvent être formatés en utilisant une syntaxe wiki simplifiée.

Fil des commentaires de ce billet