New Book: MySQL 8 Query Performance Tuning

I have over the last few years been fortunate to have two books published through Apress, Pro MySQL NDB Cluster which I wrote together with Mikiya Okuno and MySQL Connector/Python Revealed. With the release of MySQL 8 around a year ago, I started to think of how many changes there has been in the last few MySQL versions. Since MySQL 5.6 was released as GA in early 2013, some of the major features related to performance tuning includes the Performance Schema which was greatly changed in 5.6, histograms, EXPLAIN ANALYZE, hash joins, and visual explain. Some of these are even unique in MySQL 8.

So, I was thinking that it could be interesting to write a book that focuses on performance tuning in MySQL 8. In order to try to limit the scope somewhat (which as you can see from the page count that I was not too successful with), I decided to mainly look at the topics related to query performance. I proposed this to my acquisition editor Jonathan Gennick, and he was very interested. Oracle whom I worked for at the time was also interested (thanks Adam Dixon, Victoria Reznichenko, Edwin DeSouza, and Rich Mason for supporting me and approving the project). Also thanks to the Apress editors and staff who has been involved including but not limited to Jonathan Gennick, Jill Balzano, Laura Berendson, and Arockia Rajan Dhurai.

Now around a year later, the final result is ready: MySQL 8 Query Performance Tuning. If you are interested, you can read more about the content and/or buy it at Apress, Amazon, and others book shops:

ShopPaper BookE-Book
ApressSoftcoverDRM free ePub/PDF
Amazon USSoftcoverMobi (Kindle)

Book Structure

The book is divided into six parts with a total of 27 chapters. I have attempted to keep each chapter relatively self-contained with the aim that you can use the book as a reference book. The drawback of this choice is that there is some duplication of information from time to time. An example is Chapter 18 which describes the more theoretical side of locks and how to monitor locks, and Chapter 22 which provides practical examples of investigating lock contention. Chapter 22 naturally draws on the information in Chapter 18, so some of the information is repeated. This was a deliberate choice, and I hope it helps you reduce the amount of page flipping to find the information you need.

The six parts progressively move you through the topics starting with some basic background and finishing with more solution-oriented tasks. The first part starts out discussing the methodology, benchmarks, and test data. The second part focuses on the sources of information such as the Performance Schema. The third part covers the tools such as MySQL Shell used in this book. The fourth part provides the theoretical background used in the last two parts. The fifth part focuses on analyzing queries, transactions, and locks. Finally, the sixth part discusses how to improve performance through the configuration, query optimization, replication, and caching. There are cases where some content is a little out of place, like all replication information is contained in a single chapter.

Chapters

Part I: Getting Started

Part I introduces you to the concepts of MySQL query performance tuning. This includes some high-level considerations, of which some are not unique to MySQL (but are of course discussed in the context of MySQL). The four chapters are

  • Chapter 1 – MySQL Performance Tuning
    This introductory chapter covers some high-level concepts of MySQL performance tuning such as the importance of considering the whole stack and the lifecycle of a query.
  • Chapter 2 – Query Tuning Methodology
    It is important to work in an effective way to solve performance problems. This chapter introduces a methodology to work effectively and emphasizes the importance of working proactively rather than doing firefighting.
  • Chapter 3 – Benchmarking with Sysbench
    It is often necessary to use benchmarks to determine the effect of a change. This chapter introduces benchmarking in general and specifically discusses the Sysbench tool including how to create your own custom benchmarks.
  • Chapter 4 – Test Data
    The book mostly uses a few standard test databases which are introduced in this chapter.

Part II: Sources of Information

MySQL exposes information about the performance through a few sources. The Performance Schema, the sys schema, the Information Schema, and the SHOW statement are introduced in each their chapter. There are only relatively few examples of using these sources in this part; however, these four sources of information are used extensively in the remainder of the book. If you are not already familiar with them, you are strongly encouraged to read this part. Additionally, the slow query log is covered. The five chapters are

  • Chapter 5 – The Performance Schema
    The main source of performance related information in MySQL is – as the name suggests – the Performance Schema. This chapter introduces the terminology, the main concepts, the organization, and the configuration.
  • Chapter 6 – The sys Schema
    The sys schema provides reports through predefined views and utilities in stored functions and programs. This chapter provides an overview of what features are available.
  • Chapter 7 – The Information Schema
    If you need metadata about the MySQL and the databases, the Information Schema is the place to look. It also includes important information for performance tuning such as information about indexes, index statistics, and histograms. This chapter provides an overview of the views available in the Information Schema.
  • Chapter 8 – SHOW Statements
    The SHOW statements are the oldest way to obtain information ranging from which queries are executing to schema information. This chapter relates the SHOW statements to the Information Schema and Performance Schema and covers in somewhat more detail the SHOW statements without counterparts in the two schemas.
  • Chapter 9 – The Slow Query Log
    The traditional way to find slow queries is to log them to the slow query log. This chapter covers how to configure the slow query log, how to read the log events, and how to aggregate the events with the mysqldump utility.

Part III: Tools

MySQL provides several tools that are useful when performing the daily work as well as specialized tasks. This part covers three tools ranging from monitoring to simple query execution. This book uses Oracle’s dedicated MySQL monitoring solution (requires commercial subscription but is also available as a trial) as an example of monitoring. Even if you are using other monitoring solutions, you are encouraged to study the examples as there will be a large overlap. These three tools are also used extensively in the remainder of the book. The three chapters in this part are

  • Chapter 10 – MySQL Enterprise Monitor
    Monitoring is one of the most important aspects of maintaining a stable and well-performing database. This chapter introduces MySQL Enterprise Monitor (MEM) and shows how you can install the trial and helps you navigate and use the graphical user interface (GUI).
  • Chapter 11 – MySQL Workbench
    MySQL provides a graphical user interface through the MySQL Workbench product. This chapter shows how you can install and use it. In this book, MySQL Workbench is particularly important for its ability to create diagrams – known as Visual Explain – representing the query execution plans.
  • Chapter 12 – MySQL Shell
    One of the newest tools around from Oracle for MySQL is MySQL Shell which is a second-generation commandline client with support for executing code in both SQL, Python, and JavaScript. This chapter gets you up to speed with MySQL Shell and teaches you about its support for using external code modules, its reporting infrastructure, and how to create custom modules, reports, and plugins.

Part IV: Schema Considerations and the Query Optimizer

In Part IV, there is a change of pace, and the focus moves to the topics more directly related to performance tuning starting with topics related to the schema, the query optimizer, and locks. The six chapters are

  • Chapter 13 – Data Types
    In relational databases, each column has a data type. This data type defines which values can be stored, which rules apply when comparing two values, how the data is stored, and more. This chapter covers the data types available in MySQL and gives guidance on how to decide which data types to use.
  • Chapter 14 – Indexes
    An index is used to locate data, and a good indexing strategy can greatly improve the performance of your queries. This chapter covers the index concepts, considerations about indexes, index types, index features, and more. It also includes a discussion on how InnoDB uses indexes and how to come up with an indexing strategy.
  • Chapter 15 – Index Statistics
    When the optimizer needs to determine how useful an index is and how many rows match a condition on an indexed value, it needs information on the data in the index. This information is index statistics. This chapter covers how index statistics work in MySQL, how to configure them, monitoring, and updating the index statistics.
  • Chapter 16 – Histograms
    If you want the optimizer to know how frequent a value occurs for a given column, you need to create a histogram. This is a new feature in MySQL 8, and this chapter covers how histograms can be used, their internals, and how to query the histogram metadata and statistics.
  • Chapter 17 – The Query Optimizer
    When you execute a query, it is the query optimizer that determines how to execute it. This chapter covers the tasks performed by the optimizer, join algorithms, join optimizations, configuration of the optimizer, and resource groups.
  • Chapter 18 – Locking Theory and Monitoring
    One of the problems that can cause the most frustration is lock contention. The first part of this chapter explains why locks are needed, lock access levels, and lock types (granularities). The second part of the chapter goes into what happens when a lock cannot be obtained, how to reduce lock contention, and where to find information about locks.

Part V: Query Analysis

With the information from Part IV, you are now ready to start analyzing queries. This includes finding the queries for further analysis and then analyzing the query using EXPLAIN or the Performance Schema. You also need to consider how transactions work and investigate lock contention when you have two or more queries fighting for the same locks. The four chapters are

  • Chapter 19 – Finding Candidate Queries for Optimization
    Whether part of the daily maintenance or during an emergency, you need to find the queries that you need to analyze and potentially optimize. This chapter shows how you can use the Performance Schema, the sys schema, MySQL Workbench, your monitoring solution, and the slow query log to find the queries that are worth looking into.
  • Chapter 20 – Analyzing Queries
    Once you have a candidate query, you need to analyze why it is slow or impacts the system too much. The main tool is the EXPLAIN statement which provides information about the query plan chosen by the optimizer. How to generate and read – including examples – the query plans using EXPLAIN is the main focus of the chapter. You can also use the optimizer trace to get more information on how the optimizer arrived at the selected query plan. An alternative way to analyze queries is to use the Performance Schema and sys schema to break queries down into smaller parts.
  • Chapter 21 – Transactions
    InnoDB executes everything as a transaction, and transactions is an important concept. Proper use of transactions ensures atomicity, consistency, and isolation. However, transactions can also be the cause of severe performance and lock problems. This chapter discusses how transactions can become a problem and how to analyze them.
  • Chapter 22 – Diagnosing Lock Contention
    This chapter goes through four scenarios with lock contention (flush locks, metadata locks, record-level locks, and deadlocks) and discusses the symptoms, the cause, how to set up the scenario, the investigation, the solution, and how to prevent problems.

