innodb保护行锁对象的mutext争用导致LINUX内核态CPU使用率高诊断

MSYQL 版本：

mysql> select version()\G

*************************** 1. row ***************************

version(): 5.6.27-log

1 row in set (0.00 sec)

 

1. 测试数据如下

mysql> select * from t1;

+------+------+

| id   | name |

+------+------+

|   15 | a    |

|   10 | b    |

|    6 | c    |

|   10 | d    |

|   11 | f    |

|    2 | zz   |

+------+------+

6 rows in set (0.00 sec)

 

表中只有6条数据都存储在同一个数据块中。

 

mysql> show index from t1\G

*************************** 1. row ***************************

        Table: t1

   Non_unique: 0

     Key_name: PRIMARY

 Seq_in_index: 1

  Column_name: name

    Collation: A

  Cardinality: 5

     Sub_part: NULL

       Packed: NULL

         Null:

   Index_type: BTREE

      Comment:

Index_comment:

1 row in set (0.00 sec)

 

T1表只有在 name 字段上的主键索引。

 

 

2. 创建用来测试的存储过程

 

DELIMITER $$

 

USE `test`$$

 

DROP PROCEDURE IF EXISTS `p4`$$

 

CREATE DEFINER=`root`@`localhost` PROCEDURE `p4`()

BEGIN

DECLARE i INT;

SET i = 1;

WHILE i < 10000000000 DO

UPDATE t1 SET id=15 WHERE id=15;

commit;

SET i = i +1;

END WHILE;

END$$

 

DELIMITER ;

 

 

 

DELIMITER $$

 

USE `test`$$

 

DROP PROCEDURE IF EXISTS `p5`$$

 

CREATE DEFINER=`root`@`localhost` PROCEDURE `p5`()

BEGIN

DECLARE i INT;

SET i = 1;

WHILE i < 10000000000 DO

UPDATE t1 SET id=6 WHERE id=6;

commit;

SET i = i +1;

END WHILE;

END$$

 

DELIMITER ;

 

 

 

DELIMITER $$

 

USE `test`$$

 

DROP PROCEDURE IF EXISTS `p6`$$

 

CREATE DEFINER=`root`@`localhost` PROCEDURE `p6`()

BEGIN

DECLARE i INT;

SET i = 1;

WHILE i < 10000000000 DO

UPDATE t1 SET id=10 WHERE id=10;

commit;

SET i = i +1;

END WHILE;

END$$

 

DELIMITER ;

 

 

3. 分别在三个会话中调用存储过程

会话一调用 存储过程 p4

mysql> call p4();

 

会话二调用存储过程 p5

mysql > call p5();

 

 

会话三调用存储过程 p6

mysql > call p6();

 

 

4. 运行 pt-stalk  采集性能数据

 

bin/pt-stalk  --collect-oprofile  TRUE    --dest /root/olm/pt-stalk-data-12-07  --no-stalk --run-time 300 --iterations 1 --sleep=3

 

上面这条命令的意思是启动 pt-stalk 立即采集性能数据，总采集时长为300秒，没采集一次

数据休眠3秒。收集到的数据存放在 /root/olm/pt-stalk-data-12-07 目录中。

 

 

5. 分析 pt-stalk 采集到的性能数据

 

从收集到的 TOP 输出的数据我们看到用户空间使用的CPU只有10.6%，内核空间使用的CPU 有34.7%（非常高）；然后我们再看下具体进程使用的CPU，

看到 MYSQL 使用了164.1%，测试的服务器只有2个逻辑CPU，MYSQLD 进程使用了164.1% 的CPU，也就是说 CPU都是MSYQLD消耗的，结合CPU使

用率汇总信息中用户空间10.6%、内核空间CPU 使用率 34.7%，可以判断内核这么高的CPU使用率也是 MYSQLD进行系统调用消耗的。

 

 

上图中是 oprofile 采集的MYSQLD 线程堆栈的报告，按 CPU 时间排序。

 

buf_page_get_gen  是从 INNODB 缓冲池中读取数据页。

mutex_spin_wait函数是 MSYQL 线程等待 mutex 在CPU上自旋。

