Troubleshooting MySQL Performance Issues Using the Slow Log and Performance Schema

Don’t you just love getting that email with the subject: “The application is slow! Please check the database!”?  You’re then expected to very quickly figure out what’s behind the slowdown – usually with zero context information – and, if it is a database issue, get it running at full throttle again ASAP.

If the users only knew what checking the database entails in this situation.  With so many causes and solutions to go through, you might expect to be spending the night at work, instead of in your warm bed.  (Sadly, I’ve seen it happen.)

In order to avoid that cursed fate, read on to learn two ways to get at the root cause of slow MySQL performance using a couple of built-in MySQL features: the Slow Log and Performance Schema.

The MySQL Slow Query Log

It’s been my experience that, under normal utilization, the most common cause of database slowdowns are out of control queries that hog all of the system resources while trying to retrieve every transaction – i.e. purchase, case, etc. – for the past five years.

You can home in on these queries using the slow query log.  It consists of SQL statements that took more than the number of seconds in the long_query_time system variable to execute and required at least the number of rows set in the min_examined_row_limit variable to be examined.

You can check if the MySQL slow query log is enabled using the following statement:

SHOW VARIABLES Like 'slow_query_log%';

Variable_name        Value
 --------------------------
 slow_query_log       OFF
 slow_query_log_file  C:Program FilesMySQLMySQL Server 5.6dataLH12CU19884-slow.log

If you don’t currently have the Slow Query Log enabled, I would suggest that you do so before the next crisis strikes.  Here’s how:

  1. Shut down any applications that are using MySQL.
  2. Shut down MySQL itself.
  3. Add the following configuration options to my.ini or my.cnf (see the “Where is the MySQL Configuration file located?” section for more information):
		# What's the threshold for a slow query to be logged?
		long_query_time=0.5


		# Where should the queries be logged to?
		slow_query_log_file=/path/to/logfile


		# Enable slow query logging - note the dashes rather than underscores:
		slow-query-log=1
  1. Save the file, and restart MySQL.
  2. Restart your connected applications.

Where is the MySQL Configuration File Located?

The location of the MySQL configuration file (either my.ini or my.cnf) depends on your OS.

MySQL will look at each location in order, and use the first file that it finds.  Often, if the file does not exist, it must be created first.

Linux based MySQL systems will use configuration files in the following order of precedence:

  • etc/my.cnf
  • etc/mysql/my.cnf
  • SYSCONFDIR/my.cnf
  • $MYSQL_HOME/my.cnf

SYSCONFDIR refers to the directory specified when MySQL was built; and typically reverse to the etc directory located under the compiled-in installation directory.

MYSQL_HOME is an environment variable referring to the path where my.cnf can be found.

Windows based MySQL systems will use the configuration files in the following order of precedence

  • %PROGRAMDATA%MySQL<MySQL ServerVersion>my.ini
  • %PROGRAMDATA%MySQL<MySQL ServerVersion>my.cnf
  • %WINDIR%my.ini
  • %WINDIR%my.cnf
  • C:my.ini
  • C:my.cnf
  • INSTALLDIRmy.ini
  • INSTALLDIRmy.cnf

Viewing the Slow Query Log

MySQL provides a tool called mysqldumpslow, which can be used to analyze the log file.

The following syntax will show you the top 10 queries sorted by average query time (Remember to update the file names and paths to suit your environment):

mysqldumpslow -t 10 mysql-slow-query.log > mysqldumpslow.out

Here is some sample output:

Reading mysql slow query log from /usr/local/mysql/data/mysqld51-apple-slow.log
Count: 90  Time=56.73s 6183s) Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
 select * from t1

The important values to look at here are the Count and the Time. The Count is the number of times this query ran within your log set. The Time is an average amount of time for each of those queries runs to complete. With the number in parentheses, in this case 6183s, being the total (Count x Time) amount of time spent on running this query.

The Performance Schema

It provides details about query execution in a structured way, accessible through SQL.  PERFORMANCE_SCHEMA is a storage Engine that is only used for special tables in the performance_schema database.  It contains 52 tables and no views.  These are a mix of configuration and data tables.  In fact, these can be further broken down into:

  • Configuration Tables
  • Object Tables
  • Current Tables
  • History Tables
  • Summary Tables
  • Other Tables

The PERFORMANCE_SCHEMA can be utilized to troubleshoot:

  • Internal server’s bottlenecks, caused by locks, mutexes, IO
  • Less optimal statements
  • Most expensive operations
  • Connection issues
  • Memory usage
  • Replication failures
  • More…

