Собрал я лог медленных запросов, натравил на него
перконовский тулкит и получил замечательный отчет.
# 11.1s user time, 60ms system time, 37.28M rss, 114.69M vsz
# Current date: Mon Nov 26 09:00:15 2012
# Hostname: dbm01b
# Files: /tmp/slow.log
# Overall: 26.64k total, 253 unique, 0.31 QPS, 0.81x concurrency _____
# Time range: 2012-11-25 09:00:07 to 2012-11-26 08:59:45
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 69753s 1s 2393s 3s 7s 15s 1s
# Lock time 357s 0 1s 13ms 48ms 23ms 27us
# Rows sent 600.53M 0 153.65M 23.08k 9.83 1.38M 0
# Rows examine 2.59G 0 153.65M 102.08k 1.09M 1.41M 0
# Rows affecte 3.93k 0 98 0.15 0.99 0.89 0
# Rows read 600.53M 0 153.65M 23.08k 9.83 1.38M 0
# Bytes sent 13.50G 0 2.69G 531.35k 1.96k 27.19M 51.63
# Merge passes 5 0 1 0.00 0 0.01 0
# Tmp tables 1.97k 0 4 0.08 0.99 0.30 0
# Tmp disk tbl 18 0 1 0.00 0 0.03 0
# Tmp tbl size 795.48M 0 200.99M 30.58k 123.85k 1.19M 0
# Query size 7.42M 6 18.99k 291.98 1.26k 542.45 76.28
# InnoDB:
# IO r bytes 11.48G 0 3.98G 865.77k 15.96k 41.26M 0
# IO r ops 1.17M 0 434.90k 88.30 0.99 4.40k 0
# IO r wait 3220s 0 2151s 232ms 8ms 18s 0
# pages distin 33.94M 0 63.79k 2.50k 15.96k 6.07k 4.96
# queue wait 30099s 0 17s 2s 11s 3s 1s
# rec lock wai 5s 0 1s 336us 0 12ms 0
# Boolean:
# Filesort 6% yes, 93% no
# Filesort on 0% yes, 99% no
# Full join 0% yes, 99% no
# Full scan 10% yes, 89% no
# Tmp table 6% yes, 93% no
# Tmp table on 0% yes, 99% no
# Profile
# Rank Query ID Response time Calls R/Call Apdx V/M Item
# ==== ================== ================ ===== ========= ==== ===== ====
# 1 0x813031B8BBC3B329 17471.3170 25.0% 12713 1.3743 0.56 0.09 COMMIT
# 2 0xD96E5125DDE561B1 11197.7439 16.1% 2555 4.3827 0.32 2.82 SELECT config
# 3 0x308989BE50A05867 7507.2040 10.8% 1821 4.1226 0.34 2.94 SELECT user
# 4 0x1C1CE7739FFBE68D 3427.3964 4.9% 820 4.1798 0.34 2.85 SELECT user
# 5 0x933552E69A3D4786 3283.6093 4.7% 1155 2.8430 0.43 2.75 UPDATE user
# 6 0xD73A57A12165993A 2736.5430 3.9% 918 2.9810 0.49 0.15 SELECT user user_photo
# 7 0x80E467E273FF53A9 2406.3752 3.4% 995 2.4185 0.47 2.59 UPDATE user_info
и вот дальше начинается по запросам. И первым пунктом идет
# Query 1: 0.15 QPS, 0.21x concurrency, ID 0x813031B8BBC3B329 at byte 15331863
# This item is included in the report because it matches --limit.
# Scores: Apdex = 0.56 [1.0], V/M = 0.09
# Query_time sparkline: | ^ |
# Time range: 2012-11-25 09:02:35 to 2012-11-26 08:39:47
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 47 12713
# Exec time 25 17471s 1s 3s 1s 2s 353ms 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
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 0 0 0 0 0 0 0
# Bytes sent 0 136.57k 11 11 11 11 0 11
# Merge passes 0 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0 0
# Query size 0 74.49k 6 6 6 6 0 6
# InnoDB:
# String:
# Databases user
# Hosts
# Last errno 0
# Users user (12557/98%), user_1... (139/1%)... 1 more
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
commit\G
сами понимаете — полезного ноль, а занимает четверть всей нагрузки.
в самом слоулоге
# Time: 121121 9:01:48
# User@Host: user[user] @ [192.168.2.83]
# Thread_id: 310269650 Schema: user Last_errno: 0 Killed: 0
# Query_time: 1.298979 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 11 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
SET timestamp=1353474108;
commit;
как понять, что там комититься?
Средний
Средний
