Analyze slow MySQL queries with pt-query-digest

tuning-primer.sh [TEMP TABLES]

เริ่มเรื่องจากการรัน tuning-primer.sh เพื่อดูการทำงาน/parameters ของ MySQL เป็นอย่างไรบ้าง ?
พบว่ามีข้อความสีแดงแจ้ง notice เรื่องการ create temporary tables on Disk ในสัดส่วนที่เยอะ หลังจากเพิ่ง restart MySQL ไปเพื่อ enable slow_query_log_file ประมาณ 5 นาทีได้ ตามรูป

ที่ใช้งานอยู่ยังเป็น MySQL version: 5.5.54-log MySQL Community Server (GPL) by Remi บน vps Centos 5.11 i386 ไม่ได้ลงเครื่องใหม่ที 😯 ลองค้นหาจะปรับลดค่านี้ได้อย่างไรบ้าง ?

ก็ไปเจอว่าลอง double value tmp_table_size, max_heap_table_size บน /etc/my.cnf หากเป็น mariadb ก็ mariadb-server.cnf หรือ ไฟล์ cnf ที่สร้างขึ้นมาเองก็แล้วแต่นะครับ

ลองปรับเป็นเพิ่มเป็น 2 เท่า / 4 เท่าก็ไม่ช่วยลดจำนวนการ Created_tmp_disk_tables หลังจาก restart ด้านล่าง


mysql> SHOW GLOBAL STATUS LIKE 'created_tmp%tables';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 758   |
| Created_tmp_tables      | 1158  |
+-------------------------+-------+
2 rows in set (0.00 sec)

mysql> SHOW GLOBAL STATUS LIKE 'created_tmp%tables';

+-------------------------+-------+

| Variable_name | Value |

+-------------------------+-------+

| Created_tmp_disk_tables | 758 |

| Created_tmp_tables | 1158 |

+-------------------------+-------+

2 rows in set (0.00 sec)

อธิบายเพิ่ม Created_tmp_tables คือจำนวนที่สร้าง tmp_tables ทั้งหมด (disk+memory)

ดังนั้นคิดว่าค่านี้ไม่ช่วยในการลดจำนวน Created_tmp_disk_tables ก็ค้นหาต่อ
พบว่า query ใดก็ตามที่มีการใช้งานที่ต้อง sort ข้อมูล เช่น function distinct,group by, order by ที่มีการ rand()
[อันนี้ไม่ได้หาข้อมูลแบบละเอียด ว่ามี fn อะไรบ้าง เอาหลักๆ แค่นี้พอนะ เพราะแค่เกริ่นนำ ค่อย explain query ดูกันเองนะ]
ก็ต้องมีการใช้ temporary table เข้ามาช่วยในการทำงาน หาก output result ใช้ memory

น้อยกว่า min(max_heap_table_size,tmp_table_size) ก็สร้างบน memory
หากมากกว่าก็สร้างบน disk

ยกเว้นว่ามี columns เป็น type BLOB or TEXT จะสร้างบน disk เท่านั้น

WordPress Tables contain BLOB or TEXT

เนื่องจาก vps นี้ใช้งาน MySQL เฉพาะ WordPress เท่านั้น ดังนั้นเลยไปดูกันว่า wp มี table ไหนที่มี column เป็น 2 data type ข้างต้น


mysql> select distinct table_name 
from information_schema.columns 
where (data_type like '%text' or data_type like '%blob') 
and table_schema='mr2t';
+---------------------------+
| table_name                |
+---------------------------+
| mr_backlinks              |
| mr_backlinks_block_domain |
| mr_backlinks_cron         |
| mr_blc_filters            |
| mr_blc_instances          |
| mr_blc_links              |
| mr_cf7dbplugin_submits    |
| mr_cformsdata             |
| mr_commentmeta            |
| mr_comments               |
| mr_ewwwio_images          |
| mr_ez_adsense_options     |
| mr_gpi_page_blacklist     |
| mr_gpi_page_reports       |
| mr_gpi_page_stats         |
| mr_links                  |
| mr_options                |
| mr_postmeta               |
| mr_posts                  |
| mr_ratings                |
| mr_smush_dir_images       |
| mr_term_taxonomy          |
| mr_termmeta               |
| mr_usermeta               |
| mr_wfConfig               |
| mr_wfHits                 |
| mr_wfHoover               |
| mr_wfIssues               |
| mr_wfKnownFileList        |
| mr_wfLogins               |
| mr_wfNotifications        |
| mr_wfPendingIssues        |
+---------------------------+
32 rows in set (0.00 sec)

mysql> select distinct table_name

from information_schema.columns

where (data_type like '%text' or data_type like '%blob')

and table_schema='mr2t';

+---------------------------+

| table_name |

+---------------------------+

| mr_backlinks |

| mr_backlinks_block_domain |

| mr_backlinks_cron |

| mr_blc_filters |

| mr_blc_instances |

| mr_blc_links |

| mr_cf7dbplugin_submits |

| mr_cformsdata |

| mr_commentmeta |

| mr_comments |

| mr_ewwwio_images |

| mr_ez_adsense_options |

| mr_gpi_page_blacklist |

| mr_gpi_page_reports |

| mr_gpi_page_stats |

| mr_links |

| mr_options |

| mr_postmeta |