Here are a few examples:

———————

  1. Determine which queries do not use indexes:
		 SELECT THREAD_ID AS TID, 
		        SUBSTR(SQL_TEXT, 1, 50) AS SQL_TEXT, 
		        ROWS_SENT AS RS, 
		        ROWS_EXAMINED AS RE, 
		        CREATED_TMP_TABLES, 
		        NO_INDEX_USED,
		        NO_GOOD_INDEX_USED 
		 FROM performance_schema.events_statements_history 
		 WHERE NO_INDEX_USED=1 OR NO_GOOD_INDEX_USED=1G
		  ********************** 1. row ********************** 
		 TID: 10124 
		 SQL_TEXT: select emp_no, first_name, last_name from employee 
		 RS: 97750 
		 RE: 397774 
		 CREATED_TMP_TABLES: 0 
		 NO_INDEX_USED: 1 
		 NO_GOOD_INDEX_USED: 0
  1. Index usage with sys schema:
		SELECT query, 
		        total_latency,
		        no_index_used_count, 
		        rows_sent,
		        rows_examined 
		 FROM sys.statements_with_full_table_scans
		 WHERE db=’employees’ 
		 AND   query NOT LIKE ’%performance_schema%’G 


	
		********************** 1. row ********************** 
		 query: SELECT COUNT ( ‘emp_no‘ ) FROM ... ‘emp_no‘ ) WHERE ‘title‘ = ? 
		 total_latency: 805.37 ms 
		 no_index_used_count: 1 
		 rows_sent: 1 
		 rows_examined: 397774
  1. Memory Usage:
    1. How much RAM does a server have? Available since version 5.7, the sys tables provide detailed information about memory usage of each server’s allocated internal memory:
	SELECT * FROM sys.memory_global_total; 
	
	+-----------------+ 
	 | total_allocated | 
	 +-----------------+ 
	 | 458.44 MiB      | 
	 +-----------------+
    1. Memory allocated by thread:
		SELECT thread_id, 
		        user, 
		        current_avg_alloc, 
		        current_allocated
		 FROM sys.memory_by_thread_by_current_bytes
		 WHERE thread_id IN (145, 146)G 
		
		********************** 1. row ********************** 
		 thread_id: 145 
		 user: sql/slave_io 
		 current_allocated: 1.04 GiB 
		 current_avg_alloc: 2.64 KiB 
		
		
		 ********************** 2. row ********************** 
		 thread_id: 146 
		 user: sql/slave_sql 
		 current_allocated: 1.79 MiB 
		 current_avg_alloc: 72 bytes 
		
		2 rows in set (0.11 sec)
  1. As described in my Performance Schema overview article, here’s a great way to find a long-running query that is monopolizing resources:
		SELECT PROCESSLIST_ID AS id, 
		        PROCESSLIST_USER AS user, 
		        PROCESSLIST_HOST AS host, 
		        PROCESSLIST_DB AS db, 
		        PROCESSLIST_COMMAND AS command, 
		        PROCESSLIST_TIME AS time, 
		        PROCESSLIST_STATE AS state, 
		        LEFT(PROCESSLIST_INFO, 80) AS info
		 FROM performance_schema.threads
		 WHERE PROCESSLIST_ID IS NOT NULL
		 AND PROCESSLIST_COMMAND NOT IN ('Sleep', 'Binlog Dump')
		 ORDER BY PROCESSLIST_TIME ASC;
		 
		 +----+------+-----------+------+---------+------+---------------------+----------------------+
		 | id | user | host      | db   | command | time | state               | info                 |
		 +----+------+-----------+------+---------+------+---------------------+----------------------+
		 | 2  | root | localhost | test | Query   | 5944 | Creating sort index | SELECT PROCESSLIST...|
		 +----+------+-----------+------+---------+------+---------------------+----------------------+

Conclusion

During those inevitable slowdowns that plague all relational databases, you’ll be thankful to be managing MySQL.  Its Slow Log and Performance Schema are both indispensable in determining the cause of many database-related issues, including poor performance.

See all articles by Rob Gravelle

Robert Gravelle
Robert Gravelle
Rob Gravelle resides in Ottawa, Canada, and has been an IT guru for over 20 years. In that time, Rob has built systems for intelligence-related organizations such as Canada Border Services and various commercial businesses. In his spare time, Rob has become an accomplished music artist with several CDs and digital releases to his credit.

Get the Free Newsletter!

Subscribe to Cloud Insider for top news, trends & analysis

Latest Articles