线上慢查询的排查

Posted 2020-10-15 kabibo

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了线上慢查询的排查相关的知识，希望对你有一定的参考价值。

最近查看慢查询日志，一直有看到SELECT * FROM tb_name的SQL语句，在之前SQL审核的时候，也没发现有这些SQL的存在，所以很好奇这里怎么出现的，后来用了vc-mysql-sniffer脚本去抓SQL来分析，也没有找出SELECT * 之类的SQL，下面我上图让分析一下：

slow.log

可以看到大量的SELECT * 的SQL，如果细心的小伙伴会发现，SQL之前都有use某个库，从这里应该可以想到一般程序里不可能会出现use xxx之类的SQL，所以可以排除程序在作怪的可能了，一般use某个库再执行SQL，普遍都是人为操作的比较多，但是DB服务器只有我才有权限，所以觉得好奇怪，在想这些SQL从哪里飞出来的，后来认真分析了一下slow log发现每次出现这类SQL的频率都是间隔一个小时左右，后来我再检查一下些库是否有定时器，结果发现没有，这下我就大概知道什么原因了，我在slave上是每个小时一备份的，以下是模拟的过程：

在测试服务器把慢查询时间设置为0.5s，然后把查询日志打开：（测试完后，记得关掉general_log）

mysql> set global long_query_time=0.5;
Query OK, 0 rows affected (0.00 sec)
mysql> set global general_log=on;
Query OK, 0 rows affected (0.01 sec)

然后把备份导入测试服务器：

[root@Test_server ~]# mysql -uroot -p123456 testdb < ./testdb.sql 
[root@Test_server ~]#

在session1窗口执行查看general_log的操作：

[root@Test_server ~]# tail -f /data/mysql3306/Test_server.log

在session2窗口执行备份操作：

[root@Test_server ~]# mysqldump -uroot -p123456  -R --events --triggers=true --master-data=2 --single-transaction  testdb > testdb.sql

再在session1上查看打印日志：

[root@Test_server ~]# tail -f /data/mysql3306/Test_server.log 
/data/service/mysql/bin/mysqld, Version: 5.6.25-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /tmp/mysql3306.sock
Time                 Id Command    Argument
151006 14:21:21 583376 Quit
151006 14:21:22 583389 Connect  root@localhost on 
                583389 Query    select @@version_comment limit 1
151006 14:21:24 583389 Query    show variables like \'%gen%\'
151006 14:21:25 583389 Quit
151006 14:43:18 583786 Connect  root@localhost on 
                583786 Query    /*!40100 SET @@SQL_MODE=\'\' */
                583786 Query    /*!40103 SET TIME_ZONE=\'+00:00\' */
                583786 Query    FLUSH /*!40101 LOCAL */ TABLES
151006 14:43:19 583786 Query    FLUSH TABLES WITH READ LOCK
                583786 Query    SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
                583786 Query    START TRANSACTION /*!40100 WITH CONSISTENT SNAPSHOT */
                583786 Query    SHOW VARIABLES LIKE \'gtid\\_mode\'
                583786 Query    SHOW MASTER STATUS
                583786 Query    UNLOCK TABLES
                583786 Query    SELECT LOGFILE_GROUP_NAME, FILE_NAME, TOTAL_EXTENTS, INITIAL_SIZE, ENGINE, EXTRA FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = \'UNDO LOG\' AND FILE_NAME IS NOT NULL AND LOGFILE_GROUP_NAME IN (SELECT DISTINCT LOGFILE_GROUP_NAME FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = \'DATAFILE\' AND TABLESPACE_NAME IN (SELECT DISTINCT TABLESPACE_NAME FROM INFORMATION_SCHEMA.PARTITIONS WHERE TABLE_SCHEMA IN (\'testdb\'))) GROUP BY LOGFILE_GROUP_NAME, FILE_NAME, ENGINE ORDER BY LOGFILE_GROUP_NAME
                583786 Query    SELECT DISTINCT TABLESPACE_NAME, FILE_NAME, LOGFILE_GROUP_NAME, EXTENT_SIZE, INITIAL_SIZE, ENGINE FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = \'DATAFILE\' AND TABLESPACE_NAME IN (SELECT DISTINCT TABLESPACE_NAME FROM INFORMATION_SCHEMA.PARTITIONS WHERE TABLE_SCHEMA IN (\'testdb\')) ORDER BY TABLESPACE_NAME, LOGFILE_GROUP_NAME
151006 14:43:20 583786 Query    SHOW VARIABLES LIKE \'ndbinfo\\_version\'
                583786 Init DB  testdb
                583786 Query    SAVEPOINT sp
                583786 Query    show tables
                583786 Query    show table status like \'sys\\_config\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `sys_config`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `sys_config`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `sys_aa`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'sys\\_config\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_auto\\_login\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_auto_login`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_auto_login`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_bb`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_auto\\_login\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_fans\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_fans`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_fans`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_cc`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_fans\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_media\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_media`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_media`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_dd`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_media\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_message\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_message`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_message`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_ee`
