Почему нельзя писать логи в syslog в критичных к времени выполнения местах

Любой способ записи логов так или иначе даёт дополнительную нагрузку на CPU и замедляет выполнение кода. Но запись в syslog имеет одну очень неприятную особенность: оно может быть блокирующем и может приостанавливать поток выполнения на очень значительный промежуток времени.

Причина кроется в использовании сокета домена Unix в режиме датаграмм (socket(AF_UNIX, SOCK_DGRAM, 0)) с путём /dev/log в файловой системе. Этот сокет имеет свой буффер, который может переполняться. При его переполнении, в зависимости от реализации (я бегло просмотрел несколько), может выводиться сообщение об ошибке в консоль либо сам процесс отправки сообщения блокироваться. В реализации библиотеки C от glibc поток выполнения именно блокируется вызовом syslog. Попробую это показать на наглядном примере.

Проверка времени, затраченного на выполнение вызова syslog

Для начала нужен исходный код примера, сохраните его как файл с именем app.c:

/*
 * The example shows that a process can wait on 'syslog' call.
 *
 * Compilation:
 * $ gcc --std=c89 -o app app.c
 *
 * Run example:
 * $ ./app > out
 *
 * In a second terminal:
 * # cpulimit --pid $(pidof systemd-journald) --limit 1
 */
#define _POSIX_C_SOURCE 199309L
#include <stdio.h>
#include <syslog.h>
#include <time.h>

#define MESSAGE_SIZE 8192

int main() {
	struct timespec before, after;
	time_t seconds;
	long useconds;
	char message[MESSAGE_SIZE];
	int i;

	/* fills a message */
	for(i = 0; i < MESSAGE_SIZE - 1; i++) {
		message[i] = 'X';
	}
	message[MESSAGE_SIZE - 1] = '\0';

	/* you can to change flags in your taste */
	openlog("ozilog", LOG_CONS | LOG_PID | LOG_NDELAY, LOG_LOCAL1);

	/* you need to press Ctrl+C to close the program */
	while(1) {
		/* get time before logging */
		clock_gettime(CLOCK_REALTIME, &before);
		/* log the message */
		syslog(LOG_INFO, message);
		/* get time after logging */
		clock_gettime(CLOCK_REALTIME, &after);
		/* calculate time of logging */
		seconds = after.tv_sec - before.tv_sec;
		useconds = (after.tv_nsec / 1000) - (before.tv_nsec / 1000);
		if (useconds > 999999) {
			useconds = 0;
			seconds++;
		}
		if (useconds < 0) {
			useconds += 1000000;
			seconds--;
		}
		/* and output the result in us */
		printf("%u\n", (unsigned) seconds * 1000000 + (unsigned) useconds);
	}
}

Или просто скачайте.

Затем скомпилируйте:

$ gcc --std=c89 -o app app.c

И запустите (для удобства анализа и чтобы избежать ненужных задержек из-за вывода в консоль — с перенаправлением вывода в файл):

$ ./app > out_free

В файле out_free будут накапливаться числа — время выполнения вызова syslog в миллисекундах. Теперь откройте второй терминал и посмотрите на вывод команды top:

Как видно, наше приложение не может полностью загрузить ядро процессора (а на ПК у меня их 6), что-то ему мешает. Проверим время выполнения вызова syslog. Для этого нужно остановить выполнение программы app и использовать магию bash для сортировки полученных чисел (я опустил за … некоторые значения, слева — кол-во, справа — задержка в миллисекундах):

$ kill -SIGKILL $(pidof app)
$ cat out_free | sort -n | uniq -c
  70444 3
 878422 4
 569593 5
 372045 6
  98590 7
   8680 8
  44451 9
...
      1 1203
      1 1238
      1 1325
      1 2563

Время выполнения отдельных вызовов может достигать микросекунд. Но может быть это просто ошибка в измерениях (ядро и задача не real-time, приоритет не высокий — может кто-то вытеснял) или банально неверная интерпретации результатов? Вполне возможно, всякое бывает.

Попробуем сэмулировать высокую нагрузку на процессор, чтобы демону, читающему данные с сокета /dev/log, оставалось мало времени на обработку входящих сообщений. Или, что несколько проще, ограничим это самое время для демона логирования с помощью команды cpulimit, установить её в Arch Linux можно так:

# pacman -s cpulimit

А в Debian, Ubuntu и т.д. вот так:

# apt-get install cpulimit

Теперь можно ограничить потребление CPU для демона в Linux, который занимается записью логов, оставив тому 1%.

# cpulimit --pid $(pidof systemd-journald) --limit 1

Ещё раз запустим наше приложение с перенаправлением вывода в другой файл:

$ ./app > out_load

И посмотрим на вывод команды top.

Программа практически не работает. В принципе, этого уже достаточно, но можно посмотреть и на сухие числа (в левом столбце — кол-во, в правом — задержка в миллисекундах):

$ kill -SIGKILL $(pidof app)
$ cat out_free | sort -n | uniq -c
      9 5
    158 6
     68 7
    145 8
    533 9
...
      1 2305165
      1 3411570
      1 3513700
      1 5015429

Задержки стали больше, а время отдельных вызовов функции syslog может достигать 5 секунд. На мой неискушенный взгляд, это вполне достаточное доказательство на практике.

Заключение

Если вы не хотите, чтобы под высокой нагрузкой поток выполнения программы был заблокирован надолго, то не стоит использовать syslog, ну а если используете — не нужно очень часто туда что-то писать (но ведь очень часто может писать кто-то другой, а нас вас места уже не хватит).

Можно воспользовать уже готовыми решениями для обхода этой проблемы, благо библиотек для логирования предостаточно. Или же можно самостоятельно открыть сокет /var/log в неблокирующем режиме и что-то придумать для обработки ошибок записи (в первую очередь EAGAIN). К примеру, подобный подход реализован тут.