DokuWiki

Document contains periodic audit of query performance and mysql server optimizations.

Server opts

Upgrade MySQL server to 5.6. Reported performance boosts. Setup indexes, MasterMaster, Sharding. Research Percona 5.5 XtraDB Cluster & MariaDB ($$)

Queries

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

DokuWiki

Site Tools

Server opts

Queries

Page Tools