Mengapa syslog jauh lebih lambat daripada file IO?

9

Saya menulis program pengujian sederhana untuk mengukur kinerja fungsi syslog. Ini adalah hasil dari sistem pengujian saya: (Debian 6.0.2 dengan Linux 2.6.32-5-amd64)

Uji Kasus Memanggil Soal Durasi Payload 
                      [] [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 pengujian melakukan 200000 panggilan sistem menulis 50 Bytes data selama setiap panggilan.

Mengapa Syslog lebih dari sepuluh kali lebih lambat daripada file IO?

Ini adalah program yang saya gunakan untuk melakukan tes:

#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 ();
}
ceving
sumber
Agaknya, panggilan syslog lebih kompleks, dengan mekanisme "pesan & respons", memiliki lebih banyak overhead, perjalanan antara beberapa proses ruang pengguna (tidak seperti menulis ke perangkat atau konsol), dan tidak akan kembali sampai pesan berhasil diterima.
Afrazier
1
Menurut jawaban Richard, apakah angka-angkanya terlihat sama jika Anda menambahkan fflush (fp) setelah fprintf ()?
sep332
@ sep3332 Setelah menambahkan O_SYNCtanda pada open()fungsi dan fflush(fp)setelah setiap fprintf()panggilan, hasilnya menjadi [3.86, 3.63, 151.53, 23.00] MB/sdi komputer saya (Lenovo T61, pengujian Debian). Tampaknya lebih baik sekarang tetapi, periksa /etc/rsyslog.conf, ini sudah dalam mode non-sinkronisasi untuk syslogs.
Xiè Jìléi

Jawaban:

11

Panggilan syslog keduanya mengeluarkan satu pengiriman () ke soket AF_UNIX per panggilan. Bahkan jika syslogd membuang data, ia masih harus membacanya terlebih dahulu. Semua ini butuh waktu.

Write ke / dev / null juga mengeluarkan satu write () per panggilan tetapi karena data tersebut dibuang, maka dapat diproses dengan sangat cepat oleh kernel.

Panggilan fprintf () hanya menghasilkan satu write () untuk setiap 4096 byte yang ditransfer, yaitu sekitar satu setiap delapan puluh panggilan printf. Masing-masing hanya melibatkan transfer data dari buffer libc ke buffer kernel. Komit ke disk akan (dalam perbandingan setidaknya) sangat lambat, tetapi jika tidak ada panggilan sinkronisasi eksplisit dapat terjadi kemudian (mungkin bahkan setelah proses berakhir).

Singkatnya: syslog lebih lambat dari / dev / null karena ia melakukan banyak pekerjaan dan lebih lambat daripada printf ke file karena buffering.

Richard Kettlewell
sumber