Slow MySQL Start Time in GTID? Binary Log File Size May Be The Issue
Tags: mysql, database, hosting, developer
Published: 2018-12-06 21:23:38

---
title: Slow MySQL Start Time in GTID? Binary Log File Size May Be The Issue
published: true
description: Experiencing slow MySQL startup times in GTID mode? Your binary log files could be slowing your restart. See how to debug and increase your MySQL startup speed.
tags: MySQL, Database, Hosting, Developer, 
canonical_url: https://scalegrid.io/blog/slow-mysql-start-time-in-gtid-binary-log-file-size-may-be-the-issue/
---
<link rel="canonical" href="https://scalegrid.io/blog/slow-mysql-start-time-in-gtid-binary-log-file-size-may-be-the-issue/" />

<a href="https://scalegrid.io/blog/slow-mysql-start-time-in-gtid-binary-log-file-size-may-be-the-issue/"><img src="https://scalegrid.io/blog/wp-content/uploads/2018/12/Slow-MySQL-Start-Time-in-GTID-Binary-Log-File-Size-May-Be-The-Issue.png" width="100%" height="auto"></a>
<p style="text-align: justify">Have you been experiencing slow MySQL startup times in GTID mode? We recently ran into this issue on one of our <a style="color: #2da964" title="MySQL Hosting" href="https://scalegrid.io/mysql.html" target="_blank">MySQL hosting </a>deployments and set out to solve the problem. In this blog, we break down the issue that could be <a style="color: #2da964" title="MySQL Hosting" href="https://scalegrid.io/blog/slow-mysql-start-time-in-gtid-binary-log-file-size-may-be-the-issue/" target="_blank">slowing down your MySQL restart times</a>, how to debug for your deployment, and what you can do to decrease your start time and improve your understanding of <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/5.7/en/replication-gtids.html" target="_blank">GTID-based replication</a>.</p>

<h2 style="padding-top: 10px">How We Found The Problem</h2>
<p style="text-align: justify">We were investigating slow MySQL startup times on a low-end, disk-based MySQL 5.7.21 deployment which had GTID mode enabled. The system was part of a <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/8.0/en/replication.html" target="_blank">master-slave</a> pair and was under a moderate write load. When restarting during a scheduled maintenance, we noticed that the database server took 5-10 minutes to start up and begin accepting connections. That kind of delay didn't make sense, so we set out to investigate.</p>

<h2 style="padding-top: 10px">Debugging Your Slow MySQL Start Time</h2>
<p style="text-align: justify">We used the popular <a style="color: #2da964" href="https://www.percona.com/" target="_blank">Percona </a>tool pt-ioprofile to see what the database was doing. <tt>pt-ioprofile</tt> is a very important utility in Percona's <a style="color: #2da964" href="https://www.percona.com/doc/percona-toolkit/LATEST/index.html" target="_blank">popular toolkit</a> that's used to debug MySQL issues, and you can see the complete list of features in their <a style="color: #2da964" href="https://www.percona.com/doc/percona-toolkit/LATEST/pt-ioprofile.html" target="_blank">documentation</a>. The <tt>pt-ioprofile</tt> tool uses <tt>strace</tt> and <tt>lsof</tt> to watch a process’s I/O and print out a table of files and I/O activity.</p>
<p style="text-align: justify">So, we started MySQL, waited for the <tt>mysqld</tt> process to get spawned, and started <tt>pt-ioprofile</tt> to see what the issue might be:</p>

<pre># pt-ioprofile --profile-process mysqld --run-time 200
Tue Oct 9 15:42:24 UTC 2018
Tracing process ID 18677
total      pread       read     pwrite      write      fsync  fdatasync       open      close   getdents      lseek      fcntl filename
...
216.550641   0.000000  216.550565   0.000000   0.000000   0.000000   0.000000   0.000015   0.000040   0.000000   0.000021   0.000000 /mysql_data/binlogs/<strong>mysql-bin.000014</strong>
...
</pre>
<h3 style="padding-top: 10px">What's Slowing Your MySQL Restart?</h3>
<p style="text-align: justify">On running this multiple times, we observed the following:</p>

<ul>
	<li style="text-align: justify">The <tt>mysqld</tt> process was spending most of its time reading the latest binary log file. This was the case even when the server had been stopped gracefully and there was no need for a <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/5.7/en/innodb-recovery.html#innodb-crash-recovery" target="_blank">crash recovery</a>, etc.</li>
	<li style="text-align: justify">The server also spent a considerable amount of time loading the <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/5.7/en/innodb-multiple-tablespaces.html" target="_blank">InnoDB data files</a>, but that time was much smaller compared to the time spent reading the latest binary log file.</li>
	<li style="text-align: justify">If the server was restarted again immediately, this subsequent restart would be much faster.</li>
	<li style="text-align: justify">Since a database shutdown flushes the binary log and creates a new one at startup, we did an additional experiment - before shutting down the server, we<a style="color: #2da964" href="https://dev.mysql.com/doc/refman/8.0/en/flush.html" target="_blank"> flushed the binary logs</a>. The subsequent server start was fast again.</li>
</ul>
<p style="text-align: justify">The<span style="text-align: justify">se observations clearly pointed to the fact that MySQL was spending a lot of time reading the latest binary log file. If the file was small, like it would be when the log file was flushed before a </span>shutdown<span style="text-align: justify">, the startup was fast.</span></p>


