After upgrading from MySQL 5.0 to MySQL Percona 5.5 my P99 on many queries has gotten significantly worse.
Here is the mysqlslap command I ran:
mysqlslap --concurrency=50 --iterations=500 --query=test.sql --create-schema=my_schema --user my_user --password
Here is an example of one such query:
cat test.sql
SELECT aaa.big_int_val FROM aaa INNER JOIN bbb ON aaa.bbb_id = bbb.id WHERE aaa.big_int_val > 8206166128 AND aaa.big_int_val <= 8206166260 ORDER BY aaa.big_int_val;
I captured the 5.5 queries in the slow query log with profiling on and the major time difference is in Profile_Sending_data:
Here the time spend for a slow query and a fast query in MySQL Percona 5.5
Profile_Sending_data: 0.099546
Profile_Sending_data: 0.000031
When run on MySQL 5.5 (Percona)
mysqlslap --concurrency=50 --iterations=500 --query=test3.sql
–create-schema=nm --user root --password
Enter password:
Benchmark
Average number of seconds to run all queries: 0.003 seconds
Minimum number of seconds to run all queries: 0.002 seconds
Maximum number of seconds to run all queries: 0.106 seconds
Number of clients running queries: 50
Average number of queries per client: 1
When run on MySQL 5.0
mysqlslap --concurrency=50 --iterations=500 --query=test2.sql
–create-schema=nm --user root --password
Enter password:
Benchmark
Average number of seconds to run all queries: 0.001 seconds
Minimum number of seconds to run all queries: 0.001 seconds
Maximum number of seconds to run all queries: 0.005 seconds
Number of clients running queries: 50
Average number of queries per client: 1
select COUNT() from aaa;
1849233
select COUNT() from bbb;
1202229
SELECT aaa.big_int_val FROM aaa INNER JOIN bbb ON aaa.bbb_id = bbb.id WHERE aaa.big_int_val > 8206166128 AND aaa.big_int_val <= 8206166260 ORDER BY aaa.big_int_val;
0
mysql> show create table aaa \G
*************************** 1. row ***************************
Table: aaa
Create Table: CREATE TABLE aaa (
aaa_id varchar(255) NOT NULL,
bbb_id varchar(255) NOT NULL,
other_id varchar(255) DEFAULT NULL,
int_1 int(10) unsigned NOT NULL,
enum_val enum(‘network’,‘subnet’) NOT NULL,
big_int_val bigint(20) unsigned NOT NULL,
deleted_flag tinyint(1) NOT NULL DEFAULT ‘0’,
creation_big_int_val bigint(20) unsigned NOT NULL,
deletion_big_int_val bigint(20) unsigned DEFAULT NULL,
creation_timestamp timestamp NULL DEFAULT NULL,
deletion_timestamp timestamp NULL DEFAULT NULL,
PRIMARY KEY (aaa_id),
UNIQUE KEY big_int_val (big_int_val),
KEY bbb_id (bbb_id)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)
mysql> show create table bbb \G
*************************** 1. row ***************************
Table: bbb
Create Table: CREATE TABLE bbb (
id varchar(255) NOT NULL,
other_id_2 varchar(255) NOT NULL,
name_of_something varchar(255) DEFAULT NULL,
PRIMARY KEY (id),
KEY other_id_2 (other_id_2),
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)
I captured the 5.5 queries in the slow query log with profiling enabled in
order to compare a slow query to a fast query.
Here is a slow query:
Time: 150531 19:02:33.447599
User@Host: root[root] @ localhost
Thread_id: 2607933 Schema: nm Last_errno: 0 Killed: 0
Query_time: 0.100234 Lock_time: 0.000325 Rows_sent: 0 Rows_examined: 0
Rows_affected: 0 Rows_read: 0
Bytes_sent: 131
Profile_starting: 0.000118
Profile_starting_cpu: 0.000099
Profile_checking_permissions: 0.000020
Profile_checking_permissions_cpu: 0.000020
Profile_checking_permissions: 0.000019
Profile_checking_permissions_cpu: 0.000019
Profile_Opening_tables: 0.000142
Profile_Opening_tables_cpu: 0.000128
Profile_System_lock: 0.000013
Profile_System_lock_cpu: 0.000013
Profile_mysql_lock_tables()_unlocking_tables_II: 0.000018
Profile_mysql_lock_tables()_unlocking_tables_II_cpu: 0.000018
Profile_exit_mysqld_lock_tables(): 0.000017
Profile_exit_mysqld_lock_tables()_cpu: 0.000013
Profile_init: 0.000017
Profile_init_cpu: 0.000017
Profile_optimizing: 0.000034
Profile_optimizing_cpu: 0.000027
Profile_statistics: 0.000145
Profile_statistics_cpu: 0.000124
Profile_preparing: 0.000041
Profile_preparing_cpu: 0.000031
Profile_executing: 0.000024
Profile_executing_cpu: 0.000019
Profile_Sorting_result: 0.000033
Profile_Sorting_result_cpu: 0.000024
*************************************** Profile_Sending_data: 0.099546
Profile_Sending_data_cpu: 0.000084
Profile_end: 0.000005
Profile_end_cpu: 0.000005
Profile_query_end: 0.000015
Profile_query_end_cpu: 0.000014
Profile_closing_tables: 0.000019
Profile_closing_tables_cpu: 0.000019
Profile_freeing_items: 0.000026
Profile_freeing_items_cpu: 0.000026
Profile_logging_slow_query: 0.000031
Profile_logging_slow_query_cpu: 0.000018
Profile_total: 0.100281
Profile_total_cpu: 0.000719
SET timestamp=1433091753;
Here is a fast query:
Time: 150531 19:02:33.449295
User@Host: root[root] @ localhost
Thread_id: 2607952 Schema: nm Last_errno: 0 Killed: 0
Query_time: 0.000198 Lock_time: 0.000073 Rows_sent: 0 Rows_examined: 0
Rows_affected: 0 Rows_read: 0
Bytes_sent: 131
Profile_starting: 0.000028
Profile_starting_cpu: 0.000028
Profile_checking_permissions: 0.000003
Profile_checking_permissions_cpu: 0.000003
Profile_checking_permissions: 0.000003
Profile_checking_permissions_cpu: 0.000003
Profile_Opening_tables: 0.000036
Profile_Opening_tables_cpu: 0.000036
Profile_System_lock: 0.000004
Profile_System_lock_cpu: 0.000004
Profile_mysql_lock_tables()_unlocking_tables_II: 0.000002
Profile_mysql_lock_tables()_unlocking_tables_II_cpu: 0.000002
Profile_exit_mysqld_lock_tables(): 0.000004
Profile_exit_mysqld_lock_tables()_cpu: 0.000004
Profile_init: 0.000013
Profile_init_cpu: 0.000013
Profile_optimizing: 0.000006
Profile_optimizing_cpu: 0.000006
Profile_statistics: 0.000030
Profile_statistics_cpu: 0.000030
Profile_preparing: 0.000012
Profile_preparing_cpu: 0.000011
Profile_executing: 0.000002
Profile_executing_cpu: 0.000001
Profile_Sorting_result: 0.000002
Profile_Sorting_result_cpu: 0.000002
*************************************** Profile_Sending_data: 0.000031
Profile_Sending_data_cpu: 0.000031
Profile_end: 0.000003
Profile_end_cpu: 0.000003
Profile_query_end: 0.000005
Profile_query_end_cpu: 0.000005
Profile_closing_tables: 0.000005
Profile_closing_tables_cpu: 0.000005
Profile_freeing_items: 0.000012
Profile_freeing_items_cpu: 0.000012
Profile_logging_slow_query: 0.000002
Profile_logging_slow_query_cpu: 0.000002
Profile_total: 0.000203
Profile_total_cpu: 0.000202
SET timestamp=1433091753;