Dlaczego syslog jest o wiele wolniejszy niż plik IO?

Napisałem prosty program testowy do pomiaru wydajności funkcji syslog. Oto wyniki mojego systemu testowego: (Debian 6.0.2 z Linuksem 2.6.32-5-amd64)

Przypadki testowe wywołują ładunek czas trwania 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     

Program testowy wykonał 200 000 wywołań systemowych zapisujących 50 bajtów danych podczas każdego połączenia.

Dlaczego Syslog jest ponad dziesięć razy wolniejszy niż we / wy pliku?

Oto program, którego użyłem do wykonania testu:

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

Oba wywołania syslog wysyłają po jednym wywołaniu send () do gniazda AF_UNIX. Nawet jeśli syslogd odrzuci dane, nadal będzie musiał je najpierw odczytać. Wszystko to wymaga czasu.

Zapis do / dev / null również wydaje jeden zapis () na każde wywołanie, ale ponieważ dane są odrzucane, jądro może je bardzo szybko przetworzyć.

Wywołania fprintf () generują tylko jeden write () na każde 4096 bajtów, które są przesyłane, tj. Około jednego na osiemdziesiąt wywołań printf. Każde z nich wymaga jedynie przeniesienia danych z bufora libc do buforów jądra. Zatwierdzenie na dysku będzie (przynajmniej w porównaniu) bardzo wolne, ale przy braku wyraźnej synchronizacji wywołania mogą nastąpić później (być może nawet po zakończeniu procesu).

W skrócie: syslog jest wolniejszy niż / dev / null, ponieważ wykonuje dużo pracy i wolniej niż printf do pliku z powodu buforowania.