<h2 style="padding-top: 10px">Understanding Binlog GTID Recovery</h2>
<p style="text-align: justify">As it turns out, in order to populate the values of <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/8.0/en/replication-options-gtids.html#sysvar_gtid_executed" target="_blank">gtid_executed</a> and <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/8.0/en/replication-options-gtids.html#sysvar_gtid_purged" target="_blank">gtid_purged</a>, the MySQL server must parse the binary log files.</p>
<p style="text-align: justify">Here's the summary the MySQL 5.7 <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/5.7/en/replication-options-gtids.html#sysvar_binlog_gtid_simple_recovery" target="_blank">documentation </a>method recommendation based on a FALSE or TRUE reading:</p>

<h4 style="text-align: justify;padding-top: 15px">When <strong>binlog_gtid_simple_recovery </strong>= FALSE:</h4>
<p style="text-align: justify; padding-top: 10px;">To compute <strong>gtid_executed:</strong></p>
<ul>
	<li style="text-align: justify">Iterate binary log files from the newest, stopping at the first file that has a <strong>Previous_gtids_log_event </strong>entry.</li>
	<li style="text-align: justify">Consume all GTIDs from <strong>Previous_gtids_log_event</strong> and <strong>Gtid_log_events</strong> from this binary log file, and store this GTID set internally. It is referred to as <em>gtids_in_binlog.</em></li>
	<li style="text-align: justify">Value of <strong>gtid_executed</strong> is computed as the union of <em>gtids_in_binlog</em> and the GTIDs in the <strong>mysql.gtid_executed table</strong>.</li>
</ul>
<em> This process can be very time consuming if there are a large number of binary log files without GTIDs, for example, created when <strong>gtid_mode</strong>=OFF.</em>

<p style="text-align: justify; padding-top: 10px;">Similarly, to compute<strong> gtid_purged:</strong></p>
<ul>
	<li style="text-align: justify">Iterate binary log files from the oldest to the newest, stopping at the first binary log that contains either a nonempty <strong>Previous_gtids_log_event</strong> (has at least one GTID), or that has at least one <strong>Gtid_log_event</strong>.</li>
	<li style="text-align: justify">Read <strong>Previous_gtids_log_event</strong> from this file. Compute the internal variable <em>gtids_in_binlog_not_purged</em> as this GTID set subtracted from <em>gtids_in_binlog.</em></li>
	<li style="text-align: justify">Value of <strong>gtid_purged</strong> is set to <strong>gtid_executed</strong>, minus <em>gtids_in_binlog_not_purged</em>.</li>
</ul>

<p style="text-align: justify">So, this forms the basis of our understanding on how things used to work in older versions. However, certain optimizations can be made when <strong>binlog_gtid_simple_recovery</strong> is TRUE. This is the case we are interested in:</p>

<h4 style="padding-top: 15px">When<strong> binlog_gtid_simple_recovery </strong>= TRUE:</h4>
<p style="text-align: justify">(Note, this is the default in MySQL 5.7.7 and later)</p>

<ul>
	<li style="text-align: justify">Read just the oldest and the newest binary log files.</li>
	<li style="text-align: justify">Compute<strong> gtid_purged</strong> from the <strong>Previous_gtids_log_event</strong> or <strong>Gtid_log_event</strong> found in the oldest binary log file.</li>
	<li style="text-align: justify">Compute <strong>gtid_executed</strong> from the <strong>Previous_gtids_log_event</strong> or <strong>Gtid_log_event</strong> found in newest binary log file.</li>
	<li style="text-align: justify">Thus, <strong>only two binary log files</strong> are read during the server restart or when purging binary logs.</li>
</ul>
<p style="text-align: justify">So, for MySQL versions 5.7.7 and above, the latest and the old binary log files are always read during system startup to correctly initialize <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/5.7/en/replication-options-gtids.html#replication-sysvars-gtids" target="_blank">GTID system variables</a>. Reading the oldest binary log file isn't as expensive since the <a style="color: #2da964" href="https://dev.mysql.com/doc/internals/en/binlog-event.html" target="_blank">event</a> MySQL is looking for, <a style="color: #2da964" href="https://dev.mysql.com/doc/dev/mysql-server/8.0.2/classPrevious__gtids__log__event.html" target="_blank">Previous_gtids_log_event</a>, is always the first event in a binary log file.</p>
<p style="text-align: justify">However, in order to correctly compute <tt>gtid_executed</tt>, the server must read through the entire latest binary log file and collect all the events in that file. <strong>So, the system startup time becomes directly proportional to the size of the latest binary log file</strong>.</p>
<p style="text-align: justify">Note that the situation is even worse when <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/5.7/en/replication-options-gtids.html#sysvar_binlog_gtid_simple_recovery" target="_blank"><tt>binlog_gtid_simple_recovery</tt> </a>is <tt>FALSE</tt>. Since it is no longer the default option in recent releases, it is not much of a concern.</p>

<h2 style="padding-top: 10px">How To Resolve Your Slow Start Time</h2>
<p style="text-align: justify">Having understood the cause of the issue we were running into, the solution we decided on was fairly obvious - <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/8.0/en/replication-options-binary-log.html#sysvar_max_binlog_size" target="_blank">reduce the size of the binary log files</a>. The default size of binary log files is 1GB. It takes time to parse through a file of this size during startup, so it makes sense to decrease the value of <a style="color: #2da964" href="https://dev.mysql.com/doc/refman/8.0/en/replication-options-binary-log.html#sysvar_max_binlog_size" target="_blank"><tt>max_binlog_size</tt> </a>to a lower value.</p>
<p style="text-align: justify;padding-bottom: 20px">If decreasing the size of the binary log file is not an option, then flushing the binary log files just before a maintenance shutdown of the mysqld process can help to decrease the binlog GTID recovery times.</p>