Impact of InnoDB Log Buffer on INSERT

MySQL Tutorials - Herong's Tutorial Examples

∟Impact of InnoDB Log Buffer on INSERT

This section provides a tutorial example to demonstrate the performance impact of InnoDB Log Buffer. Setting innodb_flush_log_at_trx_commit=0 can reduce execution time reduction on INSERT and other data change statements from 35 ms to 1 ms.

What Is InnoDB Log Buffer? InnoDB Log Buffer is the memory area that is used by the InnoDB engine to hold data to be written to the log files on disk. The contents of the log buffer are periodically flushed to disk. The Log Buffer generally helps to reduce the number of disk output operations and improves server performance.

The Log Buffer behavior is mainly controlled by two system variables:

1. innodb_log_buffer_size (Default: 16777216) - The size in bytes of the buffer that InnoDB uses to write to the log files on disk.

A large log buffer enables large transactions to run without the need to write redo log data to disk before the transactions commit. Thus, if you have transactions that update, insert, or delete many rows, increasing the size of the log buffer reduces disk output operations.

2. innodb_flush_log_at_trx_commit (Default: 1) - The method ID that represents how frequently the contents of the log buffer are written and flushed to disk.

1 - Logs are written and flushed to disk at each transaction commit. This is required for full ACID (Atomicity, Consistency, Isolation, and Durability) compliance. This will increase the number of disk output operations if you do frequent and small commits.
0 - Logs are written and flushed to disk once per second. Transactions for which logs have not been flushed can be lost in a crash. This is a big saving comparing to method 1, if you have many commits within a second. The risk of losing logs within a second is not a big deal in most situations.
2 - Logs are written after each transaction commit and flushed to disk once per second. This is like half way between method 1 and 0. Logs are written but not flushed after each transaction commit. They flushed to disk once per second.

Here is what I did to find out the impact of InnoDB log buffer on INSERT statements used in previous tutorials.

1. Turn off binary logging, turn on query profiling, and create the "Tests" table again. And make sure the InnoDB engine is used for the table.

mysql> SET sql_log_bin = 0;
mysql> SET SESSION profiling = 1

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

mysql> select table_name, engine
    -> from information_schema.tables where table_name='Tests';
+------------+--------+
| TABLE_NAME | ENGINE |
+------------+--------+
| Tests      | InnoDB |
+------------+--------+

2. Set innodb_flush_log_at_trx_commit=0 and run some INSERT statements:

mysql> set global innodb_flush_log_at_trx_commit=0;

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

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

mysql> INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000));
Query OK, 1 row affected (0.00 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
-------- ---------- -----------------------------------------------
      22 0.00018600 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
      23 0.00018550 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))
      24 0.00018600 INSERT INTO Tests VALUES (FLOOR(1+RAND()*1000))

4. Get Profiling details on the query 24:

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

Status                        Duration CPU_user/_system  Block_in/out
----------------------------- -------- --------/-------- --------/---
starting                      0.000056 0.000000/0.000055        0/  0
Executing hook on transaction 0.000003 0.000000/0.000004        0/  0
starting                      0.000006 0.000000/0.000006        0/  0
checking permissions          0.000005 0.000000/0.000005        0/  0
Opening tables                0.000024 0.000000/0.000024        0/  0
init                          0.000006 0.000000/0.000006        0/  0
System lock                   0.000007 0.000000/0.000006        0/  0
update                        0.000036 0.000000/0.000036        0/  0
end                           0.000004 0.000000/0.000003        0/  0
query end                     0.000003 0.000000/0.000003        0/  0
waiting for handler commit    0.000014 0.000000/0.000014        0/  0
closing tables                0.000006 0.000000/0.000006        0/  0
freeing items                 0.000010 0.000000/0.000011        0/  0
cleaning up                   0.000007 0.000000/0.000006        0/  0

Cool. The execution is reduced to < 1 ms now. 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
----------------------------- -------- --------/-------- --------/---

with sql_log_bin=0
     innodb_flush_log_at_trx_commit=0
waiting for handler commit    0.000014 0.000000/0.000014        0/  0

with sql_log_bin=0
     innodb_flush_log_at_trx_commit=1
waiting for handler commit    0.034835 0.000862/0.000000        0/  8

with sql_log_bin=1
     innodb_flush_log_at_trx_commit=1
waiting for handler commit    0.062925 0.000161/0.002778        0/ 40

Conclusion: if you are not doing any database replication, have frequent backups and don't care about the losing log entries of the last second when system crashes, you can turn off binary logging and innodb_flush_log_at_trx_commit=0. to reduce execution time of INSERT and other data change statements from 55 ms to 1ms!