| mr_posts |

| mr_ratings |

| mr_smush_dir_images |

| mr_term_taxonomy |

| mr_termmeta |

| mr_usermeta |

| mr_wfConfig |

| mr_wfHits |

| mr_wfHoover |

| mr_wfIssues |

| mr_wfKnownFileList |

| mr_wfLogins |

| mr_wfNotifications |

| mr_wfPendingIssues |

+---------------------------+

32 rows in set (0.00 sec)

ผมใช้ prefix=’mr_’ และ wordpress 4.9.1 ใหม่สุดตอนนี้เลย ไปดู WordPress Table Overview ตอนนี้เป็น 4.4.2 ไม่เป็นไรเราต้องการดูหลักๆ ว่าอันไหนเป็น 12 tables default (ไม่ใช่ plugin ที่ติดตั้งเพิ่ม)

wp_commentmeta
wp_comments
wp_links
wp_options
wp_postmeta
wp_posts
wp_terms
wp_termmeta
wp_term_relationships
wp_term_taxonomy
wp_usermeta
wp_users

บรื๋อ… 😕 ของ WordPress เองก็มีการใช้ data type: text สำหรับเก็บข้อมูล 64k bytes เลย
ไม่เป็นไร…เราค่อยไปดูต่อว่าจะมี top query อะไรบ้าง ? ใช้เวลาเท่าไหร่ / tuning ได้อย่างไร ? หรือเป็น query พวกที่ต้องใช้ tmp_tables หรือไม่ ?

สำหรับกรณีหากมีค่า Created_tmp_disk_tables สูง + query ทำงานช้า + การปรับแก้ data type column ยุ่งแน่ เพราะต้องตามมาปรับแก้อยู่เรื่อยไป หากมี WordPress / Plugin version ใหม่ ให้อัพเดท หรือติดตั้ง Plugin ใหม่ก็ดี
แนวทางแก้ไขผ่าน OS คือ mount tmpfs บน tmpdir (ใน /etc/my.cnf) เลย โดยมีรายละเอียดเพิ่มเติมดังนี้

ไม่ใช้ filesystem ramfs เพราะว่าจะขยาย size ไปเรื่อยๆ จน RAM เต็มทำให้กระทบงานอย่างอื่น
ต้องประมาณขนาด output result จาก query ต่าง ๆที่เกิดขึ้น เพื่อกัน RAM มา mount fs ให้เพียงพอ
ตัวอย่างของผม vps RAM 2GB, db ขนาดแค่ 10MB และใน code คงไม่มีการเขียนแบบ SQL cartesian join (All to All join)
- เริ่มต้นสร้าง tmpfs ที่ 100MB ให้ใหญ่ไว้ก่อน แต่ไม่ถึงขนาดเว่อร์มากไปครับ
- จากนั้น monitor ขนาด filesystem ผ่าน shell script ง่ายๆ หรืออะไรก็แล้วแต่
- ค่อยปรับเปลี่ยนลดขนาดให้เหมาะสมต่อไป ผ่าน mount -o remount เพื่อความปลอดภัยควร freeze db (ปิด service เลย/ปิดการ access db ผ่าน app) ก่อนทำการ downsize filesystem ต่อไป

Percona Toolkit

vps ผมเป็น Centos 5.11 i386 เลยเลือก download percona-toolkit-3.0.5_i386.tar.gz ตามนี้

ตรวจสอบ checksum กันหน่อยผ่าน md5sum


[at@vps4 ~]# cat percona-toolkit-3.0.5_i386.tar.gz.md5sum
4c4553125f9c9532e1bce91e6142d061  percona-toolkit-3.0.5_i386.tar.gz
[at@vps4 ~]# md5sum /opt/percona-toolkit-3.0.5_i386.tar.gz                    
4c4553125f9c9532e1bce91e6142d061  /opt/percona-toolkit-3.0.5_i386.tar.gz

[at@vps4 ~]# cat percona-toolkit-3.0.5_i386.tar.gz.md5sum

4c4553125f9c9532e1bce91e6142d061 percona-toolkit-3.0.5_i386.tar.gz

[at@vps4 ~]# md5sum /opt/percona-toolkit-3.0.5_i386.tar.gz

4c4553125f9c9532e1bce91e6142d061 /opt/percona-toolkit-3.0.5_i386.tar.gz

pt-query-digest

จริงๆ ที่สนใจคือ pt-query-digest ที่ไว้สำหรับ Analyze MySQL queries from logs, processlist, and tcpdump.

ดูรายละเอียดการใช้งาน pt-query-digest ก่อนเริ่มต้นใช้งานต้องไปเปิด slow query logs บน MySQL ก่อน

Enabling MySQL Slow Query


slow_query_log = 1 # 0-disable 1-enable
long_query_time = 0 # 0-log every query, 0.1,...
log-queries-not-using-indexes = 0 # 0-disble 1-enable
slow_query_log_file = /var/log/mysqld-slow.log

slow_query_log = 1 # 0-disable 1-enable

long_query_time = 0 # 0-log every query, 0.1,...

log-queries-not-using-indexes = 0 # 0-disble 1-enable

slow_query_log_file = /var/log/mysqld-slow.log