Part VI: Improving Queries

You have found your problem queries and analyzed them and their transaction to understand why they are underperforming. But how do you improve the queries? This chapter goes through the most important configuration options not covered elsewhere, how to change the query plan, schema changes and bulk loading, replication, and caching as means to improve the performance. The five chapters are

  • Chapter 23 – Configuration
    MySQL requires resources when executing a query. This chapter covers the best practices for configuring these resources and the most important configuration options that are not covered in other discussions. There is also an overview of the data lifecycle in InnoDB as background for the discussion of configuring InnoDB.
  • Chapter 24 – Change the Query Plan
    While the optimizer usually does a good job at finding the optimal query execution plan, you will from time to time have to help it on its way. It may be that you end up with full table scans because no indexes exist or the existing indexes cannot be used. You may also wish to improve the index usage, or you may need to rewrite complex conditions or entire queries. This chapter covers these scenarios as well as shows how you can use the SKIP LOCKED clause to implement a queue system.
  • Chapter 25 – DDL and Bulk Data Load
    When you perform schema changes or load large data sets into the system, you ask MySQL to perform a large amount of work. This chapter discusses how you can improve the performance of such tasks including using the parallel data load feature of MySQL Shell. There is also a section on general data load considerations which also applies to data modifications in general and shows the difference between sequential and random order inserts. That discussion is followed by considerations on what this means for the choice of primary key.
  • Chapter 26 – Replication
    The ability to replicate between instances is a popular feature in MySQL. From a performance point of view, replication has two sides: you need to ensure replication performs well, and you can use replication to improve performance. This chapter discusses both sides of the coin including covering the Performance Schema tables that can be used to monitor replication.
  • Chapter 27 – Caching
    One way to improve the performance of queries is to not execute them at all, or at least avoid executing part of the query. This chapter discusses how you can use caching tables to reduce the complexity of queries and how you can use Memcached, the MySQL InnoDB Memcached plugin, and ProxySQL to avoid executing the queries altogether.

I hope you will enjoy the book.

The Format for Timestamps in MySQL Logs

MySQL changed the timestamp format in the log files in MySQL 5.7. Since then, I have a few times seen questions about the new format, and how to change the time zone that is used. Latest in a comment to my blog about log_slow_extra in 8.0.14, where the question was what T and Z in the timestamp (for example 2019-01-31T07:24:06.100447Z) means. In this blog, I will discuss the timestamp format and show you how you can change the time zone used.

Examples of the timestamps from the MySQL error log when restarting MySQL (click to enlarge).

The MySQL 5.7 Change

In MySQL 5.7 it was decided to make two changes to the timestamps affecting the format and time zone:

  • The format was changed to use the ISO 8601 / RFC 3339 format: YYYY-MM-DDThh:mm:ss.uuuuuu plus a tail value to signify the time zone.
  • The time zone used for the timestamps defaults to UTC (in 5.6 it defaulted to system time).

Tip

A couple of useful free resources, if you want to know more about the ISO 8601 / RFC 3339 format is the RFC specification and Wikipedia. The actual ISO 8601 specification can be purchased.

So there are two slightly different ways the timestamps can be displayed. The following two examples are for the default where the timestamp is in UTC and one where it is in UTC+11:00 (Australian Eastern Daylight Time):

2019-03-02T02:53:39.781592Z 0 [System] [MY-010116] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld.exe (mysqld 8.0.15) starting as process 1516

2019-03-02T13:54:17.155810+11:00 0 [System] [MY-010116] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld.exe (mysqld 8.0.15) starting as process 2812

Tip

In MySQL 8.0, you can also change the format itself, e.g. to JSON. See the MySQL reference manual on the error log format for for more information.

Changing the Time Zone

How do you change between the UTC and system time zones? You do that using the log_timestamps option which can take one of two values:

  • UTC: Use UTC as the time zone. This is the default.
  • SYSTEM: Use the same time zone as the operating system.

The option affects both the error log, slow query log, and general query log. The the slow and general query logs, though, it is only the case when logging to a file.

From XKCD comic 1179.

That Do T and Z Mean?

Back to the T and Z in the timestamps – what do they mean? The T is simply used as a separator between the data and time part. Think of it as T for Time. The Z means Zulu – another word for using the UTC time zone. That is:

  • T: Separator between the data and time parts.
  • Z: Zulu – the UTC time zone.

Thanks for reading.

More Statistics for Slow Queries: log_slow_extra

The slow query log is the trusted old method of recording slow query, so the database administrator can determine which queries are in the most need for optimization. Since MySQL 5.6, it has to some extend been overshadowed by the Performance Schema which has lower overhead and thus allows collecting statistics about all queries. The slow query log has one major advantage though: the data is persisted. In MySQL 8.0.14 which was recently released, there is an improvement for the slow query log: additional statistics about the recorded queries.

The slow query log with log_slow_extra enabled.
The slow query log with log_slow_extra enabled.

Contribution

Thanks for Facebook for contributing a patch for the new feature.

The additional information is not recorded by default. To enable the feature, enable the log_slow_extra option:

mysql> SET PERSIST log_slow_extra = ON;
Query OK, 0 rows affected (0.05 sec)

Here, SET PERSIST is used, so the configuration change is persisted when MySQL is restarted. If you just want to try the feature, you can use SET GLOBAL, then decide later whether you want to keep it enabled.

That is all that is required. You can now execute a “slow” query and take a look at the recorded data. An easy way to execute a slow query is to execute DO SLEEP(...) where you can replace ... with the number of seconds you want to sleep. However that is not a very interesting query. Another option is to lower long_query_time to ensure your query is captured. If you set long_query_time to zero, all queries are recorded:

mysql> SET SESSION long_query_time = 0.0;
Query OK, 0 rows affected (0.01 sec)

Here SET SESSION is used so only the current connection is affected.

Be Aware

The slow query log does have overhead. It is for most systems not recommended to set long_query_time to zero for all connections all the time. Doing so can cause performance problems.

Finally, execute a query:

mysql> SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
+------+------------------+-------------+------------------+------------+
| ID   | Name             | CountryCode | District         | Population |
+------+------------------+-------------+------------------+------------+
| 1024 | Mumbai (Bombay)  | IND         | Maharashtra      |   10500000 |
| 2331 | Seoul            | KOR         | Seoul            |    9981619 |
|  206 | São Paulo        | BRA         | São Paulo        |    9968485 |
| 1890 | Shanghai         | CHN         | Shanghai         |    9696300 |
|  939 | Jakarta          | IDN         | Jakarta Raya     |    9604900 |
| 2822 | Karachi          | PAK         | Sindh            |    9269265 |
| 3357 | Istanbul         | TUR         | Istanbul         |    8787958 |
| 2515 | Ciudad de México | MEX         | Distrito Federal |    8591309 |
| 3580 | Moscow           | RUS         | Moscow (City)    |    8389200 |
| 3793 | New York         | USA         | New York         |    8008278 |
+------+------------------+-------------+------------------+------------+
10 rows in set (0.04 sec)

The resulting slow query log record is:

# Time: 2019-01-31T07:24:20.518505Z
# User@Host: root[root] @ localhost [::1]  Id:    15
# Query_time: 0.001827  Lock_time: 0.000087 Rows_sent: 10  Rows_examined: 4089 Thread_id: 15 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 694 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 4080 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 10 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2019-01-31T07:24:20.516678Z End: 2019-01-31T07:24:20.518505Z
SET timestamp=1548919460;
SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;

The extra data can be a little hard to see due to the formatting of the blog – the extra fields are:

  • Thread_id: 15
  • Errno: 0
  • Killed: 0
  • Bytes_received: 0
  • Bytes_sent: 694
  • Read_first: 1
  • Read_last: 0
  • Read_key: 1
  • Read_next: 0
  • Read_prev: 0
  • Read_rnd: 0
  • Read_rnd_next: 4080
  • Sort_merge_passes: 0
  • Sort_range_count: 0
  • Sort_rows: 10
  • Sort_scan_count: 1
  • Created_tmp_disk_tables: 0
  • Created_tmp_tables: 0
  • Start: 2019-01-31T07:24:20.516678Z
  • End: 2019-01-31T07:24:20.518505Z

As comparison, here is the information for the same query with log_slow_extra = OFF:

# Time: 2019-01-31T07:24:06.100447Z
# User@Host: root[root] @ localhost [::1]  Id:    15
# Query_time: 0.002286  Lock_time: 0.000133 Rows_sent: 10  Rows_examined: 4089
SET timestamp=1548919446;
SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;

Enjoy.

MySQL 8: Performance Schema Digests Improvements

