ISUCON10に参加して惨敗した。その後のDiscordや参加者記事で知らなかったことなどを調べたり試してみた。
MySQLのクエリキャッシュ
そもそもクエリキャッシュを有効にしてなかったorz
キャッシュヒット率はQcache_hits / ( Qcache_hits + Qcache_inserts + Qcache_not_cached ) で算出可能。
# vi /etc/mysql/my.cnf query_cache_type = 1 を追加 # mysql -uroot -p mysql> SHOW VARIABLES LIKE '%query_cache_%'; +------------------------------+----------+ | Variable_name | Value | +------------------------------+----------+ | query_cache_limit | 1048576 | | query_cache_min_res_unit | 4096 | | query_cache_size | 16777216 | | query_cache_type | ON | | query_cache_wlock_invalidate | OFF | +------------------------------+----------+ 5 rows in set (0.00 sec) mysql> SHOW STATUS LIKE 'Qcache%'; +-------------------------+----------+ | Variable_name | Value | +-------------------------+----------+ | Qcache_free_blocks | 1 | # クエリキャッシュ内の空きメモリブロック数 | Qcache_free_memory | 16601384 | # クエリキャッシュ用の空きメモリ量 | Qcache_hits | 7 | # クエリキャッシュヒット数 | Qcache_inserts | 9 | # クエリキャッシュに追加されるクエリ数 | Qcache_lowmem_prunes | 0 | # メモリ不足でクエリーキャッシュから削除されたクエリ数 | Qcache_not_cached | 231 | # 非キャッシュクエリ数 | Qcache_queries_in_cache | 9 | # クエリキャッシュ内に登録されたクエリ数 | Qcache_total_blocks | 21 | # クエリキャッシュ内のブロック合計数 +-------------------------+----------+ 8 rows in set (0.00 sec)
pt-query-digest
・スローログをノーマライズ・集計し、人間が判断しやすい形式で出力させることが可能。
・Percona社が開発・配布するMySQL用のユーティリティーキットで「Percona Toolkit」の1つ。
# apt install percona-toolkit
...
# pt-query-digest slow.log
# 400ms user time, 20ms system time, 29.04M rss, 84.09M vsz
# Current date: Mon Sep 14 11:49:22 2020
# Hostname: team135-003
# Files: slow.log
# Overall: 705 total, 21 unique, 0.01 QPS, 0.00x concurrency _____________
# Time range: 2020-09-13T16:35:35 to 2020-09-14T06:25:01
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 8s 2us 3s 11ms 3ms 170ms 152us
# Lock time 57ms 0 5ms 81us 204us 181us 57us
# Rows sent 1.75k 0 301 2.55 19.46 14.58 0.99
# Rows examine 876.54k 0 36.11k 1.24k 1012.63 5.66k 0.99
# Query size 351.14k 26 683 510.03 652.75 251.53 621.67
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== =============
# 1 0xF418F8958C3A84C3 3.3505 41.5% 6 0.5584 2.53 SELECT estate
# 2 0xD5E8472C4FDAEE41 3.1777 39.4% 9 0.3531 2.58 SELECT chair
# 3 0x85DF0F23BB694539 0.9487 11.7% 2 0.4743 0.92 SELECT estate
# 4 0x4F5BBA6F46285FBC 0.1663 2.1% 9 0.0185 0.00 SELECT chair
# 5 0xBB5556170BADF35E 0.0871 1.1% 531 0.0002 0.00 SELECT estate
# MISC 0xMISC 0.3442 4.3% 148 0.0023 0.0 <16 ITEMS>
# Query 1: 0.50 QPS, 0.28x concurrency, ID 0xF418F8958C3A84C3 at byte 492810
# Scores: V/M = 2.53
# Time range: 2020-09-13T18:01:19 to 2020-09-13T18:01:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 6
# Exec time 41 3s 36us 3s 558ms 3s 1s 21ms
# Lock time 0 445us 0 205us 74us 204us 80us 116us
# Rows sent 3 60 0 20 10 19.46 9.73 19.46
# Rows examine 10 88.05k 0 29.39k 14.67k 28.66k 14.33k 28.66k
# Query size 0 700 116 117 116.67 112.70 0.00 112.70
# String:
# Databases isuumo
# Hosts 10.161.35.101
# Users isucon
# Query_time distribution
# 1us
# 10us ################################################################
# 100us
# 1ms
# 10ms ##########################################
# 100ms
# 1s #####################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuumo` LIKE 'estate'\G
# SHOW CREATE TABLE `isuumo`.`estate`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM estate WHERE door_width >= 110 AND door_width < 150 ORDER BY popularity DESC, id ASC LIMIT 20 OFFSET 0\G
# Query 2: 0.01 QPS, 0.00x concurrency, ID 0xD5E8472C4FDAEE41 at byte 281849
# Scores: V/M = 2.58
# Time range: 2020-09-13T17:22:12 to 2020-09-13T17:43:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 1 9
# Exec time 39 3s 51us 3s 353ms 3s 954ms 17ms
# Lock time 2 1ms 0 225us 146us 224us 79us 159us
# Rows sent 0 7 0 1 0.78 0.99 0.41 0.99
# Rows examine 23 205.08k 0 29.30k 22.79k 28.66k 11.91k 28.66k
# Query size 0 675 75 75 75 75 0 75
# String:
# Databases isuumo
# Hosts 10.161.35.101
# Users isucon
# Query_time distribution
# 1us
# 10us #####################
# 100us
# 1ms
# 10ms ################################################################
# 100ms
# 1s ##########
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuumo` LIKE 'chair'\G
# SHOW CREATE TABLE `isuumo`.`chair`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) FROM chair WHERE width >= 110 AND width < 150 AND stock > 0\G
# Query 3: 0.00 QPS, 0.00x concurrency, ID 0x85DF0F23BB694539 at byte 287070
# Scores: V/M = 0.92
# Time range: 2020-09-13T16:38:01 to 2020-09-13T17:44:13
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 2
# Exec time 11 949ms 7ms 941ms 474ms 941ms 660ms 474ms
# Lock time 0 492us 176us 316us 246us 316us 98us 246us
# Rows sent 29 531 230 301 265.50 301 50.20 265.50
# Rows examine 0 1.04k 460 602 531 602 100.41 531
# Query size 0 383 190 193 191.50 193 2.12 191.50
# String:
# Databases isuumo
# Hosts 10.161.35.101
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuumo` LIKE 'estate'\G
# SHOW CREATE TABLE `isuumo`.`estate`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM estate WHERE latitude <= '35.926868653041' AND latitude >= '35.733136223134' AND longitude <= '139.64172363281' AND longitude >= '139.31488037109' ORDER BY popularity DESC, id ASC\G
# Query 4: 0.01 QPS, 0.00x concurrency, ID 0x4F5BBA6F46285FBC at byte 283764
# Scores: V/M = 0.00
# Time range: 2020-09-13T17:22:12 to 2020-09-13T17:43:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 1 9
# Exec time 2 166ms 36us 21ms 18ms 21ms 6ms 20ms
# Lock time 2 1ms 0 243us 142us 236us 59us 138us
# Rows sent 8 160 0 20 17.78 19.46 6.12 19.46
# Rows examine 26 234.63k 0 29.38k 26.07k 28.66k 9.01k 28.66k
# Query size 0 1.05k 119 120 119.22 118.34 0 118.34
# String:
# Databases isuumo
# Hosts 10.161.35.101
# Users isucon
# Query_time distribution
# 1us
# 10us ########
# 100us
# 1ms
# 10ms ################################################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuumo` LIKE 'chair'\G
# SHOW CREATE TABLE `isuumo`.`chair`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM chair WHERE width >= 110 AND width < 150 AND stock > 0 ORDER BY popularity DESC, id ASC LIMIT 20 OFFSET 40\G
# Query 5: 0.13 QPS, 0.00x concurrency, ID 0xBB5556170BADF35E at byte 13203
# Scores: V/M = 0.00
# Time range: 2020-09-13T16:38:01 to 2020-09-13T17:44:13
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 75 531
# Exec time 1 87ms 98us 453us 163us 214us 38us 152us
# Lock time 60 35ms 47us 214us 65us 80us 15us 57us
# Rows sent 20 370 0 1 0.70 0.99 0.46 0.99
# Rows examine 0 370 0 1 0.70 0.99 0.46 0.99
# Query size 97 341.63k 638 683 658.82 652.75 15.40 621.67
# String:
# Databases isuumo
# Hosts 10.161.35.101
# Users isucon
# Query_time distribution
# 1us
# 10us #
# 100us ################################################################
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `1` LIKE 'estate'\G
# SHOW CREATE TABLE `1`.`estate`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM estate WHERE id = '27762' AND ST_Contains(ST_PolygonFromText('POLYGON((35.750970 139.498901,35.750970 139.586792,35.753199 139.630737,35.757657 139.671936,35.773258 139.710388,35.782171 139.729614,35.920196 139.644470,35.944659 139.627991,35.953553 139.614258,35.960223 139.595032,35.960223 139.551086,35.951330 139.512634,35.949106 139.504395,35.940212 139.487915,35.924645 139.471436,35.902400 139.449463,35.860118 139.408264,35.842308 139.400024,35.826721 139.394531,35.784399 139.394531,35.764343 139.411011,35.757657 139.441223,35.753199 139.463196,35.750970 139.498901))'), ST_GeomFromText('POINT(35.801034 139.625385)'))\G
ノーマライズされた上でスローログが分析されるが、[EXPLAIN]項目はそのままEXPLAINできるように出力されている。
その提案をもとに改善する。
# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 28
Server version: 5.7.31-0ubuntu0.18.04.1-log (Ubuntu)
mysql> use isuumo
mysql> explain SELECT * FROM estate WHERE door_width >= 110 AND door_width < 150 ORDER BY popularity DESC, id ASC LIMIT 20 OFFSET 0\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: estate
partitions: NULL
type: ALL
possible_keys: index_estate_width_height,index_estate_width_height_order
key: NULL
key_len: NULL
ref: NULL
rows: 28688
filtered: 44.07
Extra: Using where; Using filesort
1 row in set, 1 warning (0.00 sec)
MySQLTuner
・サーバのパフォーマンスの概観を表示し、推奨設定を提示してくれるツール
# apt install mysqltuner
...
# mysqltuner
>> MySQLTuner 1.7.2 - Major Hayden <major@mhtx.net>
>> Bug reports, feature requests, and downloads at http://mysqltuner.com/
>> Run with '--help' for additional options and output filtering
[--] Skipped version check for MySQLTuner script
[OK] Logged in using credentials from debian maintenance account.
[OK] Currently running supported MySQL version 5.7.31-0ubuntu0.18.04.1-log
[OK] Operating on 64-bit architecture
-------- Log file Recommendations ------------------------------------------------------------------
[--] Log file: /var/log/mysql/error.log(782B)
[OK] Log file /var/log/mysql/error.log exists
[OK] Log file /var/log/mysql/error.log is readable.
[OK] Log file /var/log/mysql/error.log is not empty
[OK] Log file /var/log/mysql/error.log is smaller than 32 Mb
[OK] /var/log/mysql/error.log doesn't contain any warning.
[!!] /var/log/mysql/error.log contains 5 error(s).
[--] 0 start(s) detected in /var/log/mysql/error.log
[--] 0 shutdown(s) detected in /var/log/mysql/error.log
-------- Storage Engine Statistics -----------------------------------------------------------------
[--] Status: +ARCHIVE +BLACKHOLE +CSV -FEDERATED +InnoDB +MEMORY +MRG_MYISAM +MyISAM +PERFORMANCE_SCHEMA
[--] Data in InnoDB tables: 51M (Tables: 7)
[OK] Total fragmented tables: 0
-------- Security Recommendations ------------------------------------------------------------------
[OK] There are no anonymous accounts for any database users
[!!] User 'root@localhost' has no password set.
[!!] User 'isucon@%' has user name as password.
[!!] User 'isucon@localhost' has user name as password.
[!!] User 'isucon@%' hasn't specific host restriction.
[--] There are 612 basic passwords in the list.
-------- CVE Security Recommendations --------------------------------------------------------------
[OK] NO SECURITY CVE FOUND FOR YOUR VERSION
-------- Performance Metrics -----------------------------------------------------------------------
[--] Up for: 23h 10m 5s (1K q [0.014 qps], 49 conn, TX: 1M, RX: 551K)
[--] Reads / Writes: 100% / 0%
[--] Binary logging is disabled
[--] Physical Memory : 1.9G
[--] Max MySQL memory : 4.1G
[--] Other process memory: 98.4M
[--] Total buffers: 2.1G global + 4.2M per thread (500 max threads)
[--] P_S Max memory usage: 72B
[--] Galera GCache Max memory usage: 0B
[!!] Maximum reached memory usage: 2.1G (107.19% of installed RAM)
[!!] Maximum possible memory usage: 4.1G (211.82% of installed RAM)
[!!] Overall possible memory usage with other process exceeded memory
[!!] Slow queries: 100% (1K/1K)
[OK] Highest usage of available connections: 0% (2/500)
[OK] Aborted connections: 0.00% (0/49)
[!!] Query cache may be disabled by default due to mutex contention.
[!!] Query cache efficiency: 3.3% (34 cached / 1K selects)
[OK] Query cache prunes per day: 0
[OK] Sorts requiring temporary tables: 0% (0 temp sorts / 13 sorts)
[OK] No joins without indexes
[OK] Temporary tables created on disk: 0% (0 on disk / 27 total)
[OK] Thread cache hit rate: 95% (2 created / 49 connections)
[OK] Table cache hit rate: 60% (97 open / 160 opened)
[OK] Open file limit used: 0% (7/5K)
[OK] Table locks acquired immediately: 100% (110 immediate / 110 locks)
-------- Performance schema ------------------------------------------------------------------------
[--] Memory used by P_S: 72B
[--] Sys schema is installed.
-------- ThreadPool Metrics ------------------------------------------------------------------------
[--] ThreadPool stat is disabled.
-------- MyISAM Metrics ----------------------------------------------------------------------------
[!!] Key buffer used: 18.2% (3M used / 16M cache)
[OK] Key buffer size / total MyISAM indexes: 16.0M/43.0K
[!!] Read Key buffer hit rate: 50.0% (6 cached / 3 reads)
-------- InnoDB Metrics ----------------------------------------------------------------------------
[--] InnoDB is enabled.
[--] InnoDB Thread Concurrency: 0
[OK] InnoDB File per table is activated
[OK] InnoDB buffer pool / data size: 2.0G/51.3M
[!!] Ratio InnoDB log file size / InnoDB Buffer pool size (150 %): 1.5G * 2/2.0G should be equal 25%
[!!] InnoDB buffer pool instances: 8
[--] Number of InnoDB Buffer Pool Chunk : 16 for 8 Buffer Pool Instance(s)
[OK] Innodb_buffer_pool_size aligned with Innodb_buffer_pool_chunk_size & Innodb_buffer_pool_instances
[OK] InnoDB Read buffer efficiency: 96.79% (68237 hits/ 70499 total)
[!!] InnoDB Write Log efficiency: 0% (2 hits/ 0 total)
[OK] InnoDB log waits: 0.00% (0 waits / 2 writes)
-------- AriaDB Metrics ----------------------------------------------------------------------------
[--] AriaDB is disabled.
-------- TokuDB Metrics ----------------------------------------------------------------------------
[--] TokuDB is disabled.
-------- XtraDB Metrics ----------------------------------------------------------------------------
[--] XtraDB is disabled.
-------- RocksDB Metrics ---------------------------------------------------------------------------
[--] RocksDB is disabled.
-------- Spider Metrics ----------------------------------------------------------------------------
[--] Spider is disabled.
-------- Connect Metrics ---------------------------------------------------------------------------
[--] Connect is disabled.
-------- Galera Metrics ----------------------------------------------------------------------------
[--] Galera is disabled.
-------- Replication Metrics -----------------------------------------------------------------------
[--] Galera Synchronous replication: NO
[--] No replication slave(s) for this server.
[--] This is a standalone server.
-------- Recommendations ---------------------------------------------------------------------------
General recommendations:
Control error line(s) into /var/log/mysql/error.log file
Set up a Password for user with the following SQL statement ( SET PASSWORD FOR 'user'@'SpecificDNSorIp' = PASSWORD('secure_password'); )
Set up a Secure Password for user@host ( SET PASSWORD FOR 'user'@'SpecificDNSorIp' = PASSWORD('secure_password'); )
Restrict Host for user@% to user@SpecificDNSorIp
MySQL started within last 24 hours - recommendations may be inaccurate
Reduce your overall MySQL memory footprint for system stability
Dedicate this server to your database for highest performance.
Variables to adjust:
*** MySQL's maximum memory usage is dangerously high ***
*** Add RAM before increasing MySQL buffer variables ***
query_cache_size (=0)
query_cache_type (=0)
query_cache_limit (> 1M, or use smaller result sets)
innodb_log_file_size * innodb_log_files_in_group should be equal to 1/4 of buffer pool size (=1G) if possible.
innodb_buffer_pool_instances(=2)
参考
・MySQL クエリキャッシュの概要と導入・評価方法
・スローログの集計に便利な「pt-query-digest」を使ってみよう