By 兰春

Updated:

Contents
  1. 1. 一、症状
  2. 2. 二、排查
  3. 3. MySQL开启slow=0的抓包模式
  4. 4. php-pdo 两种prepare模式
  5. 5. 验证两种prepare模式
  6. 6. 调整和验证
  7. 7. 总结

大家都知道，slow query系统做的好不好，直接决定了解决slow query的效率问题

一个数据库管理平台，拥有一个好的slow query系统，基本上就拥有了解锁性能问题的钥匙

但是今天主要分享的并不是平台，而是在平台中看到的奇葩指数五颗星的slow issue

好了，关子卖完了，直接进入正题

一、症状

一堆如下慢查询 

1
2
3
4
5
6
7
8
9
10
11
# 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优化案例中从来没有过的情况，比较好奇，也比较兴奋，至此决心要好好看看这个问题

二、排查

要解决这个问题，首先想到的是，如何复现这个问题，如何模拟复现这个症状

  • MySQL客户端 模拟prepare
1
2
3
4
5
6
7
8
9
10
11
12
* 模拟
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

  • perl 模拟prepare
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
#!/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 faia_operation_log where id in (?)};
my $sth = $dbh->prepare($sql);
$sth->bind_param (1, '100');
sleep 3;
$sth->execute();

结论是：跟MySQL客户端一样，同样是看不到administrator command: Prepare

  • php 模拟prepare
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
1. 官方网址：
https://dev.mysql.com/doc/apis-php/en/apis-php-mysqli-stmt.prepare.html
<?php
$link = mysqli_connect("xx", "dba", "xx", "xx_db");
/* check connection */
if (mysqli_connect_errno()) {
    printf("Connect failed: %s\n", mysqli_connect_error());
    exit();
}
$city = '1';
/* create a prepared statement */
$stmt = mysqli_stmt_init($link);
if (mysqli_stmt_prepare($stmt, 'select * from xx_operation_log where id in (1,2,3)'){
    /* bind parameters for markers */
    /* mysqli_stmt_bind_param($stmt, "s", $city);
    /* execute query */
    mysqli_stmt_execute($stmt);
    /* bind result variables */
    mysqli_stmt_bind_result($stmt, $district);
    /* fetch value */
    mysqli_stmt_fetch($stmt);
    printf("%s is in district %s\n", $city, $district);
    /* close statement */
    mysqli_stmt_close($stmt);
}
/* close connection */
mysqli_close($link);
?>
  • php模拟得到的slow 结果
1
2
3
4
5
[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的抓包模式

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
可以定位到同一个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模式

1
2
3
4
5
6
7
1. 本地prepare  $dbh->setAttribute(PDO::ATTR_EMULATE_PREPARES,true); 
	不会发送给MySQL Server
2. 服务器端prepare  $dbh->setAttribute(PDO::ATTR_EMULATE_PREPARES,false); 
	发送给MySQL Server

验证两种prepare模式

  • 服务端prepare模式( ATTR_EMULATE_PREPARES = false)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
<?php
$dbms='mysql';     //数据库类型
$host='xxx'; //数据库主机名
$dbName='test';    //使用的数据库
$user='xx';      //数据库连接用户名
$pass='123456';          //对应的密码
$dsn="$dbms:host=$host;dbname=$dbName";
try {
    $pdo = new PDO($dsn, $user, $pass); //初始化一个PDO对象
    $pdo->setAttribute(PDO::ATTR_EMULATE_PREPARES,false);
    echo "----- prepare begin  -----\n";
    $stmt = $pdo->prepare("select * from test.chanpin where id = ?");
    echo "----- prepare after -----\n";
    $stmt->execute([333333]);
    echo "----- execute after -----\n";
    $rs = $stmt->fetchAll();
} catch (PDOException $e) {
    die ("Error!: " . $e->getMessage() . "<br/>");
}

strace -s200 -f php mysql1.php 跟踪

MGR

大家可以看到这个模式下，prepare的时候，是将query+占位符 发送给服务端的

  • 本地prepare模式 (ATTR_EMULATE_PREPARES = true )
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
<?php
$dbms='mysql';     //数据库类型
$host='xx'; //数据库主机名
$dbName='test';    //使用的数据库
$user='xx';      //数据库连接用户名
$pass='123456';          //对应的密码
$dsn="$dbms:host=$host;dbname=$dbName";
try {
    $pdo = new PDO($dsn, $user, $pass); //初始化一个PDO对象
    $pdo->setAttribute(PDO::ATTR_EMULATE_PREPARES,true);
    echo "----- prepare begin  -----\n";
    $stmt = $pdo->prepare("select * from test.chanpin where id = ?");
    echo "----- prepare after -----\n";
    $stmt->execute([333333]);
    echo "----- execute after -----\n";
    $rs = $stmt->fetchAll();
} catch (PDOException $e) {
    die ("Error!: " . $e->getMessage() . "<br/>");
}

strace -s200 -f php mysql1.php 跟踪

pdo_prepare_local_new

大家可以看到这个模式下，prepare的时候，是不会将query发送给服务端的，只有execute的时候才会发送

跟业务方确认后，他们使用的是后者，也就是修改了默认值，他们原本是想提升数据库的性能，因为预处理后只需要传参数就好了
但是对于我们的业务场景并不适合，我们的场景是频繁打开关闭连接，也就是预处理基本就用不到

另外文档上面也明确指出prepared statements 性能会不好

pdo_prepare_bad_perfomance

调整和验证

如何验证业务方是否将prepare修改为local了呢？ 

1
2
3
4
5
6
7
dba:(none)> show global status like 'Com_stmt_prepare';
+------------------+-----------+
| Variable_name    | Value     |
+------------------+-----------+
| Com_stmt_prepare | 716836596 |
+------------------+-----------+
1 row in set (0.00 sec)

通过观察，发现这个值没有变化，说明调整已经生效

总结

  • prepare的优点
1
2
3
4
1. 防止SQL注入
2. 特定场景下提升性能
	什么是特定场景： 就是先去服务端用占位符占位，后面可以直接发送请求来填空（参数值）     
	这样理论上来说， 你填空的次数非常多，性能才能发挥出来
  • prepare的缺点
1
2
3
4
5
1. 在服务器端的prepare毕竟有消耗，当并发量大，频繁prepare的时候，就会有性能问题   
2. 服务端的prepare模式还会带来的另外一个问题就是，排错和slow 优化有困难，因为大部分情况下是看不到真实query的      
3. 尽量设置php-pdo为  $pdo->setAttribute(PDO::ATTR_EMULATE_PREPARES,true) ，在本地prepare，不要给服务器造成额外压力
  • 建议
1
2
3
1. 默认情况下，应该使用php-pdo的默认配置，采用本地prepare的方式，这样可以做到防SQL注入的效果，性能差不到哪里去  
2. 除非真的是有上述说的特定场景，可以考虑配置成服务器prepare模式，前提是要做好测试
Contents
  1. 1. 一、症状
  2. 2. 二、排查
  3. 3. MySQL开启slow=0的抓包模式
  4. 4. php-pdo 两种prepare模式
  5. 5. 验证两种prepare模式
  6. 6. 调整和验证
  7. 7. 总结

幸福,不在于得到的多

而在于计较的少