开发人员MySQL调优-实战篇3-profile日志和锁

时间 2019-11-12

原文原文链接

profile日志分析

经过使用explain命令查看执行计划，并对SQL调优后，若是还想对SQL执行过程更详细的了解，查找慢更底层的缘由，可使用profile分析。html

打开日志记录

先查看profile配置mysql

mysql> show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | OFF   |
+---------------+-------+
1 row in set

在当前会话中打开profile配置sql

mysql> set profiling=on;
Query OK, 0 rows affected

执行几个SQL数据库

select count(1) from tb_v_user;
select count(1) from tb_v_user;
select user_id,count(1) from tb_vote group by user_id;

看profile信息并发

mysql> show profiles;
+----------+------------+-------------------------------------------------------+
| Query_ID | Duration   | Query                                                 |
+----------+------------+-------------------------------------------------------+
|        1 |  0.2433095 | select count(1) from tb_v_user                        |
|        2 | 0.00085075 | unlock tables                                         |
|        3 |   0.114828 | select count(1) from tb_v_user                        |
|        4 |  0.1181025 | select count(1) from tb_v_user                        |
|        5 | 0.11777725 | select count(1) from tb_v_user                        |
|        6 |   4.482654 | select user_id,count(1) from tb_vote group by user_id |
+----------+------------+-------------------------------------------------------+
6 rows in set

Query_ID：收集到的执行SQL的序列号，后面指定要分析那一条SQL时候须要用到这个值高并发

Duration：执行SQL耗时oop

Query：SQL测试

分析日志记录

先使用以下命令参数。不知道为何这个命令在navicat中不能识别，我是登陆到虚拟机中打开mysql客户端执行的优化

mysql> ? show profile
Name: 'SHOW PROFILE'
Description:
Syntax:
SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

type:
    ALL
  | BLOCK IO
  | CONTEXT SWITCHES
  | CPU
  | IPC
  | MEMORY
  | PAGE FAULTS
  | SOURCE
  | SWAPS

type列出来了不少，但我通常就看看CPU和BLOCK IO，若是经过这两项看不出什么问题，能够再挨个查看一下spa

若是你想看全部的信息，那么能够这样写

show profile all for query 1

查看上面日志收集到的第一条sql的全部执行过程信息（步骤、耗时），返回的列会很是多，我就不贴出来了。

查看一下执行慢的SQL(ID=6)好比：

show profile CPU,BLOCK IO for query 6

mysql> show profile CPU,BLOCK IO for query 6;
+---------------------------+----------+----------+------------+--------------+---------------+
| Status                    | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+---------------------------+----------+----------+------------+--------------+---------------+
| starting                  | 0.000101 | NULL     | NULL       | NULL         | NULL          |
| checking permissions      | 6E-6     | NULL     | NULL       | NULL         | NULL          |
| Opening tables            | 0.004756 | NULL     | NULL       | NULL         | NULL          |
| init                      | 3.9E-5   | NULL     | NULL       | NULL         | NULL          |
| System lock               | 7E-6     | NULL     | NULL       | NULL         | NULL          |
| optimizing                | 3E-6     | NULL     | NULL       | NULL         | NULL          |
| statistics                | 4.7E-5   | NULL     | NULL       | NULL         | NULL          |
| preparing                 | 2.6E-5   | NULL     | NULL       | NULL         | NULL          |
| Creating tmp table        | 6.2E-5   | NULL     | NULL       | NULL         | NULL          |
| Sorting result            | 3E-6     | NULL     | NULL       | NULL         | NULL          |
| executing                 | 1E-6     | NULL     | NULL       | NULL         | NULL          |
| Sending data              | 0.797651 | NULL     | NULL       | NULL         | NULL          |
| converting HEAP to MyISAM | 0.762739 | NULL     | NULL       | NULL         | NULL          |
| Sending data              | 1.574018 | NULL     | NULL       | NULL         | NULL          |
| Creating sort index       | 1.333006 | NULL     | NULL       | NULL         | NULL          |
| end                       | 7E-6     | NULL     | NULL       | NULL         | NULL          |
| removing tmp table        | 0.009357 | NULL     | NULL       | NULL         | NULL          |
| end                       | 8E-6     | NULL     | NULL       | NULL         | NULL          |
| query end                 | 6E-6     | NULL     | NULL       | NULL         | NULL          |
| closing tables            | 1E-5     | NULL     | NULL       | NULL         | NULL          |
| freeing items             | 0.000784 | NULL     | NULL       | NULL         | NULL          |
| cleaning up               | 1.9E-5   | NULL     | NULL       | NULL         | NULL          |
+---------------------------+----------+----------+------------+--------------+---------------+
22 rows in set

