Impact of Binary Logging on INSERT

MySQL Tutorials - Herong's Tutorial Examples

∟Impact of Binary Logging on INSERT

This section provides a tutorial example to demonstrate the performance impact of binary logging, about 50% of execution time reduction on INSERT and other data change statements.

What Is Binary Logging? Binary logging is feature in MySQL server that logs “events” that describe database changes such as table creation operations or changes to table data.

Binary logging is turned on by default in MySQL server. You can run the "mysqlbinlog" command to view its log files. For example:

herong$ sudo /usr/bin/mysqlbinlog --start-position=7413281 \
  /var/lib/mysql/binlog.000030 | more

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 156
#211112 17:50:54 server id 1  end_log_pos 125 CRC32 0x09c34d76
Start: binlog v 4, server v 8.0.21 created 211112 17:50:54 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
/jiOYQ8BAAAAeQAAAH0AAAABAAQAOC4wLjIxAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAD+OI5hEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA
CigBdk3DCQ==
'/*!*/;
# at 7413281
#211116 13:24:34 server id 1  end_log_pos 7413332 CRC32 0x3ae8bf07 \
  Table_map: `test`.`Tests` mapped to number 181
# at 7413332
#211116 13:24:34 server id 1  end_log_pos 7413372 CRC32 0x06659132 \
  Write_rows: table id 181 flags: STMT_END_F

BINLOG '
kkCTYRMBAAAAMwAAAFQecQAAALUAAAAAAAEABHRlc3QABVRlc3RzAAEDAAEBAQAHv+g6
kkCTYR4BAAAAKAAAAHwecQAAALUAAAAAAAEAAgAB/wAAAAAAMpFlBg==
'/*!*/;
...

The binary log files generated by the binary log feature are serving two important purposes:

Database Replication - The binary log on a replication source server provides a record of the data changes to be sent to replicas. The source sends the information contained in its binary log to its replicas, which reproduce those transactions to make the same data changes that were made on the source.
Data Recovery - Certain data recovery operations require use of the binary log. After a backup has been restored, the events in the binary log that were recorded after the backup was made are re-executed. These events bring databases up to date from the point of the backup.

There are 2 system variables that turns on and off binary logging:

SET sql_log_bin=ON/OFF - Turn on or off binary logging for this session only.
SHOW VARIABLES LIKE 'log_bin' - Read-only variable for the binary logging flag at the global level. You can use --skip-log-bin or --disable-log-bin mysqld command options to turn of 'log_bin'.

Obviously, running MySQL server with binary logging enabled makes performance slightly slower. Here is what I did to find out the impact of binary logging on INSERT statements used in previous tutorials.

1. Turn off binary logging and create the "Tests" table again.

mysql> SET sql_log_bin = 0;

mysql> CREATE TABLE Tests (Quantity INTEGER);
Query OK, 0 rows affected (0.30 sec)

2. Turn on query profiling and run some INSERT statements:

mysql> SET SESSION profiling = 1

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.03 sec)

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.02 sec)

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.03 sec)

3. Get a list of profiled queries. The average of execution time is about still about 55 ms.

mysql> SHOW PROFILES;

Query_ID Duration   Query
-------- ---------- -----------------------------------------------
...
      16 0.03504750 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
      17 0.02237725 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
      18 0.02602950 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
..

4. Get Profiling details on the query 16:

mysql> SHOW PROFILE CPU, BLOCK IO, PAGE FAULTS, SWAPS FOR QUERY 16;

Status                        Duration CPU_user/system   Block_in/0ut P_F_major/minor Swaps
----------------------------- -------- --------/-------- --------/--- ---------/----- -----
starting                      0.000059 0.000052/0.000006        0/  0         0/    0     0
Executing hook on transaction 0.000004 0.000004/0.000001        0/  0         0/    0     0
starting                      0.000006 0.000006/0.000000        0/  0         0/    0     0
checking permissions          0.000005 0.000004/0.000001        0/  0         0/    0     0
Opening tables                0.000022 0.000020/0.000002        0/  0         0/    0     0
init                          0.000007 0.000006/0.000001        0/  0         0/    0     0
System lock                   0.000007 0.000006/0.000000        0/  0         0/    0     0
update                        0.000056 0.000051/0.000006        0/  0         0/    0     0
end                           0.000004 0.000003/0.000000        0/  0         0/    0     0
query end                     0.000003 0.000003/0.000001        0/  0         0/    0     0
waiting for handler commit    0.034835 0.000862/0.000000        0/  8         0/    0     0
closing tables                0.000020 0.000018/0.000002        0/  0         0/    0     0
freeing items                 0.000018 0.000016/0.000002        0/  0         0/    0     0
cleaning up                   0.000008 0.000007/0.000000        0/  0         0/    0     0

Cool. The execution is reduced by 50%. The main difference is at the "waiting for handler commit" step:

mysql> SHOW PROFILE CPU, BLOCK IO, PAGE FAULTS, SWAPS FOR QUERY 16;

Status                        Duration CPU_user/system   Block_in/0ut P_F_major/minor Swaps
----------------------------- -------- --------/-------- --------/--- ---------/----- -----

with binary logging off
waiting for handler commit    0.034835 0.000862/0.000000        0/  8         0/    0     0

with binary logging on:
waiting for handler commit    0.062925 0.000161/0.002778        0/ 40         0/    0     0

Conclusion: if you are not doing any database replication and have frequent backups, you can turn off binary logging to reduce execution time of INSERT and other data change statements by 50%. The only risk is losing data changes occurred since your last backup. You can manage this risk by re-doing those changes.