My Ubuntu server started running a high amount of IO operations. The server has a few WordPress websites on it, but they get at most a few dozen views per day. In a couple of days 30GB of disk space was used.
Checking iotop
Running iotop showed that mysql was constantly writing to disk. A typical output was like this:
Total DISK READ: 0.00 B/s | Total DISK WRITE: 390.38 K/s
Current DISK READ: 0.00 B/s | Current DISK WRITE: 664.80 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
298 be/3 root 0.00 B/s 0.00 B/s 0.00 % 4.79 % [jbd2/vda1-8]
981 be/4 mysql 0.00 B/s 0.00 B/s 0.00 % 0.55 % mysqld [ib_log_flush]
960 be/4 mysql 0.00 B/s 0.00 B/s 0.00 % 0.42 % mysqld [ib_io_wr-1]
63310 be/4 mysql 0.00 B/s 30.92 K/s 0.00 % 0.17 % mysqld [connection]
62908 be/4 mysql 0.00 B/s 34.79 K/s 0.00 % 0.09 % mysqld [connection]
64165 be/4 mysql 0.00 B/s 34.79 K/s 0.00 % 0.07 % mysqld [connection]
964 be/4 mysql 0.00 B/s 185.52 K/s 0.00 % 0.05 % mysqld [ib_pg_flush_co]
983 be/4 mysql 0.00 B/s 100.49 K/s 0.00 % 0.00 % mysqld [ib_log_writer]
71067 be/4 www-data 0.00 B/s 3.87 K/s 0.00 % 0.00 % apache2 -k start
Indeed, checking in the /var/lib/mysql directory showed hundreds of binlog files, totaling a size of about 30GB. The timestamps indicated that mysql was writing to binlogs at a rate close to 1GB per hour, with no sign of slowing.
Checking mysql processes
Running mysql -p -e "show processlist" to view mysql processes showed nothing.
+--------+------+-----------+------+---------+------+-------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+------+-----------+------+---------+------+-------+------------------+
| 627525 | root | localhost | NULL | Query | 0 | init | show processlist |
+--------+------+-----------+------+---------+------+-------+------------------+
Checking the binlog files
Using mysqlbinlog to view the binlog files showed they were full of some sort of hash. A typical file looked like:
# The proper term is pseudo_replica_mode, but we use this compatibility alias
# to make the statement usable on server versions 8.0.24 and older.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#220515 4:09:54 server id 1 end_log_pos 126 CRC32 0x070b8f09 Start: binlog v 4, server v 8.0.29-0ubuntu0.20.04.3 created 220515 4:09:54
BINLOG '
En2AYg8BAAAAegAAAH4AAAAAAAQAOC4wLjI5LTB1YnVudHUwLjIwLjA0LjMAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYgAEGggAAAAICAgCAAAACgoKKioAEjQA
CigAAQmPCwc=
'/*!*/;
# at 126
#220515 4:09:54 server id 1 end_log_pos 157 CRC32 0x433aa4c9 Previous-GTIDs
# [empty]
# at 157
#220515 4:09:54 server id 1 end_log_pos 236 CRC32 0x671d08bc Anonymous_GTID last_committed=0 sequence_number=1 rbr_only=yes original_committed_timestamp=1652587794635604 immediate_commit_timestamp=1652587794635604 transaction_length=14092
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1652587794635604 (2022-05-15 04:09:54.635604 UTC)
# immediate_commit_timestamp=1652587794635604 (2022-05-15 04:09:54.635604 UTC)
/*!80001 SET @@session.original_commit_timestamp=1652587794635604*//*!*/;
/*!80014 SET @@session.original_server_version=80029*//*!*/;
/*!80014 SET @@session.immediate_server_version=80029*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 236
#220515 4:09:54 server id 1 end_log_pos 334 CRC32 0x71a6c06f Query thread_id=614826 exec_time=0 error_code=0
SET TIMESTAMP=1652587794/*!*/;
SET @@session.pseudo_thread_id=614826/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1149239296/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=246,@@session.collation_connection=246,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 334
#220515 4:09:54 server id 1 end_log_pos 415 CRC32 0x6976a620 Table_map: `wordpress-jessjohn`.`wp_options` mapped to number 81
# at 415
#220515 4:09:54 server id 1 end_log_pos 14218 CRC32 0x8cd2158b Update_rows: table id 81 flags: STMT_END_F
BINLOG '
En2AYhMBAAAAUQAAAJ8BAAAAAFEAAAAAAAEAEndvcmRwcmVzcy1qZXNzam9obgAKd3Bfb3B0aW9u
cwAECA/8DwX8AgRQAAABAYACAfYgpnZp
En2AYh8BAAAA6zUAAIo3AAAAAFEAAAAAAAEAAgAE//8AHQAAAAAAAAANAHJld3JpdGVfcnVsZXMA
AAAAA3llcwAdAAAAAAAAAA0AcmV3cml0ZV9ydWxlc4c1AABhOjE0MDp7czoxMToiXndwLWpzb24v
PyQiO3M6MjI6ImluZGV4LnBocD9yZXN0X3JvdXRlPS8iO3M6MTQ6Il53cC1qc29uLyguKik/Ijtz
OjMzOiJpbmRleC5waHA/cmVzdF9yb3V0ZT0vJG1hdGNoZXNbMV0iO3M6MjE6Il5pbmRleC5waHAv
d3AtanNvbi8/JCI7czoyMjoiaW5kZXgucGhwP3Jlc3Rfcm91dGU9LyI7czoyNDoiXmluZGV4LnBo
cC93cC1qc29uLyguKik/IjtzOjMzOiJpbmRleC5waHA/cmVzdF9yb3V0ZT0vJG1hdGNoZXNbMV0i
O3M6MTc6Il53cC1zaXRlbWFwXC54bWwkIjtzOjIzOiJpbmRleC5waHA/c2l0ZW1hcD1pbmRleCI7
... 245 lines of this ...
dD0kbWF0Y2hlc1sxXSZjcGFnZT0kbWF0Y2hlc1syXSI7czoyMjoiW14vXSsvKFteL10rKS9lbWJl
ZC8/JCI7czo0MzoiaW5kZXgucGhwP2F0dGFjaG1lbnQ9JG1hdGNoZXNbMV0mZW1iZWQ9dHJ1ZSI7
fQN5ZXOLFdKM
'/*!*/;
# at 14218
#220515 4:09:54 server id 1 end_log_pos 14249 CRC32 0x322d3658 Xid = 18716628
COMMIT/*!*/;
# at 14249
#220515 4:09:54 server id 1 end_log_pos 14329 CRC32 0xc4b6c15a Anonymous_GTID last_committed=1 sequence_number=2 rbr_only=yes original_committed_timestamp=1652587794702570 immediate_commit_timestamp=1652587794702570 transaction_length=100144
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1652587794702570 (2022-05-15 04:09:54.702570 UTC)
# immediate_commit_timestamp=1652587794702570 (2022-05-15 04:09:54.702570 UTC)
/*!80001 SET @@session.original_commit_timestamp=1652587794702570*//*!*/;
/*!80014 SET @@session.original_server_version=80029*//*!*/;
/*!80014 SET @@session.immediate_server_version=80029*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 14329
#220515 4:09:54 server id 1 end_log_pos 14427 CRC32 0x1328bf8c Query thread_id=614825 exec_time=0 error_code=0
SET TIMESTAMP=1652587794/*!*/;
BEGIN
/*!*/;
# at 14427
#220515 4:09:54 server id 1 end_log_pos 14507 CRC32 0x64436ee3 Table_map: `wordpress-jessjohn`.`wp_usermeta` mapped to number 95
# at 14507
#220515 4:09:54 server id 1 end_log_pos 114362 CRC32 0xec16092b Update_rows: table id 95 flags: STMT_END_F
BINLOG '
En2AYhMBAAAAUAAAAKs4AAAAAF8AAAAAAAEAEndvcmRwcmVzcy1qZXNzam9obgALd3BfdXNlcm1l
dGEABAgID/wD/AMEDAEBwAIB9uNuQ2Q=
En2AYh8BAAAAD4YBALq+AQAAAF8AAAAAAAEAAgAE//8ANwAAAAAAAAABAAAAAAAAAA4Ac2Vzc2lv
... and so on for another >200 lines
What is causing all this logging?
I'm not very familiar with mysql logging so not sure where to go from here. I suppose a quick fix would be to just turn logging off. I don't understand what the binlog files are saying, or what might be causing so much to be logged.
