Mysql – Performance schema: ‘stage/sql/Sending data’

mariadbmysql-5.6performance

Background

I am using MariaDB 10.0 but MySQL 5.6 answers are also of interest.

Two machines cloned from the same image, same MariaDB configuration as far as I could tell, same dataset. One machine is way slower than the other (the production machine, of course).

I have enabled performance profiling to investigate (performance_schema=1 in /etc/my.cnf), restarted.

A query on development host:

SELECT
  event_name AS Stage,
  TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration
FROM
  performance_schema.events_stages_history_long
WHERE
  NESTING_EVENT_ID=23;

Output:

+--------------------------------+----------+
| Stage                          | Duration |
+--------------------------------+----------+
| stage/sql/init                 | 0.000122 |
| stage/sql/checking permissions | 0.000005 |
| stage/sql/Opening tables       | 0.000610 |
| stage/sql/After opening tables | 0.000004 |
| stage/sql/System lock          | 0.000012 |
| stage/sql/Table lock           | 0.000002 |
| stage/sql/After opening tables | 0.000006 |
| stage/sql/init                 | 0.000042 |
| stage/sql/optimizing           | 0.000022 |
| stage/sql/statistics           | 0.000591 |
| stage/sql/preparing            | 0.000040 |
| stage/sql/executing            | 0.000003 |
| stage/sql/Sorting result       | 0.000003 |
| stage/sql/Sending data         | 0.345838 |
| stage/sql/end                  | 0.000006 |
| stage/sql/query end            | 0.000003 |
| stage/sql/closing tables       | 0.000012 |
| stage/sql/freeing items        | 0.000009 |
| stage/sql/cleaning up          | 0.000001 |
+--------------------------------+----------+
19 rows in set (0.00 sec)

Same query on production host:

SELECT
  event_name AS Stage,
  TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration
FROM
  performance_schema.events_stages_history_long
WHERE
  NESTING_EVENT_ID=7;

Output:

+--------------------------------+-----------+
| Stage                          | Duration  |
+--------------------------------+-----------+
| stage/sql/init                 |  0.000124 |
| stage/sql/checking permissions |  0.000005 |
| stage/sql/Opening tables       |  0.000024 |
| stage/sql/After opening tables |  0.000006 |
| stage/sql/System lock          |  0.000005 |
| stage/sql/Table lock           |  0.000003 |
| stage/sql/After opening tables |  0.000007 |
| stage/sql/init                 |  0.000043 |
| stage/sql/optimizing           |  0.000029 |
| stage/sql/statistics           |  0.003686 |
| stage/sql/preparing            |  0.000061 |
| stage/sql/executing            |  0.000003 |
| stage/sql/Sorting result       |  0.000004 |
| stage/sql/Sending data         | 11.537281 |
| stage/sql/end                  |  0.000010 |
| stage/sql/query end            |  0.000003 |
| stage/sql/closing tables       |  0.000016 |
| stage/sql/freeing items        |  0.000012 |
| stage/sql/logging slow query   |  0.000007 |
| stage/sql/cleaning up          |  0.000002 |
+--------------------------------+-----------+
20 rows in set (0.00 sec)

Which is over 3000% slower. The data returned by the queries is the same in both cases, only 33 rows and four columns, about 300 bytes in all.

Questions

  • What is the stage/sql/Sending data metric actually measuring?

  • What could possibly be the reason for such a slow performance?

Best Answer

Sadly, stage/sql/Sending data (something that you will see on SHOW PROCESSLIST as Sending data) does not tell us much about the query internals.

The thread is reading and processing rows for a SELECT statement...

Is like saying nothing, why is it different in both cases?

Your effort is not in vain, you have proved what is NOT affecting the query- permissions, optimization, opening tables, locking, logging and other support bits. There is something wrong with the query itself, likely either a different query plan or a configuration/hardware issue.

In order to continue answering, please provide the output of the following commands on both servers:

EXPLAIN SELECT ... [REST OF YOUR QUERY] \G

and

FLUSH STATUS;
SELECT ... [REST OF YOUR QUERY, do not show the actual results, we do not care];
SHOW STATUS like 'Hand%';

Those are 2 commands that will tell us more about query execution before checking other more complex possibilities. It is the most common cause so there is a high chance of getting something interesting out of it. Also please show us the table structure SHOW CREATE TABLE (in both servers) for reference.

Related Question