long_query_time = 0 เพื่อให้เก็บทุก query ไว้ใน logfile ไม่ควรเปิดใช้งานตลอด เก็บข้อมูลบางช่วงเวลา แล้ว disble slow query หรือเปลี่ยน long_query_time ให้เป็นค่าที่มากขึ้นเช่น 0.5, 1 คือ 0.5, 1 second เป็นต้น

หากไม่มีไฟล์ /var/log/mysqld-slow.log ต้องสร้างและเปลี่ยน owner ไฟล์ แล้ว restart mysqld service ดังนี้


[root@vps4 ~]# touch /var/log/mysqld-slow.log
[root@vps4 ~]# chown mysql.mysql /var/log/mysqld-slow.log
[root@vps4 ~]# service mysqld restart

[root@vps4 ~]# touch /var/log/mysqld-slow.log

[root@vps4 ~]# chown mysql.mysql /var/log/mysqld-slow.log

[root@vps4 ~]# service mysqld restart

pt-query-digest with mysqld-slow.log


[root@vps4 opt]# tar -zxf percona-toolkit-3.0.5_i386.tar.gz
[root@vps4 opt]# cd /opt/percona-toolkit-3.0.5/bin
[root@vps4 bin]# ls
glide                     pt-fifo-split       pt-kill                  pt-query-digest   pt-summary
pt-align                  pt-find             pt-mext                  pt-show-grants    pt-table-checksum
pt-archiver               pt-fingerprint      pt-mongodb-query-digest  pt-sift           pt-table-sync
pt-config-diff            pt-fk-error-logger  pt-mongodb-summary       pt-slave-delay    pt-table-usage
pt-deadlock-logger        pt-heartbeat        pt-mysql-summary         pt-slave-find     pt-upgrade
pt-diskstats              pt-index-usage      pt-online-schema-change  pt-slave-restart  pt-variable-advisor
pt-duplicate-key-checker  pt-ioprofile        pt-pmp                   pt-stalk          pt-visual-explain

[root@vps4 bin]# pt-query-digest /var/log/mysqld-slow.log > /tmp/mysqld-slow-digest.log

[root@vps4 opt]# tar -zxf percona-toolkit-3.0.5_i386.tar.gz

[root@vps4 opt]# cd /opt/percona-toolkit-3.0.5/bin

[root@vps4 bin]# ls

glide pt-fifo-split pt-kill pt-query-digest pt-summary

pt-align pt-find pt-mext pt-show-grants pt-table-checksum

pt-archiver pt-fingerprint pt-mongodb-query-digest pt-sift pt-table-sync

pt-config-diff pt-fk-error-logger pt-mongodb-summary pt-slave-delay pt-table-usage

pt-deadlock-logger pt-heartbeat pt-mysql-summary pt-slave-find pt-upgrade

pt-diskstats pt-index-usage pt-online-schema-change pt-slave-restart pt-variable-advisor

pt-duplicate-key-checker pt-ioprofile pt-pmp pt-stalk pt-visual-explain

[root@vps4 bin]# pt-query-digest /var/log/mysqld-slow.log > /tmp/mysqld-slow-digest.log

ในชุดของ Percona Toolkit ประกอบด้วยหลาย tools โดยทดลองใช้งานคำสั่ง pt-show-grants ผลลัพธ์ตามด้านล่าง


[root@vps4 bin]# pt-show-grants
-- Grants dumped by pt-show-grants
-- Dumped from server Localhost via UNIX socket, MySQL 5.5.54 at 2017-12-24 23:00:16
-- Grants for ''@'localhost'
GRANT USAGE ON *.* TO ''@'localhost';
GRANT USAGE ON *.* TO 'mr2t'@'127.0.0.1' IDENTIFIED BY PASSWORD '<<password hash>>';
GRANT ALL PRIVILEGES ON `mr2t`.* TO 'mr2t'@'127.0.0.1';
-- Grants for 'mr2t'@'localhost'
GRANT USAGE ON *.* TO 'mr2t'@'localhost' IDENTIFIED BY PASSWORD '<<password hash>>';
GRANT ALL PRIVILEGES ON `mr2t`.* TO 'mr2t'@'localhost';
-- Grants for 'root'@'127.0.0.1'
GRANT ALL PRIVILEGES ON *.* TO 'root'@'127.0.0.1' WITH GRANT OPTION;
-- Grants for 'root'@'localhost'
GRANT ALL PRIVILEGES ON *.* TO 'root'@'localhost' WITH GRANT OPTION;

[root@vps4 bin]# pt-show-grants

-- Grants dumped by pt-show-grants

-- Dumped from server Localhost via UNIX socket, MySQL 5.5.54 at 2017-12-24 23:00:16

-- Grants for ''@'localhost'

GRANT USAGE ON *.* TO ''@'localhost';

GRANT USAGE ON *.* TO 'mr2t'@'127.0.0.1' IDENTIFIED BY PASSWORD '<>';

GRANT ALL PRIVILEGES ON `mr2t`.* TO 'mr2t'@'127.0.0.1';

-- Grants for 'mr2t'@'localhost'

GRANT USAGE ON *.* TO 'mr2t'@'localhost' IDENTIFIED BY PASSWORD '<>';

GRANT ALL PRIVILEGES ON `mr2t`.* TO 'mr2t'@'localhost';

-- Grants for 'root'@'127.0.0.1'

