Change 967293 had a related patch set uploaded (by BCornwall; author: BCornwall):

[operations/software/fifo-log-demux@master] Add Prometheus metrics for fifo-log-demux

https://gerrit.wikimedia.org/r/967293

Change 967293 abandoned by BCornwall:

[operations/software/fifo-log-demux@master] Add Prometheus metrics for fifo-log-demux

Reason:

Migrated to gitlab

https://gerrit.wikimedia.org/r/967293

I went on a different tangent with this problem, and tried to figure out why we're having ATS fail writes to the notpurge log pipe in the first place. After some hours of digging around this problem (I'll spare you endless details of temporary test configs and strace outputs of various daemons' behavior, etc), these are the basic issues I see:

1. The basic data flow goes: ATS -> named_pipe -> fifo_log_demux -> named_unix_socket -> fifo_log_tailer -> anon_pipe -> mtail. Every single stage of this pipeline has some kind of buffering in kernel and/or application land.
2. fifo-log-demux, as described by its own code commentary, is synchronous in nature. If a socket reader is slow on the output side of it, its own reads from the named pipe are also slowed down, because it's just a blocking loop over reads and writes.
3. The default size of the kernel pipe buffer in the named pipe is 64k on our linuxes, and this is very small relative to the size and frequency of our log messages, making it easy to temporarily max out the pipe buffer with routine bursts.
4. mtail doesn't seem well-suited to reading high-speed data from a socket or pipe. The design seems to be centered on disk files and it has a polling interval that defaults to 250ms for checking for new data. We can decrease the polling interval at the cost of more syscall churn, but there doesn't seem to be a parameter to have it simply use a true kernel event readiness mechanism like select or epoll. At the default current value of 250ms, it reads from the pipe rather slowly at times!

My recommendations for how to remediate this:

1. In the ATS logging.yaml config of the notpurge.pipe output named pipe, add the parameter pipe_buffer_size: 1048576. This is 16x larger than the default, and is the maximum we can configure here without a non-default ulimit and/or a kernel sysctl config change, I think.
2. In the mtail arguments deployed to /lib/systemd/system/atsmtail@backend.service, add the mtail CLI param -poll_interval 10ms, which is 25x quicker than the default 250ms.
3. Amend fifo-log-demux to use an async event loop and perhaps a larger (and configurable) application-layer buffer to help smooth this over further in edge cases.

I've tried (1) and (2) in isolation and they each reduced the error message counts, but they weren't enough to eliminate the error messages entirely. With both together, at least on cp4052 as a test host (with real pooled traffic), it made the errors go away completely over ~10 minutes or more while I was testing.

Followup: did a 3-minute test of the same pair of parameter changes on cp3066 for a higher-traffic case. No write failures detected via strace in this case (we don't have the error log outputs to go by in 9.1 builds). mtail CPU usage at 10ms polling interval was significantly higher than it was in ulsfo, but still seems within reason overall and not saturating anything.