一、错误日志
错误日志的作用:
记录数据库在启动、重启、运行过程中的一些状态信息、错误、警告。
错误日志的查看:
mysql[(none)]>select @@log_error;
+--------------------+
| @@log_error |
+--------------------+
| /var/log/mysql.log |
+--------------------+
1 row in set (0.00 sec)
mysql[(none)]>show variables like 'log_error';
+---------------+--------------------+
| Variable_name | Value |
+---------------+--------------------+
| log_error | /var/log/mysql.log |
+---------------+--------------------+
1 row in set (0.02 sec)
在配置文件下的修改:
log_error=/var/log/mysql.log
如果没有给定file_name,则mysql自动使用错误日志名host_name.err(host_name为主机名)
修改完需要重启生效
cat var/log/mysql.log 可以看到一些系统的开启、关闭、日常运行的过程,警告,状态信息,错误
二、slow日志
slow日志的作用:
定位在MySQL中效率较低的SQL语句并且记录他们的执行日志。
slow日志开关:
slow_query_log=1
文件位置:
slow_query_log_file=/opt/mysql-data/mysql/slow.log 可自行定义
日志输出方式为文件写:
3306[(none)]>select @@log_output;
+--------------+
| @@log_output |
+--------------+
| FILE |
+--------------+
1 row in set (0.00 sec)
3306[(none)]>show variables like '%output%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_status_output | OFF |
| innodb_status_output_locks | OFF |
| log_output | FILE |
+----------------------------+-------+
3 rows in set (0.00 sec)
记录不走索引的语句:
log_queries_not_using_indexes
记录执行时间超过多久的语句:
配置文件中的参数:
long_query_time=0.1 超过0.5秒的SQL语句就直接记录到slow日志中
直接在mysql数据库中设置:
set log_query_time=0.5;
也可以借助第三方分析慢日志
在mysqldumpslow情况下使用:
mysqldumpslow -s c -t 10 /opt/mysql-data/mysql/slow.log
按次数查看slow日志前10的慢SQL语句:
[root@localhost mysql]# mysqldumpslow -s c -t 10 slow.log
Reading mysql slow query log from slow.log
Count: 3 Time=0.60s (1s) Lock=0.00s (0s) Rows=20.0 (60), root[root]@localhost
select num,count(id) from t_100w where num<N group by num order by count(id) desc limit N
Count: 2 Time=0.79s (1s) Lock=0.00s (0s) Rows=100.0 (200), root[root]@localhost
select * from t_100w where id>N order by num limit N
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=100.0 (100), root[root]@localhost
select * from t_100w limit N
Count: 1 Time=3.21s (3s) Lock=0.00s (0s) Rows=20.0 (20), root[root]@localhost
select num,count(id) from t_100w where num>N group by num order by num desc limit N
Count: 1 Time=0.60s (0s) Lock=0.00s (0s) Rows=20.0 (20), root[root]@localhost
select num,count(id) from t_100w where num<N group by num order by num desc limit N
Died at /opt/mysql-basedir/mysql/bin/mysqldumpslow line 161, <> chunk 8.
在第三方工具下的拓展:
https://www.percona.com/downloads/percona-toolkit/LATEST/
下载完成然后scp到linux下
安装percona软件的依赖包:
yum install perl-DBI perl-DBD-MySQL perl-Time-HiRes perl-IO-Socket-SSL perl-Digest-MD5 perl-TermReadKey.x86_64
安装完成以后安装percona软件:
[root@localhost mysql-tar]# rpm -ivh percona-toolkit-3.1.0-2.el7.x86_64.rpm
警告:percona-toolkit-3.1.0-2.el7.x86_64.rpm: 头V4 RSA/SHA256 Signature, 密钥 ID 8507efa5: NOKEY
准备中... ################################# [100%]
正在升级/安装...
1:percona-toolkit-3.1.0-2.el7 ################################# [100%]
到这里安装就完成了
讲解一下pt-query-digest如果使用
该命令的参数:
--limit 展示最耗时SQL的数量
--since 指定分析SQL的开始时间
--type 指定分析SQL的哪种日志类型(可以为binlog、slowlogtcpdump、rawlog)
--until 指定分析SQL的结束时间
分析2020-02-22从14点到15点的慢查询日志:
第5行overall:表示有8个慢SQL,有5个不同的SQL,也就是说这5个不同的SQL出现了9次
第6行time range:显示的是慢SQL的时间跨度
第7行attribute:这一行和接下来的5行显示了其它的一些信息
Exec time:慢SQL执行时间(这行的total列表示慢SQL总执行时间为8s)
Rows sent:慢SQL的返回行数(这一行的avg显示50,表示慢SQL的平均返回条数是50条)
Rows examine:慢SQL检索的记录行数
Profile以下就是SQL的汇总部分:
1、Query ID为SQL的指纹id,如果只是常量不同,会被识别为同一个指纹id
2、Response time表示慢SQL总的执行时间和占时间的百分比
3、Calls为慢SQL的执行次数(显示Rank为2的这条语句执行了3次)
4、R/Calls表示慢SQL平均执行时间(例:Rank2中总执行时间为1.7936s,Calls为3次,平均时间为1.7936除以3为0.5979s)
一、第二个Attribute行后面7行则就是每个SQL的明细部分,跟SQL汇总那块一致
二、String部分列出了数据库名、客户端的IP、用户名、慢SQL执行时间在每个时间段的比例
三、根据这些信息能很容易的定位慢SQL来自哪个应用,慢SQL分布在哪个时间区间。
四、最后还给出explain执行计划、方便去数据库中执行。
如果是专门的数据库公司,可以通过Anemometer平台自动分析慢SQL,通过可视化的界面,更清晰的定位慢SQL所存在的问题。
[root@localhost mysql]# pt-query-digest --since '2020-02-22 14:00:00' --until '2020-02-22 15:00:00' --limit 100% slow.log
# 110ms user time, 60ms system time, 25.94M rss, 220.37M vsz
# Current date: Sat Feb 22 15:34:14 2020
# Hostname: localhost.localdomain
# Files: slow.log
# Overall: 8 total, 5 unique, 0.04 QPS, 0.03x concurrency ________________
# Time range: 2020-02-22T14:52:08 to 2020-02-22T14:55:36
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 7s 892us 3s 897ms 3s 904ms 580ms
# Lock time 3ms 178us 609us 316us 596us 139us 247us
# Rows sent 400 20 100 50 97.36 37.71 19.46
# Rows examine 12.56M 100 2.15M 1.57M 2.15M 613.61k 1.69M
# Query size 612 30 95 76.50 92.72 22.61 88.31
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ================================== ============= ===== ====== =====
# 1 0x0F0AFB1536F59412C7AF67BAC7F8D44F 3.2077 44.7% 1 3.2077 0.00 SELECT t_?w
# 2 0xBFEC75F594AB73D45DA57D4FD883C907 1.7936 25.0% 3 0.5979 0.00 SELECT t_?w
# 3 0x326BF13CEB4AE80C0748E888DD5395CE 1.5746 21.9% 2 0.7873 0.00 SELECT t_?w
# 4 0xF04FE46E7CFBFDDD37C9E4381F1AD05E 0.6027 8.4% 1 0.6027 0.00 SELECT t_?w
# 5 0xC56EBF83C61F6384AD7F0E6A1651294A 0.0009 0.0% 1 0.0009 0.00 SELECT t_?w
# Query 1: 0 QPS, 0x concurrency, ID 0x0F0AFB1536F59412C7AF67BAC7F8D44F at byte 751
# Scores: V/M = 0.00
# Time range: all events occurred at 2020-02-22T14:54:21
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 12 1
# Exec time 44 3s 3s 3s 3s 3s 0 3s
# Lock time 19 492us 492us 492us 492us 492us 0 492us
# Rows sent 5 20 20 20 20 20 0 20
# Rows examine 17 2.15M 2.15M 2.15M 2.15M 2.15M 0 2.15M
# Query size 14 90 90 90 90 90 0 90
# String:
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS LIKE 't_100w'\G
# SHOW CREATE TABLE `t_100w`\G
# EXPLAIN /*!50100 PARTITIONS*/
select num,count(id) from t_100w where num>300000 group by num order by num desc limit 20\G