| 
                        副标题[/!--empirenews.page--]
                           
大家都知道,slow query系统做的好不好,直接决定了解决slow query的效率问题 
一个数据库管理平台,拥有一个好的slow query系统,基本上就拥有了解锁性能问题的钥匙 
但是今天主要分享的并不是平台,而是在平台中看到的奇葩指数五颗星的slow issue 
好了,关子卖完了,直接进入正题 
一、症状   
- 一堆如下慢查询  
 
  
- # User@Host: cra[cra] @ [xx] Id: 3352884621  
 - # Query_time: 0.183673 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0  
 - use xx_db;  
 - SET timestamp=1549900927;  
 - # administrator command: Prepare;  
 - # Time: 2019-02-12T00:02:07.516803+08:00  
 - # User@Host: cra[cra] @ [xx] Id: 3351119968  
 - # Query_time: 0.294081 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0  
 - SET timestamp=1549900927;  
 - # administrator command: Prepare; 
 
  
从我们的监控图上可以看到,每天不定时间段的slow query 总数在攀升,但是却看不到任何query 语句 
这是我接触到的slow query优化案例中从来没有过的情况,比较好奇,也比较兴奋,至此决心要好好看看这个问题 
二、排查 
要解决这个问题,首先想到的是,如何复现这个问题,如何模拟复现这个症状 
- * 模拟  
 - root:xx> prepare stmt1 from 'select * from xx_operation_log where id = ?';  
 - Query OK, 0 rows affected (0.00 sec)  
 - Statement prepared  
 - * 结果  
 - # Time: 2019-02-14T14:14:50.937462+08:00  
 - # User@Host: root[root] @ localhost [] Id: 369  
 - # Query_time: 0.000105 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0  
 - SET timestamp=1550124890;  
 - prepare stmt1 from 'select * from xx_operation_log where id = ?'; 
 
  
结论是: MySQL client 模拟出来的prepare 并不是我们期待的,并没有得到我们想要的 administrator command: Prepare 
- #!/usr/bin/perl  
 - use DBI;  
 - my $dsn = "dbi:mysql:database=${db_name};hostname=${db_host};port=${db_port}";#数据源  
 - #获取数据库句柄  
 - my $dbh = DBI->connect("DBI:mysql:database=xx;host=xx", "xx", "xx", {'RaiseError' => 1});  
 - my $sql = qq{select * from xx_operation_log where id in (?)};  
 - my $sth = $dbh->prepare($sql);  
 - $sth->bind_param (1, '100');  
 - sleep 3;  
 - $sth->execute(); 
 
  
结论是:跟MySQL客户端一样,同样是看不到administrator command: Prepare 
php模拟得到的slow 结果 
- [root@xx 20190211]# cat xx-slow.log | grep 'administrator command: Prepare' -B4 | grep 'User@Host' | grep 'xx_rx' | wc -l  
 - 7891  
 - [root@xx 20190211]# cat xx-slow.log | grep 'administrator command: Prepare' -B4 | grep 'User@Host' | wc -l  
 - 7908 
 
  
结论: 通过php代码,我们成功模拟出了想要的结果 
那顺藤摸瓜,抓取下这段时间有相同session id的整个sql执行过程 
MySQL开启slow=0的抓包模式 
- 可以定位到同一个session id(3415357118) 的 prepare + execute + close stmt  
 - # User@Host: xx_rx[xx_rx] @ [xx.xxx.xxx.132] Id: 3415357118  
 - # Query_time: 0.401453 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0  
 - use xx_db;  
 - SET timestamp=1550017125;  
 - # administrator command: Prepare;  
 - # Time: 2019-02-13T08:18:45.624671+08:00  
 - --  
 - # User@Host: xx_rx[xx_rx] @ [xx.xxx.xxx.132] Id: 3415357118  
 - # Query_time: 0.001650 Lock_time: 0.000102 Rows_sent: 0 Rows_examined: 1  
 - use xx_db;  
 - SET timestamp=1550017125;  
 - update `xx` set `updated_at` = '2019-02-13 08:18:45', `has_sales_office_phone` = 1, `has_presale_permit` = 1 where `id` = 28886;  
 - # Time: 2019-02-13T08:18:45.626138+08:00  
 - --  
 - # User@Host: xx_rx[xx_rx] @ [xx.xxx.xxx.132] Id: 3415357118  
 - # Query_time: 0.000029 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 1  
 - use xx_db;  
 - SET timestamp=1550017125;  
 - # administrator command: Close stmt;  
 - # Time: 2019-02-13T08:18:45.626430+08:00 
 
  
结论:我们发现,prepare时间的确很长,但是sql语句却执行的很快,这就很尴尬了 
本来是想通过抓包,,看看是否能够验证我们的猜想: prepare的语句非常大,或者条件非常复杂,从而导致prepare在服务器端很慢 
结果发现query语句也都非常简单 
那么既然如此,我们就找了业务方,将对应业务的prepare方法一起看看 
结果发现,业务使用的是php-pdo的方式,所以我们就又有了如下发现 
php-pdo 两种prepare模式 
    -  http://php.net/manual/zh/pdo.prepare.php
 
 
1. 本地prepare $dbh->setAttribute(PDO::ATTR_EMULATE_PREPARES,true); 
不会发送给MySQL Server 
2. 服务器端prepare $dbh->setAttribute(PDO::ATTR_EMULATE_PREPARES,false); 
发送给MySQL Server 
                                                (编辑:泰州站长网) 
【声明】本站内容均来自网络,其相关言论仅代表作者个人观点,不代表本站立场。若无意侵犯到您的权利,请及时与联系站长删除相关内容! 
                     |