Version Specific Information¶

• 5.5.8-20.0: Added values profiling and profiling_use_getrusage to variable log_slow_verbosity.

• 5.5.10-20.1:

• 5.5.34-32.0:
  • New slow_query_log_always_write_time variable introduced.
• 5.5.41-37.0:
  • Implemented improved slow log reporting for queries in stored procedures.
• 5.5.44-37.3:
  • log_slow_sp_statements now supports skipping the logging of stored procedures into the slow log entirely with new OFF_NO_CALLS option.

Other Information¶

• Author / Origin: Maciej Dobrzanski, Percona

System Variables¶

When this variable is enabled, administrative statements will be logged to the slow query log. Upstream version of the MySQL server has implemented command line option with same name. Significant difference is that this feature is implemented as variable in Percona Server, that means it can be enabled/disabled dynamically without restarting the server.

Filters the slow log by the query’s execution plan. The value is a comma-delimited string, and can contain any combination of the following values:

• qc_miss: The query was not found in the query cache.
• full_scan: The query performed a full table scan.
• full_join: The query performed a full join (a join without indexes).
• tmp_table: The query created an implicit internal temporary table.
• tmp_table_on_disk: The query’s temporary table was stored on disk.
• filesort: The query used a filesort.
• filesort_on_disk: The filesort was performed on disk.

Values are OR’ed together. If the string is empty, then the filter is disabled. If it is not empty, then queries will only be logged to the slow log if their execution plan matches one of the types of plans present in the filter.

For example, to log only queries that perform a full table scan, set the value to full_scan. To log only queries that use on-disk temporary storage for intermediate results, set the value to tmp_table_on_disk,filesort_on_disk.

Specifies semantic of log_slow_rate_limit - session or query.

Behavior of this variable depends from log_slow_rate_type.

Specifies that only a fraction of session/query should be logged. Logging is enabled for every nth session/query. By default, n is 1, so logging is enabled for every session/query. Please note: when log_slow_rate_type is session rate limiting is disabled for the replication thread.

• When log_slow_rate_type is session, this option lets you log full sessions, so you have complete records of sessions for later analysis; but you can rate-limit the number of sessions that are logged. Note that this feature will not work well if your application uses any type of connection pooling or persistent connections. Note that if you change log_slow_rate_limit to session mode, you should reconnect for the setting to take effect.
• When log_slow_rate_type is query, this option lets you log just some queries for later analysis. For example, if you set the value to 100, then one percent of queries will be logged.

Note that every query has global unique query_id and every connection can has it own (session) log_slow_rate_limit.

Decision “log or no” calculated in following manner:

• if log_slow_rate_limit is 1 - log every query
• If log_slow_rate_limit > 1 - randomly log every 1/log_slow_rate_limit query.

This allows flexible setup logging behavior.

For example, if you set the value to 100, then one percent of sessions/queries will be logged. In Percona Server 5.5.34-32.0 information about the log_slow_rate_limit has been added to the slow query log. This means that if the log_slow_rate_limit is effective it will be reflected in the slow query log for each written query. Example of the output looks like this:

Log_slow_rate_type: query  Log_slow_rate_limit: 10

Prior to 5.5.37-35.0 implementation of the log_slow_rate_type set to query with log_slow_rate_limit feature would log every nth query deterministically. With the current implementation each query has a non-deterministic probability of 1/n to get logged.”

Specifies that slow queries replayed by the slave SQL thread on a MySQL slave will be logged. Upstream version of the MySQL server has implemented command line option with same name. Significant difference is that this feature is implemented as variable in Percona Server, that means it can be enabled/disabled dynamically without restarting the server.

To start the logging from the slave thread, you should change the global value: set global log_slow_slave_statements =ON; and then execute: STOP SLAVE; START SLAVE;. This will destroy and recreate the slave SQL thread, so it will see the newly set global value.

To stop the logging from the slave thread, you should just change the global value: set global log_slow_slave_statements =OFF; the logging stops immediately.

This variable controls the logging of stored procedures in the slow query log. The options are to log the CALL statements, to log the individual statements in the stored procedure, or to log neither. These options correspond to values OFF, ON, and OFF_NO_CALLS respectively.

• Each query from a stored procedure is now logged to the slow query log individually
• CALL itself isn’t logged to the slow query log anymore as this would be counting twice for the same query which would lead to incorrect results
• Queries that were called inside of stored procedures are annotated in the slow query log with the stored procedure name in which they run.

