Mysql日誌分析

0x01.About

MySQL有四種類型的日誌：Error Log、General Query Log、Binary Log 和 Slow Query Log。

第一種錯誤日誌，記錄MySQL運行過程ERROR,WARNING,NOTE等信息，系統出錯或者某條記錄出問題能夠查看ERROR日誌。

第二種平常運行日誌，記錄MySQL運行中的每條請求數據。

第三種二進制日誌，包含了一些事件，這些事件描述了數據庫的改動，如建表、數據改動等，也包括一些潛在改動，主要用於備份恢復、回滾等操做。

第四種慢查詢日誌，用於MySQL性能調優。

---

0x02.Error Log

MySQL錯誤日誌默認以hostname.err存放在MySQL日誌目錄，若是不知道MySQL當前的錯誤日誌目錄可使用查詢語句：

mysql> show variables like 'log_error';

+---------------+--------------------------------------+
| Variable_name | Value                                |
+---------------+--------------------------------------+
| log_error     | /usr/local/var/mysql/mysql-error.log |
+---------------+--------------------------------------+

修改錯誤日誌地址能夠在/etc/my.cnf中添加--log-error[=file_name]選項來開啓mysql錯誤日誌。

錯誤日誌記錄了MySQL Server每次啓動和關閉的詳細信息以及運行過程當中全部較爲嚴重的警告和錯誤信息。

知道了MySQL錯誤日誌地址，咱們就能夠查看MySQL錯誤日誌：

2015-09-12 16:03:20 2624 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 35
2015-09-12 16:03:20 2624 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
2015-09-13 00:03:21 2183 [Note] InnoDB: Shutdown completed; log sequence number 426783897

InnoDB: Unable to lock ./ibdata1, error: 35 能夠得出資源被搶佔，有多是開了多個MySQL線程。

---

0x03.General Query Log

平常請求的SQL：
添加方式同樣在 /etc/my.cnf 中添加 general-log-file[=file_name]。

---

0x04.Binary Log

啓用Binlog

修改 /etc/my.cnf：

binlog_format = STATEMENT
binlog_cache_size = 2M
max_binlog_cache_size = 4M
max_binlog_size = 512M
log-bin = master-bin
log-bin-index = master-bin.index

log-bin-index 指向 master-bin 這個文件，記錄有哪些分塊的Binlog文件名。
log-bin 記錄Binlog文件名前綴，後綴會用數字遞增。

Binlog格式

Binlog有3種格式，STATMENT,ROW,MIXED。https://dev.mysql.com/doc/refman/5.1/en/binary-log-mixed.html

混合格式（mixed）會在適當時候切換row和statment格式，statment就是直接的SQL語句格式。

分析Binlog

經過MySQL自帶的mysqlbinlog 命令，能夠直接查看到Binlog轉碼數據：

mysqlbinlog /usr/local/var/mysql/master-bin.000117

獲得：

# at 335
#150913  0:05:12 server id 1  end_log_pos 366 CRC32 0xa31b50db     Xid = 151
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

第一行包含日誌文件偏移字節值（335）。

第二行包含：

• 事件的日期事件，MySQL會使用他們來產生SET TIMESTAMP

• 服務器的服務器id

• end_log_pos 下一個事件的偏移字節

• 事件類型，這裏是Xid，常見的還有其餘，例如：Intvar，Query，Stop，Format_desc

• 原服務器上執行語句的線程id，用於審計和CONNECTION_ID()

• exec_time對於master端的Binlog來講是執行這個event所花費的時間

• 原服務器產生的錯誤代碼

經過

mysql> show binlog events;

也能夠的到binlog數據：

| master-bin.000002 | 3861 | Query       |         1 |        3954 | BEGIN                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           |
| master-bin.000002 | 3954 | Intvar      |         1 |        3986 | INSERT_ID=5                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     |
| master-bin.000002 | 3986 | Query       |         1 |        4475 | use `dropbox`; INSERT INTO `UserLog` (`uid`, `fids`, `nids`, `msg`, `log`, `from`, `type`, `ctime`) VALUES ('1', '[\"35\",\"33\",\"21\"]', '[\"22\",\"21\",\"11\",\"4\",\"3\"]', '從垃圾箱恢復: 恢復文件 \'[\"35\",\"33\",\"21\"]\' 恢復文件夾 \'[\"22\",\"21\",\"11\",\"4\",\"3\"]\'', '[[\"35\",\"33\",\"21\"],[\"22\",\"21\",\"11\",\"4\",\"3\"]]', 'cloud.jue.so', 'recover_by_trash', '2015-09-07 00:51:31')                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               |
| master-bin.000002 | 4475 | Xid         |         1 |        4506 | COMMIT /* xid=423 */