下图是它的执行计划（说明一下：这个SQL只是为了测试慢，实际状况下除非脑壳短路才会对unique的列作group by ）

执行计划告诉我：使用了临时表和文件排序

那么对于上面的profile都是些是什么喃？他们就是下面截取这一段

| Creating tmp table        | 6.2E-5   | NULL     | NULL       | NULL         | NULL          |
| Sorting result            | 3E-6     | NULL     | NULL       | NULL         | NULL          |
| executing                 | 1E-6     | NULL     | NULL       | NULL         | NULL          |
| Sending data              | 0.797651 | NULL     | NULL       | NULL         | NULL          |
| converting HEAP to MyISAM | 0.762739 | NULL     | NULL       | NULL         | NULL          |
| Sending data              | 1.574018 | NULL     | NULL       | NULL         | NULL          |
| Creating sort index       | 1.333006 | NULL     | NULL       | NULL         | NULL          |
| end                       | 7E-6     | NULL     | NULL       | NULL         | NULL          |
| removing tmp table        | 0.009357 | NULL     | NULL       | NULL         | NULL          |

尝试着对这不合常规的SQL作优化

create index idx_tb_vote_user_id on tb_vote(user_id);
mysql> explain select user_id,count(1) from tb_vote group by user_id;
+----+-------------+---------+-------+---------------------+---------------------+---------+------+--------+-------------+
| id | select_type | table   | type  | possible_keys       | key                 | key_len | ref  | rows   | Extra       |
+----+-------------+---------+-------+---------------------+---------------------+---------+------+--------+-------------+
|  1 | SIMPLE      | tb_vote | index | idx_tb_vote_user_id | idx_tb_vote_user_id | 62      | NULL | 398784 | Using index |
+----+-------------+---------+-------+---------------------+---------------------+---------+------+--------+-------------+
1 row in set

没有再使用临时表和文件排序，虽然依然取了398784行，但取的是索引的，而不是表的，IO次数会明显减少，特别是那种列很是多的字段效果更明显

锁

表级锁

先看看lock命令的语法，在主机后台登陆mysql

[hadoop@hadoop00 /home/hadoop]$ mysql -u root -p
Enter password: 

mysql> ? lock
Name: 'LOCK'
Description:
Syntax:
LOCK TABLES
    tbl_name [[AS] alias] lock_type
    [, tbl_name [[AS] alias] lock_type] ...

lock_type:
    READ [LOCAL]
  | [LOW_PRIORITY] WRITE

经过命令能够看出能够在表上面添加读锁和写锁，下面分别对读锁和写锁作测试

更全面的信息能够参考https://dev.mysql.com/doc/refman/5.6/en/lock-tables.html，视本身的MySQL版本选择对应帮助文档版本

读锁

在会话1给表添加读锁

lock table tb_v_s_user read;

建立两个会话（打开两个sql窗口），在会话1中对tb_v_s_user表加读锁

操做	会话1	会话2
select user_name from tb_v_s_user limit 1;	能够	能够
select user_id from tb_vote limit 1;	不能够	能够
update tb_v_s_user set user_name = '1F7sJ' where user_name = '1F7sJ';	不能够，直接报错	阻塞-得到锁-执行
lock table tb_v_s_user read;	能够，并且不管执行多少次，一个会话只能对一个表加一个读锁，证实它是可重入锁	能够，表上的读锁加1
unlock tables	释放该会话全部的锁	释放该会话全部的锁

