mysql slow log

https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

slow log是工作中最重要的日志了。mysql启动不了看error log,查询慢就看slow log。

查看slow log 配置

(root@localhost) [(none)]>show variables like '%slow%';
+---------------------------+----------------+
| Variable_name             | Value          |
+---------------------------+----------------+
| log_slow_admin_statements | ON             |
| log_slow_slave_statements | ON             |
| slow_launch_time          | 2              |
| slow_query_log            | ON             |
| slow_query_log_file       | mysql-slow.log |
+---------------------------+----------------+

online设置slow log

set global slow_query_log =ON;
set global slow_query_log_file= 'mysql-slow.log';
set global long_query_time= 2;
set session long_query_time= 2;

注意long_query_time变量是global/session 级别的。就是说online设置完毕后原来已经存在的连接的session级别long_query_time变量的值还是老值。会碰到明明修改了却不生效的问题。
对比下官网文档的long_query_time和slow_query_log:

long_query_time
Command-Line Format --long-query-time=#
System Variable long_query_time
Scope   Global, Session
Dynamic Yes
SET_VAR Hint Applies    No
Type    Numeric
Default Value   10
Minimum Value   0
slow_query_log
Command-Line Format --slow-query-log[={OFF|ON}]
System Variable slow_query_log
Scope   Global
Dynamic Yes
SET_VAR Hint Applies    No
Type    Boolean
Default Value   OFF

可见long_query_time的Scope= Global, Session,全局和会话级别;slow_query_log的Scop=Global只是全局级别;我们需要close掉老连接,这样新打开一个连接就是新long_query_time值了。
对于当前连接我们还可以这样,同时设置session 和global 的值,防止出现当前连接不生效。

(root@localhost) [mysql]>set session long_query_time= 2;
Query OK, 0 rows affected (0.00 sec)
(root@localhost) [mysql]>set global long_query_time= 2;
Query OK, 0 rows affected (0.00 sec)

先放出slow_log配置信息

slow_query_log=1
slow_query_log_file=mysql-slow.log
long_query_time=2
log_queries_not_using_indexes=1
log_throttle_queries_not_using_indexes=10
log_slow_admin_statements=1
log_slow_slave_statements=1
min_examined_row_limit=1000
log_output=FILE
[mysqld-5.7]
log_timestamps=system

1、slow_query_log:表示是否开启slow log ,此参数与log_slow_queries的作用没有区别,5.6以后的版本使用此参数替代log_slow_queries。

2、 slow_query_log_file:当使用文件存储slow log时(log_output设置为”FILE”或者”FILE,TABLE”时),slow log存储于指定路径的文件,默认的slow log文件名为”主机名-slow.log”,slow log的位置为datadir参数所对应的目录位置,一般情况下为 /var/lib/mysql。

3、long_query_time:表示”多长时间的查询被认定为慢查询,此值得默认值为10秒,表示超过10秒的查询被认定为慢查询。大于long_query_time 会被记录,而刚好等于long_query_time 不会记录。

4、log_queries_not_using_indexes:将没有使用索引的语句记录到slow log。 有些语句虽然执行很快,没有达到long_query_time阈值,这时也要记录下来。如测试环境下数据量非常少,即使sql写的烂也会很快,但是放到线上环境下就会变的非常慢然后又不会记录到slow.log(就是为了杜绝这种情况)。另外有些语句使用了索引,当时有使用派生表(派生表不会使用索引)也会被记录下来,这点有点讨厌。当然还是看具体情况如何,建议开启。

5、log_throttle_queries_not_using_indexes:5.6.5版本新引入的参数,当log_queries_not_using_inde设置为ON时,没有使用索引的查询语句也会被当做慢查询语句记录到slow log中,使用log_throttle_queries_not_using_indexes可以限制这种语句每分钟记录到slow log中的次数,因为在生产环境中,有可能有很多没有使用索引的语句,此类语句频繁地被记录到slow log中,可能会导致slow log快速不断的增长,管理员可以通过此参数进行控制。设置10,每分钟最多记录10条同样的没有使用索引的慢查询。

6、min_examined_row_limit: 扫描记录数少于设定值的语句不会被记录到slow log。比如sleep(5) 就不会记录下来,因为它扫描记录数是0小于min_examined_row_limit 。设置1000,超过1000时才会记录。防止slow.log过大。

7、log_slow_admin_statements:记录执行缓慢的DDL语句,如alter table,analyze table, check table, create index, drop index, optimize table, repair table等。

8、log_slow_slave_statements:记录从库上执行的慢查询语句。

9、log_timestamps:5.7版本新增时间戳所属时区参数,默认记录UTC时区的时间戳到slow log;应修改为记录系统时区(这是5.7的一个坑,建议设置为system。若不设置则会慢8小时)。因为log_timestamps在mysql5.6下无效,因此我们可以这样配置:

[mysqld-5.7]
log_timestamps=system 

10、log_output:指定慢查询日志的输出方式,从5.5版本开始可以记录到日志文件(FILE,慢查询日志)和数据库表(TABLE,mysql.slow_log)中 。建议设置为FILE,不建议记录到表中。

  • 记录到TABLE性能开销更大。
  • 如果数据进行备份的话,可能把这个表也备份了;当然这是没有意义的。

当然记录到TABLE中也有好处:

  • 可以直观展示slow log信息。
    最终选择啥,具体情况具体分析吧~