Since MySQL 5.6, the digest feature of the MySQL Performance Schema has provided a convenient and effective way to obtain statistics of queries based on their normalized form. The feature works so well that it has almost completely (from my experience) replaced the connector extensions and proxy for collecting query statistics for the Query Analyzer (Quan) in MySQL Enterprise Monitor (MEM).

MySQL 8 adds further improvements to the digest feature in the Performance Schema including a sample query with statistics for each digest, percentile information, and a histogram summary. This blog will explore these new features.

The MySQL Enterprise Monitor Query Analyzer
MySQL Enterprise Monitor is one of the main users of the Performance Schema digests for its Query Analyzer.

Let’s start out looking at the the good old summary by digest table.

Query Sample

The base table for digest summary information is the events_statements_summary_by_digest table. This has been around since MySQL 5.6. In MySQL 8.0 it has been extended with six columns of which three have data related to a sample query will be examined in this section.

The three sample columns are:

  • QUERY_SAMPLE_TEXT: An actual example of a query.
  • QUERY_SAMPLE_SEEN: When the sample query was seen.
  • QUERY_SAMPLE_TIMER_WAIT: How long time the sample query took to execute (in picoseconds).

As an example consider the query SELECT * FROM world.city WHERE id = <value>. The sample information for that query as well as the digest and digest text (normalized query) may look like:

mysql> SELECT DIGEST, DIGEST_TEXT, QUERY_SAMPLE_TEXT, QUERY_SAMPLE_SEEN,
              sys.format_time(QUERY_SAMPLE_TIMER_WAIT) AS SampleTimerWait
         FROM performance_schema.events_statements_summary_by_digest
        WHERE DIGEST_TEXT LIKE '%`world` . `city`%'\G
*************************** 1. row ***************************
           DIGEST: 9431aed9635923565d7bc92cc36d6411c3abb9f52d2c22715be21b5472e3c366
      DIGEST_TEXT: SELECT * FROM `world` . `city` WHERE `ID` = ?
QUERY_SAMPLE_TEXT: SELECT * FROM world.city WHERE ID = 130
QUERY_SAMPLE_SEEN: 2018-10-09 17:19:20.500944
  SampleTimerWait: 17.34 ms
1 row in set (0.00 sec)

There are a few things to note here:

  • The digest in MySQL 8 is a sha256 hash whereas in 5.6 and 5.7 it was an md5 hash.
  • The digest text is similar to the normalized query that the mysqldumpslow script can generate for queries in the slow query log; just that the Performance Schema uses a question mark as a placeholder.
  • The QUERY_SAMPLE_SEEN value is in the system time zone.
  • The sys.format_time() function is in the query used to convert the picoseconds to a human readable value.

The maximum length of the sample text is set with the performance_schema_max_sql_text_length option. The default is 1024 bytes. It is the same option that is used for the SQL_TEXT columns in the statement events tables. It requires a restart of MySQL to change the value. Since the query texts are stored in several contexts and some of the Performance Schema tables can have thousands of rows, do take care not to increase it beyond what you have memory for.

How is the sample query chosen? The sample is the slowest example of a query with the given digest. If the performance_schema_max_digest_sample_age option is set to a non-zero value (the default is 60 seconds) and the existing sample is older than the specified value, it will always be replaced.

The events_statements_summary_by_digest also has another set of new columns: percentile information.

Percentile Information

Since the beginning, the events_statements_summary_by_digest table has included some statistical information about the query times for a given digest: the minimum, average, maximum, and total query time. In MySQL 8 this has been extended to include information about the 95th, 99th, and 99.9th percentile. The information is available in the QUANTILE_95, QUANTILE_99, and QUANTILE_999 column respectively. All of the values are in picoseconds.

What does the new columns mean? Based on the histogram information of the query (see the next section), MySQL calculates a high estimate of the query time. For a given digest, 95% of the executed queries are expected to be faster than the query time given by QUANTILE_95. Similar for the two other columns.

As an example consider the same digest as before:

mysql> SELECT DIGEST, DIGEST_TEXT, QUERY_SAMPLE_TEXT,
              sys.format_time(SUM_TIMER_WAIT) AS SumTimerWait,
              sys.format_time(MIN_TIMER_WAIT) AS MinTimerWait,
              sys.format_time(AVG_TIMER_WAIT) AS AvgTimerWait,
              sys.format_time(MAX_TIMER_WAIT) AS MaxTimerWait,
              sys.format_time(QUANTILE_95) AS Quantile95,
              sys.format_time(QUANTILE_99) AS Quantile99,
              sys.format_time(QUANTILE_999) AS Quantile999
         FROM performance_schema.events_statements_summary_by_digest
        WHERE DIGEST_TEXT LIKE '%`world` . `city`%'\G
*************************** 1. row ***************************
           DIGEST: 9431aed9635923565d7bc92cc36d6411c3abb9f52d2c22715be21b5472e3c366
      DIGEST_TEXT: SELECT * FROM `world` . `city` WHERE `ID` = ?
QUERY_SAMPLE_TEXT: SELECT * FROM world.city WHERE ID = 130
     SumTimerWait: 692.77 ms
     MinTimerWait: 50.32 us
     AvgTimerWait: 68.92 us
     MaxTimerWait: 17.34 ms
       Quantile95: 104.71 us
       Quantile99: 165.96 us
      Quantile999: 363.08 us
1 row in set (0.00 sec)

Having the 95th, 99th, and 99.9th percentile helps predict the performance of a query and show the spread of the query times. Even more information about the spread can be found using the new family member: histograms.

Histograms

Histograms is a way to put the query execution times into buckets, so it is possible to see how the query execution times spread. This can for example be useful to see how evenly the query time is. The average query time may be fine, but if that is based on some queries executing super fast and others very slow, it will still result in unhappy users and customers.

The MAX_TIMER_WAIT column of the events_statements_summary_by_digest table discussed this far shows the high watermark, but it does not say whether it is a single outlier or a result of general varying query times. The histograms give the answer to this.

Using the query digest from earlier in the blog, the histogram information for the query can be found in the events_statements_histogram_by_digest table like:

mysql> SELECT BUCKET_NUMBER,
              sys.format_time(BUCKET_TIMER_LOW) AS TimerLow,
              sys.format_time(BUCKET_TIMER_HIGH) AS TimerHigh,
              COUNT_BUCKET, COUNT_BUCKET_AND_LOWER, BUCKET_QUANTILE
         FROM performance_schema.events_statements_histogram_by_digest
        WHERE DIGEST = '9431aed9635923565d7bc92cc36d6411c3abb9f52d2c22715be21b5472e3c366'
              AND COUNT_BUCKET > 0
        ORDER BY BUCKET_NUMBER;