ut_delay 函数是在CPU上自旋时进行空转。该函数消耗MSYQLD总执行时间的22%。

 

2016_12_07_15_17_07-mutex-status1：mutext 状态信息采集的数据日如下

Type Name       Status

InnoDB     trx0trx.cc:108 os_waits=33637

InnoDB     trx0trx.cc:108 os_waits=36124

InnoDB     trx0trx.cc:108 os_waits=49444

InnoDB     trx0sys.cc:597 os_waits=1298

InnoDB     lock0lock.cc:614       os_waits=13552558

InnoDB     lock0lock.cc:611       os_waits=175740

InnoDB     log0log.cc:844 os_waits=16

InnoDB     buf0buf.cc:1334       os_waits=7

InnoDB     fil0fil.cc:1690   os_waits=1

InnoDB     combined buf0buf.cc:1068       os_waits=2

InnoDB     log0log.cc:907 os_waits=3118

InnoDB     trx0i_s.cc:1439        os_waits=11

InnoDB     combined buf0buf.cc:1069       os_waits=411

 

mutext status 数据显示有大量的 os_waits，os_waits 是 MYSQL线程通过自旋没有获得 mutext 而进入了睡眠状态。

 

 

 

 

   Info: SHOW FULL PROCESSLIST

TS 1481095031.012708878 2016-12-07 15:17:11

*************************** 1. row ***************************

     Id: 76

   User: root

   Host: localhost

     db: test

Command: Query

   Time: 0

  State: closing tables

   Info: UPDATE t1 SET id=15 WHERE id=15

*************************** 2. row ***************************

     Id: 77

   User: root

   Host: localhost

     db: test

Command: Query

   Time: 0

  State: Searching rows for update

   Info: UPDATE t1 SET id=6 WHERE id=6

*************************** 3. row ***************************

     Id: 78

   User: lixia

   Host: Lenovo-PC:52948

     db: test

Command: Sleep

   Time: 2022

  State:

   Info: NULL

*************************** 4. row ***************************

     Id: 79

   User: lixia

   Host: Lenovo-PC:52949

     db: NULL

Command: Sleep

   Time: 2027

  State:

   Info: NULL

*************************** 5. row ***************************

     Id: 81

   User: root

   Host: localhost

     db: test

Command: Query

   Time: 0

  State: Searching rows for update

   Info: UPDATE t1 SET id=10 WHERE id=10

*************************** 6. row ***************************

     Id: 14644

   User: root

   Host: localhost

     db: NULL

Command: Sleep

   Time: 1

  State:

   Info: NULL

*************************** 7. row ***************************

     Id: 14654

   User: root

   Host: localhost

     db: NULL

Command: Query

   Time: 0

  State: init

   Info: SHOW FULL PROCESSLIST

 

 

上面是 pt-stalk 采集的MYSQL线程状态（保持数据的文件名是 2016_12_07_15_17_07-processlist），出现 mutext争用MYSQL CPU使用率很高时，MYSQL 在循环执行UPDATE 操作。

 

综合我们分析的各种性能数据推断MYSQL CPU使用率很高（操作系统内核CPU使用率达到30%）就是因为频繁的保护锁对象的 mutext 争用导致的。

 

 

优化方法：在 T1 表的 ID 字段上创建索引。

6. 在T1表的ID 字段上创建索引进行优化

 

create index idx_t1_id on t1(id);

 

创建好索引后再执行上面的测试，同时使用 pt-stalk 采集性能数据。

 

7. 分析优化后pt-stalk 采集性能数据

 

文件2016_12_15_22_13_12-top 中是pt-stalk  采集的TOP 命令输出的信息，内容如下：

我们看到内核空间CPU使用率不到2%，pt-stalk 只在开始时采集了一次 TOP 命令的输出信息，后面我直接使用 TOP 命令进行监控，在用户空间CPU使

用率达到95%的时候，内核空间CPU使用率只有3%。

 

文件2016_12_15_22_13_12-opreport 中是pt-stalk  生成的oprofile 采集的MYSQLD 线程堆栈的报告，按 CPU 时间排序，内容如下：

