Why Logging to the MySQL Database is an Antipattern
At work, we have been alerted by our monitoring system that a server is running out of disk space at night for a period of around two hours.
Investigating disk usage peaks
On the next day, I was asked to investigate the alert. I first had a lookat the detailed disk usage graph over time. There were several peaks in the disk usage within the defined time frame. These peaks had also been there for some longer time in the past, on every day at the same time. They do not get unexpectedly high, but the baseline was rising over time, resulting in the nightly peaks exceeding the critical level.
The peaks could be traced back to a backup script that uses tar. tar and that has a reputation of producing spikes in disk usage. But before I was rethinking the backup strategy, I first had a look around on the server if there is some huge chunk of data that can be deleted or reduced in size.
How to free up some disk space then?
After firing up my favorite tool ncdu to get a detailed overview of disk allocation, it was easy to spot one 15 GB file representing just one database table. This file’s size was suspicious as it was the logging table of the TYPO3 system (sys_log). 15 GB of logging data appears to be quite a lot for this particular application.
Logging is huge. Is there some other issue?
I decided to have a more detailed look into the table. To decide whether there was something wrong with the application or it’s just operating normal. At a first glance, there was nothing that needed an immediate reaction. The table has 15400 entries and the oldest entries are from a reasonable time ago. This means that entries seem to be automatically truncated.
1 MB per log entry?
But wait, why are ~15k entries in the sys_log table consuming 15 GB? This would mean that each log entry is using approximately 1 MB of disk space. Looking into some records tells me that each record is around 1 KB in size. Therefore, the representation on the disk is three magnitudes bigger than the actual data. My suspicion is that the table contains a lot more entries from some time ago.
Getting back the disk space
I had a memory from another project where MySQL was never giving back any disk space it has once allocated. My first thinking was that I need to drop the table and recreate it with an SQL dump, but this would include some downtime for the website, which I generally like to avoid. Some more searching led me to the optimize table table command of MySQL which might do the job depending on the setup of the database.
We run a staging system that is synchronized to the live system each night. It suffered from the same issue on the disk. After setting up a high-frequency uptime check for the staging system, I decided to run optimize table sys_log; on the staging system. There was no noticeable downtime on the staging system and the size of the table on the disk was reduced to 12 MB.
As the solution worked well on the staging system and it was looking stable without any downtime, I also applied it to the live system. This resulted in a noticeable drop of disk usage and shifted the peaks caused by the backup script way below the alarm threshold of our monitoring. The issue could be marked as resolved.
The takeaway
TYPO3 is logging its system events to the database by default. As a MySQL database is not freeing up disk space automatically, this might result in a full disk over time. We will have an eye on this in the future to make a decision if this was a one-time event or if we need to take action and invent a different logging mechanism for TYPO3 system logs.
Thanks to my Colleagues
Thanks to Andrew Howden for looking over my shoulder while my first live system investigation at Sitewards GmbH. Also thanks to Behrouz Abbasi for sharing his TYPO3 knowledge and our lovely project manager Antonius Koch taking care of communication to the customer.