+---------------+-----------+-----------+--------------+------------------------+-----------------+
| BUCKET_NUMBER | TimerLow  | TimerHigh | COUNT_BUCKET | COUNT_BUCKET_AND_LOWER | BUCKET_QUANTILE |
+---------------+-----------+-----------+--------------+------------------------+-----------------+
|            36 | 50.12 us  | 52.48 us  |          524 |                    524 |        0.052400 |
|            37 | 52.48 us  | 54.95 us  |         2641 |                   3165 |        0.316500 |
|            38 | 54.95 us  | 57.54 us  |          310 |                   3475 |        0.347500 |
|            39 | 57.54 us  | 60.26 us  |          105 |                   3580 |        0.358000 |
|            40 | 60.26 us  | 63.10 us  |           48 |                   3628 |        0.362800 |
|            41 | 63.10 us  | 66.07 us  |         3694 |                   7322 |        0.732200 |
|            42 | 66.07 us  | 69.18 us  |          611 |                   7933 |        0.793300 |
|            43 | 69.18 us  | 72.44 us  |          236 |                   8169 |        0.816900 |
|            44 | 72.44 us  | 75.86 us  |          207 |                   8376 |        0.837600 |
|            45 | 75.86 us  | 79.43 us  |          177 |                   8553 |        0.855300 |
|            46 | 79.43 us  | 83.18 us  |          236 |                   8789 |        0.878900 |
|            47 | 83.18 us  | 87.10 us  |          186 |                   8975 |        0.897500 |
|            48 | 87.10 us  | 91.20 us  |          203 |                   9178 |        0.917800 |
|            49 | 91.20 us  | 95.50 us  |          116 |                   9294 |        0.929400 |
|            50 | 95.50 us  | 100.00 us |          135 |                   9429 |        0.942900 |
|            51 | 100.00 us | 104.71 us |          105 |                   9534 |        0.953400 |
|            52 | 104.71 us | 109.65 us |           65 |                   9599 |        0.959900 |
|            53 | 109.65 us | 114.82 us |           65 |                   9664 |        0.966400 |
|            54 | 114.82 us | 120.23 us |           59 |                   9723 |        0.972300 |
|            55 | 120.23 us | 125.89 us |           40 |                   9763 |        0.976300 |
|            56 | 125.89 us | 131.83 us |           34 |                   9797 |        0.979700 |
|            57 | 131.83 us | 138.04 us |           33 |                   9830 |        0.983000 |
|            58 | 138.04 us | 144.54 us |           27 |                   9857 |        0.985700 |
|            59 | 144.54 us | 151.36 us |           16 |                   9873 |        0.987300 |
|            60 | 151.36 us | 158.49 us |           25 |                   9898 |        0.989800 |
|            61 | 158.49 us | 165.96 us |           20 |                   9918 |        0.991800 |
|            62 | 165.96 us | 173.78 us |            9 |                   9927 |        0.992700 |
|            63 | 173.78 us | 181.97 us |           11 |                   9938 |        0.993800 |
|            64 | 181.97 us | 190.55 us |           11 |                   9949 |        0.994900 |
|            65 | 190.55 us | 199.53 us |            4 |                   9953 |        0.995300 |
|            66 | 199.53 us | 208.93 us |            6 |                   9959 |        0.995900 |
|            67 | 208.93 us | 218.78 us |            6 |                   9965 |        0.996500 |
|            68 | 218.78 us | 229.09 us |            6 |                   9971 |        0.997100 |
|            69 | 229.09 us | 239.88 us |            3 |                   9974 |        0.997400 |
|            70 | 239.88 us | 251.19 us |            2 |                   9976 |        0.997600 |
|            71 | 251.19 us | 263.03 us |            2 |                   9978 |        0.997800 |
|            72 | 263.03 us | 275.42 us |            2 |                   9980 |        0.998000 |
|            73 | 275.42 us | 288.40 us |            4 |                   9984 |        0.998400 |
|            74 | 288.40 us | 302.00 us |            2 |                   9986 |        0.998600 |
|            75 | 302.00 us | 316.23 us |            2 |                   9988 |        0.998800 |
|            76 | 316.23 us | 331.13 us |            1 |                   9989 |        0.998900 |
|            78 | 346.74 us | 363.08 us |            3 |                   9992 |        0.999200 |
|            79 | 363.08 us | 380.19 us |            2 |                   9994 |        0.999400 |
|            80 | 380.19 us | 398.11 us |            1 |                   9995 |        0.999500 |
|            83 | 436.52 us | 457.09 us |            1 |                   9996 |        0.999600 |
|           100 | 954.99 us | 1.00 ms   |            1 |                   9997 |        0.999700 |
|           101 | 1.00 ms   | 1.05 ms   |            1 |                   9998 |        0.999800 |
|           121 | 2.51 ms   | 2.63 ms   |            1 |                   9999 |        0.999900 |
|           162 | 16.60 ms  | 17.38 ms  |            1 |                  10000 |        1.000000 |
+---------------+-----------+-----------+--------------+------------------------+-----------------+
49 rows in set (0.02 sec)

In this example, 3694 times (the COUNT_BUCKET column) when the query were executed, the query time was between 63.10 microseconds and 66.07 microseconds, so the execution time matched the interval of bucket number 41. There has been at total of 7322 executions (the COUNT_BUCKET_AND_LOWER column) of the query with a query time of 66.07 microseconds or less. This means that 73.22% (the BUCKET_QUANTILE column) of the queries have a query time of 66.07 microseconds or less.

In addition to the shown columns, there is SCHEMA_NAME and DIGEST (which together with BUCKET_NUMBER form a unique key). For each digest there are 450 buckets with the width of the bucket (in terms of difference between the low and high timers) gradually becoming larger and larger. The first, middle, and last five buckets are:

mysql> SELECT BUCKET_NUMBER,
              sys.format_time(BUCKET_TIMER_LOW) AS TimerLow,
              sys.format_time(BUCKET_TIMER_HIGH) AS TimerHigh
         FROM performance_schema.events_statements_histogram_by_digest
        WHERE DIGEST = '9431aed9635923565d7bc92cc36d6411c3abb9f52d2c22715be21b5472e3c366'
              AND (BUCKET_NUMBER < 5 OR BUCKET_NUMBER > 444 OR BUCKET_NUMBER BETWEEN 223 AND 227);
+---------------+-----------+-----------+
| BUCKET_NUMBER | TimerLow  | TimerHigh |
+---------------+-----------+-----------+
|             0 | 0 ps      | 10.00 us  |
|             1 | 10.00 us  | 10.47 us  |
|             2 | 10.47 us  | 10.96 us  |
|             3 | 10.96 us  | 11.48 us  |
|             4 | 11.48 us  | 12.02 us  |
|           223 | 275.42 ms | 288.40 ms |
|           224 | 288.40 ms | 302.00 ms |
|           225 | 302.00 ms | 316.23 ms |
|           226 | 316.23 ms | 331.13 ms |
|           227 | 331.13 ms | 346.74 ms |
|           445 | 2.11 h    | 2.21 h    |
|           446 | 2.21 h    | 2.31 h    |
|           447 | 2.31 h    | 2.42 h    |
|           448 | 2.42 h    | 2.53 h    |
|           449 | 2.53 h    | 30.50 w   |
+---------------+-----------+-----------+
15 rows in set (0.02 sec)

The bucket thresholds are fixed and thus the same for all digests. There is also a global histogram in the events_statements_histogram_global.

This includes the introduction to the new Performance Schema digest features. As monitoring tools start to use this information, it will help create a better monitoring experience. Particularly the histograms will benefit from being shown as graphs.

Monitoring NDBCluster Copying Alter Progress

MySQL NDB Cluster has great support for online (inplace) schema changes, but it is still sometimes necessary to perform an offline (copying) ALTER TABLE. These are relatively expensive to make as the entire table is copied into a new table which eventually replace the old table.

One example where a copying ALTER TABLE is required is when upgrading from MySQL NDB Cluster 7.2 or earlier to MySQL NDB Cluster 7.3 or later. The format used for temporal columns changed between these version (corresponding to MySQL Server 5.5 to 5.6). In order to take advantage of the new temporal format, a table rebuild is required.

Note

Support for the old temporal format has been removed in MySQL 8.0. So, you must upgrade your tables before an upgrade is possible. There is at the time of writing no MySQL NDB Cluster releases based on MySQL Server 8.0.

Schematic representation of a copying ALTER TABLE
Schematic representation of a copying ALTER TABLE

For long running operations, it can be useful to monitor the progress. There is no built-in way to do this like there is for InnoDB in MySQL 5.7 and later (see the blog InnoDB Progress Information), however the ndbinfo schema can give some information about the progress.

The ndbinfo schema is a virtual schema with views that show information from the data nodes. You can argue it is MySQL NDB Cluster’s answer to the Performance Schema. The ndbinfo schema was introduced in MySQL NDB Cluster 7.1 more than eight years ago and has steadily seen more and more information becoming available.

One of these changes arrived in MySQL NDB Cluster 7.4 where the memory_per_fragment view was added. This view shows detailed information about the memory used per fragment (in most cases the same as partitions). This can also be used to get an estimate of the progress of a copying ALTER TABLE.

As mentioned, a copying ALTER TABLE is similar to creating a new table with the new schema (which may potential be the same as the old schema), then inserting all of the data from the old table to the new. At the end, the two tables are swapped and the old table dropped.

Important

Remember that a copying ALTER TABLE is an offline operation. Any changes made to the table during the operation may be lost! Make sure the table is read-only while the ALTER TABLE is executing.

The temporary table (that later become the real table) is an NDBCluster table like other user created tables. This means the table will show up in ndbinfo.memory_per_fragment as a normal table, just with a special table name.

Temporary tables are named like #sql-7f4b_4 where the part after the – is generated based on the operating system process ID of the mysqld process and the connection id of the connection executing the ALTER TABLE. The schema name for the temporary table is the same as for the original table. In the example the process ID is 32587 or 7f4b in hexadecimal notation and the connection ID is 4.

As an example consider a rebuild of the db1.t1 table. In this case the fully qualified name (the name used by NDB Cluster instead of the normal table name) is db1/def/t1, i.e. the schema name and table name with /def/ between them. You can choose to create the fully qualified name for the temporary table as described above. An alternative, if you just have one concurrent table rebuild in the schema is to just look for the fully qualified name matching db1/def/#sql-%.

So, you can use the ndbinfo.memory_per_fragment table to see how much memory is allocated per fragment of the temporary table compared to the original table. For example:

mysql> SELECT fq_name, parent_fq_name, type, table_id,
              (fixed_elem_alloc_bytes-fixed_elem_free_bytes) AS FixedBytes,
              (var_elem_alloc_bytes-var_elem_free_bytes) AS VarBytes,
              hash_index_alloc_bytes
         FROM ndbinfo.memory_per_fragment
        WHERE fq_name = 'db1/def/t1' OR fq_name LIKE 'db1/def/#sql-%'
              OR parent_fq_name = 'db1/def/t1' OR parent_fq_name LIKE 'db1/def/#sql-%';
