Document contains periodic audit of query performance and mysql server optimizations.
Upgrade MySQL server to 5.6. Reported performance boosts. Setup indexes, MasterMaster, Sharding. Research Percona 5.5 XtraDB Cluster & MariaDB ($$)
Configuration :
sync_binlog=1 slow-query-log = 1 slow-query-log-file = /var/log/mysql/mysql-slow.log long_query_time = 1 log-queries-not-using-indexes
# Overall: 69.24k total, 142 unique, 0.84 QPS, 0.00x concurrency _________
# Time range: 2014-06-29 00:15:27 to 23:05:31
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 129s 117us 10s 2ms 8ms 39ms 541us
# Lock time 10s 0 116ms 138us 204us 974us 119us
# Rows sent 739.49k 0 1.73k 10.94 1.96 121.88 0
# Rows examine 41.32M 0 1.05M 625.84 1.78k 7.06k 22.53
# Query size 14.59M 16 2.86k 220.95 363.48 94.38 234.30
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ======= ===== ==============
# 1 0x82E7D47835BE4056 55.2638 42.7% 6899 0.0080 0.00 SELECT users
# 2 0x5725EFD7A21CCC98 16.5702 12.8% 32305 0.0005 0.00 SELECT delayed_jobs
# 3 0x9D6306F0A5C31C72 16.1724 12.5% 14628 0.0011 0.00 SELECT permalinks
# 4 0xF9A57DD5A41825CA 10.2317 7.9% 1 10.2317 0.00 SELECT
# 5 0x57EC86EA18BB59A3 10.0432 7.8% 455 0.0221 0.00 SELECT users
# 6 0xBA85D722D89C814E 4.6461 3.6% 537 0.0087 0.04 SELECT users
# 7 0xA2F83841F2519905 4.0722 3.1% 3 1.3574 0.00 SELECT activities
# 8 0x8E20783F0D97D2A4 2.2644 1.7% 472 0.0048 0.03 SELECT posts featured_items users
# 9 0x95BA57AFA503BFC5 1.5929 1.2% 3540 0.0004 0.00 SELECT disk_usages
# 10 0x48F7FFE893831DF2 1.2886 1.0% 1310 0.0010 0.00 SELECT live_events
# 11 0x23CA16FF481B4519 1.1693 0.9% 299 0.0039 0.12 SELECT progress_breakups
# MISC 0xMISC 6.0977 4.7% 8788 0.0007 0.0 <131 ITEMS>
# Query 1: 0.09 QPS, 0.00x concurrency, ID 0x82E7D47835BE4056 at byte 20331321
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 01:24:37 to 23:05:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 9 6899
# Exec time 42 55s 7ms 14ms 8ms 8ms 604us 8ms
# Lock time 4 435ms 40us 4ms 63us 89us 64us 54us
# Rows sent 1 10.96k 1 3 1.63 2.90 0.61 1.96
# Rows examine 28 11.67M 1.73k 1.73k 1.73k 1.69k 0 1.69k
# Query size 5 869.11k 129 129 129 129 0 129
# String:
# Databases cbprod
# Hosts (6881/99%), 10-166-152... (18/0%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'users'\G
# SHOW CREATE TABLE `cbprod`.`users`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `users` WHERE (`users`.company_id = 3) AND ((sb_last_seen_at > '2014-06-30 00:02:11') AND (`users`.company_id = 3))\G
# Query 2: 0.40 QPS, 0.00x concurrency, ID 0x5725EFD7A21CCC98 at byte 931
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 00:34:20 to 23:05:29
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 46 32305
# Exec time 12 17s 166us 33ms 512us 657us 239us 490us
# Lock time 60 6s 53us 32ms 181us 224us 179us 176us
# Rows sent 0 24 0 1 0.00 0 0.03 0
# Rows examine 0 50 0 2 0.00 0 0.05 0
# Query size 50 7.41M 240 241 240.64 234.30 0 234.30
# String:
# Databases cbprod
# Hosts (16176/50%), 10-166-152... (16129/49%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms #
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'delayed_jobs'\G
# SHOW CREATE TABLE `cbprod`.`delayed_jobs`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `delayed_jobs` WHERE ((run_at <= '2014-06-29 07:34:20' AND (locked_at IS NULL OR locked_at < '2014-06-29 03:34:20') OR (locked_by = 'host:prodapp01 pid:16233')) AND failed_at IS NULL) ORDER BY priority DESC, run_at ASC LIMIT 5\G
# Query 3: 0.18 QPS, 0.00x concurrency, ID 0x9D6306F0A5C31C72 at byte 9480
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 00:35:31 to 23:03:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 21 14628
# Exec time 12 16s 155us 94ms 1ms 2ms 837us 1ms
# Lock time 11 1s 42us 87ms 76us 131us 715us 57us
# Rows sent 1 14.29k 1 1 1 1 0 1
# Rows examine 42 17.72M 9 2.01k 1.24k 1.96k 520.44 1.26k
# Query size 18 2.67M 189 200 191.22 192.76 3.23 183.58
# String:
# Databases cbprod
# Hosts (7560/51%), 10-166-152... (7068/48%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us ###############
# 1ms ################################################################
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'permalinks'\G
# SHOW CREATE TABLE `cbprod`.`permalinks`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `permalinks` WHERE (`permalinks`.link_id = 175 AND `permalinks`.link_type = 'Post') AND (permalinks.deleted_at IS NULL OR permalinks.deleted_at > '2014-06-29 07:35:32') LIMIT 1\G
# Query 4: 0 QPS, 0x concurrency, ID 0xF9A57DD5A41825CA at byte 0 ________
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2014-06-29 00:15:27
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1
# Exec time 7 10s 10s 10s 10s 10s 0 10s
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 0 1 1 1 1 1 0 1
# Rows examine 0 0 0 0 0 0 0 0
# Query size 0 16 16 16 16 16 0 16
# String:
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(10)\G
# Query 5: 0.01 QPS, 0.00x concurrency, ID 0x57EC86EA18BB59A3 at byte 2993789
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 00:45:41 to 23:02:42
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 455
# Exec time 7 10s 19ms 39ms 22ms 26ms 2ms 21ms
# Lock time 0 24ms 36us 140us 52us 98us 19us 44us
# Rows sent 90 668.25k 1.47k 1.47k 1.47k 1.46k 0 1.46k
# Rows examine 1 787.77k 1.73k 1.73k 1.73k 1.69k 0 1.69k
# Query size 0 23.11k 52 52 52 52 0 52
# String:
# Databases cbprod
# Hosts (256/56%), 10-166-152... (199/43%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ################################################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'users'\G
# SHOW CREATE TABLE `cbprod`.`users`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `users` WHERE (`users`.company_id = 3)\G
# Query 6: 0.01 QPS, 0.00x concurrency, ID 0xBA85D722D89C814E at byte 221218
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.04
# Time range: 2014-06-29 00:39:30 to 23:04:26
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 537
# Exec time 3 5s 7ms 444ms 9ms 8ms 18ms 8ms
# Lock time 0 38ms 41us 192us 70us 131us 32us 52us
# Rows sent 0 1.20k 1 4 2.29 2.90 0.63 1.96
# Rows examine 2 929.72k 1.73k 1.73k 1.73k 1.69k 0 1.69k
# Query size 0 36.18k 69 69 69 69 0 69
# String:
# Databases cbprod
# Hosts 10-166-152... (269/50%), (268/49%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms #
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'users'\G
# SHOW CREATE TABLE `cbprod`.`users`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `users` WHERE (sb_last_seen_at > '2014-06-29 07:37:20')\G
# Query 7: 0.00 QPS, 0.01x concurrency, ID 0xA2F83841F2519905 at byte 250580
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 00:40:22 to 00:52:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 3
# Exec time 3 4s 1s 1s 1s 1s 31ms 1s
# Lock time 0 497us 109us 234us 165us 224us 48us 152us
# Rows sent 0 15 5 5 5 5 0 5
# Rows examine 7 3.14M 1.05M 1.05M 1.05M 1.03M 0 1.03M
# Query size 0 1.27k 432 432 432 432 0 432
# String:
# Databases cbprod
# Hosts 10-166-152-19.cloud.opsource.net
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'activities'\G
# SHOW CREATE TABLE `cbprod`.`activities`\G
# SHOW TABLE STATUS FROM `cbprod` LIKE 'activities'\G
# SHOW CREATE TABLE `cbprod`.`activities`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `activities` WHERE (`activities`.user_id = 1275) AND ((((activities.id = (SELECT a.id from activities as a where a.item_id = activities.item_id AND a.item_type = activities.item_type ORDER BY a.created_at DESC LIMIT 1)) AND (`activities`.`action` = 'viewed')) AND (`activities`.`item_type` IN ('Course','Certification','LiveEvent','InPersonEvent'))) AND (`activities`.user_id = 1275)) ORDER BY created_at desc LIMIT 5\G
# Query 8: 0.01 QPS, 0.00x concurrency, ID 0x8E20783F0D97D2A4 at byte 528307
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.03
# Time range: 2014-06-29 00:45:40 to 23:02:41
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 472
# Exec time 1 2s 2ms 259ms 5ms 6ms 12ms 4ms
# Lock time 0 48ms 77us 703us 101us 159us 41us 89us
# Rows sent 1 9.22k 20 20 20 20 0 20
# Rows examine 0 111.74k 241 243 242.42 234.30 0 234.30
# Query size 1 247.06k 536 536 536 536 0 536
# String:
# Databases cbprod
# Hosts (263/55%), 10-166-152... (209/44%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms #
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'posts'\G
# SHOW CREATE TABLE `cbprod`.`posts`\G
# SHOW TABLE STATUS FROM `cbprod` LIKE 'featured_items'\G
# SHOW CREATE TABLE `cbprod`.`featured_items`\G
# SHOW TABLE STATUS FROM `cbprod` LIKE 'users'\G
# SHOW CREATE TABLE `cbprod`.`users`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `posts`.* FROM `posts` INNER JOIN `featured_items` ON `featured_items`.item_id = `posts`.id AND `featured_items`.item_type = 'Post' INNER JOIN `users` ON `posts`.user_id = `users`.id WHERE ((`users`.company_id = 3)) AND (((published_as = 'live' AND display_in_catalog_start_date <= '2014-06-29 07:45:40' AND (display_in_catalog_end_date >= '2014-06-29 07:45:40' OR display_in_catalog_end_date IS NULL)) AND ((`users`.company_id = 3))) AND (posts.deleted_at IS NULL OR posts.deleted_at > '2014-06-29 07:45:40')) ORDER BY position\G
# Query 9: 131.11 QPS, 0.06x concurrency, ID 0x95BA57AFA503BFC5 at byte 2038193
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 01:59:59 to 02:00:26
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 5 3540
# Exec time 1 2s 117us 86ms 449us 657us 1ms 403us
# Lock time 2 212ms 31us 64ms 59us 54us 1ms 38us
# Rows sent 0 3.46k 1 1 1 1 0 1
# Rows examine 7 2.99M 1 1.73k 885.50 1.61k 499.22 874.75
# Query size 1 250.22k 70 73 72.38 72.65 1.50 69.19
# String:
# Databases cbprod
# Hosts (1770/50%), 10-166-152... (1770/50%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms #
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'disk_usages'\G
# SHOW CREATE TABLE `cbprod`.`disk_usages`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `disk_usages` WHERE (`disk_usages`.user_id = 1) LIMIT 1\G
# Query 10: 0.02 QPS, 0.00x concurrency, ID 0x48F7FFE893831DF2 at byte 15521312
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-06-29 00:36:20 to 23:04:26
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 1 1310
# Exec time 0 1s 694us 6ms 983us 1ms 229us 972us
# Lock time 1 168ms 50us 249us 128us 176us 40us 138us
# Rows sent 0 1.57k 0 2 1.23 1.96 0.94 1.96
# Rows examine 0 345.83k 269 272 270.33 258.32 1.12 258.32
# Query size 1 275.05k 215 215 215 215 0 215
# String:
# Databases cbprod
# Hosts (656/50%), 10-166-152... (654/49%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us ####################################
# 1ms ################################################################
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'live_events'\G
# SHOW CREATE TABLE `cbprod`.`live_events`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `live_events` WHERE ((scheduled_end_time >= '2014-06-28 19:36:20' && scheduled_end_time <= '2014-06-29 19:36:20') AND (live_events.deleted_at IS NULL OR live_events.deleted_at > '2014-06-29 19:36:20'))\G
# Query 11: 0.00 QPS, 0.00x concurrency, ID 0x23CA16FF481B4519 at byte 640266
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.12
# Time range: 2014-06-29 00:47:23 to 23:02:16
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 299
# Exec time 0 1s 2ms 381ms 4ms 3ms 21ms 3ms
# Lock time 1 129ms 44us 112ms 432us 93us 6ms 49us
# Rows sent 0 292 0 1 0.98 0.99 0.15 0.99
# Rows examine 4 1.92M 6.56k 6.58k 6.57k 6.31k 0 6.31k
# Query size 0 40.29k 138 138 138 138 0 138
# String:
# Databases cbprod
# Hosts (288/96%), 10-166-152... (11/3%)
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'progress_breakups'\G
# SHOW CREATE TABLE `cbprod`.`progress_breakups`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `progress_breakups` WHERE (`progress_breakups`.progress_score_id = 4132) ORDER BY progress_breakups.created_at desc LIMIT 1\G
137s-MacBook-Pro:Expertus p137$ ./pt-query-digest mysql-slow
mysql-slow-mast.log mysql-slow.log
137s-MacBook-Pro:Expertus p137$ ./pt-query-digest mysql-slow-mast.log
# 320ms user time, 60ms system time, 23.21M rss, 2.36G vsz
# Current date: Mon Jun 30 14:27:31 2014
# Hostname: 137s-MacBook-Pro.local
# Files: mysql-slow-mast.log
# Overall: 433 total, 31 unique, 0.01 QPS, 0.00x concurrency _____________
# Time range: 2014-06-29 00:15:44 to 23:05:40
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 23s 64us 10s 54ms 6ms 602ms 194us
# Lock time 9ms 0 790us 20us 69us 59us 0
# Rows sent 7.31M 0 3.61M 17.28k 1.69k 243.33k 2.90
# Rows examine 7.39M 0 3.61M 17.47k 1.96k 243.32k 46.83
# Query size 39.59k 6 1.00k 93.63 271.23 88.84 54.21
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ======= ===== ============
# 1 0x67A347A2812914DF 11.9692 51.2% 300 0.0399 4.97 SELECT carts
# 2 0xF9A57DD5A41825CA 10.0010 42.8% 1 10.0010 0.00 SELECT
# 3 0x813031B8BBC3B329 1.2120 5.2% 1 1.2120 0.00 COMMIT
# MISC 0xMISC 0.1911 0.8% 131 0.0015 0.0 <28 ITEMS>
# Query 1: 0.01 QPS, 0.00x concurrency, ID 0x67A347A2812914DF at byte 60326
# This item is included in the report because it matches --limit.
# Scores: V/M = 4.97
# Time range: 2014-06-29 01:05:01 to 13:05:07
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 69 300
# Exec time 51 12s 64us 6s 40ms 6ms 445ms 125us
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 99 7.30M 0 3.61M 24.93k 2.27k 292.02k 38.53
# Rows examine 98 7.30M 0 3.61M 24.93k 2.27k 292.02k 38.53
# Query size 39 15.77k 44 73 53.81 62.76 6.00 51.63
# String:
# Databases cbprod
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us ###################################################
# 100us ################################################################
# 1ms ###############
# 10ms ###
# 100ms #
# 1s #
# 10s+
# Tables
# SHOW TABLE STATUS FROM `cbprod` LIKE 'carts'\G
# SHOW CREATE TABLE `cbprod`.`carts`\G
SELECT /*!40001 SQL_NO_CACHE */ * FROM `carts`\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
SELECT /*!40001 SQL_NO_CACHE */ * FROM `carts`\G
# Query 2: 0 QPS, 0x concurrency, ID 0xF9A57DD5A41825CA at byte 0 ________
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2014-06-29 00:15:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1
# Exec time 42 10s 10s 10s 10s 10s 0 10s
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 0 1 1 1 1 1 0 1
# Rows examine 0 0 0 0 0 0 0 0
# Query size 0 16 16 16 16 16 0 16
# String:
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(10)\G
# Query 3: 0 QPS, 0x concurrency, ID 0x813031B8BBC3B329 at byte 39316 ____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2014-06-29 01:22:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1
# Exec time 5 1s 1s 1s 1s 1s 0 1s
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Query size 0 6 6 6 6 6 0 6
# String:
# Databases cbprod
# Hosts
# Users cbpuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
COMMIT\G