2

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?

  • Ok, I found the answer to the first question: dev.mysql.com/doc/refman/5.6/en/… ("The thread is reading and processing rows for a SELECT statement, and sending data to the client. Because operations occurring during this state tend to perform large amounts of disk access (reads), it is often the longest-running state over the lifetime of a given query.") – Monitor13 Apr 16 '16 at 17:04
0

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.

| improve this answer | |
  • Yup, it turned out to be a hardware issue as you mention. Comparing the read speeds (hdparm -t /dev/sdd) of the data disk on the slow host and the normal running one, the former was abysmal, about ten times slower. I have cloned the disk onto a different rack now and life is good again. Cheers! ☺ – Monitor13 Apr 16 '16 at 21:27
  • I should have mentioned in the original post, but the queries themselves are fine, it's just a SELECT with a straight primary key hit. No joins, aggregations, or anything. The queries and the schema have been stable over the last ten years and offering consistently good performance in a variety of systems. – Monitor13 Apr 16 '16 at 21:40
  • I do disagree that "[t]he thread is reading and processing rows" is "like saying nothing". On the contrary, it is a strong indicator of an I/O problem and a weak indicator of a CPU problem. Knowing in this case that the problem could not have been due to database design factors, based on both formal analysis and intimate knowledge of what in this case is a simple schema, and on a performance comparison with a redundant system of substantially similar characteristics, immediately puts one on the scent of a hardware fault. – Monitor13 Apr 16 '16 at 21:50
  • "an I/O problem" for a database IS saying nothing. The database is an I/O-focused service. You have to fight hard to maximize your CPU usage by using compression or complex calculations, which of course it is possible, but regular MySQL usage patterns (single thread OLTP vs. Analytics, map-reduce) tend not to be large CPU users. the fact that it takes 10 seconds to return 30 rows means that you are probably doing a full table scan (there is no index on NESTING_EVENT_ID) and/or the table is not on cache/too large to fit cache. I would not be so fast as to discard query plan issues. – jynus Apr 17 '16 at 12:44

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.