Warum ist syslog so viel langsamer als File IO?

3393
ceving

Ich habe ein einfaches Testprogramm geschrieben, um die Leistung der Syslog-Funktion zu messen. Dies sind die Ergebnisse meines Testsystems: (Debian 6.0.2 unter Linux 2.6.32-5-amd64)

Testfall fordert die Dauer der Nutzlast auf  [] [MB] [s] [MB / s]  -------------------- ---------- ---------- ---------- ---------- Syslog 200000 10.00 7.81 1.28  syslog% s 200000 10,00 9,94 1,01  schreibe / dev / null 200000 10,00 0,03 343,93  printf% s 200000 10,00 0,13 76,29

Das Testprogramm hat bei 200000 Systemaufrufen während jedes Aufrufs 50 Byte Daten geschrieben.

Warum ist Syslog mehr als zehnmal langsamer als File IO?

Mit diesem Programm habe ich den Test durchgeführt:

#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 (); }
9
Vermutlich sind Syslog-Aufrufe komplexer, mit einem "Message & Response" -Mechanismus, haben mehr Overhead, laufen zwischen mehreren Benutzer-Space-Prozessen (im Gegensatz zum Schreiben auf ein Gerät oder die Konsole) und kehren erst zurück, wenn die Nachricht erfolgreich war akzeptiert. afrazier vor 12 Jahren 0
Sehen die Zahlen laut Richards Antwort ähnlich aus, wenn Sie fflush (fp) nach fprintf () hinzufügen? sep332 vor 11 Jahren 1
@ sep3332 Nach dem Hinzufügen von `O_SYNC`-Flag zur Funktion 'open ()' und von 'fflush (fp)' nach jedem Aufruf von 'fprintf ()' werden die Ergebnisse zu [[[3.86], 3.63, 151.53, 23.00] MB / s] Mein Computer (Lenovo T61, Debian-Test). Es scheint jetzt besser zu sein, aber überprüfen Sie `/ etc / rsyslog.conf`, es befindet sich bereits im Nicht-Sync-Modus für Syslogs. Xiè Jìléi vor 10 Jahren 0

1 Antwort auf die Frage

11
Richard Kettlewell

Die Syslog-Aufrufe geben pro Aufruf ein send () an einen AF_UNIX-Socket aus. Selbst wenn das syslogd die Daten verwirft, muss es zuerst gelesen werden. Das alles braucht Zeit.

Die Schreibvorgänge in / dev / null geben auch ein write () pro Aufruf aus. Da die Daten jedoch verworfen werden, können sie vom Kernel sehr schnell verarbeitet werden.

Die fprintf () - Aufrufe generieren nur ein write () für jeweils 4096 Bytes, die übertragen werden, dh etwa alle achtzig printf-Aufrufe. Bei jedem Vorgang werden nur Daten aus dem libc-Puffer in die Puffer des Kernels übertragen. Die Festschreibung der Festplatte ist (im Vergleich zumindest) sehr langsam, aber wenn keine expliziten Synchronisationsaufrufe vorliegen, können Aufrufe später (möglicherweise sogar nach Beendigung des Prozesses) erfolgen.

Kurz gesagt: syslog ist langsamer als / dev / null, weil es viel Arbeit leistet und langsamer als printf für eine Datei aufgrund von Pufferung.

Verwandte Probleme