Почему системный журнал намного медленнее, чем файловый ввод-вывод?

Question

Я написал простую тестовую программу для измерения производительности функции syslog. Вот результаты моей тестовой системы: (Debian 6.0.2 с 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     

Тестовая программа выполнила 200000 системных вызовов, записывая 50 байтов данных за каждый вызов.

Почему системный журнал более чем в десять раз медленнее, чем файловый ввод-вывод?

Это программа, которую я использовал для выполнения теста:

#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

Оба системных вызова выдают один send() для сокета AF_UNIX за вызов. Даже если syslogd отбрасывает данные, ему все равно придется сначала их прочитать. Все это требует времени.

Операции записи в /dev /null также выдают одну запись () на вызов, но поскольку данные отбрасываются, ядро может очень быстро их обработать.

Вызовы fprintf() генерируют только одну запись () для каждых 4096 байтов, которые передаются, то есть примерно один раз в восемьдесят вызовов printf. Каждый из них включает только передачу данных из буфера libc в буферы ядра. Фиксация на диск будет (по крайней мере, по сравнению) очень медленной, но при отсутствии каких-либо явных вызовов синхронизации могут произойти позже (возможно, даже после завершения процесса).

Вкратце: syslog работает медленнее, чем /dev /null, потому что он выполняет большую работу, и медленнее, чем printf, в файл из-за буферизации.