+------------------------+---------------------+-------------------+----------+------------+----------+------------------------+
| fq_name                | parent_fq_name      | type              | table_id | FixedBytes | VarBytes | hash_index_alloc_bytes |
+------------------------+---------------------+-------------------+----------+------------+----------+------------------------+
| db1/def/NDB$BLOB_45_3  | db1/def/t1          | User table        |       46 |     100580 |  1038088 |                  40960 |
| db1/def/NDB$BLOB_45_3  | db1/def/t1          | User table        |       46 |      99320 |  1056380 |                  40960 |
| db1/def/NDB$BLOB_45_3  | db1/def/t1          | User table        |       46 |     100580 |  1038088 |                  40960 |
| db1/def/NDB$BLOB_45_3  | db1/def/t1          | User table        |       46 |      99320 |  1056380 |                  40960 |
| sys/def/45/val1$unique | db1/def/t1          | Unique hash index |       49 |      77640 |        0 |                  40960 |
| sys/def/45/val1$unique | db1/def/t1          | Unique hash index |       49 |      76184 |        0 |                  40960 |
| sys/def/45/val1$unique | db1/def/t1          | Unique hash index |       49 |      77640 |        0 |                  40960 |
| sys/def/45/val1$unique | db1/def/t1          | Unique hash index |       49 |      76184 |        0 |                  40960 |
| sys/def/45/val1        | db1/def/t1          | Ordered index     |       48 |      39424 |        0 |                      0 |
| sys/def/45/val1        | db1/def/t1          | Ordered index     |       48 |      37792 |        0 |                      0 |
| sys/def/45/val1        | db1/def/t1          | Ordered index     |       48 |      39424 |        0 |                      0 |
| sys/def/45/val1        | db1/def/t1          | Ordered index     |       48 |      37792 |        0 |                      0 |
| sys/def/45/PRIMARY     | db1/def/t1          | Ordered index     |       47 |      39424 |        0 |                      0 |
| sys/def/45/PRIMARY     | db1/def/t1          | Ordered index     |       47 |      37792 |        0 |                      0 |
| sys/def/45/PRIMARY     | db1/def/t1          | Ordered index     |       47 |      39424 |        0 |                      0 |
| sys/def/45/PRIMARY     | db1/def/t1          | Ordered index     |       47 |      37792 |        0 |                      0 |
| db1/def/NDB$BLOB_14_3  | db1/def/#sql-7f4b_4 | User table        |       15 |      43180 |   446148 |                  24576 |
| db1/def/NDB$BLOB_14_3  | db1/def/#sql-7f4b_4 | User table        |       15 |      44404 |   471920 |                  24576 |
| db1/def/NDB$BLOB_14_3  | db1/def/#sql-7f4b_4 | User table        |       15 |      43360 |   450184 |                  24576 |
| db1/def/NDB$BLOB_14_3  | db1/def/#sql-7f4b_4 | User table        |       15 |      44404 |   471920 |                  24576 |
| sys/def/14/val1$unique | db1/def/#sql-7f4b_4 | Unique hash index |       44 |      33448 |        0 |                  24576 |
| sys/def/14/val1$unique | db1/def/#sql-7f4b_4 | Unique hash index |       44 |      34176 |        0 |                  24576 |
| sys/def/14/val1$unique | db1/def/#sql-7f4b_4 | Unique hash index |       44 |      33532 |        0 |                  24576 |
| sys/def/14/val1$unique | db1/def/#sql-7f4b_4 | Unique hash index |       44 |      34176 |        0 |                  24576 |
| sys/def/14/PRIMARY     | db1/def/#sql-7f4b_4 | Ordered index     |       42 |      15904 |        0 |                      0 |
| sys/def/14/PRIMARY     | db1/def/#sql-7f4b_4 | Ordered index     |       42 |      16992 |        0 |                      0 |
| sys/def/14/PRIMARY     | db1/def/#sql-7f4b_4 | Ordered index     |       42 |      15904 |        0 |                      0 |
| sys/def/14/PRIMARY     | db1/def/#sql-7f4b_4 | Ordered index     |       42 |      16992 |        0 |                      0 |
| sys/def/14/val1        | db1/def/#sql-7f4b_4 | Ordered index     |       43 |      15904 |        0 |                      0 |
| sys/def/14/val1        | db1/def/#sql-7f4b_4 | Ordered index     |       43 |      16992 |        0 |                      0 |
| sys/def/14/val1        | db1/def/#sql-7f4b_4 | Ordered index     |       43 |      15904 |        0 |                      0 |
| sys/def/14/val1        | db1/def/#sql-7f4b_4 | Ordered index     |       43 |      16992 |        0 |                      0 |
| db1/def/t1             | NULL                | User table        |       45 |     110792 |   775260 |                  40960 |
| db1/def/t1             | NULL                | User table        |       45 |     108712 |   760568 |                  40960 |
| db1/def/t1             | NULL                | User table        |       45 |     110792 |   775260 |                  40960 |
| db1/def/t1             | NULL                | User table        |       45 |     108712 |   760568 |                  40960 |
| db1/def/#sql-7f4b_4    | NULL                | User table        |       14 |      47536 |   332412 |                  24576 |
| db1/def/#sql-7f4b_4    | NULL                | User table        |       14 |      48656 |   340252 |                  24576 |
| db1/def/#sql-7f4b_4    | NULL                | User table        |       14 |      47696 |   333532 |                  24576 |
| db1/def/#sql-7f4b_4    | NULL                | User table        |       14 |      48656 |   340252 |                  24576 |
+------------------------+---------------------+-------------------+----------+------------+----------+------------------------+
40 rows in set (0.86 sec)

The columns with information about the node ID, block instance, and fragment number have been left out. This is why it looks like there are duplicate rows. It is also worth noticing that there are several “child tables” for the indexes and a blob column.

There are three memory columns. The first is for the fixed size column format, the second for the variable width columns format, and the last for hash indexes.

MySQL NDB Cluster supports two storage formats for the columns. The fixed format uses less memory for columns that are fixed width in nature (such as integers), however variable (called DYNAMIC in CREATE TABLE and ALTER TABLE statements) is more flexible. The variable/dynamic column format is also the only one supported when adding a column inplace (online). See also the manual page for CREATE TABLE for more information about the column format.

The hash memory is the memory used by hash indexes (for the primary key and unique indexes).

For the fixed and variable element memory usages there is both allocated and free bytes. Here the free bytes is used as a measure of the amount of fragmentation. A copying ALTER TABLE defragments the table, so it is necessary to the the fragmentation into consideration when estimating the progress. In reality it is more complicated than the query suggest, so the memory values in the query result will not end up matching 100%, however in most cases it should be a reasonable estimate.

You can also choose to aggregate the memory, for example:

mysql> SELECT IF(fq_name LIKE 'db1/def/%'
                    AND fq_name NOT LIKE 'db1/def/NDB$BLOB%',
                 fq_name,
                 parent_fq_name
              ) AS FqName,
              sys.format_bytes(
                 SUM(fixed_elem_alloc_bytes-fixed_elem_free_bytes)
              ) AS FixedBytes,
              sys.format_bytes(
                 SUM(var_elem_alloc_bytes-var_elem_free_bytes)
              ) AS VarBytes,
              sys.format_bytes(
                 SUM(hash_index_alloc_bytes)
              ) AS HashBytes
         FROM ndbinfo.memory_per_fragment
        WHERE fq_name = 'db1/def/t1' OR fq_name LIKE 'db1/def/#sql-%'
              OR parent_fq_name = 'db1/def/t1' OR parent_fq_name LIKE 'db1/def/#sql-%'
        GROUP BY FqName;
+---------------------+------------+----------+------------+
| FqName              | FixedBytes | VarBytes | HashBytes  |
+---------------------+------------+----------+------------+
| db1/def/#sql-7f4b_4 | 629.20 KiB | 3.08 MiB | 288.00 KiB |
| db1/def/t1          | 1.39 MiB   | 6.92 MiB | 480.00 KiB |
+---------------------+------------+----------+------------+
2 rows in set (0.69 sec)

This aggregate query also uses the sys schema function format_bytes() to convert the number of bytes into human readable numbers. The sys schema is installed by default for MySQL NDB Cluster 7.5 and later and is available from MySQL’s repository on GitHub for MySQL NDB Cluster 7.3 and 7.4.

This way of estimating the progress of a copying ALTER TABLE is not perfect, but at least it can give an idea of how the operation progresses.

What Does I/O Latencies and Bytes Mean in the Performance and sys Schemas?

The MEM InnoDB File I/O Graphs showing a peak in latency and bytes at 12:51.

The Performance Schema and sys schema are great for investigating what is going on in MySQL including investigating performance issues. In my work in MySQL Support, I have several times heard questions whether a peak in the InnoDB Data File I/O – Latency graph in MySQL Enterprise Monitor (MEM) or some values from the corresponding tables and view in the Performance Schema and sys schema are cause for concern. This blog will discuss what these observations means and how to use them.

The Tables and Views Involved

This blog will look into three sources in the Performance Schema for I/O latencies, so let’s first take a look at those tables. The three Performance Schema tables are:

  • events_waits_summary_global_by_event_name: with the event name set to wait/io/table/sql/handler or wait/io/file/%. This is the table used for the waits_global_by_latency and wait_classes_global_by_% views in the sys schema.
  • table_io_waits_summary_by_table: this is the table used for the schema_table_statistics% views in the sys schema.
  • file_summary_by_instance: this is the table used for the io_global_by_file_by% views in the sys schema.

