Por que o syslog é muito mais lento que o arquivo IO?

Question

Eu escrevi um programa de teste simples para medir o desempenho da função syslog. Estes são os resultados do meu sistema de teste: (Debian 6.0.2 com Linux 2.6.32-5-amd64)

Test Case             Calls       Payload     Duration    Thoughput 
                      []          [MB]        [s]         [MB/s]    
--------------------  ----------  ----------  ----------  ----------
syslog                200000      10.00       7.81        1.28      
syslog %s             200000      10.00       9.94        1.01      
write /dev/null       200000      10.00       0.03        343.93    
printf %s             200000      10.00       0.13        76.29     

O programa de teste fez 200.000 chamadas do sistema escrevendo 50 bytes de dados durante cada chamada.

Por que o Syslog é mais de dez vezes mais lento do que o arquivo IO?

Este é o programa que usei para realizar o teste:

#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 ();
}

    

Answer 1

O syslog chama ambos emitem um send () para um soquete AF_UNIX por chamada. Mesmo se o syslogd descartar os dados, ele ainda terá que lê-lo primeiro. Tudo isso leva tempo.

As gravações em / dev / null também emitem um write () por chamada, mas como os dados são descartados, podem ser processados muito rapidamente pelo kernel.

As chamadas fprintf () geram apenas uma gravação () para cada 4096 bytes que são transferidos, ou seja, cerca de uma a cada oitenta chamadas printf. Cada um envolve apenas a transferência de dados do buffer da libc para os buffers do kernel. O commit para o disco será (em comparação pelo menos) muito lento, mas na ausência de qualquer sincronização explícita, as chamadas podem acontecer mais tarde (talvez mesmo após o processo terminar).

Em suma: o syslog é mais lento que / dev / null porque está fazendo muito trabalho e é mais lento que o printf em um arquivo devido ao buffering.