ut_delay 函数没有排在前面了，而且排在前面的函数CPU使用率最高的也只有2.6591%。

 

文件2016_12_15_22_13_12-mutex-status1中是pt-stalk  采集的mutex等待信息，内容如下：

Type Name       Status

InnoDB     trx0sys.cc:597 os_waits=2389

InnoDB     lock0lock.cc:611       os_waits=13929  #之前锁对象MUTEX OS_WAITS有1355万，现在只有1.39万，其他类型的 OS_WIATS也比优化前低很多。

InnoDB     log0log.cc:844 os_waits=15

InnoDB     buf0buf.cc:1334       os_waits=5

InnoDB     fil0fil.cc:1690   os_waits=1

InnoDB     combined buf0buf.cc:1068       os_waits=1316

InnoDB     dict0dict.cc:1066     os_waits=1

InnoDB     log0log.cc:907 os_waits=962

InnoDB     trx0i_s.cc:1439        os_waits=30

InnoDB     combined buf0buf.cc:1069       os_waits=625

 

 

 

文件2016_12_15_22_13_12-processlist中是 pt-stalk  采集的MSYQL线程信息，内容如下：

.......

 

*************************** 1. row ***************************

     Id: 4

   User: root

   Host: localhost

     db: test

Command: Sleep

   Time: 811

  State:

   Info: NULL

*************************** 2. row ***************************

     Id: 6

   User: root

   Host: localhost

     db: test

Command: Query

   Time: 0

  State: System lock

   Info: UPDATE t1 SET id=15 WHERE id=15

*************************** 3. row ***************************

     Id: 7

   User: root

   Host: localhost

     db: test

Command: Query

   Time: 0

  State: Opening tables

   Info: UPDATE t1 SET id=6 WHERE id=6

*************************** 4. row ***************************

     Id: 8

   User: root

   Host: localhost

     db: test

Command: Query

   Time: 0

  State: Searching rows for update

   Info: UPDATE t1 SET id=10 WHERE id=10

*************************** 5. row ***************************

     Id: 1832

   User: root

   Host: localhost

     db: NULL

Command: Sleep

   Time: 1

  State:

   Info: NULL

*************************** 6. row ***************************

     Id: 1912

   User: unauthenticated user

   Host: localhost

     db: NULL

Command: Connect

   Time: NULL

  State: Reading from net

   Info: NULL

*************************** 7. row ***************************

     Id: 1913

   User: root

   Host: localhost

     db: NULL

Command: Query

   Time: 0

  State: init

   Info: SHOW FULL PROCESSLIST

TS 1481811209.008936284 2016-12-15 22:13:29

 

......

 

在收集到的线程信息中，执行UPDATE操作的线程状态为 Searching rows for update 的情况比较少，优化前执行UPDATE 操作的线程状态绝大部分情况是 Searching rows for update 的状态。

 

从pt-stalk采集的数据我们看到没有锁等待的情况。

 

小结：

通过创建索引后的测试证明优化前的 MUTEX 争用都是发生在锁对象上的，导致操作系统内核空间CPU使用率达到30%的原因就是锁对象MUTEX争用。

 

现在还有个猜想，如果在ID字段有索引的情况3个会话对相同记录进行更新，应该也会出现很高的锁对象 MUTEX争用导致操作系统内核CPU使用率高。

 

mutext 获取的大致过程：

线程检查某 mutext 是否能够获取 --> 如果不能获取线自旋 --> 自旋MSYQL 系统设定次数后还无法获得 mutext MYSQL 线程 SLEEP --> MSYQL 线程 SLEEP 时有 LINUX 负责在LINUX 内核中进行自旋操作等待 mutext

LINUX 自旋时在 LINUX 内核空间消耗 CPU ，如果在LINUX 层面自旋等待 MUTEXT 的MYSQL 线程很多，或导致LINUX 内核空间CPU 使用率很高。当

MYSQL 线程 SLEEP 由 LINUX 内核自旋等待 MUTEXT 在 MYSQL 对应的等待是 OS_WAITS 。

 

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/21582653/viewspace-2130607/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/21582653/viewspace-2130607/