These are also the sources used in MySQL Enterprise Monitor for the InnoDB Data File I/O graphs shown above. Let’s take a look at an example of each of the tables.

events_waits_summary_global_by_event_name

The events_waits_summary_global_by_event_name has aggregate data for wait events grouped by the event name. For the purpose of this discussion it is the table and file wait/io events that are of interested. An example of the data returned is:

mysql> SELECT *
         FROM performance_schema.events_waits_summary_global_by_event_name
        WHERE EVENT_NAME = 'wait/io/table/sql/handler'
              OR EVENT_NAME LIKE 'wait/io/file/%'
        ORDER BY SUM_TIMER_WAIT DESC
        LIMIT 5;
+--------------------------------------+------------+----------------+----------------+----------------+----------------+
| EVENT_NAME                           | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT |
+--------------------------------------+------------+----------------+----------------+----------------+----------------+
| wait/io/file/innodb/innodb_log_file  |    4003029 | 97371921796204 |        5371684 |       24324412 |   180878537324 |
| wait/io/table/sql/handler            |    4049559 | 43338753895440 |         494128 |       10702072 |   138756437188 |
| wait/io/file/innodb/innodb_data_file |      25850 | 11395061934996 |              0 |      440814508 |    43029060332 |
| wait/io/file/sql/binlog              |      20041 |  1316679917820 |              0 |       65699088 |    25816580304 |
| wait/io/file/sql/io_cache            |       2439 |    68212824648 |        1448920 |       27967360 |      628484180 |
+--------------------------------------+------------+----------------+----------------+----------------+----------------+
5 rows in set (0.00 sec)

mysql> SELECT EVENT_NAME, COUNT_STAR,
              sys.format_time(SUM_TIMER_WAIT) AS SumTimerWait,
              sys.format_time(MIN_TIMER_WAIT) AS MinTimeWait,
              sys.format_time(AVG_TIMER_WAIT) AS AvgTimerWait,
              sys.format_time(MAX_TIMER_WAIT) AS MaxTimerWait
         FROM performance_schema.events_waits_summary_global_by_event_name
        WHERE EVENT_NAME = 'wait/io/table/sql/handler'
              OR EVENT_NAME LIKE 'wait/io/file/
%' ORDER BY SUM_TIMER_WAIT DESC LIMIT 5;
+--------------------------------------+------------+--------------+-------------+--------------+--------------+
| EVENT_NAME                           | COUNT_STAR | SumTimerWait | MinTimeWait | AvgTimerWait | MaxTimerWait |
+--------------------------------------+------------+--------------+-------------+--------------+--------------+
| wait/io/file/innodb/innodb_log_file  |    4003029 | 1.62 m       | 5.37 us     | 24.32 us     | 180.88 ms    |
| wait/io/table/sql/handler            |    4049559 | 43.34 s      | 494.13 ns   | 10.70 us     | 138.76 ms    |
| wait/io/file/innodb/innodb_data_file |      25853 | 11.40 s      | 0 ps        | 440.78 us    | 43.03 ms     |
| wait/io/file/sql/binlog              |      20041 | 1.32 s       | 0 ps        | 65.70 us     | 25.82 ms     |
| wait/io/file/sql/io_cache            |       2439 | 68.21 ms     | 1.45 us     | 27.97 us     | 628.48 us    |
+--------------------------------------+------------+--------------+-------------+--------------+--------------+
5 rows in set (0.01 sec)

mysql> SELECT *
         FROM sys.waits_global_by_latency
        WHERE events = 'wait/io/table/sql/handler'
              OR events LIKE 'wait/io/file/%'
        LIMIT 5;
+--------------------------------------+---------+---------------+-------------+-------------+
| events                               | total   | total_latency | avg_latency | max_latency |
+--------------------------------------+---------+---------------+-------------+-------------+
| wait/io/file/innodb/innodb_log_file  | 4003029 | 1.62 m        | 24.32 us    | 180.88 ms   |
| wait/io/table/sql/handler            | 4049559 | 43.34 s       | 10.70 us    | 138.76 ms   |
| wait/io/file/innodb/innodb_data_file |   25874 | 11.43 s       | 441.88 us   | 43.03 ms    |
| wait/io/file/sql/binlog              |   20131 | 1.32 s        | 65.66 us    | 25.82 ms    |
| wait/io/file/sql/io_cache            |    2439 | 68.21 ms      | 27.97 us    | 628.48 us   |
+--------------------------------------+---------+---------------+-------------+-------------+
5 rows in set (0.01 sec)

These three queries show the same data, just obtained and displayed in different ways.

In the result there are two groups of events. The wait/io/table events (the wait/io/table/sql/handler is the only event of this group which is why it can be listed explicitly) and the wait/io/file group.

The table events are for accessing data in tables. It does not matter whether the data is cached in the buffer pool or is accessed on disk. In this table and view, there is no distinguishing between different types of access (read, write, etc.).

The file events are, as the name suggest, for actually accessing files. There is one file event per file type. For example, in he output there are the wait/io/file/innodb/innodb_log_file event for accessing the InnoDB redo log files, the wait/io/file/innodb/innodb_data_file event for accessing the InnoDB data files themselves, the wait/io/file/sql/binlog event for the binary log files, etc.

In the second query, all of the timings are wrapped in the sys.format_time() function. The timings returned by the Performance Schema are in picoseconds (10^-12 second) which are somewhat hard for us humans to read. The sys.format_time() function converts the picoseconds to human readable strings. When you sort, however, make sure you sort by the original non-converted values.

Tip

Use the sys.format_time() function to convert the picoseconds to a human readable value, but do only so for the returned row; sort and filter by the original values. The Performance Schema always returns timings in picoseconds irrespective of the timer used internally for the event.

The sys schema by default returns the timing as human readable values. If you need the values in picoseconds prefix the table name with x$, for example sys.x$waits_global_by_latency. The sys schema includes an ORDER BY clause in most views. For the waits_global_by_latency view, the default ordering is by the total latency, so there is no need to add an ORDER BY clause in this example.

table_io_waits_summary_by_table

The table_io_waits_summary_by_table Performance Schema table and schema_table_statistics% sys schema views are related to the wait/io/table/sql/handler event just discussed. These provide information about the amount of time spent per table. Unlike querying the wait/io/table/sql/handler in the wait_events_% tables, it split the time spent into whether it is used for reads, writes, fetch, insert, update, or delete. The read and write columns are the aggregates for the corresponding read and write operations, respectively. Since fetch is the only read operation, the read and fetch columns will have the same values.

The table and view show the table I/O, i.e. the access to table data irrespective of whether the data is accessed in-memory or on disk. This is similar to the wait/io/table/sql/handler event. An example of the result of querying the table and view for the employees.salaries table is:

mysql> SELECT *
         FROM performance_schema.table_io_waits_summary_by_table
        WHERE OBJECT_SCHEMA = 'employees'
              AND OBJECT_NAME = 'salaries'\
*************************** 1. row ***************************
     OBJECT_TYPE: TABLE
   OBJECT_SCHEMA: employees
     OBJECT_NAME: salaries
      COUNT_STAR: 2844047
  SUM_TIMER_WAIT: 31703741623644
  MIN_TIMER_WAIT: 4975456
  AVG_TIMER_WAIT: 11147072
  MAX_TIMER_WAIT: 138756437188
      COUNT_READ: 0
  SUM_TIMER_READ: 0
  MIN_TIMER_READ: 0
  AVG_TIMER_READ: 0
  MAX_TIMER_READ: 0
     COUNT_WRITE: 2844047
 SUM_TIMER_WRITE: 31703741623644
 MIN_TIMER_WRITE: 4975456
 AVG_TIMER_WRITE: 11147072
 MAX_TIMER_WRITE: 138756437188
     COUNT_FETCH: 0
 SUM_TIMER_FETCH: 0
 MIN_TIMER_FETCH: 0
 AVG_TIMER_FETCH: 0
 MAX_TIMER_FETCH: 0
    COUNT_INSERT: 2844047
SUM_TIMER_INSERT: 31703741623644
MIN_TIMER_INSERT: 4975456
AVG_TIMER_INSERT: 11147072
MAX_TIMER_INSERT: 138756437188
    COUNT_UPDATE: 0
SUM_TIMER_UPDATE: 0
MIN_TIMER_UPDATE: 0
AVG_TIMER_UPDATE: 0
MAX_TIMER_UPDATE: 0
    COUNT_DELETE: 0
SUM_TIMER_DELETE: 0
MIN_TIMER_DELETE: 0
AVG_TIMER_DELETE: 0
MAX_TIMER_DELETE: 0
1 row in set (0.00 sec)

mysql> SELECT *
         FROM sys.schema_table_statistics
        WHERE table_schema = 'employees'
              AND table_name = 'salaries'\G
*************************** 1. row ***************************
     table_schema: employees
       table_name: salaries
    total_latency: 31.70 s
     rows_fetched: 0
    fetch_latency: 0 ps
    rows_inserted: 2844047
   insert_latency: 31.70 s
     rows_updated: 0
   update_latency: 0 ps
     rows_deleted: 0
   delete_latency: 0 ps
 io_read_requests: 493
          io_read: 7.70 MiB
  io_read_latency: 611.04 ms
