Fix MySQL Constantly Writing to Binlog

loggingMySQLUbuntu

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.

Best Answer

Binlogs in MySQL are used for replication between master and slave(s). If you do not use such architecture you can disable it by executing this:

SET sql_log_bin = 0;

If you have such structure you can strip old (already replicated) records by using command like:

PURGE BINARY LOGS BEFORE '2019-04-02 22:46:26';

or

PURGE BINARY LOGS TO 'mysql-bin.010';

For more information you can use this answer.

Related Topic