GRANT ALL PRIVILEGES ON *.* TO 'root'@'127.0.0.1' WITH GRANT OPTION;

-- Grants for 'root'@'localhost'

GRANT ALL PRIVILEGES ON *.* TO 'root'@'localhost' WITH GRANT OPTION;

เห็นว่ามีการ grant [email protected] เพิ่มขึ้นมา เพื่อไว้ทดสอบ pt-query-digest กับ tcpdump ในกรณีที่ไม่ต้องการ restart service MySQL โดยต้องมีการแก้ code wp-config.php ตรง DB_HOST จาก localhost เป็น 127.0.0.1 เพราะว่า หากเป็น localhost เวลา capture packet ด้วย tcpdump จะไม่มี packet ที่จับได้ นั่นแสดงว่า connection วิ่งผ่าน Unix Socket


/** MySQL hostname */
# Socket
#define('DB_HOST', 'localhost');
# TCP
define('DB_HOST', '127.0.0.1');

/** MySQL hostname */

# Socket

#define('DB_HOST', 'localhost');

# TCP

define('DB_HOST', '127.0.0.1');

pt-query-digest with tcpdump


[root@vps4 bin]# tcpdump -s 65535 -x -nn -q -tttt -i lo -c 1000 port 3306 > /tmp/mysqltcp.cap
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes
1000 packets captured
3176 packets received by filter
1148 packets dropped by kernel

[root@vps4 bin]# pt-query-digest --type tcpdump /tmp/mysqltcp.cap > /tmp/mysqltcp-digest.log

[root@vps4 bin]# tcpdump -s 65535 -x -nn -q -tttt -i lo -c 1000 port 3306 > /tmp/mysqltcp.cap

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode

listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes

1000 packets captured

3176 packets received by filter

1148 packets dropped by kernel

[root@vps4 bin]# pt-query-digest --type tcpdump /tmp/mysqltcp.cap > /tmp/mysqltcp-digest.log

-i lo => lo คือ loopback interface เพราะว่าผม bind-address mysql ที่ 127.0.0.1 หรืออาจระบุเป็น any คือ ทุก interface เลย
-c 1000 คือ count จับแค่ 1000 packet พอ สำหรับการจับจริงอาจปรับเพิ่มเพื่อดูการใช้งานยาวๆ ได้เช่น 100000 เป็นต้น

pt-query-digest output

มาดูผลลัพธ์ทั้ง pt-query-digest จาก mysqld slowlog และ pt-query-digest จาก tcpdump


[root@vps4 bin]# more /tmp/mysqld-slow-digest.log

# 23.2s user time, 130ms system time, 19.41M rss, 22.53M vsz
# Current date: Sun Dec 24 22:49:11 2017
# Hostname: vps4.server.com
# Files: /var/log/mysqld-slow.log
# Overall: 115.42k total, 282 unique, 2.79 QPS, 0.00x concurrency ________
# Time range: 2017-12-24 01:41:01 to 13:10:15
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            77s     1us      1s   665us     1ms     7ms    54us
# Lock time             3s       0   135ms    26us   138us   787us       0
# Rows sent        701.76k       0     946    6.23    4.96   68.56       0
# Rows examine       1.31M       0   9.64k   11.86    6.98  192.57       0
# Query size        15.89M       5 140.42k  144.32  212.52  809.94   92.72

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0xF8389888DD16BD1E 46.6190 60.7% 52575 0.0009  0.09 SELECT mr_options
#    2 0x154A9D34E8B21DE8  5.0700  6.6%  1715 0.0030  0.03 SELECT mr_options
#    3 0x38E102FFB5AF896F  2.9081  3.8%  2432 0.0012  0.02 SELECT mr_postmeta
#    4 0x21A13801B6379D2D  1.8712  2.4%  1713 0.0011  0.78 SHOW COLUMNS
#    5 0xCD1FEBC742AFE6EB  1.7182  2.2%  1713 0.0010  0.04 SELECT mr_wfConfig
#    6 0xF72C777DA5A55F6C  1.6724  2.2%  1705 0.0010  0.01 SELECT mr_wfBlocks
#    7 0xCE23C19A76FFAD82  1.2668  1.6%  1320 0.0010  0.01 SELECT mr_usermeta
#    8 0x9C8B3E3382D2B943  1.2316  1.6%  1447 0.0009  0.03 SELECT mr_posts
#    9 0xDB12BFAD01EA76C5  0.7492  1.0%  1705 0.0004  0.02 SHOW COLUMNS
#   10 0x2D21CDC4D1821BD5  0.7466  1.0%  1705 0.0004  0.14 SELECT mr_wfBlocks
#   11 0xD58555DEA0711184  0.6828  0.9%    47 0.0145  0.00 SELECT mr_posts mr_postmeta mr_term_relationships mr_term_taxonomy
#   12 0x295F03D5E1A02452  0.6474  0.8%  1757 0.0004  0.00 SELECT mr_wfLockedOut
#   13 0xBD2CC5976E54E969  0.6461  0.8%   722 0.0009  0.05 SELECT mr_options
#   14 0xF0265D81808CE240  0.5977  0.8%  1715 0.0003  0.20 SELECT
#   15 0xF7296F58DE637D27  0.5861  0.8%   734 0.0008  0.01 SELECT
#   16 0x7D3810D55360FB59  0.5754  0.7%   556 0.0010  0.01 SELECT mr_usermeta
#   17 0x93A1BBDE124D93CF  0.5512  0.7%  1955 0.0003  0.00 SELECT mr_terms mr_term_taxonomy
#   18 0x44AE35A182869033  0.5499  0.7%  1725 0.0003  0.02 ADMIN INIT DB
#   19 0x5FA7E7BC60AFEE39  0.5190  0.7%   555 0.0009  0.07
#   20 0x185941BD306266FE  0.4309  0.6%  1713 0.0003  0.04 SELECT information_schema.TABLES
# MISC 0xMISC              7.1941  9.4% 35914 0.0002   0.0 <262 ITEMS>