io_write_requests: 8628
         io_write: 134.91 MiB
 io_write_latency: 243.19 ms
 io_misc_requests: 244
  io_misc_latency: 2.50 s
1 row in set (0.05 sec)

In this case it shows that there has been mostly writes – inserts – for the table. The sys schema view effectively joins on the performance_schema.file_summary_by_instance for the read columns, so for the schema_table_statistics view fetch and read are not synonyms.

So, what is it the file_summary_by_instance table shows that is different table the “table I/O” that has been the topic of the first two tables? Let’s see.

file_summary_by_instance

Unlike the two previous tables, the file_summary_by_instance shows how much time is spent on actual file I/O and how much data is accessed. This makes the file_summary_by_instance table and the corresponding sys schema views very useful for determining where time is spent doing disk I/O and which files have the most data accesses on disk.

An example of using the Performance Schema and two of the sys schema views is:

mysql> SELECT *
         FROM performance_schema.file_summary_by_instance
        WHERE FILE_NAME LIKE '%\\\\employees\\\\salaries.ibd'\G
*************************** 1. row ***************************
                FILE_NAME: C:\ProgramData\MySQL\MySQL Server 8.0\Data\employees\salaries.ibd
               EVENT_NAME: wait/io/file/innodb/innodb_data_file
    OBJECT_INSTANCE_BEGIN: 2230271392896
               COUNT_STAR: 9365
           SUM_TIMER_WAIT: 3351594917896
           MIN_TIMER_WAIT: 11970500
           AVG_TIMER_WAIT: 357885020
           MAX_TIMER_WAIT: 40146113948
               COUNT_READ: 493
           SUM_TIMER_READ: 611040652056
           MIN_TIMER_READ: 65421052
           AVG_TIMER_READ: 1239433224
           MAX_TIMER_READ: 16340582272
 SUM_NUMBER_OF_BYTES_READ: 8077312
              COUNT_WRITE: 8628
          SUM_TIMER_WRITE: 243186542696
          MIN_TIMER_WRITE: 11970500
          AVG_TIMER_WRITE: 28185588
          MAX_TIMER_WRITE: 1984546920
SUM_NUMBER_OF_BYTES_WRITE: 141459456
               COUNT_MISC: 244
           SUM_TIMER_MISC: 2497367723144
           MIN_TIMER_MISC: 154910196
           AVG_TIMER_MISC: 10235113564
           MAX_TIMER_MISC: 40146113948
1 row in set (0.00 sec)

mysql> SELECT *
         FROM sys.io_global_by_file_by_latency
        WHERE file = '@@datadir\\employees\\salaries.ibd'\G
*************************** 1. row ***************************
         file: @@datadir\employees\salaries.ibd
        total: 9365
total_latency: 3.35 s
   count_read: 493
 read_latency: 611.04 ms
  count_write: 8628
write_latency: 243.19 ms
   count_misc: 244
 misc_latency: 2.50 s
1 row in set (0.09 sec)

mysql> SELECT *
         FROM sys.io_global_by_file_by_bytes
         WHERE file = '@@datadir\\employees\\salaries.ibd'\G
*************************** 1. row ***************************
         file: @@datadir\employees\salaries.ibd
   count_read: 493
   total_read: 7.70 MiB
     avg_read: 16.00 KiB
  count_write: 8628
total_written: 134.91 MiB
    avg_write: 16.01 KiB
        total: 142.61 MiB
    write_pct: 94.60
1 row in set (0.10 sec)

This example is from Microsoft Windows, and as always when backslashes are in play, it is fun to try to determine the appropriate number of backslashes to use. When specifying the file name with LIKE, you need four backslashes per backslash in the file name; when using = you need two backslashes.

Again, the values are split into reads and writes (though not as detailed as before with fetch, insert, update, and delete – that is not known at the level where the file I/O happens). The miscellaneous values include everything that is not considered reads or write; this includes opening and closing the file.

The sys schema queries not only have formatted the timings, but also the path and the bytes. This has been done using the sys.format_path() and sys.format_bytes() functions, respectively.

From the output, it can be seen that despite no rows were ever fetched (read) from the employees.salaries table (that was found in the previous output), there has still been some read file I/O. This was what the sys.schema_table_statistics view reflected.

So, what does all of this mean? The graph in MySQL Enterprise Monitor showed that there was six seconds file I/O latency for the InnoDB data files. Is that bad? As often with these kinds of questions, the answer is: “it depends”.

What to Make of the Values

In this case we have a case where the graphs in MySQL Enterprise Monitor show a peak for the latency and bytes used doing I/O on the InnoDB data files. This is actually disk I/O. But what exactly does that means and should the alarm sound?

Let’s first refresh our memory on how the graphs looks:

The MEM InnoDB File I/O Graphs showing a peak in latency and bytes at 12:31.

If you are not using MySQL Enterprise Monitor, you may have similar graphs from your monitoring solution, or you have obtained latency and bytes values from the tables and views discussed in this blog.

The latency graph shows that we have done six seconds if I/O. What does that mean? It is the aggregate I/O during the period the data was collected. In this case, the data is plotted for every minute, so in the one minute around 12:51, of the 60 seconds a total of six seconds was spent doing I/O. Now, the six seconds suddenly do no sound so bad. Similar for the bytes, around 4.6MiB of data was read or written.

In general, the values obtained either from the monitoring graphs or from the underlying tables cannot be used to conclude whether the is a problem or not. They just show how much I/O was done at different times.

Similar for the values from the Performance Schema. On their own they do not tell much. You can almost say they are too neutral – they just state how much work was done, not whether it was too much or too little.

A more useful way to use this data is in case a problem is reported. This can be that system administrator reports the disks are 100% utilized or that end users report the system is slow. Then, you can go and look at what happened. If the disk I/O was unusually high at that point in time, then that is likely related, and you can continue your investigation from there.

There are more reports in MySQL Enterprise Monitor both as time series graphs and as point-in-time snapshots. The point-in-time snapshots are often using the sys schema views but allows sorting. An example is the Database File I/O reports:

MEM's Database File I/O Report

MySQL Workbench also provides performance reports based on the sys scheme. The equivalent to the previous report is the Top File I/O Activity Report:

MySQL Workbench's Top File I/O Activity Report

The MySQL Workbench performance reports also allows you to export the report or copy the query used to generate the report, so you can execute it manually.

With respect to the wait/io/table/sql/handler events, then remember that I/O here does not mean disk I/O, but table I/O. So, all it means that time is accumulating for these events – including when looking at the per table is that the data in the table is used. There are also per index values in table_io_waits_summary_by_index_usage Performance Schema table and the schema_index_statistics sys view which have the same meaning. Whether a given usage is too high depends on many things. However, it can again be useful to investigate what is causing problems.

For the example data from this blog, it was triggered by loading the employees sample database. So, there was no problem. If you want to put data into your database, it must necessarily be written to the data file, otherwise it will not be persisted. However, if you think the data import took too long, you can use the data as part of your investigation on how to make the import faster.

The conclusion is that you should not panic if you see the I/O latencies peak. On their own they just mean that more work was done during that period that usual. Without context a peak is no worse than a dip (which could indicate something is preventing work from being done or that there is a natural slow period). Instead use the I/O latencies and bytes together with other observations to understand where MySQL is spending time and for which files data is being read and written.

References

I will recommend you look at the following references, if you want to understand more about the Performance Schema tables and sys schema views discussed in this blog:

The GitHub repository for the sys schema includes all the definitions of the views (and other objects). Since these are written in plain SQL, they are very useful to see in more depth where the data is coming from. The GitHub website allows you to browse through each of the files. Each sys schema object is defined in its own file.

Install MySQL Enteprise Monitor (MEM) 3.0 Using Limited Resources

MySQL Enterprise Monitor (MEM) is the monitoring solution offered as part of MySQL Enterprise Edition and MySQL Cluster Carrier Grade Edition. In this blog, I will not go into details of the features of MEM, but rather focus on the case where you want to install MEM 3.0 to try it out on your personal desktop or laptop.

A trial version (the full product, but the can only be used for 30 days) is available from Oracle’s Software Delivery Cloud. If you are a MySQL customer, it is recommended that you download MEM from My Oracle Support (MOS).

Once you have downloaded and extracted the installation binaries, you can start the installation. You have the choice between using a GUI, text based, and unattended install. Here I will use the GUI install, but if you want to try one of the other install options, launch the installer with the –help option to get more information.

MEM 3.0 consists of two parts:

  • The Service Manager
  • Agents

Only the Service Manager is required, so that will be the first thing to install. As this is intended to show how you can test MEM, I will use a normal user rather than root for the installation.

It is also recommended to take a look at the MEM 3.0 Reference Manual.

Installation Wizard

When launching the installer the first screen asks which language to use – you have the choice of English and Japanese:

Installing the MEM 3.0 Service Manager - Step 1: Choose language
Step 1: Choose language

Next is an information screen that you should ensure you keep track of the usernames and passwords entered during the installation process:

Installing the MEM 3.0 Service Manager - Step 2: Remember the usernames and passwords entered during the installation process
Step 2: Remember the usernames and passwords entered during the installation process

