Pourquoi syslog est-il tellement plus lent que IO de fichier?

J'ai écrit un programme de test simple pour mesurer les performances de la fonction syslog. Voici les résultats de mon système de test: (Debian 6.0.2 avec Linux 2.6.32-5-amd64)

Cas de test appelle la durée de charge utile 
                      [] [Mo] [s] [Mo / s]    
-------------------- ---------- ---------- ---------- ----------
syslog 200000 10,00 7,81 1,28      
syslog% s 200000 10,00 9,94 1,01      
écriture / dev / null 200000 10,00 0,03 343,93    
printf% s 200000 10,00 0,13 76,29     

Le programme de test a effectué 200 000 appels système en écrivant 50 octets de données lors de chaque appel.

Pourquoi Syslog est-il dix fois plus lent que les E / S sur fichiers?

Voici le programme que j'ai utilisé pour effectuer le test:

#include <fcntl.h>
#include <stdio.h>
#include <string.h>
#include <sys/stat.h>
#include <sys/time.h>
#include <sys/types.h>
#include <syslog.h>
#include <unistd.h>

const int  iter  = 200000;
const char msg[] = "123456789 123456789 123456789 123456789 123456789";

struct timeval t0;
struct timeval t1;

void start ()
{
    gettimeofday (&t0, (void*)0);
}

void stop ()
{
    gettimeofday (&t1, (void*)0);
}

void report (char *action)
{
    double dt = (double)t1.tv_sec - (double)t0.tv_sec +
        1e-6 * ((double)t1.tv_usec - (double)t0.tv_usec);
    double mb = 1e-6 * sizeof (msg) * iter;

    if (action == NULL)
        printf ("Test Case             Calls       Payload     Duration    Thoughput \n"
                "                      []          [MB]        [s]         [MB/s]    \n"
                "--------------------  ----------  ----------  ----------  ----------\n");
    else {
        if (strlen (action) > 20) action[20] = 0;
        printf ("%-20s  %-10d  %-10.2f  %-10.2f  %-10.2f\n",
                action, iter, mb, dt, mb / dt);
    }
}

void test_syslog ()
{
    int i;

    openlog ("test_syslog", LOG_PID | LOG_NDELAY, LOG_LOCAL0);
    start ();
    for (i = 0; i < iter; i++)
        syslog (LOG_DEBUG, msg);
    stop ();
    closelog ();
    report ("syslog");
}

void test_syslog_format ()
{
    int i;

    openlog ("test_syslog", LOG_PID | LOG_NDELAY, LOG_LOCAL0);
    start ();
    for (i = 0; i < iter; i++)
        syslog (LOG_DEBUG, "%s", msg);
    stop ();
    closelog ();
    report ("syslog %s");
}

void test_write_devnull ()
{
    int i, fd;

    fd = open ("/dev/null", O_WRONLY);
    start ();
    for (i = 0; i < iter; i++)
        write (fd, msg, sizeof(msg));
    stop ();
    close (fd);
    report ("write /dev/null");
}

void test_printf ()
{
    int i;
    FILE *fp;

    fp = fopen ("/tmp/test_printf", "w");
    start ();
    for (i = 0; i < iter; i++)
        fprintf (fp, "%s", msg);
    stop ();
    fclose (fp);
    report ("printf %s");
}

int main (int argc, char **argv)
{
    report (NULL);
    test_syslog ();
    test_syslog_format ();
    test_write_devnull ();
    test_printf ();
}

Les appels syslog émettent tous les deux un envoi () vers un socket AF_UNIX par appel. Même si syslogd supprime les données, il devra tout de même les lire en premier. Tout cela prend du temps.

Les écritures dans / dev / null émettent également une écriture () par appel, mais comme les données sont supprimées, elles peuvent être traitées très rapidement par le noyau.

Les appels fprintf () ne génèrent qu'un seul write () pour chaque 4096 octets transférés, soit environ un tous les quatre-vingt appels printf. Chacun implique uniquement le transfert de données du tampon de libc vers les tampons du noyau. La validation sur le disque sera (en comparaison au moins) très lente, mais en l'absence de toute synchronisation explicite, des appels peuvent se produire plus tard (peut-être même après la fin du processus).

En bref: syslog est plus lent que / dev / null car il fait beaucoup de travail et plus lent que printf dans un fichier à cause de la mise en mémoire tampon.