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 onSHOW PROCESSLIST
asSending data
) does not tell us much about the query internals.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:
and
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.