The actual install process is now ready to start:

Installing the MEM 3.0 Service Manager - Step 3: Ready to start the actual install process
Step 3: Ready to start the actual install process

The following steps are to configure the installation – the first of which is to decide where to install the Service Manager:

Installing the MEM 3.0 Service Manager - Step 4: Choose the installation directory
Step 4: Choose the installation directory

The Service Manager will need three ports:

  • Tomcat Server Port: For the web UI when using non-SSL connections
  • Tomcat Shutdown Port: Used internally to shutdown the web server
  • Tomcat SSL Port: For the web UI when using SSL connections
Installing the MEM 3.0 Service Manager - Step 5: Choose the port numbers
Step 5: Choose the port numbers

The Service Manager uses a MySQL database to store the data collected. The next screen allows you to choose between using the MySQL database bundled with MEM or an existing one. Using the bundled instance has the advantage that MEM will configure it automatically and upgrades can be easier, however it will mean running two MySQL instances if you already have MySQL installed. For a test instance using the bundled instance also has the advantage that it’s easy to uninstall the whole installation again, so we will use the bundled instance in this example:

Installing the MEM 3.0 Service Manager - Step 6: Choose whether to use the bundled MySQL database or an existing one
Step 6: Choose whether to use the bundled MySQL database or an existing one

The final of the pre-installation configuration is to choose the username and password to use for the connection to the MySQL database. This is the username and password that you were reminded of earlier to make sure you remember:

Installing the MEM 3.0 Service Manager - Step 7: Specify username and password for the Service Manager to connect to the MySQL database storing the data collected through the monitoring
Step 7: Specify username and password for the Service Manager to connect to the MySQL database storing the data collected through the monitoring

Next a note that because we have chosen to install the Service Manager as a non-root user, it will not be started automatically when the server is restarted:

Installing the MEM 3.0 Service Manager - Step 8: Info that MEM will not start automatically when not installed as root
Step 8: Info that MEM will not start automatically when not installed as root

Ready to Install:

Installing the MEM 3.0 Service Manager - Step 9: Configuration completed
Step 9: Configuration completed – ready to install

The Service Manager is now being installed – this will take a little while as it both includes copying all the files in place as well as configuring and starting the web server and the bundled MySQL database:

Installing the MEM 3.0 Service Manager - Step 10: Installation is in progress
Step 10: Installation is in progress

MEM includes an uninstall script if you need to remove the Service Manager again:

Installing the MEM 3.0 Service Manager - Step 11: Files are now installed
Step 11: Files are now installed

To improve security MEM 3.0 by default uses SSL. The installation process adds a self-signed certificate, but you can choose to install your own certificate later:

Installing the MEM 3.0 Service Manager - Step 12: Information that MEM is using SSL with a self-signed certificate by default
Step 12: Information that MEM is using SSL with a self-signed certificate by default

The installer is now done and it is time to launch the UI:

Installing the MEM 3.0 Service Manager - Step 13: Ready to launch the Service Manager
Step 13: Ready to launch the Service Manager

Unattended Install

If you go through the installation process often, it is more convenient to use the unattended installation as it allows you to automate the installation. To perform the same installation as above using the unattended installation you can execute:

shell$ ./mysqlmonitor-3.0.3.2912-linux-x86_64-installer.bin \
            --mode unattended --unattendedmodeui none \
            --installdir /home/jesper/mysql/enterprise/monitor \
            --adminuser service_manager --adminpassword mypassword \
            --dbport 13306 --mysql_installation_type bundled \
            --tomcatport 18080 --tomcatshutdownport 18005 \
            --tomcatsslport 18443

As several of the values are the default ones, you can skip some of the options, but they are included here for completeness.

When the above command completes, continue with the post-installation configuration as you would have done using the installation wizard.

Post-Installation Configuration

Once the Service Manager UI has opened in your browser there is a little post-installation configuration to take care of:

  • You need to create an admin user for the web UI
  • You need to create a user agents can use if you choose to install any agents
  • You can choose whether to have the Service Manager automatically check for updates and how for how long time to keep historical data
Installing the MEM 3.0 Service Manager - Step 14: Post installation configuration
Step 14: Post installation configuration

The last step if to choose your timezone and which locale to use in the user interface:

Installing the MEM 3.0 Service Manager - Step 15: Choose timezone and the locale
Step 15: Choose timezone and the locale

After this you are ready to play around with the monitor. If you choose to install agents, the steps are similar.

Reducing Memory Footprint

One thing to be aware of though is that the default configuration used by the Service Manager is aimed at a small to medium production installation. If you for example installed MEM in a virtual machine or computer with limited memory available, the default configuration may not be optimal.

With the installation above just completed, the memory usage of the web server (Tomcat) and the bundled MySQL database is:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
15653 jesper    20   0 3794m 924m  13m S  1.0 23.4   4:46.01 java
15586 jesper    20   0 3425m 608m 9588 S  2.6 15.4   2:23.88 mysqld

So around 1.5G resident memory. That is without adding any additional agents and/or MySQL instances to monitor.

So when I use MEM for testing, the first thing I do is to change a few configuration values to reduce the memory usage. The configuration options I change are located in two files (paths are given relative to the installation directory):

  • mysql/my.cnf – options related to the bundled MySQL database
  • apache-tomcat/bin/setenv.sh – options related to the web server

mysql/my.cnf

For the MySQL database I change two setting:

  • innodb_buffer_pool_size – this is by default 768M, but if you only monitor a couple of MySQL instances, something like 100M is enough
  • table_definition_cache – this is by default 2048. One side effect of the value being so large is that the auto-sizing of the Performance Schema considers the installation as a large instance, so the Performance Schema tables are made large. Reducing the value to 800 is enough for testing and will reduce the memory usage of the Performance Schema with several hundred megabytes.

So my mysql/my.cnf looks something like this after the changes:

...
[mysqld]
...
# Main Caches
table_definition_cache = 800
...

# InnoDB
...
innodb_buffer_pool_size = 100M
...

 apache-tomcat/bin/setenv.sh

It is only necessary to edit one line in the Tomcat configuration file – the default settings are:

JAVA_OPTS="-Xmx768M -Xms768M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/jesper/mysql/enterprise/monitor/apache-tomcat/temp -XX:+UseParallelOldGC -XX:MaxPermSize=512M"

I change that to:

JAVA_OPTS="-Xmx256M -Xms256M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/jesper/mysql/enterprise/monitor/apache-tomcat/temp -XX:+UseParallelOldGC -XX:MaxPermSize=200M"

I.e. the three setting I have changed are:

  • -Xmx (maximum  heap size) from 768M to 256M
  • -Xms (minimum heap size) from 768M to 256M
  • -XX:MaxPermSize from 512M to 200M

Enabling the New Configurations

It requires restarting the Service Manager to make the new configurations take effect. You can do the restart by going into the installation directory and execute:

monitor$ ./mysqlmonitorctl.sh restart
Using CATALINA_BASE:   /home/jesper/mysql/enterprise/monitor/apache-tomcat
Using CATALINA_HOME:   /home/jesper/mysql/enterprise/monitor/apache-tomcat
Using CATALINA_TMPDIR: /home/jesper/mysql/enterprise/monitor/apache-tomcat/temp
Using JRE_HOME:        /home/jesper/mysql/enterprise/monitor/java
Using CLASSPATH:       /home/jesper/mysql/enterprise/monitor/apache-tomcat/bin/bootstrap.jar:/home/jesper/mysql/enterprise/monitor/apache-tomcat/bin/tomcat-juli.jar
Using CATALINA_PID:    /home/jesper/mysql/enterprise/monitor/apache-tomcat/temp/catalina.pid
Stopping tomcat service . [ OK ]
Stopping mysql service . [ OK ]
./mysqlmonitorctl.sh : mysql  started
131128 13:58:59 mysqld_safe Logging to '/home/jesper/mysql/enterprise/monitor/mysql/runtime/mysqld.log'.
131128 13:58:59 mysqld_safe Starting mysqld daemon with databases from /home/jesper/mysql/enterprise/monitor/mysql/data/
Using CATALINA_BASE:   /home/jesper/mysql/enterprise/monitor/apache-tomcat
Using CATALINA_HOME:   /home/jesper/mysql/enterprise/monitor/apache-tomcat
Using CATALINA_TMPDIR: /home/jesper/mysql/enterprise/monitor/apache-tomcat/temp
Using JRE_HOME:        /home/jesper/mysql/enterprise/monitor/java
Using CLASSPATH:       /home/jesper/mysql/enterprise/monitor/apache-tomcat/bin/bootstrap.jar:/home/jesper/mysql/enterprise/monitor/apache-tomcat/bin/tomcat-juli.jar
Using CATALINA_PID:    /home/jesper/mysql/enterprise/monitor/apache-tomcat/temp/catalina.pid

The memory usage is now somewhat smaller:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
19521 jesper    20   0 2847m 544m  15m S  2.0 13.8   1:51.61 java
19484 jesper    20   0 2407m 160m 9296 S  0.3  4.1   0:09.21 mysqld