查看Binlog信息

mysql> show variables like '%binlog%';

+-----------------------------------------+----------------------+
| Variable_name                           | Value                |
+-----------------------------------------+----------------------+
| binlog_cache_size                       | 2097152              |
| binlog_checksum                         | CRC32                |
| binlog_direct_non_transactional_updates | OFF                  |
| binlog_error_action                     | IGNORE_ERROR         |
| binlog_format                           | STATEMENT            |
| binlog_gtid_simple_recovery             | OFF                  |
| binlog_max_flush_queue_time             | 0                    |
| binlog_order_commits                    | ON                   |
| binlog_rows_query_log_events            | OFF                  |
| binlog_stmt_cache_size                  | 32768                |
| binlogging_impossible_mode              | IGNORE_ERROR         |
| innodb_api_enable_binlog                | OFF                  |
| innodb_locks_unsafe_for_binlog          | OFF                  |
| max_binlog_cache_size                   | 4194304              |
| max_binlog_size                         | 536870912            |
| max_binlog_stmt_cache_size              | 18446744073709547520 |
| simplified_binlog_gtid_recovery         | OFF                  |
+-----------------------------------------+----------------------+

---

Slow Query Log

開啓 Slow Query

修改/etc/my.cnf：

slow-query-log = 1
slow-query-log-file = /usr/loval/var/mysql/mysql-slow.log
long_query_time = 1 #設置滿請求時間
log-queries-not-using-indexes

Slow Query工具

Slow Query有不少查看工具，好比：MySQL自帶的mysqldumpslow 和 mysqlsla，用的比較多的 py-query-digest，還能夠將滿請求數據丟給zabbix作顯示分析處理。

這裏我用 py-query-digest /usr/local/var/mysql/mysql-slow.log 導出了滿請求的數據，例如：

# Query 1: 0.02 QPS, 0.55x concurrency, ID 0xFC19E4D04D8E60BF at byte 12547
# This item is included in the report because it matches --limit.
# Scores: V/M = 118.26
# Time range: 2015-09-12 05:52:03 to 05:57:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          1       7
# Exec time     78    194s   250ms    169s     28s    167s     57s   992ms
# Lock time      0   901us   111us   158us   128us   152us    18us   119us
# Rows sent      0       5       0       1    0.71    0.99    0.45    0.99
# Rows examine   7 545.01k  14.18k  97.66k  77.86k  97.04k  32.08k  97.04k
# Query size     0     868     123     125     124  124.25       1  118.34
# String:
# Databases    mysqltest
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ################################################################
#    1s  ##########################################
#  10s+  ##########################################
# Tables
#    SHOW TABLE STATUS FROM `mysqltest` LIKE 'File'\G
#    SHOW CREATE TABLE `mysqltest`.`File`\G
#    SHOW TABLE STATUS FROM `mysqltest` LIKE 'User'\G
#    SHOW CREATE TABLE `mysqltest`.`User`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT count(*) FROM `File` LEFT JOIN `User` ON `User`.`name`= `File`.`name` WHERE `User`.`name` LIKE '%r%' order by `last`\G

能夠看到該SQL被調用7次，平均每次28s，好慢...平均檢測數據大小77.86k。

再來看看SQL語句：

SELECT count(*) FROM File LEFT JOIN User ON User.name= File.name WHERE User.name LIKE '%r%' order by last

看着都以爲慢 ON User.name= File.name 在沒有創建索引的狀況下，全部數據將進行字符串匹配name字段。

這個庫有 15W條User數據，10W條File數據，也就是要比對15*10 WW 次數據。

MySQL的slow log的做用也就在這裏了，優化慢查詢。

---

參考：

1.《高性能MySQL》

2.(Analyse slow-query-log using mysqldumpslow & pt-query-digest)[https://rtcamp.com/tutorials/mysql/slow-query-log/]

3.初探：MySQL 的 Binlog&version=11020201&pass_ticket=DNtPK7ePVYl93tx1FiRMBNsJMm3DEgwRdO1XEZUustRXuYf6KyUU4gID1Lv7aVTB)

本文出自 夏日小草,轉載請註明出處:http://homeway.me/2015/09/12/mysql-log

-by小草

2015-09-12 01:49:10