After upgrading from MySQL 5.0 to Percona 5.5 P99 is much slower

vnicotravnicotra EntrantInactive User Role Participant
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
# [email protected]: 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
# [email protected]: 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;

Comments

  • vnicotravnicotra Entrant Inactive User Role Participant
    Here is the explain:
    explain 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;
    +----+
    +
    +
    +
    +
    +
    +
    +
    +
    +
    | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra +----+
    +
    +
    +
    +
    +
    +
    +
    +
    +
    | 1 | SIMPLE | aaa | range | big_int_val,bbb_id | big_int_val | 8 | NULL | 1 | Using where |
    | 1 | SIMPLE | bbb | eq_ref | PRIMARY | PRIMARY | 257 | my_schema.aaa.bbb_id | 1 | Using index |
    +----+
    +
    +
    +
    +
    +
    +
    +
    +
    +
Sign In or Register to comment.

MySQL, InnoDB, MariaDB and MongoDB are trademarks of their respective owners.
Copyright ©2005 - 2020 Percona LLC. All rights reserved.