In 5.5.44-37.3 new OFF_NO_CALLS option has been implemented that can be used for skipping the logging of stored procedures into the slow log entirely.

Example of the improved stored procedure slow query log entry:

mysql> DELIMITER //
mysql> CREATE PROCEDURE improved_sp_log()
       BEGIN
        SELECT * FROM City;
        SELECT * FROM Country;
       END//
mysql> DELIMITER ;
mysql> CALL improved_sp_log();

When we check the slow query log after running the stored procedure ,with variable:log_slow_sp_statements set to TRUE, it should look like this:

# Time: 150109 11:38:55
# User@Host: root[root] @ localhost []
# Thread_id: 40  Schema: world  Last_errno: 0  Killed: 0
# Query_time: 0.012989  Lock_time: 0.000033  Rows_sent: 4079  Rows_examined: 4079  Rows_affected: 0  Rows_read: 4079
# Bytes_sent: 161085
# Stored routine: world.improved_sp_log
SET timestamp=1420803535;
SELECT * FROM City;
# User@Host: root[root] @ localhost []
# Thread_id: 40  Schema: world  Last_errno: 0  Killed: 0
# Query_time: 0.001413  Lock_time: 0.000017  Rows_sent: 4318  Rows_examined: 4318  Rows_affected: 0  Rows_read: 4318
# Bytes_sent: 194601
# Stored routine: world.improved_sp_log
SET timestamp=1420803535;
SELECT * FROM Country;

If variable log_slow_sp_statements is set to FALSE:

• Entry is added to a slow-log for a CALL statement only and not for any of the individual statements run in that stored procedure
• Execution time is reported for the CALL statement as the total execution time of the CALL including all its statements

If we run the same stored procedure with the variable log_slow_sp_statements is set to FALSE slow query log should look like this:

# Time: 150109 11:51:42
# User@Host: root[root] @ localhost []
# Thread_id: 40  Schema: world  Last_errno: 0  Killed: 0
# Query_time: 0.013947  Lock_time: 0.000000  Rows_sent: 4318  Rows_examined: 4318  Rows_affected: 0  Rows_read: 4318
# Bytes_sent: 194612
SET timestamp=1420804302;
CALL improved_sp_log();

Specifies how much information to include in your slow log. The value is a comma-delimited string, and can contain any combination of the following values:

• microtime: Log queries with microsecond precision.
• query_plan: Log information about the query’s execution plan.
• innodb: Log InnoDB statistics.
• minimal: Equivalent to enabling just microtime.
• standard: Equivalent to enabling microtime,innodb.
• full: Equivalent to all other values OR’ed together without the profiling and profiling_use_getrusage options.
• profiling: Enables profiling of all queries in all connections.
• profiling_use_getrusage: Enables usage of the getrusage function.

Values are OR’ed together.

For example, to enable microsecond query timing and InnoDB statistics, set this option to microtime,innodb or standard. To turn all options on, set the option to full.

If TRUE, a timestamp is printed on every slow log record. Multiple records may have the same time.

Normally, entries to the slow query log are in seconds precision, in this format:

# Time: 090402 9:23:36 # User@Host: XXX @ XXX [10.X.X.X]

If slow_query_log_timestamp_precision =microsecond, entries to the slow query log are in microsecond precision, in this format:

# Time: 090402 9:23:36.123456 # User@Host: XXX @ XXX [10.X.X.X]

Specifies which variables have global scope instead of local. For such variables, the global variable value is used in the current session, but without copying this value to the session value. Value is a “flag” variable - you can specify multiple values separated by commas:

• none: All variables use local scope
• log_slow_filter: Global variable log_slow_filter has effect (instead of local)
• log_slow_rate_limit: Global variable log_slow_rate_limit has effect (instead of local)
• log_slow_verbosity: Global variable log_slow_verbosity has effect (instead of local)
• long_query_time: Global variable long_query_time has effect (instead of local)
• min_examined_row_limit: Global variable min_examined_row_limit has effect (instead of local)
• all Global variables has effect (instead of local)

NOTE: This variable has been renamed from log_slow_timestamp_every since 5.5.10-20.1.

This variable can be used to specify the query execution time after which the query will be written to the slow query log. It can be used to specify an additional execution time threshold for the slow query log, that, when exceeded, will cause a query to be logged unconditionally, that is, log_slow_rate_limit will not apply to it.

