Skip to content
logo
Percona Server for MySQL
Slow query log
Initializing search
    percona/psmysql-docs
    percona/psmysql-docs
    • Home
      • The Percona XtraDB storage engine
      • List of features available in Percona Server for MySQL releases
      • Percona Server for MySQL feature comparison
      • Changed in Percona Server 8.0
      • Understand version numbers
      • Install Percona Server for MySQL
        • Install using APT repository
        • Files in DEB package
        • Build APT packages
        • Install from downloaded DEB packages
        • Apt pinning
        • Run Percona Server for MySQL
        • Uninstall
        • Install using a RPM repository
        • Files in RPM package
        • Install from downloaded RPM packages
        • Run Percona Server for MySQL
        • Uninstall
        • Install with binary tarballs
        • Binary tarballs available
        • Install Percona Server for MySQL from a source tarball
        • Compile Percona Server for MySQL 8.0 from source
      • Post-installation
      • Percona Server for MySQL in-place upgrading guide: from 5.7 to 8.0
      • Upgrade using the Percona repositories
      • Upgrade from systems that use the MyRocks or TokuDB storage engine and partitioned tables
      • Upgrade using Standalone Packages
      • Downgrade Percona Server for MySQL
      • Running Percona Server for MySQL in a Docker Container
      • Docker environment variables
      • Improved InnoDB I/O scalability
      • Adaptive network buffers
      • Multiple page asynchronous I/O requests
      • Thread pool
      • XtraDB performance improvements for I/O-bound highly-concurrent workloads
      • Prefix index queries optimization
      • Limit the estimation of records in a Query
      • Jemalloc memory allocation profiling
      • The ProcFS plugin
      • Binary logs and replication improvements
      • Compressed columns with dictionaries
      • Extended SELECT INTO OUTFILE/DUMPFILE
      • Extended SET VAR optimizer hint
      • Improved MEMORY storage engine
      • Suppress warning messages
      • Limiting the disk space used by binary log files
      • Support for PROXY protocol
      • SEQUENCE_TABLE(n) function
      • Slow query log rotation and expiration
      • Trigger updates
      • Extended mysqlbinlog
      • Extended mysqldump
      • InnoDB full-text search improvements
      • Too many connections warning
      • Handle corrupted tables
      • Percona Toolkit UDFs
      • Kill idle transactions
      • XtraDB changed page tracking
      • Enforcing storage engine
      • Expanded fast index creation
      • Backup locks
      • Audit log plugin
      • Start transaction with consistent snapshot
      • Extended SHOW GRANTS
      • Utility user
      • Working with SELinux
      • Working with AppArmor
      • PAM authentication plugin
      • Server variables
      • SSL improvements
      • Data masking
        • Using LDAP authentication plugins
        • LDAP authentication plugin system variables
        • Data at Rest Encryption
        • Use the keyring component or keyring plugin
          • Using the Key Management Interoperability Protocol (KMIP)
          • Use the Amazon Key Management Service (AWS KMS)
          • FIDO authentication plugin
        • Encryption functions
        • Encrypt File-Per-Table Tablespace
        • Encrypt schema or general tablespace
        • Encrypt system tablespace
        • Encrypt temporary files
        • Encrypt Binary Log Files and Relay Log Files
        • Encrypting the Redo Log data
        • Encrypt the undo tablespace
        • Rotate the master key
        • Advanced encryption key rotation
        • Encrypt doublewrite buffers
        • Verify the encryption for tables, tablespaces, and schemas
      • User statistics
      • Slow query log
        • Version specific information
        • System Variables
          • log_slow_filter
          • log_slow_rate_type
          • log_slow_rate_limit
          • log_slow_sp_statements
          • log_slow_verbosity
          • slow_query_log_use_global_control
          • slow_query_log_always_write_time
        • Other information
          • Changes to the log format
          • Connection and Schema Identifier
          • Microsecond time resolution and extra row information
          • Memory footprint
          • Query plan information
          • InnoDB usage information
        • Related reading
      • Extended show engine InnoDB status
      • Show storage engines
      • Process list
      • Misc. INFORMATION_SCHEMA tables
      • Thread based profiling
      • InnoDB page fragmentation counters
      • Stacktrace
      • Libcoredumper
      • Manage group replication flow control
      • Group replication system variables
      • Percona MyRocks introduction
      • Percona MyRocks installation guide
      • Updated supported features
      • MyRocks limitations
      • Differences between Percona MyRocks and Facebook MyRocks
      • MyRocks Information Schema tables
      • MyRocks server variables
      • MyRocks status variables
      • Gap locks detection
      • Data loading
      • Installing and configuring Percona Server for MySQL with ZenFS support
      • TokuDB introduction
      • TokuDB installation
      • Use TokuDB
      • Fast updates with TokuDB
      • TokuDB files and file types
      • TokuDB file management
      • TokuDB background ANALYZE TABLE
      • TokuDB variables
      • TokuDB status variables
      • TokuDB fractal tree indexing
      • TokuDB troubleshooting
      • TokuDB Performance Schema integration
      • Frequently asked questions
      • Migrate and removing the TokuDB storage engine
      • Percona TokuBackup
      • Release notes index
      • Percona Server for MySQL 8.0.32-24 (2023-03-20)
      • Percona Server for MySQL 8.0.31-23 (2023-02-09)
      • Percona Server for MySQL 8.0.30-22 Update (2022-11-21)
      • Percona Server for MySQL 8.0.30-22 (2022-11-21)
      • Percona Server for MySQL 8.0.29-21 (2022-08-08)
      • Percona Server for MySQL 8.0.28-20 (2022-06-20)
      • Percona Server for MySQL 8.0.28-19 (2022-05-12)
      • Percona Server for MySQL 8.0.27-18 (2022-03-02)
      • Percona Server for MySQL 8.0.26-17 (2022-01-26)
      • Percona Server for MySQL 8.0.26-16 (2021-10-20)
      • Percona Server for MySQL 8.0.25-15 (2021-07-13)
      • Percona Server for MySQL 8.0.23-14 (2021-05-12)
      • Percona Server for MySQL 8.0.22-13 (2020-12-14)
      • Percona Server for MySQL 8.0.21-12 (2020-10-13)
      • Percona Server for MySQL 8.0.20-11 (2020-07-21)
      • Percona Server for MySQL 8.0.19-10 (2020-03-23)
      • Percona Server for MySQL 8.0.18-9
      • Percona Server for MySQL 8.0.17-8
      • Percona Server for MySQL 8.0.16-7
      • Percona Server for MySQL 8.0.15-6
      • Percona Server for MySQL 8.0.15-5
      • Percona Server for MySQL 8.0.14
      • Percona Server for MySQL 8.0.13-4
      • Percona Server for MySQL 8.0.13-3
      • Percona Server for MySQL 8.0.12-2rc1
      • List of variables introduced in Percona Server for MySQL 8.0
      • Development of Percona Server for MySQL
      • Trademark policy
      • Index of INFORMATION_SCHEMA tables
      • Frequently asked questions
      • Copyright and licensing information
      • Glossary

    • Version specific information
    • System Variables
      • log_slow_filter
      • log_slow_rate_type
      • log_slow_rate_limit
      • log_slow_sp_statements
      • log_slow_verbosity
      • slow_query_log_use_global_control
      • slow_query_log_always_write_time
    • Other information
      • Changes to the log format
      • Connection and Schema Identifier
      • Microsecond time resolution and extra row information
      • Memory footprint
      • Query plan information
      • InnoDB usage information
    • Related reading

    Slow query log¶

    This feature adds microsecond time resolution and additional statistics to the slow query log output. It lets you enable or disable the slow query log at runtime, adds logging for the replica SQL thread, and adds fine-grained control over what and how much to log into the slow query log.

    You can use Percona-Toolkit’s pt-query-digest tool to aggregate similar queries together and report on those that consume the most execution time.

    Version specific information¶

    • 8.0.12-1: The feature was ported from Percona Server for MySQL 5.7.

    System Variables¶

    log_slow_filter¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global, Session
    Dynamic Yes

    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:

    • 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.

    log_slow_rate_type¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global
    Dynamic yes
    Data type Enumerated
    Default session, query

    Specifies semantic of log_slow_rate_limit - session or query.

    log_slow_rate_limit¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global, session
    Dynamic yes
    Default 1
    Range 1-1000

    Behavior of this variable depends on the selected 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.

    Logging all queries might consume I/O bandwidth and cause the log file to grow large.

    * 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 you change log_slow_rate_limit in `session` mode, you should reconnect for get 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 for MySQL 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.

    Expected output
    Log_slow_rate_type: query  Log_slow_rate_limit: 10
    

    log_slow_sp_statements¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global
    Dynamic Yes
    Data type Enumerated
    Default session
    Range session, query

    If TRUE, statements executed by stored procedures are logged to the slow if it is open.

    Percona Server for MySQL implemented improvements for logging of stored procedures to the slow query log:

    * 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.
    

    Example of the improved stored procedure slow query log entry:

    mysqlDELIMITER //
    mysqlCREATE PROCEDURE improved_sp_log()
           BEGIN
            SELECT * FROM City;
            SELECT * FROM Country;
           END//
    mysqlDELIMITER ;
    mysqlCALL improved_sp_log();
    

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

    Expected output
    # 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;
    

    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 log_slow_sp_statements is set to FALSE slow query log should look like this:

    Expected output
    # 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();
    

    Note

    Support for logging stored procedures doesn’t involve triggers, so they won’t be logged even if this feature is enabled.

    log_slow_verbosity¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global, session
    Dynamic Yes

    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,query_plan.

    • 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.

    • query_info: Enables printing Query_tables and Query_digest into the slow query log. These fields are disabled by default.

    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.

    slow_query_log_use_global_control¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global
    Dynamic Yes
    Default None

    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)

    slow_query_log_always_write_time¶

    Option Description
    Command-line Yes
    Config file Yes
    Scope Global
    Dynamic Yes
    Default 10

    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¶

    Changes to the log format¶

    The feature adds more information to the slow log output.

    Expected output
    # Time: 130601  8:01:06.058915
    # User@Host: root[root] @ localhost []  Id:    42
    # Schema: imdb  Last_errno: 0  Killed: 0
    # Query_time: 7.725616  Lock_time: 0.000328  Rows_sent: 4  Rows_examined: 1543720  Rows_affected: 0
    # Bytes_sent: 272  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
    # Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
    # Filesort: No  Filesort_on_disk: No  Merge_passes: 0
    SET timestamp=1370073666;
    SELECT id,title,production_year FROM title WHERE title = 'Bambi';
    

    Another example (log_slow_verbosity =profiling):

    Expected output
    # Time: 130601  8:03:20.700441
    # User@Host: root[root] @ localhost []  Id:    43
    # Schema: imdb  Last_errno: 0  Killed: 0
    # Query_time: 7.815071  Lock_time: 0.000261  Rows_sent: 4  Rows_examined: 1543720  Rows_affected: 0
    # Bytes_sent: 272
    # Profile_starting: 0.000125 Profile_starting_cpu: 0.000120
    Profile_checking_permissions: 0.000021 Profile_checking_permissions_cpu: 0.000021
    Profile_Opening_tables: 0.000049 Profile_Opening_tables_cpu: 0.000048 Profile_init: 0.000048
    Profile_init_cpu: 0.000049 Profile_System_lock: 0.000049 Profile_System_lock_cpu: 0.000048
    Profile_optimizing: 0.000024 Profile_optimizing_cpu: 0.000024 Profile_statistics: 0.000036 
    Profile_statistics_cpu: 0.000037 Profile_preparing: 0.000029 Profile_preparing_cpu: 0.000029
    Profile_executing: 0.000012 Profile_executing_cpu: 0.000012 Profile_Sending_data: 7.814583
    Profile_Sending_data_cpu: 7.811634 Profile_end: 0.000013 Profile_end_cpu: 0.000012
    Profile_query_end: 0.000014 Profile_query_end_cpu: 0.000014 Profile_closing_tables: 0.000023
    Profile_closing_tables_cpu: 0.000023 Profile_freeing_items: 0.000051
    Profile_freeing_items_cpu: 0.000050 Profile_logging_slow_query: 0.000006
    Profile_logging_slow_query_cpu: 0.000006
    # Profile_total: 7.815085 Profile_total_cpu: 7.812127
    SET timestamp=1370073800;
    SELECT id,title,production_year FROM title WHERE title = 'Bambi';
    

    Notice that the Killed: \` keyword is followed by zero when the query successfully completes. If the query was killed, the ``Killed:` keyword is followed by a number other than zero:

    Killed Numeric Code Exception
    0 NOT_KILLED
    1 KILL_BAD_DATA
    1053 ER_SERVER_SHUTDOWN (see MySQL Documentation)
    1317 ER_QUERY_INTERRUPTED (see MySQL Documentation)
    3024 ER_QUERY_TIMEOUT (see MySQL Documentation)
    Any other number KILLED_NO_VALUE (Catches all other cases)

    Connection and Schema Identifier¶

    Each slow log entry now contains a connection identifier, so you can trace all the queries coming from a single connection. This is the same value that is shown in the Id column in SHOW FULL PROCESSLIST or returned from the CONNECTION_ID() function.

    Each entry also contains a schema name, so you can trace all the queries whose default database was set to a particular schema.

    Expected output
    # Id: 43  Schema: imdb
    

    Microsecond time resolution and extra row information¶

    This is the original functionality offered by the microslow feature. Query_time and Lock_time are logged with microsecond resolution.

    The feature also adds information about how many rows were examined for SELECT queries, and how many were analyzed and affected for UPDATE, DELETE, and INSERT queries,

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

    Values and context:

    • Rows_examined: Number of rows scanned - SELECT

    • Rows_affected: Number of rows changed - UPDATE, DELETE, INSERT

    Memory footprint¶

    The feature provides information about the amount of bytes sent for the result of the query and the number of temporary tables created for its execution - differentiated by whether they were created on memory or on disk - with the total number of bytes used by them.

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

    Values and context:

    • Bytes_sent: The amount of bytes sent for the result of the query

    • Tmp_tables: Number of temporary tables created on memory for the query

    • Tmp_disk_tables: Number of temporary tables created on disk for the query

    • Tmp_table_sizes: Total Size in bytes for all temporary tables used in the query

    Query plan information¶

    Each query can be executed in various ways. For example, it may use indexes or do a full table scan, or a temporary table may be needed. These are the things that you can usually see by running EXPLAIN on the query. The feature will now allow you to see the most important facts about the execution in the log file.

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

    The values and their meanings are documented with the log_slow_filter option.

    InnoDB usage information¶

    The final part of the output is the InnoDB usage statistics. MySQL currently shows many per-session statistics for operations with SHOW SESSION STATUS, but that does not include those of InnoDB, which are always global and shared by all threads. This feature lets you see those values for a given query.

    Expected output
    #   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
    

    Values:

    • innodb_IO_r_ops: Counts the number of page read operations scheduled. The actual number of read operations may be different, but since this can be done asynchronously, there is no good way to measure it.

    • innodb_IO_r_bytes: Similar to innodb_IO_r_ops, but the unit is bytes.

    • innodb_IO_r_wait: Shows how long (in seconds) it took InnoDB to actually read the data from storage.

    • innodb_rec_lock_wait: Shows how long (in seconds) the query waited for row locks.

    • innodb_queue_wait: Shows how long (in seconds) the query spent either waiting to enter the InnoDB queue or inside that queue waiting for execution.

    • innodb_pages_distinct: Counts approximately the number of unique pages the query accessed. The approximation is based on a small hash array representing the entire buffer pool, because it could take a lot of memory to map all the pages. The inaccuracy grows with the number of pages accessed by a query, because there is a higher probability of hash collisions.

    If the query did not use InnoDB tables, that information is written into the log instead of the above statistics.

    Related reading¶

    • Impact of logging on MySQL’s performance

    • log_slow_filter Usage

    • Added microseconds to the slow query log event time

    Contact us

    For free technical help, visit the Percona Community Forum.

    To report bugs or submit feature requests, open a JIRA ticket.

    For paid support and managed or consulting services , contact Percona Sales.


    Last update: 2023-01-12
    Percona LLC and/or its affiliates, © 2023
    Made with Material for MkDocs

    Cookie consent

    We use cookies to recognize your repeated visits and preferences, as well as to measure the effectiveness of our documentation and whether users find what they're searching for. With your consent, you're helping us to make our documentation better.