# Query 1: 1.27 QPS, 0.00x concurrency, ID 0xF8389888DD16BD1E at byte 28177673
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.09

[root@vps4 bin]# more /tmp/mysqld-slow-digest.log

# 23.2s user time, 130ms system time, 19.41M rss, 22.53M vsz

# Current date: Sun Dec 24 22:49:11 2017

# Hostname: vps4.server.com

# Files: /var/log/mysqld-slow.log

# Overall: 115.42k total, 282 unique, 2.79 QPS, 0.00x concurrency ________

# Time range: 2017-12-24 01:41:01 to 13:10:15

# Attribute total min max avg 95% stddev median

# ============ ======= ======= ======= ======= ======= ======= =======

# Exec time 77s 1us 1s 665us 1ms 7ms 54us

# Lock time 3s 0 135ms 26us 138us 787us 0

# Rows sent 701.76k 0 946 6.23 4.96 68.56 0

# Rows examine 1.31M 0 9.64k 11.86 6.98 192.57 0

# Query size 15.89M 5 140.42k 144.32 212.52 809.94 92.72

# Profile

# Rank Query ID Response time Calls R/Call V/M Item

# ==== ================== ============= ===== ====== ===== ===============

# 1 0xF8389888DD16BD1E 46.6190 60.7% 52575 0.0009 0.09 SELECT mr_options

# 2 0x154A9D34E8B21DE8 5.0700 6.6% 1715 0.0030 0.03 SELECT mr_options

# 3 0x38E102FFB5AF896F 2.9081 3.8% 2432 0.0012 0.02 SELECT mr_postmeta

# 4 0x21A13801B6379D2D 1.8712 2.4% 1713 0.0011 0.78 SHOW COLUMNS

# 5 0xCD1FEBC742AFE6EB 1.7182 2.2% 1713 0.0010 0.04 SELECT mr_wfConfig

# 6 0xF72C777DA5A55F6C 1.6724 2.2% 1705 0.0010 0.01 SELECT mr_wfBlocks

# 7 0xCE23C19A76FFAD82 1.2668 1.6% 1320 0.0010 0.01 SELECT mr_usermeta

# 8 0x9C8B3E3382D2B943 1.2316 1.6% 1447 0.0009 0.03 SELECT mr_posts

# 9 0xDB12BFAD01EA76C5 0.7492 1.0% 1705 0.0004 0.02 SHOW COLUMNS

# 10 0x2D21CDC4D1821BD5 0.7466 1.0% 1705 0.0004 0.14 SELECT mr_wfBlocks

# 11 0xD58555DEA0711184 0.6828 0.9% 47 0.0145 0.00 SELECT mr_posts mr_postmeta mr_term_relationships mr_term_taxonomy

# 12 0x295F03D5E1A02452 0.6474 0.8% 1757 0.0004 0.00 SELECT mr_wfLockedOut

# 13 0xBD2CC5976E54E969 0.6461 0.8% 722 0.0009 0.05 SELECT mr_options

# 14 0xF0265D81808CE240 0.5977 0.8% 1715 0.0003 0.20 SELECT

# 15 0xF7296F58DE637D27 0.5861 0.8% 734 0.0008 0.01 SELECT

# 16 0x7D3810D55360FB59 0.5754 0.7% 556 0.0010 0.01 SELECT mr_usermeta

# 17 0x93A1BBDE124D93CF 0.5512 0.7% 1955 0.0003 0.00 SELECT mr_terms mr_term_taxonomy

# 18 0x44AE35A182869033 0.5499 0.7% 1725 0.0003 0.02 ADMIN INIT DB

# 19 0x5FA7E7BC60AFEE39 0.5190 0.7% 555 0.0009 0.07

# 20 0x185941BD306266FE 0.4309 0.6% 1713 0.0003 0.04 SELECT information_schema.TABLES

# MISC 0xMISC 7.1941 9.4% 35914 0.0002 0.0 <262 ITEMS>

# Query 1: 1.27 QPS, 0.00x concurrency, ID 0xF8389888DD16BD1E at byte 28177673

# This item is included in the report because it matches --limit.

# Scores: V/M = 0.09


