Introducing Buffered Error Logging in Percona Server for MySQL

The MySQL error log is usually used to store and later analyze error and warning messages, but in some cases, it is also used for high throughput debug messages for analyzing complex issues. These messages take up more space, slow down the server, and also make the error log harder to use for other issues. To solve this problem, Percona Server for MySQL 8.0.28-20 introduces new error log variables to separate the debug messages.

Motivation

Percona XtraDB Cluster, and the wsrep and galera libraries in it, have quite high output debug logging facilities. These log files also cause significant slow down: lower debugging levels take 15 percent more time than a normal execution, but if everything is enabled, logging can increase the execution time to 170 percent even on a fast NVMe SSD.

Another issue with them is their increased output: while the error_log is usually relatively small, these debug messages could output gigabytes of messages in a short time. This means that normal log messages are hard to find within, and this could also cause issues for production systems where log messages are archived for a long time.

To improve this situation, MariaDB Enterprise introduced WSREP Black Box logging, which solved the issue by writing the debug messages into a shared memory ring buffer instead. Since it is a ring buffer, debug messages are discarded continuously, and since it is written into a shared memory buffer, they don’t take up disk space: they get only written to the disk after a crash, or when users manually request it, in case of detecting an error.

This implementation is ideal for galera and wsrep most of the time, where these high-output debug messages are only needed when an error occurs, but in some hard-to-reproduce situations, encountering that error might require running a server with debug settings for a long time.

Our implementation

After running various measurements with different log outputs, we realized that the performance hit of the debug logging is caused by two main factors, roughly by the same amount:

• Writing many small messages to the disk
• The string formatting code used to insert the dynamic parameters into the otherwise fixed log messages

Modifying the string formatting code would require changing every place where the galera and wsrep libraries emit log messages, one by one, and wouldn’t be practical.

However, we did notice that the issue with writing to the disk was writing many small messages, not writing high amounts in itself. With high-performance SSD disks, we didn’t notice a significant performance hit of writing the memory buffer out in big blocks instead of simply discarding it when it became full.

We designed this feature, buffered error logging, based on these findings: this new feature introduces two new variables, one specifying a filename, and one a memory buffer size.

If the buffer size is zero, everything works as before, all log messages are written directly to the error log.

If it is non-zero, all (not just debug) messages are written to both the memory buffer, and then normal, non-debug messages are written to the normal error log. Debug messages skip this last file write step, avoiding both the performance hit of many small disk writes, and also avoiding flooding the error log with debug information.

When the memory buffer reaches its maximum size it is written into the buffered log file, and new log messages can start at the beginning of the buffer again, overwriting previous messages that are already synced to the disk.

We also extended the crash handling code of the server: when mysqld crashes and normally shows a stack trace and other information it can collect about the error, it also writes out the remaining memory buffer into the log file, and no log messages get lost even in this case.

This means that in this implementation no log messages are lost, and every debug message gets written to the disk, but with a small delay. This adds the benefit that users are not required to figure out an optimal memory buffer size – something that’s enough to store everything about the issue, but not too big so that it doesn’t fit into the free memory of the machine.

However it also means that the server will never delete these debug logfiles by itself: for long-running debug sessions, a log rotation system should be set up for these log files to avoid completely filling up the disks with them.

Configuring buffered logging

While the issue was most noticeable in Percona XtraDB Cluster, this feature can be useful for any component or plugin with high log outputs using Percona Server for MySQL. For this reason, we introduced our implementation in Percona Server for MySQL 8.0.28-20. In this release, the related system variables do exist, but do nothing, as nothing in the base server or in our plugins and components currently uses this new logging ability. The first real user of this feature will be the next Percona XtraDB Cluster release.

To enable the feature, two variables have to be specified: buffered_error_log_filename is the name of the file the messages are written to, following the same restrictions we introduced for dynamic log file names in our previous security fix. And buffered_error_log_size species the size of the memory buffer in kilobytes. The buffer is written to the file when it gets full, or during a server shutdown or crash.