写锁

在操做以前先将两个会话中的全部读锁释放掉

unlock tables;

在会话1中添加写锁

show open tables where In_use > 0;

比较两个会话在不一样状况下的结果

操做	会话1	会话2
select user_name from tb_v_s_user limit 1;	能够	阻塞-得到锁-执行
select user_id from tb_vote limit 1;	不能够	能够
update tb_v_s_user set user_name = '1F7sJ' where user_name = '1F7sJ';	能够	阻塞-得到锁-执行
lock table tb_v_s_user read;	能够，一旦执行以前的写锁就变成了读锁，若是没有别的会话在表上有锁，仍是变回写锁	阻塞-得到锁-执行
unlock tables	释放该会话全部的锁	释放该会话全部的锁

行级锁

前面说表级锁会致使吞吐量很低，锁竞争严重，为此出现了行级锁，行级锁高并发下锁竞争小、吞吐量大。使用行级锁能够实现事务的ACID属性，避免由于并发出现的数据更新丢失、脏读、不可重复读、幻读的状况。

扩展：

ACID即为事务的原子性、一致性、隔离性、持久性：

原子性(Atomicity)：执行的SQL要么所有成功，要么所有失败，不可被拆分

一致性(Consistent)：就是数据在事务开始以前的状态会同一变为事务结束后的状态，不能部分被改变

隔离性(Isolation)：不一样会话执行SQL对结果互不影响，好比会话1写的数据在未提交以前是不能被会话2看到的

持久性(Durable)：数据一旦被提交，再被别的操做覆盖以前永久被保存着

没有行锁支持的事务致使的并发问题：

更新丢失(Lost Update)：会话1中执行的更新操做未提交以前被会话2中执行的更新操做覆盖

脏读(Dirty Reads)：会话1中执行的更新操做未提交就被会话2看到了

不可重复读(Non-Repeatable Reads)：会话1读取的数据在未提交以前不能重复读

幻读(Phantom Reads)：会话1中执行的新增操做未提交就被会话2看到了

事务隔离级别：

使用命令查看默认隔离级别

mysql> show variables like 'tx_isolation';
+---------------+-----------------+
| Variable_name | Value           |
+---------------+-----------------+
| tx_isolation  | REPEATABLE-READ |
+---------------+-----------------+
1 row in set

比较两个会话在不一样状况下的结果

测试以前先关闭掉每一个会话的自动提交功能

mysql> set autocommit=0;
Query OK, 0 rows affected

拿一条数据作测试，测试以前数据是这样的：

mysql> select * from tb_v_user where user_name = '01Vo5';
+----------------------+-----------+-----+--------+
| user_id              | user_name | age | gendor |
+----------------------+-----------+-----+--------+
| 01Vo53QWYUqgSsuUWN0s | 01Vo5     |  45 |      2 |
+----------------------+-----------+-----+--------+
1 row in set

操做	会话1	会话2
会话1中：update tb_v_user set age = 44 where user_name = '01Vo5';	查询结果：age=44	查询结果：age=45
会话1中：作commit;	查询结果：age=44	查询结果：age=45（由于会话2尚未commit）
会话2中：作commit;	查询结果：age=44	查询结果：age=44
会话1中：update tb_v_user set age = 46 where user_name = '01Vo5';	查询结果：age=46	执行一样的update语句，会阻塞等待直到会话1的commit以后，拿到锁才会成功
会话1中：select * from tb_v_user where user_name = '01Vo5';	查询结果：age=46	执行update tb_v_user set age = 47 where user_name = '01Vo5';
会话1\2中：select * from tb_v_user where user_name = '01Vo5';	查询结果：age=46	查询结果：age=47

行锁(MySQL默认事务隔离级别：REPEATABLE-READ)特色总结一下：只要在行上作写操做，行锁就会排斥其余写操做，其余读是能够继续的，并且不会读写了未提交的数据

注：在会话中执行ddl(create table ,drop table,create index ,drop index等等)操做，会触发commit操做