151006 14:43:23 583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_message\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_qrcode\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_qrcode`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_qrcode`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_ff`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_qrcode\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_ticket\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_ticket`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_ticket`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_gg`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_ticket\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'testdb\\_token\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `testdb_token`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `testdb_token`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_hh`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'testdb\\_token\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'wexin\\_template\\_msg\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `wexin_template_msg`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `wexin_template_msg`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `wexin_tem`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'wexin\\_template\\_msg\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    show table status like \'wexin\\_template\\_msg\\_data\'
                583786 Query    SET SQL_QUOTE_SHOW_CREATE=1
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    show create table `wexin_template_msg_data`
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    show fields from `wexin_template_msg_data`
                583786 Query    SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_template`
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SHOW TRIGGERS LIKE \'wexin\\_template\\_msg\\_data\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
                583786 Query    ROLLBACK TO SAVEPOINT sp
                583786 Query    RELEASE SAVEPOINT sp
                583786 Query    show events
                583786 Query    use `testdb`
                583786 Query    select @@collation_database
                583786 Query    SET SESSION character_set_results = \'binary\'
                583786 Query    SHOW FUNCTION STATUS WHERE Db = \'testdb\'
                583786 Query    SHOW PROCEDURE STATUS WHERE Db = \'testdb\'
                583786 Query    SET SESSION character_set_results = \'utf8\'
151006 14:43:27 583786 Quit

再查看一下慢查询日志：

[root@Test_server ~]# tail -f /data/mysql3306log/slow.log 
# User@Host: root[root] @ localhost []  Id: 583786
# Query_time: 0.678000  Lock_time: 0.000452 Rows_sent: 0  Rows_examined: 0
SET timestamp=1444113800;
SELECT DISTINCT TABLESPACE_NAME, FILE_NAME, LOGFILE_GROUP_NAME, EXTENT_SIZE, INITIAL_SIZE, ENGINE FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = \'DATAFILE\' AND TABLESPACE_NAME IN (SELECT DISTINCT TABLESPACE_NAME FROM INFORMATION_SCHEMA.PARTITIONS WHERE TABLE_SCHEMA IN (\'testdb\')) ORDER BY TABLESPACE_NAME, LOGFILE_GROUP_NAME;
# Time: 151006 14:43:23
# User@Host: root[root] @ localhost []  Id: 583786
# Query_time: 3.427523  Lock_time: 0.000101 Rows_sent: 303198  Rows_examined: 303198
use testdb;
SET timestamp=1444113803;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `testdb_aa`;

可以看到问题所在了。

这是用xtrabackup备份时打印的查询日志：

[root@Test_server soft]# tail -f /data/mysql3306/Test_server.log   
151006 15:49:50 584992 Connect  root@localhost on 
                584992 Query    set autocommit=1
                584992 Query    SET SESSION wait_timeout=2147483
                584992 Query    SELECT CONCAT(@@hostname, @@port)
151006 15:49:52 584992 Quit
                584993 Connect  root@localhost on 
                584993 Query    set autocommit=1
                584993 Query    SET SESSION wait_timeout=2147483
                584993 Query    SHOW VARIABLES
                584993 Query    SHOW VARIABLES
                584993 Query    SHOW SLAVE STATUS
151006 15:50:35 584993 Query    SET SESSION lock_wait_timeout=31536000
                584993 Query    FLUSH TABLES
                584993 Query    FLUSH TABLES WITH READ LOCK
                584993 Query    SHOW MASTER STATUS
                584993 Query    FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS
151006 15:50:36 584993 Query    UNLOCK TABLES
                584993 Query    SELECT UUID() AS uuid
151006 15:50:37 584993 Query    SELECT VERSION() as version
                584993 Quit

总结：

一、做好SQL的监控工作，把所有影响性能的SQL抓出来，处理掉，这样才能让服务器压力更少

二、现在普遍公司都搭建有MySQL主从架构，在从上面进行数据备份，对用户的使用体验影响比较少，所以建议在从上备份

三、数据量大的时候，用xtrabackup备份比mysqldump备份要快得多，而且是没有出现SELECT * 之类的SQL语句，如果数据量大，出现SELECT *之类的SQL，影响是灰常大的，建议用xtrabackup备份（我两个都用，因为我的slave不对外提供服务）

作者：陆炫志

出处：xuanzhi的博客 http://www.cnblogs.com/xuanzhi201111

您的支持是对博主最大的鼓励，感谢您的认真阅读。本文版权归作者所有，欢迎转载，但请保留该声明。

以上是关于线上慢查询的排查的主要内容，如果未能解决你的问题，请参考以下文章

快速定位线上慢 SQL 问题，掌握这几个性能排查工具可助你一臂之力

一次MySQL线上慢查询分析及索引使用

填坑！线上Presto查询Hudi表异常排查