This chapter explains the basics of how to improve the performance of the queries that are executed on a MariaDB server. First, the important tools required to find slow queries are described. Once we find such queries, we will need to find out why they are slow. Thus, a description of how MariaDB uses indexes follows. Then, we will discuss the EXPLAIN
command, which shows how MariaDB executes a query. Contextually, we will also discuss the main execution strategy.
The topics covered in this chapter are:
pt-query-digest
command from Percona ToolkitEXPLAIN
statementThe slow query log (or simply slow log) stores SQL statements that take too long to execute. To enable it, the slow_query_log
variable or the --slow-query-log
startup option can be set to 1
. To explicitly disable the log, the --slow-query-log
startup option must be set to 0
. Without passing any arguments, the --slow-query-log
startup option enables this log. As the slow_query_log
variable is dynamic, the slow query log can be enabled or disabled at runtime.
The default filename of the slow query log is the server's hostname followed by the -slow.log
suffix.
Just like the general query log, the slow query log can be a file, table, or both. The log output server variable can be used to specify if the log is a table or file. The allowed values to be set are FILE
, TABLE
, and NONE
(which disables both the slow query log and the general query log). A combination of these values (separated by a comma) is allowed. The NONE
value overrides other values.
For example, if the hostname is hal
, hal-slow.log
will be the default name for the slow query log. A different name can be specified using the slow_query_log_file
server variable, or using the --slow-query-file
option. In a replication environment, using the same file name for all logs is a good practice, because it may be necessary to execute the same scripts on all the servers.
If the slow query log is written into a table, the table is called slow_log
and it can be found in the mysql
database. In The general query log section in Chapter 2, Debugging, we have described in detail what can or cannot be done with the general_log
table. These sections also apply to the slow_log
table. As explained previously, in the slow query log we can find the queries that were executed too slowly. But what does this depend on? This depends on our workload, of course. For this reason, the rules that determine what queries are written in the slow query log depend on some of the server's system variables.
First, we may want to log queries that do not use indexes at all. To do this, we can set the log_queries_not_using_indexes
variable (or the --log-queries-not-using-indexes
startup option) to 1
, as its default value is 0
. This variable is dynamic, but only exists at the global level.
Even if a query uses indexes, we may want to log it if it exceeds a time-out. This can be done via the long_query_time
variable, or the --long_query_time
startup option. If the value is 0
, there is no time-out and the slow queries are not logged. This value is expressed in seconds. Decimal values are allowed with a precision of microseconds (up to six decimal digits); however, for table-based logs, the decimal part is ignored. The query execution time is counted from the time the thread acquires the necessary locks. This means that, if a query takes too much time just because it is blocked by a slow query, it is not logged. This variable is dynamic and exists at both the global and session levels. This allows connections that execute more complex queries to set a greater time-out.
A query can also have other problems that we may want to log. The classes of problems that must be logged are listed in the log_slow_filter
variable, separated by a comma. The allowed values are described as follows:
full_scan
: This value means that the query has performed a full table scan (same as log_queries_not_using_indexes
)full_join
: This value means that the query performed a join operation, which does not use indexesfilesort
: This value means that the query performed a sorting operation, which requires an internal, temporary in-memory tablefilesort_on_disk
: This value means that the query performed a sorting operation, which requires a temporary on-disk filetmp_table
: This value means that the query created an implicit temporary tabletmp_table_on_disk
: This value means that the query created an implicit temporary table written on the diskquery_cache_miss
: This value means that a query search was performed but the query was not found in the query cacheBy default, the log_slow_filter
variable contains all these values. It is dynamic and exists at both the session and global levels.
Even if a query matches the criteria defined by the log_queries_not_using_indexes
and long_query_time
system variables, the min_examined_row_limit
variable can prevent it from being logged. Queries that examined fewer than the described number of rows are never written into the slow query log. A value of 0
allows all queries to be logged. The maximum value is platform-dependent, but is always very high. This variable is dynamic and exists at both the global and session levels. This setting is usually useful because, if a query examines only a few rows, it would not benefit from the use of an index in any case (and the optimizer takes this into account). If the query exceeds the time-out, it is still possible that it does not examine many rows, for example, if the query requires complex ordering or grouping operations, or if it calls slow functions (including stored functions).
Sometimes, logging all the queries that do not use indexes can be a heavy task for a busy server. For this reason, it is possible to limit the logging of such queries using the log_throttle_queries_not_using_indexes
system variable. If the value of the system variable is 0
(the default), there is no limit. If its value is higher than 0
, it will determine the number of queries that do not use indexes and that can be logged in a minute. When this limit is reached, further queries will not be logged. A minute after the last query that does not use indexes is logged, a summary of the suppressed queries is written into the log.
By default, administrative queries (such as CHECK TABLE
or ANALYZE TABLE
) are not written to the slow query log. To change this behavior, the log_slow_admin_statements
variable can be set to 1
. This variable is dynamic, but only exists at the global level.
In a replication environment, usually, slaves do not log replicated slow queries, because such queries can be found in the master's slow query log. Normally, a slow query is logged only if it was directly sent to the slave. However, this behavior can be changed by setting the log_slow_slave_statements
variable to 1
. This variable is dynamic, but only exists at the global level. If the workload on the master is heavy and the workload on the slaves is light, using the slow query log on a slave instead of the master could be an optimization. Of course, it will still be necessary to explicitly enable the slow query on a slave and disable it on the master.
To produce a less verbose slow query logfile, the --log-short-format
startup option can be used. In the configuration files, it can be specified as log-short-format
. This option also affects the binary log.
The counterpart of the --log-short-format
startup option is log_slow_verbosity
, which can be used to add information to the slow query logfile. It is a comma-separated list of values, where each value adds some information. The allowed values are described as follows:
microtime
: This value means that the variable uses microtime precisionquery_plan
: This value means that the variable logs information about the query execution planinnodb
: This value means that the variable logs the InnoDB statisticsprofiling
: This value means that the variable enables query profilingprofiling_use_getrusage
: This value means that the variable logs the results of the getrusage
functionexplain
: This value means that the variable prints the output of the EXPLAIN
statement (discussed in the next section)To enable profiling
and profiling_use_getrusage
, it is necessary to use XtraDB. The default value is 'query_plan'
. Both log_short_format
and log_slow_verbosity
affect the file-based slow query log but not the table.
To summarize, the following variables determine the queries that should be written in the slow query log:
log_queries_not_using_indexes
log_throttle_queries_not_using_indexes
long_query_time
log_slow_filter
The following variables can filter out the variables that match the previous criteria:
min_examined_row_limit
log_slow_admin_statements
The following variables determine what information is logged (and the overhead caused by the slow query log):
log-short-format
log_slow_verbosity
Queries that examine tables with no rows or a single row are always excluded from the slow query log.
When the server starts, lines similar to the following command are written into the slow query log:
/usr/local/mysql/bin/mysqld, Version: 10.0.7-MariaDB-log (MariaDB Server). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument.
Now, let's see an entry made into a slow query log. The following example shows how a query is written in the slow query log, with a default configuration:
# Time: 140116 11:19:05 # User@Host: root[root] @ localhost [] # Thread_id: 4 Schema: test QC_hit: No # Query_time: 0.059419 Lock_time: 0.000340 Rows_sent: 1 Rows_examined: 66620 SET timestamp=1389867545; SELECT COUNT(*) FROM t WHERE a > b;
The commented lines provide general information about the cost of the query, discussed as follows:
Time
: This is the date and time the query execution was started. It follows the same format used by the logs, as we have already discussed, with a human-readable time.User@Host
: This is the account that executed the query.Thread_id
: This is the ID of the connection, and is the same value that is displayed in the information_schema
and performance_schema
tables, or returned by the CONNECTION_ID()
function. On the same line, we also see Schema
, which is the default database that was selected (as a result of the USE
statement). It is written even if the default database is not used by the query.QC_hit
: This informs us if the query is found in the query cache.The last commented line is the most important. The Query_time
value is the execution time in seconds. If the slow query log is written to a file, the Query_time
value is a floating point number with a microsecond precision. If the log is written to a table, this value is an integer. The Lock_time
value is the amount of time that the query had to wait before relevant locks were released by other sessions. If a statement takes a lot of time because of long-running queries executed in concurrent sessions, we probably will not need to optimize it. The Rows_sent
value is the quantity of data sent by the server to the client, that is, the number of rows in the result set. The Rows_examined
value is the number of lines read by the query. The server must examine the number of rows before deciding if they must be included in the result set or used to join tables. If the used indexes are not selective enough, or no indexes are used, this value is higher than necessary. This is usually the most expensive part of the query cost.
Then, we find the statements to be executed to repeat the procedure. First, we can find a SET timestamp
statement, which is sometimes necessary (for example, if functions such as CURRENT_TIMESTAMP()
are used in a WHERE
clause). A USE
statement can only be found for the first slow query issued by the connection. Of course, despite these lines, it may be impossible to repeat the procedure with a copy and paste operation; for example, if a query involves temporary tables or user-defined variables, or it may be nondeterministic. Finally, we find the slow query, as it was received from the client.
If the log-short-format
startup option is active, a much shorter format is used by the slow query log, shown as follows:
# Thread_id: 5 Schema: test QC_hit: No # Query_time: 0.230296 Lock_time: 0.000302 Rows_sent: 1 Rows_examined: 263337 SET timestamp=1389869887; SELECT COUNT(*) FROM t WHERE a > b;
These lines are a subset of the former example; thus, they do not need any further explanation.
Depending on the log_slow_verbosity
variable, more information can be added to the slow query log. The output of EXPLAIN
is the most useful information we may need to find out the reason why a query is slow, but we usually prefer to execute this statement manually.
The slow_log
table contains information that is very similar, but not identical, to the information contained in a default slow query logfile. This table contains the following columns:
start_time
column matches the Time
columnuser_host
column matches the User@Host
columnquery_time
column matches the Query_time
columnlock_time
column matches the Lock_time
columnrows_sent
column matches the Rows_sent
columnrows_examined
column matches the Rows_examined
columndb
column matches the Schema
columnlast_insert_id
and insert_id
, columns that contain information about the AUTO_INCREMENT
columns in the futureserver_id
column gives the server's server_id
variable, which is always set in a replication environmentsql_text
column, which is the original querythread_id
column matches the Thread_id
column