bug: sync logging causes sluggish ot-robot-server performance and timeout errors under certain system load conditions

[strangemonad]

Overview

We're investigating a handful of system load related issues that manifest in the following ways:

• Slow/Poor Flex performance across the ot-robot-server and on-device app performace
• Timeout errors
• Stall crash errors

This becomes especially evident in protocols that have a large number of steps/actions (eg >10k) and many chained, short-lived actions eg multiple, short executing moves.

We believe there are several contributing factors to the degraded performance. We've been able to track down at least one of them to the use of synchronous logging in the ot-robot-server (and other services).

Steps to reproduce

Under load observer

• CAN bus message summaries are written to logs (by ot-robot-server)
• Logs synchronously write to journald see robot-server/robot_server/services/logging.py#_robot_log_config()
• When journald flushes logs to disk (/var/log/.../), it will cause the ot-robot-server to block in the critical CAN bus message ack path.

There are several potential future improvements that would all be more involved to implement. eg better configuration of journald.

A very simple first improvement would be to first configure the logger to write to an async handler like a QueueHandler. This will prevent the python process from blocking during these momentary journald flushes to disc. Here's some sample code that incorporates async logging with systemd logging. This should probably be done at least to the ot-robot-server but all python services would benefit.

import logging
from logging.handlers import QueueHandler, QueueListener
from queue import Queue
from systemd.journal import JournalHandler

# Create a queue for log messages
log_queue = Queue()

# Set up the JournalHandler
journal_handler = JournalHandler()
journal_handler.setFormatter(logging.Formatter('[%(levelname)s] %(message)s'))

# Set up the QueueHandler and add it to the logger
queue_handler = QueueHandler(log_queue)
logger = logging.getLogger('async_logger')
logger.setLevel(logging.INFO)
logger.addHandler(queue_handler)

# Set up the QueueListener to process logs asynchronously
listener = QueueListener(log_queue, journal_handler)
listener.start()

# Example usage
logger.info("This is an async log message")

# Stop the listener when done
listener.stop()

Current behavior

No response

Expected behavior

No response

Operating system

None

System and robot setup or anything else?

Flex 8.3.1

[strangemonad]

FYI this is related to #17845

[SyntaxColoring]

Interesting, thanks for the investigation.

coreos/bugs#990 and this blog post seem to confirm that this is a hazard with journald (unless it's been fixed in the past 10 years).

Do you know exactly how much of these stalls are being caused by blocked logging? Re #17845, it would be very surprising to me if journald is causing multiple-second stalls. The CoreOS blog post above says they noticed stalls up to 0.5 s, which would be bad, but not CAN timeout bad.

Your queue solution (or some other kind of in-ot-robot-server non-blocking buffer) seems reasonable. We would probably want to bound the queue size to avoid memory leaks. We'd also want to look closely at threading and multiprocessing safety, because that has historically been fraught.

---

The Flex's journald config forwards everything to syslog. The journald docs warn that this can block (context behind those docs), but perhaps only if something is actually reading from the socket. I couldn't find anything in our system that reads from the socket, but I haven't looked very hard yet.

[strangemonad]

I wasn't able to verify the exact durations of the journal fsync induced stalls. Determining that would require further instrumentation that would likely exacerbate the current issue.

I'm fairly certain any sort of sync writes to journald are still susceptible to blocking (the python-systemd client is definitely a blocking client). I've seen using some form of non-blocking / async logging configuration to be pretty common in server applications (regardless of programing language). Another approach I've used successfully in the past, that would require a bit more configuration to adopt, is to use structlog https://www.structlog.org/en/stable/index.html which has a very robust async logging facility (eg log formatting., which can get slow for certain objects, also gets handled async).

With the built-in queue handler, I agree, some form of bounded queue size is almost always better than using an unbounded queue. I don't think I'd be worried about a memory leak per se, since the file socket eventually must get drained, but it's nice to keep the process memory footprint within a bounded range in its steady state.

Out of curiosity, what's the use case for forwarding to syslog by default? This effectively removes the advantage of journald's own buffering (from in memory logs written first to /run/log and periodically flushed to /var/log). Journald's forwarding is done synchronously.

https://www.freedesktop.org/software/systemd/man/latest/journald.conf.html#ForwardToSyslog=

Note: Forwarding is performed synchronously within journald, and may significantly affect its performance. This is particularly relevant when using ForwardToConsole=yes in cloud environments, where the console is often a slow, virtual serial port. Since journald is implemented as a conventional single-process daemon, forwarding to a completely hung console will block journald. This can have a cascading effect resulting in any services synchronously logging to the blocked journal also becoming blocked. Unless actively debugging/developing something, it's generally preferable to setup a journalctl --follow style service redirected to the console, instead of ForwardToConsole=yes, for production use.

For what it's worth, our business use case (and how we discovered this) is we want to be able to collect logs and node metrics across our fleet. In theory, it should be possible to do this in a non-blocking, lightweight way (e.g. a journald collector can efficiently tail the logs once they're flushed and idle otherwise if there's no syslog forwarding in the mix). We've since disabled log aggregation.

I haven't testing this but if should be possible to observe this with the following

• Run a program that has lots of short-lived gantry or pipette commands
• While one of the operations is running (eg during a pickup tip operation when you've bound live pressure sensor readings, use the http api to download the logs which should make a call to journalctl and cause logs to flush.

---

As for the oe core config, I believe the default journald flush interval is 5m (unless some upstream image layer in oe-core changes this). This may be too long of an interval and allow too many message to accumulate given the more limited io bandwidth of the built-in flash storage. It might be worth exploring smaller, more frequent flushes https://www.freedesktop.org/software/systemd/man/latest/journald.conf.html#SyncIntervalSec=

[sfoster1]

Thanks for looking into this! I am pretty sure you're right about the problems you've identified, and we'll look at fixing them as soon as we can.

The syslog forwarding was because we used to allow forwarding logs to cloud log collection services (if the user agreed with an opt-in prompt) but we removed that recently and never ended up removing the syslog forwarding.