tree ab67e93056ee248ce573d7bdd4f7296c831cc2f2
parent 560bf459ebb00302a45ea0f868092e027aefdbaa
author Willy Tarreau <w@1wt.eu> 1591878347 +0200
committer William Lallemand <wlallemand@haproxy.org> 1591971638 +0200

BUG/MEDIUM: log: don't hold the log lock during writev() on a file descriptor

In issue #648 a second problem was reported, indicating that some users
mistakenly send the log to an FD mapped on a file. This situation doesn't
even enable O_NONBLOCK and results in huge access times in the order of
milliseconds with the lock held and other threads waiting till the
watchdog fires to unblock the situation.

The problem with files is that O_NONBLOCK is ignored, and we still need
to lock otherwise we can end up with interleaved log messages.

What this patch does is different. Instead of locking all writers, it
uses a trylock so that there's always at most one logger and that other
candidates can simply give up and report a failure, just as would happen
if writev() returned -1 due to a pipe full condition. This solution is
elegant because it gives back the control to haproxy to decide to give
up when it takes too much time, while previously it was the kernel that
used to block the syscall.

However at high log rates (500000 req/s) there was up to 50% dropped logs
due to the contention on the lock. In order to address this, we try to
grab the lock up to 200 times and call ha_thread_relax() on failure. This
results in almost no failure (no more than previously with O_NONBLOCK). A
typical test with 6 competing threads writing to stdout chained to a pipe
to a single process shows around 1000 drops for 10 million logs at 480000
lines per second.

Please note that this doesn't mean that writing to a blocking FD is a good
idea, and it might only be temporarily done on testing environments for
debugging. A file or a terminal will continue to block the writing thread
while others spin a little bit and lose their logs, but the writing thread
will still experience performance-killing latencies.

This patch should be backported to 2.1 and 2.0. The code is in log.c in
2.0, but the principle is the same.

(cherry picked from commit df187875da479c71f12e2e8edb0a2e345f189523)
[wla: the lock is the one of the fd instead of log_lock]
Signed-off-by: William Lallemand <wlallemand@haproxy.org>
(cherry picked from commit 5a4e4a0346ae85d145c537f457e184684b20bb3d)
[wla: the code is in log.c and in the __do_send_log() function]
Signed-off-by: William Lallemand <wlallemand@haproxy.org>