Take the 2-minute tour ×
Super User is a question and answer site for computer enthusiasts and power users. It's 100% free, no registration required.

I wrote a simple test program to measure the performance of the syslog function. This are the results of my test system: (Debian 6.0.2 with 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     

The test program did 200000 system calls writing 50 Bytes of data during each call.

Why is Syslog more than ten times slower than file IO?

This is the program I used to perform the 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 ();
}
share|improve this question
    
Presumably, syslog calls are more complex, with a "message & response" mechanism, have more overhead, travel between multiple user-space processes (unlike writing to a device or the console), and won't return until the message has been successfully accepted. –  afrazier Jul 1 '11 at 15:25
1  
According to Richard's answer, do the numbers look similar if you add fflush(fp) after the fprintf()? –  sep332 Nov 28 '12 at 14:43
    
@sep3332 After added O_SYNC flag to the open() function and fflush(fp) after each fprintf() calls, the results become [3.86, 3.63, 151.53, 23.00] MB/s in my computer (Lenovo T61, Debian testing). It seems better now but, check /etc/rsyslog.conf, it's already in non-sync mode for syslogs. –  Xiè Jìléi Dec 4 '13 at 7:17

1 Answer 1

The syslog calls both issue one send() to an AF_UNIX socket per call. Even if the syslogd discards the data it'll still have to read it first. All this takes time.

The writes to /dev/null also issue one write() per call but since the data is discarded it can be processed very quickly by the kernel.

The fprintf() calls only generate one write() for every 4096 bytes that are transferred, i.e. about one every eighty printf calls. Each only involves transferring data from libc's buffer to the kernel's buffers. The commit to the disk will be (in comparison at least) very slow, but in the absence of any explicit synchronization calls can happen later (perhaps even after the process terminates).

In short: syslog is slower than /dev/null because it's doing a lot of work and slower than printf to a file because of buffering.

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.