[root@vps4 bin]# more /tmp/mysqltcp-digest.log
# 560ms user time, 10ms system time, 15.02M rss, 18.08M vsz
# Current date: Sun Dec 24 23:17:37 2017
# Hostname: vps4.server.com
# Files: /tmp/mysqltcp.cap
# Overall: 355 total, 58 unique, 22.28 QPS, 0.00x concurrency ____________
# Time range: 2017-12-24 23:16:01.478728 to 23:16:17.412897
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           54ms       0    16ms   151us   316us   835us    84us
# Rows affecte          11       0       1    0.03       0    0.17       0
# Query size        48.35k      17   5.41k  139.47  192.76  482.12   92.72
# Warning coun           1       0       1    0.00       0    0.05       0
# Boolean:
# No index use   7% yes,  92% no

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0xD58555DEA0711184  0.0161 29.8%     1 0.0161  0.00 SELECT mr_posts mr_postmeta mr_term_relationships mr_term_taxonomy
#    2 0xF8389888DD16BD1E  0.0133 24.8%   166 0.0001  0.00 SELECT mr_options
#    3 0x21A13801B6379D2D  0.0020  3.8%     6 0.0003  0.00 SHOW COLUMNS
#    4 0xDB12BFAD01EA76C5  0.0020  3.7%     6 0.0003  0.00 SHOW COLUMNS
#    5 0x38E102FFB5AF896F  0.0018  3.3%     5 0.0004  0.00 SELECT mr_postmeta
#    6 0xE19835E1C194D777  0.0015  2.8%     2 0.0008  0.00 SELECT mr_users
#    7 0x154A9D34E8B21DE8  0.0011  2.1%     6 0.0002  0.00 SELECT mr_options
#    8 0x27173C97C7D748F6  0.0011  2.1%     3 0.0004  0.00 UPDATE mr_options
#    9 0x5D51E5F01B88B79E  0.0010  1.9%     6 0.0002  0.00 ADMIN CONNECT
#   10 0x185941BD306266FE  0.0010  1.9%     6 0.0002  0.00 SELECT information_schema.TABLES
#   11 0x9C8B3E3382D2B943  0.0009  1.7%     7 0.0001  0.00 SELECT mr_posts
#   12 0x3E703AAEBB5D99E6  0.0008  1.5%     1 0.0008  0.00 SELECT mr_posts
#   13 0x2D21CDC4D1821BD5  0.0008  1.4%     6 0.0001  0.00 SELECT mr_wfBlocks
#   14 0xD9DE02680511CFC3  0.0006  1.1%     2 0.0003  0.00 SHOW COLUMNS
#   15 0xD2558DAA6FE2AEF3  0.0006  1.1%     2 0.0003  0.00 SELECT mr_posts
#   16 0x295F03D5E1A02452  0.0005  1.0%     6 0.0001  0.00 SELECT mr_wfLockedOut
#   17 0x8A6B56C5E8B49A47  0.0005  1.0%     1 0.0005  0.00 SELECT mr_terms mr_term_taxonomy mr_term_relationships mr_posts mr_stt?_meta
#   18 0x477FC938B654C0A7  0.0005  1.0%     2 0.0003  0.00 INSERT UPDATE mr_options
#   19 0xF72C777DA5A55F6C  0.0005  0.9%     6 0.0001  0.00 SELECT mr_wfBlocks
#   20 0xBE595FA4EAED9EA2  0.0005  0.9%     1 0.0005  0.00 SELECT mr_posts
# MISC 0xMISC              0.0066 12.2%   114 0.0001   0.0 <38 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0xD58555DEA0711184 at byte 2026767 __
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2017-12-24 23:16:05.129513
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       1
# Exec time     29    16ms    16ms    16ms    16ms    16ms       0    16ms
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     1     553     553     553     553     553       0     553
# Warning coun   0       0       0       0       0       0       0       0
# Boolean:
# No index use 100% yes,   0% no
# String:
# Databases
# Hosts        127.0.0.1
# Users        mr2t
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  ################################################################
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `1` LIKE 'mr_posts'\G
#    SHOW CREATE TABLE `1`.`mr_posts`\G
#    SHOW TABLE STATUS FROM `1` LIKE 'mr_postmeta'\G
#    SHOW CREATE TABLE `1`.`mr_postmeta`\G
#    SHOW TABLE STATUS FROM `1` LIKE 'mr_term_relationships'\G
#    SHOW CREATE TABLE `1`.`mr_term_relationships`\G
#    SHOW TABLE STATUS FROM `1` LIKE 'mr_term_taxonomy'\G
#    SHOW CREATE TABLE `1`.`mr_term_taxonomy`\G
# EXPLAIN /*!50100 PARTITIONS*/

                        SELECT DISTINCT post_title, ID, post_type, post_name
                        FROM mr_posts wposts
                        LEFT JOIN mr_postmeta wpostmeta ON wposts.ID = wpostmeta.post_id
                        LEFT JOIN mr_term_relationships ON (wposts.ID = mr_term_relationships.object_id)
                        LEFT JOIN mr_term_taxonomy ON (mr_term_relationships.term_taxonomy_id = mr_term_taxonomy.term_taxonomy_id)
                        WHERE (post_type='page'
                        OR (mr_term_taxonomy.taxonomy = 'category' AND mr_term_taxonomy.term_id IN(5)))
                        AND post_status = 'publish' AND LENGTH(post_title)>=5 ORDER BY LENGTH(post_title) ASC LIMIT 500\G

[root@vps4 bin]# more /tmp/mysqltcp-digest.log

# 560ms user time, 10ms system time, 15.02M rss, 18.08M vsz