(root@localhost) [mysql]>desc mysql.slow_log;
+----------------+---------------------+------+-----+----------------------+--------------------------------+
| Field          | Type                | Null | Key | Default              | Extra                          |
+----------------+---------------------+------+-----+----------------------+--------------------------------+
| start_time     | timestamp(6)        | NO   |     | CURRENT_TIMESTAMP(6) | on update CURRENT_TIMESTAMP(6) |
| user_host      | mediumtext          | NO   |     | NULL                 |                                |
| query_time     | time(6)             | NO   |     | NULL                 |                                |
| lock_time      | time(6)             | NO   |     | NULL                 |                                |
| rows_sent      | int(11)             | NO   |     | NULL                 |                                |
| rows_examined  | int(11)             | NO   |     | NULL                 |                                |
| db             | varchar(512)        | NO   |     | NULL                 |                                |
| last_insert_id | int(11)             | NO   |     | NULL                 |                                |
| insert_id      | int(11)             | NO   |     | NULL                 |                                |
| server_id      | int(10) unsigned    | NO   |     | NULL                 |                                |
| sql_text       | mediumblob          | NO   |     | NULL                 |                                |
| thread_id      | bigint(21) unsigned | NO   |     | NULL                 |                                |
+----------------+---------------------+------+-----+----------------------+--------------------------------+
12 rows in set (0.00 sec)

问题

1、怎么在线清理slow log?
不要直接>slow.log ,这样做空间不会释放的。

step1、先备份一下;此时文件句柄已经打开,备份之后其实日志还是输出到 mysql-slow.2020.05.16

mv mysql-slow.log mysql-slow.2020.05.16

step2、在客户端执行flush slow logs;关闭原来的slow log 文件句柄,打开新的 slow.log 文件句柄。这样才会输出到新的slow.log

(root@localhost) [(none)]>flush slow logs;
Query OK, 0 rows affected (0.00 sec)

2、因为锁等待时间过长的语句不会被记录到slow.log
slow log 只会按run time真正运行的时间来算,而不把lock_time锁等待的时间计算在内。也就是说因为lock而执行过久的语句不会被记录到slow log。slow log只会以run time时间为准!

run time = Query_time - lock_time

举个例子,如下:
Q1

(root@localhost) [test]>begin;
Query OK, 0 rows affected (0.00 sec)

(root@localhost) [test]>select * from test1 for update;
+------+------+
| id   | name |
+------+------+
|    1 | abcd |
+------+------+
1 row in set (0.00 sec)

Q2

(root@localhost) [(none)]>begin;
Query OK, 0 rows affected (0.00 sec)
(root@localhost) [(none)]>use test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
(root@localhost) [test]>update test1 set name='efg' where id=1;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

观察slow log文件内容:
update test1 set name='efg' where id=1;语句即使执行了那么久然而没有记录到slow log。

[root@localhost ~]# tail -f /mdata/mysql57/mysql-slow.log
ALTER TABLE test1 ADD PRIMARY KEY(id);
/home/mysql5.7/mysql-5.7.33-linux-glibc2.12-x86_64/bin/mysqld, Version: 5.7.33-log (MySQL Community Server (GPL)). started with:
Tcp port: 3305  Unix socket: /tmp/mysql.sock3305
Time                 Id Command    Argument
# Time: 2021-05-16T18:17:37.303914+08:00
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.000134  Lock_time: 0.000066 Rows_sent: 1  Rows_examined: 1
use test;
SET timestamp=1621160257;
select * from test1 for update;

那对于slow log记录不了lock waiting 的语句有其它方法抓取吗?
使用 show processlist;

(root@localhost) [(none)]>show processlist;
+----+------+-----------+------+---------+------+----------+----------------------------------------+
| Id | User | Host      | db   | Command | Time | State    | Info                                   |
+----+------+-----------+------+---------+------+----------+----------------------------------------+
|  2 | root | localhost | test | Query   |   21 | updating | update test1 set name='efg' where id=1 |
|  3 | root | localhost | test | Sleep   |   24 |          | NULL                                   |
|  4 | root | localhost | NULL | Query   |    0 | starting | show processlist                       |
+----+------+-----------+------+---------+------+----------+----------------------------------------+
3 rows in set (0.00 sec)

难的是有些语句是Command 是sleep状态,Time又非常长。Info又是空的。
因为应用开发的代码写错了,没有commit。导致被锁住。

3、slow log几个字段的含义

Query_time: duration`
The statement execution time in seconds.

  • Lock_time: *duration*
    The time to acquire locks in seconds.

  • Rows_sent: *N*
    The number of rows sent to the client.

  • Rows_examined:

    The number of rows examined by the server layer (not counting any processing internal to storage engines).

Each statement written to the slow query log file is preceded by a [SET]
statement that includes a timestamp indicating when the slow statement was logged (which occurs after the statement finishes executing).

Passwords in statements written to the slow query log are rewritten by the server not to occur literally in plain text. See [Section 6.1.2.3, “Passwords and Logging”]

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 226,780评论 6 526
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 97,642评论 3 411
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 174,427评论 0 373
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 62,220评论 1 306
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 71,026评论 6 405
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 54,544评论 1 319
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 42,643评论 3 433
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 41,796评论 0 283
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 48,300评论 1 329
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 40,281评论 3 352
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 42,426评论 1 364
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 37,988评论 5 354
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 43,684评论 3 342
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 34,090评论 0 25
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 35,311评论 1 280
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 51,002评论 3 385
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 47,409评论 2 370

推荐阅读更多精彩内容