Other Information¶

# User@Host: mailboxer[mailboxer] @  [192.168.10.165]
# Thread_id: 11167745  Schema: board
# Query_time: 1.009400  Lock_time: 0.000190  Rows_sent: 4  Rows_examined: 1543719  Rows_affected: 0  Rows_read: 4
# Bytes_sent: 278  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# InnoDB_trx_id: 1500
# QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 6415  InnoDB_IO_r_bytes: 105103360  InnoDB_IO_r_wait: 0.001279
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 6430
SET timestamp=1346844943;
SELECT id,title,production_year FROM title WHERE title = 'Bambi';

# Query_time: 0.962742  Lock_time: 0.000202  Rows_sent: 4  Rows_examined: 1543719  Rows_affected: 0  Rows_read: 4
# Bytes_sent: 278  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# Profile_starting: 0.000030 Profile_starting_cpu: 0.000028 Profile_Waiting_for_query_cache_lock: 0.000003
  Profile_Waiting_for_query_cache_lock_cpu: 0.000003 Profile_Waiting_on_query_cache_mutex: 0.000003
  Profile_Waiting_on_query_cache_mutex_cpu: 0.000003 Profile_checking_query_cache_for_query: 0.000076
  Profile_checking_query_cache_for_query_cpu: 0.000076 Profile_checking_permissions: 0.000011
  Profile_checking_permissions_cpu: 0.000011 Profile_Opening_tables: 0.000078 Profile_Opening_tables_cpu: 0.000078
  Profile_System_lock: 0.000022 Profile_System_lock_cpu: 0.000022 Profile_Waiting_for_query_cache_lock: 0.000003
  Profile_Waiting_for_query_cache_lock_cpu: 0.000002 Profile_Waiting_on_query_cache_mutex: 0.000054
  Profile_Waiting_on_query_cache_mutex_cpu: 0.000054 Profile_init: 0.000039 Profile_init_cpu: 0.000040
  Profile_optimizing: 0.000015 Profile_optimizing_cpu: 0.000014 Profile_statistics: 0.000021 Profile_statistics_cpu: 0.000021
  Profile_preparing: 0.000020 Profile_preparing_cpu: 0.000020 Profile_executing: 0.000003 Profile_executing_cpu: 0.000003
  Profile_Sending_data: 0.962324 Profile_Sending_data_cpu: 0.961526 Profile_end: 0.000006 Profile_end_cpu: 0.000005
  Profile_query_end: 0.000004 Profile_query_end_cpu: 0.000004 Profile_closing_tables: 0.000008 Profile_closing_tables_cpu: 0.000008
  Profile_freeing_items: 0.000007 Profile_freeing_items_cpu: 0.000007 Profile_Waiting_for_query_cache_lock: 0.000000
  Profile_Waiting_for_query_cache_lock_cpu: 0.000001 Profile_Waiting_on_query_cache_mutex: 0.000001
  Profile_Waiting_on_query_cache_mutex_cpu: 0.000001 Profile_freeing_items: 0.000017 Profile_freeing_items_cpu: 0.000016
  Profile_Waiting_for_query_cache_lock: 0.000001 Profile_Waiting_for_query_cache_lock_cpu: 0.000001
  Profile_Waiting_on_query_cache_mutex: 0.000000 Profile_Waiting_on_query_cache_mutex_cpu: 0.000001
  Profile_freeing_items: 0.000001 Profile_freeing_items_cpu: 0.000001 Profile_storing_result_in_query_cache: 0.000002
  Profile_storing_result_in_query_cache_cpu: 0.000002 Profile_logging_slow_query: 0.000001 Profile_logging_slow_query_cpu: 0.000001
# Profile_total: 0.962751 Profile_total_cpu: 0.961950
# InnoDB_trx_id: 1700

# Thread_id: 11167745  Schema: board

# Query_time: 0.962742  Lock_time: 0.000202  Rows_sent: 4  Rows_examined: 1543719  Rows_affected: 0  Rows_read: 4

# Bytes_sent: 8053  Tmp_tables: 1  Tmp_disk_tables: 0  Tmp_table_sizes: 950528

# QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0

#   InnoDB_IO_r_ops: 6415  InnoDB_IO_r_bytes: 105103360  InnoDB_IO_r_wait: 0.001279
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 6430