# Current date: Sun Dec 24 23:17:37 2017

# Hostname: vps4.server.com

# Files: /tmp/mysqltcp.cap

# Overall: 355 total, 58 unique, 22.28 QPS, 0.00x concurrency ____________

# Time range: 2017-12-24 23:16:01.478728 to 23:16:17.412897

# Attribute total min max avg 95% stddev median

# ============ ======= ======= ======= ======= ======= ======= =======

# Exec time 54ms 0 16ms 151us 316us 835us 84us

# Rows affecte 11 0 1 0.03 0 0.17 0

# Query size 48.35k 17 5.41k 139.47 192.76 482.12 92.72

# Warning coun 1 0 1 0.00 0 0.05 0

# Boolean:

# No index use 7% yes, 92% no

# Profile

# Rank Query ID Response time Calls R/Call V/M Item

# ==== ================== ============= ===== ====== ===== ===============

# 1 0xD58555DEA0711184 0.0161 29.8% 1 0.0161 0.00 SELECT mr_posts mr_postmeta mr_term_relationships mr_term_taxonomy

# 2 0xF8389888DD16BD1E 0.0133 24.8% 166 0.0001 0.00 SELECT mr_options

# 3 0x21A13801B6379D2D 0.0020 3.8% 6 0.0003 0.00 SHOW COLUMNS

# 4 0xDB12BFAD01EA76C5 0.0020 3.7% 6 0.0003 0.00 SHOW COLUMNS

# 5 0x38E102FFB5AF896F 0.0018 3.3% 5 0.0004 0.00 SELECT mr_postmeta

# 6 0xE19835E1C194D777 0.0015 2.8% 2 0.0008 0.00 SELECT mr_users

# 7 0x154A9D34E8B21DE8 0.0011 2.1% 6 0.0002 0.00 SELECT mr_options

# 8 0x27173C97C7D748F6 0.0011 2.1% 3 0.0004 0.00 UPDATE mr_options

# 9 0x5D51E5F01B88B79E 0.0010 1.9% 6 0.0002 0.00 ADMIN CONNECT

# 10 0x185941BD306266FE 0.0010 1.9% 6 0.0002 0.00 SELECT information_schema.TABLES

# 11 0x9C8B3E3382D2B943 0.0009 1.7% 7 0.0001 0.00 SELECT mr_posts

# 12 0x3E703AAEBB5D99E6 0.0008 1.5% 1 0.0008 0.00 SELECT mr_posts

# 13 0x2D21CDC4D1821BD5 0.0008 1.4% 6 0.0001 0.00 SELECT mr_wfBlocks

# 14 0xD9DE02680511CFC3 0.0006 1.1% 2 0.0003 0.00 SHOW COLUMNS

# 15 0xD2558DAA6FE2AEF3 0.0006 1.1% 2 0.0003 0.00 SELECT mr_posts

# 16 0x295F03D5E1A02452 0.0005 1.0% 6 0.0001 0.00 SELECT mr_wfLockedOut

# 17 0x8A6B56C5E8B49A47 0.0005 1.0% 1 0.0005 0.00 SELECT mr_terms mr_term_taxonomy mr_term_relationships mr_posts mr_stt?_meta

# 18 0x477FC938B654C0A7 0.0005 1.0% 2 0.0003 0.00 INSERT UPDATE mr_options

# 19 0xF72C777DA5A55F6C 0.0005 0.9% 6 0.0001 0.00 SELECT mr_wfBlocks

# 20 0xBE595FA4EAED9EA2 0.0005 0.9% 1 0.0005 0.00 SELECT mr_posts

# MISC 0xMISC 0.0066 12.2% 114 0.0001 0.0 <38 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0xD58555DEA0711184 at byte 2026767 __

# This item is included in the report because it matches --limit.

# Scores: V/M = 0.00

# Time range: all events occurred at 2017-12-24 23:16:05.129513

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 0 1

# Exec time 29 16ms 16ms 16ms 16ms 16ms 0 16ms

# Rows affecte 0 0 0 0 0 0 0 0

# Query size 1 553 553 553 553 553 0 553

# Warning coun 0 0 0 0 0 0 0 0

# Boolean:

# No index use 100% yes, 0% no

# String:

# Databases

# Hosts 127.0.0.1

# Users mr2t

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms ################################################################

# 100ms

# 1s

# 10s+

# Tables

# SHOW TABLE STATUS FROM `1` LIKE 'mr_posts'\G

# SHOW CREATE TABLE `1`.`mr_posts`\G

# SHOW TABLE STATUS FROM `1` LIKE 'mr_postmeta'\G

# SHOW CREATE TABLE `1`.`mr_postmeta`\G

# SHOW TABLE STATUS FROM `1` LIKE 'mr_term_relationships'\G

# SHOW CREATE TABLE `1`.`mr_term_relationships`\G

# SHOW TABLE STATUS FROM `1` LIKE 'mr_term_taxonomy'\G

# SHOW CREATE TABLE `1`.`mr_term_taxonomy`\G

# EXPLAIN /*!50100 PARTITIONS*/

SELECT DISTINCT post_title, ID, post_type, post_name

FROM mr_posts wposts

LEFT JOIN mr_postmeta wpostmeta ON wposts.ID = wpostmeta.post_id