始料未及的表锁灾难

先准备一点数据，将tb_v_user中的数据插入20份到tb_vv_user中。虽然里面数据重复了，在索引的状况下，根据索引字段更新仍是行级锁

在tb_vv_user的user_name字段上添加索引

create index idx_tb_vv_user_un on tb_vv_user(user_name);

更新语句走全表扫描

1.有索引，可是更新时未走索引扫描

为了测试这一点，我得先将user_name = '01Vo5'行的user_name更新为全数字

update tb_vv_user set user_name = '12345' where user_name = '01Vo5';

测试步骤：

会话1中按照走索引方式更新数据

会话2中按照不走索引方式更新数据，同时会话2中执行其余行的更新

会话1profiles:

会话2profiles:

能够看出会话1按照不走索引方式更新时，致使了会话2的更新被阻塞

有兴趣的同窗还能够再深刻查看一下每一个sql的执行过程

show profile for query id

2.无索引

既然上面没有走索引就会致使整张表被锁，那若是表上面没有索引，作更新是否是也会这样喃？测试一下

#会话1
drop index idx_tb_vv_user_un on tb_vv_user;
update tb_vv_user set age = 13 where user_name = '12345';
#会话2
update tb_vv_user set age = 13 where user_name = '0343W'

update tb_vv_user set age = 13 where user_name = '0343W'

测试步骤：删除表上的索引，在会话1中执行更新操做的同时，在会话2中执行更新操做。为了验证会话2的更新操做确实被会话1的更新阻塞，在前面的操做都执行完后再次在会话2中执行更新操做，经过比较时间来判断。下面看看profiles

会话1：

会话2：

从执行耗时上看，是符合预期的。结论：没有索引作更新时，会触发表级锁，我认为更宽泛的说法应该是“只要DML操做走全表扫描都会触发表锁”。我认为缘由是这样的：由于全表扫描过程很慢，在当前会话还没更新完数据的时候，其余会话更新了数据就违反了事务的隔离性，因此必须加表级写锁

删除语句走全表扫描

有了上面的理论，因此删除确定也是表级写锁了

会话1：

会话2：

我在这里只测试了无索引走全表扫描的状况，结果符合预期，两个会话同时执行的时候出现了阻塞

有兴趣的同窗还能够测试有索引，可是使用varchar的自动转换作删除是否会发生阻塞

建立索引

#会话1执行
create index idx_tb_vv_user_un on tb_vv_user(user_name);
#会话2执行
update tb_vv_user set age = 10 where user_name = '0343W';

查看profiles状况

会话1：

建立索引耗时31秒

会话2：建立索引时执行的更新操做

更新耗时接近7秒，为何这么耗时？由于在建立索引的时候是表锁，任何更新操做都会被阻塞

会话2：索引建立完后执行更新操做

更新耗时毫秒级

批量插入致使索引重建

我就不测试了，和上面的区别是手工建立索引与人工建立索引

间隙锁

会话1执行的DML操做是范围扫描，而会话2执行的DML操做又在会话1的范围内，那么会话2的DML操做就会被阻塞，好比：

会话1在UPDATE条件为ID>1 AND ID<5，那么会话2在会话1还未提交时对ID在1到5之间的数据作DML操做就会阻塞

总结一下：

从开发人员角度出发，须要从如下几点去避免问题和优化SQL

1.开发时在测试环境多使用explain和profile检查本身写的SQL，好比有没有走索引，索引使用是否恰当，用小表驱动大表，避免大表的全表扫描

2.上线后跟踪系统运行状况，好比打开慢日志查询，跟踪优化SQL，不断的迭代

3.数据批量操做时避免出现表锁和间隙锁，使用show open tables 查看表上锁的状况。好比插入与删除数据、重建索引等

4.开发时如何关闭了自动提交功能，要时刻注意手动提交与关闭链接或者回收链接

5.不要写超长的SQL

6.批量操做尽可能放在系统负载低的时候去作

7.对需求发布时的数据库脚本作认真的验证，作好数据备份以备发布失败回退