LEFT JOIN mr_term_relationships ON (wposts.ID = mr_term_relationships.object_id)

LEFT JOIN mr_term_taxonomy ON (mr_term_relationships.term_taxonomy_id = mr_term_taxonomy.term_taxonomy_id)

WHERE (post_type='page'

OR (mr_term_taxonomy.taxonomy = 'category' AND mr_term_taxonomy.term_id IN(5)))

AND post_status = 'publish' AND LENGTH(post_title)>=5 ORDER BY LENGTH(post_title) ASC LIMIT 500\G

จะเห็นว่า output มีบอกข้อมูลดังต่อไปนี้

Profile Rank อันดับ 1 – 20 , ลำดับถัดไปเป็น MISC กับค่า response time และ จำนวนการ call
Query 1 คือ Query ของ Rank อันดับ 1 บอกพวก Execute time, Query_time distribution, Explain Query เป็นต้น

1) เรื่อง Created_tmp_disk_tables ผมใช้ tmpfs แก้ปัญหาไปก่อนตามด้านบน ไม่อยากไปรื้อ alter table แก้ column อะไรครับ

2) ท้ายนี้ pt-query-digest เป็นเครื่องมือไว้ดู MySQL Top Query จาก mysql slow query log หรือ tcpdump log ในรูปแบบ command line

3) สำหรับ MySQL Top Query Graph ที่มีการใช้งาน pt-query-digest ขอแนะนำ Anemometer แต่ว่ามันก็เก็บข้อมูลใน MySQL ด้วย หากเก็บใน db เดียวกันจะทำให้ช้าลงไปมั้ย – หากมันช้าหรือมีปัญหาอยู่เดิม ! ควรแยกเครื่อง/แยก db สำหรับลง Anemometer ? ไว้ต่อกันบทความหน้าแล้วกันนะครับ

Analyze slow MySQL queries with pt-query-digest

Cookie	Duration	Description
cookielawinfo-checkbox-advertisement	1 year	Set by the GDPR Cookie Consent plugin, this cookie is used to record the user consent for the cookies in the "Advertisement" category .
cookielawinfo-checkbox-analytics	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookie is used to store the user consent for the cookies in the category "Analytics".
cookielawinfo-checkbox-functional	11 months	The cookie is set by GDPR cookie consent to record the user consent for the cookies in the category "Functional".
cookielawinfo-checkbox-necessary	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookies is used to store the user consent for the cookies in the category "Necessary".
cookielawinfo-checkbox-others	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookie is used to store the user consent for the cookies in the category "Other.
cookielawinfo-checkbox-performance	11 months	This cookie is set by GDPR Cookie Consent plugin. The cookie is used to store the user consent for the cookies in the category "Performance".
CookieLawInfoConsent	1 year	Records the default button state of the corresponding category & the status of CCPA. It works only in coordination with the primary cookie.
viewed_cookie_policy	11 months	The cookie is set by the GDPR Cookie Consent plugin and is used to store whether or not user has consented to the use of cookies. It does not store any personal data.

Cookie	Duration	Description
CONSENT	2 years	YouTube sets this cookie via embedded youtube-videos and registers anonymous statistical data.
_ga	2 years	The _ga cookie, installed by Google Analytics, calculates visitor, session and campaign data and also keeps track of site usage for the site's analytics report. The cookie stores information anonymously and assigns a randomly generated number to recognize unique visitors.
_gid	1 day	Installed by Google Analytics, _gid cookie stores information on how visitors use a website, while also creating an analytics report of the website's performance. Some of the data that are collected include the number of visitors, their source, and the pages they visit anonymously.
__gads	session	The __gads cookie, set by Google, is stored under DoubleClick domain and tracks the number of times users see an advert, measures the success of the campaign and calculates its revenue. This cookie can only be read from the domain they are set on and will not track any data while browsing through other sites.

Cookie	Duration	Description
IDE	1 year 24 days	Google DoubleClick IDE cookies are used to store information about how the user uses the website to present them with relevant ads and according to the user profile.
test_cookie	15 minutes	The test_cookie is set by doubleclick.net and is used to determine if the user's browser supports cookies.
VISITOR_INFO1_LIVE	5 months 27 days	A cookie set by YouTube to measure bandwidth that determines whether the user gets the new or old player interface.
YSC	session	YSC cookie is set by Youtube and is used to track the views of embedded videos on Youtube pages.
yt-remote-connected-devices	never	YouTube sets this cookie to store the video preferences of the user using embedded YouTube video.
yt-remote-device-id	never	YouTube sets this cookie to store the video preferences of the user using embedded YouTube video.
yt.innertube::nextId	never	This cookie, set by YouTube, registers a unique ID to store data on what videos from YouTube the user has seen.
yt.innertube::requests	never	This cookie, set by YouTube, registers a unique ID to store data on what videos from YouTube the user has seen.

tuning-primer.sh [TEMP TABLES]

WordPress Tables contain BLOB or TEXT

Percona Toolkit

pt-query-digest

Enabling MySQL Slow Query

pt-query-digest with mysqld-slow.log

pt-query-digest with tcpdump

pt-query-digest output

You May Also Like

MySQL Performance Tuning Scripts

Installing MySQL on AIX from Source

Briefly unavailable for scheduled maintenance. Check back in a minute.