FAQ系列 | 是什么导致MySQL数据库服务器磁盘I/O高?

0、导读

有个MySQL服务器的磁盘I/O总有过高报警,怎么回事?

1、问题

我的朋友小明,TA有个MySQL服务器最近总是报告磁盘I/O非常高,想着我这有免费的不用白不用的企业技术服务(TA自己这么想的),就找我帮忙给把把脉。

作为一个经验丰富(踩坑不断)的DBA,出现这种问题,一般来说,磁盘I/O很高无非是下面几个原因引起:

  1. 磁盘子系统设备性能差,或采用ext2/ext3之类文件系统,或采用cfq之类的io scheduler,所以IOPS提上不去;
  2. SQL效率不高,比如没有索引,或者一次性读取大量数据,所以需要更多的I/O;
  3. 可用内存太小,内存中能缓存/缓冲的数据不多,所以需要更多的I/O。

方法论已有,接下来就是动手开始排查了。

2、排查

先看磁盘I/O设备,是由十几块SSD组成的RAID 10阵列,按理说I/O性能应该不至于太差,看iops和%util的数据也确实如此。

innodb-anli10

再来看下文件系统、io scheduler的因素,发现采用xfs文件系统,而且io scheduler用的是noop,看来也不是这个原因。而且看了下iostat的数据,发现iops也不算低,说明I/O能力还是可以的。

innodb-anli2

再来看看当前的processlist,以及slow query log,也没发现当前有特别明显的slow query,所以也不是这个原因了。

innodb-anli8

现在只剩下内存不足这个因素了,看了下服务器物理内存是64G,用系统命令 free 看了下,发现大部分都在cached,而free的也不多。观察InnoDB相关的配置以及status,看能不能找到端倪。

首先,看下 innodb-buffer-pool-size 分配了多少:

innodb-anli9-jpg

嗯,分配了18G,好像不是太多啊~

再看一下 innodb status:

innodb-anli4-jpg

重点关注下几个wait值,再看下show engine innodb结果:

innodb-anli5-jpg

关注下unpurge列表大小,看起来还是比较大的(有111万)。

更为诡异的是,在已经停掉SLAVE IO & SQL线程后,发现redo log还在一直增长…

第一次看

innodb-anli6-jpg

停掉SLAVE线程后过阵子再看

innodb-anli7-jpg

看到这里,有经验的DBA应该基本上能想明白了,主要是因为 innodb buffer pool 太小,导致了下面几个后果:

  1. dirty page 和 data page 之间相互“排挤抢占”,所以会出现 Innodb_buffer_pool_wait_free 事件;
  2. redo log 也没办法及时刷新到磁盘中,所以在SLAVE线程停掉后,能看到LSN还在持续增长;
  3. 同时我们也看到unpurge的列表也积攒到很大(111万),这导致了ibdata1文件涨到了146G之大,不过这个可能也是因为有某些事务长时间未提交。

还有,不知道大家注意到没,Innodb_row_lock_current_waits 的值竟然是 18446744073709551615(想想bigint多大),显然不可能啊。事实上,这种情况已经碰到过几次了,明明当前没有行锁,这个 status 值却不小,查了一下官方bug库,竟然只报告了一例,bug id是#71520。

3、解决

既然知道原因,问题解决起来也就快了,我们主要做了下面几个调整:

  • 调大innodb-buffer-pool-size,原则上不超过物理内存的70%,所以设置为40G;
  • 调大innodb-purge-thread,原来是1,调整成4;
  • 调大innodb_io_capacity和innodb_io_capacity_max,值分别为2万和2.5万;

调整完后,重启实例(5.7版本前调整innodb-buffer-pool-size 和 innodb-purge-thread 需要重启才生效)。再经观察,发现IOPS下降的很快,不再告警,同时 Innodb_buffer_pool_wait_free 也一直为 0,unpurge列表降到了数千级别,搞定,收工,继续搬砖卖茶~

老叶茶馆镇店之宝,访问 http://yejinrong.com 直达

[MySQL FAQ]系列 — 为什么InnoDB表要建议用自增列做主键

我们先了解下InnoDB引擎表的一些关键特征:

  • InnoDB引擎表是基于B+树的索引组织表(IOT);
  • 每个表都需要有一个聚集索引(clustered index);
  • 所有的行记录都存储在B+树的叶子节点(leaf pages of the tree);
  • 基于聚集索引的增、删、改、查的效率相对是最高的;
  • 如果我们定义了主键(PRIMARY KEY),那么InnoDB会选择其作为聚集索引;
  • 如果没有显式定义主键,则InnoDB会选择第一个不包含有NULL值的唯一索引作为主键索引;
  • 如果也没有这样的唯一索引,则InnoDB会选择内置6字节长的ROWID作为隐含的聚集索引(ROWID随着行记录的写入而主键递增,这个ROWID不像ORACLE的ROWID那样可引用,是隐含的)。

综上总结,如果InnoDB表的数据写入顺序能和B+树索引的叶子节点顺序一致的话,这时候存取效率是最高的,也就是下面这几种情况的存取效率最高:

  • 使用自增列(INT/BIGINT类型)做主键,这时候写入顺序是自增的,和B+数叶子节点分裂顺序一致;
  • 该表不指定自增列做主键,同时也没有可以被选为主键的唯一索引(上面的条件),这时候InnoDB会选择内置的ROWID作为主键,写入顺序和ROWID增长顺序一致;
  • 除此以外,如果一个InnoDB表又没有显示主键,又有可以被选择为主键的唯一索引,但该唯一索引可能不是递增关系时(例如字符串、UUID、多字段联合唯一索引的情况),该表的存取效率就会比较差。

实际情况是如何呢?经过简单TPCC基准测试,修改为使用自增列作为主键与原始表结构分别进行TPCC测试,前者的TpmC结果比后者高9%倍,足见使用自增列做InnoDB表主键的明显好处,其他更多不同场景下使用自增列的性能提升可以自行对比测试下。

附图:

1、B+树典型结构

B+tree

2、InnoDB主键逻辑结构

Innodb-primary-key

 

延伸阅读:

1、TPCC-MySQL使用手册

2、B+Tree index structures in InnoDB

3、B+Tree Indexes and InnoDB – Percona

4、MySQL官方手册: Clustered and Secondary Indexes

[MySQL FAQ]系列 — 打开general log到底影响多大

我们知道,有时候为了debug或跟踪方便,会临时打开MySQL的general log。如果在线业务请求比较频繁的话,会导致瞬间产生大量的日志,一定程度上会影响IOPS性能。

此外,我们还有一种变通的办法,那就是打开slow query log,然后设置 long_query_time = 0,这样也可以记录所有请求log,而且记录的log比general log还要来的小,他产生的IOPS性能影响可能会比直接打开general log的影响来的小,可事实果真如此吗?我们来对比测试下就知道了。

测试试用MySQL版本:5.5.5-10.0.11-MariaDB-log MariaDB Server
测试工具: tpcc-mysql
测试Warehouse数: 100
warmup time: 60s
run time: 600s
并发线程数: 512

测试结果对比见下:

mysql-faq-impact-of-general-log

在“一般场景”下,我是设置 long_query_time = 1,并且关闭general log。

记录全部general log时的TpmC大约是不打开log时的73.28%,而记录全部slow log时的TpmC大约是不打开log时的59.53%。可见,直接打开general log对TpmC的影响更小一些,而且这种模式下产生的log其实也更小一些。是不是有点毁三观,哈哈O(∩_∩)O~

此外,如果 log-output = TABLE 时结果会怎样,请读者自行测试 :)

备注:MySQL 5.1及以上版本,才支持将long_query_time设置为0秒,在这之前的版本,其最小值是1秒。

[MySQL FAQ]系列 — MySQL复制中slave延迟监控

在MySQL复制环境中,我们通常只根据 Seconds_Behind_Master 的值来判断SLAVE的延迟。这么做大部分情况下尚可接受,但并不够准确,而应该考虑更多因素。

首先,我们先看下SLAVE的状态:

yejr@imysql.com [(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
***
Master_Log_File: mysql-bin.000327
Read_Master_Log_Pos: 668711237
Relay_Log_File: mysql-relay-bin.002999
Relay_Log_Pos: 214736858
Relay_Master_Log_File: mysql-bin.000327
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
***
Skip_Counter: 0
Exec_Master_Log_Pos: 654409041
Relay_Log_Space: 229039311
***
Seconds_Behind_Master: 3296
***

可以看到 Seconds_Behind_Master 的值是 3296,也就是SLAVE至少延迟了 3296 秒。

我们再来看下SLAVE上的2个REPLICATION进程状态:

yejr@imysql.com [(none)]> show full processlist\G
*************************** 1. row ***************************
Id: 6
User: system user
Host:
db: NULL
Command: Connect
Time: 22005006
State: Waiting for master to send event
Info: NULL
*************************** 2. row ***************************
Id: 7
User: system user
Host:
db: NULL
Command: Connect
Time: 3293
State: Updating
Info: UPDATE ** SET ** WHERE **

可以看到SQL线程一直在执行UPDATE操作,注意到 Time 的值是 3293,看起来像是这个UPDATE操作执行了3293秒,一个普通的SQL而已,肯定不至于需要这么久。
实际上,在REPLICATION进程中,Time 这列的值可能有几种情况:
1、SQL线程当前执行的binlog(实际上是relay log)中的timestamp和IO线程最新的timestamp的差值,这就是通常大家认为的 Seconds_Behind_Master 值,并不是某个SQL的实际执行耗时;
2、SQL线程当前如果没有活跃SQL在执行的话,Time值就是SQL线程的idle time;

而IO线程的Time值则是该线程自从启动以来的总时长(多少秒),如果系统时间在IO线程启动后发生修改的话,可能会导致该Time值异常,比如变成负数,或者非常大。

来看下面几个状态:

#设置pager,只查看关注的几个status值
yejr@imysql.com [(none)]> pager cat | egrep -i 'system user|Exec_Master_Log_Pos|Seconds_Behind_Master|Read_Master_Log_Pos'

#这是没有活跃SQL的情况,Time值是idle time,并且 Seconds_Behind_Master 为 0
yejr@imysql.com [(none)]> show processlist; show slave status\G
| 6 | system user | | NULL | Connect | 22004245 | Waiting for master to send event | NULL |
| 7 | system user | | NULL | Connect | 13 | Has read all relay log;**
Read_Master_Log_Pos: 445167889
Exec_Master_Log_Pos: 445167889
Seconds_Behind_Master: 0

#和上面一样
yejr@imysql.com [(none)]> show processlist; show slave status\G
| 6 | system user | | NULL | Connect | 22004248 | Waiting for master to send event | NULL |
| 7 | system user | | NULL | Connect | 16 | Has read all relay log;**
Read_Master_Log_Pos: 445167889
Exec_Master_Log_Pos: 445167889
Seconds_Behind_Master: 0

#这时有活跃SQL了,Time值是和 Seconds_Behind_Master 一样,即SQL线程比IO线程“慢”了1秒
yejr@imysql.com [(none)]> show processlist; show slave status\G
| 6 | system user | | NULL | Connect | 22004252 | Waiting for master to send event | NULL |
| 7 | system user | | floweradmin | Connect | 1 | Updating | update **
Read_Master_Log_Pos: 445182239
Exec_Master_Log_Pos: 445175263
Seconds_Behind_Master: 1

#和上面一样
yejr@imysql.com [(none)]> show processlist; show slave status\G
| 6 | system user | | NULL | Connect | 22004254 | Waiting for master to send event | NULL |
| 7 | system user | | floweradmin | Connect | 1 | Updating | update **
Read_Master_Log_Pos: 445207174
Exec_Master_Log_Pos: 445196837
Seconds_Behind_Master: 1

好了,最后我们说下如何正确判断SLAVE的延迟情况:
1、首先看 Relay_Master_Log_FileMaster_Log_File 是否有差异;
2、如果Relay_Master_Log_FileMaster_Log_File 是一样的话,再来看Exec_Master_Log_PosRead_Master_Log_Pos 的差异,对比SQL线程比IO线程慢了多少个binlog事件;
3、如果Relay_Master_Log_FileMaster_Log_File 不一样,那说明延迟可能较大,需要从MASTER上取得binlog status,判断当前的binlog和MASTER上的差距;

因此,相对更加严谨的做法是:
在第三方监控节点上,对MASTER和SLAVE同时发起SHOW BINARY LOGSSHOW SLAVE STATUS\G的请求,最后判断二者binlog的差异,以及 Exec_Master_Log_PosRead_Master_Log_Pos 的差异。

例如:
在MASTER上执行SHOW BINARY LOGS 的结果是:

+------------------+--------------+
| Log_name | File_size |
+------------------+--------------+
| mysql-bin.000009 | 1073742063 |
| mysql-bin.000010 | 107374193 |
+------------------+--------------+

而在SLAVE上执行SHOW SLAVE STATUS\G 的结果是:

Master_Log_File: mysql-bin.000009
 Read_Master_Log_Pos: 668711237
Relay_Master_Log_File: mysql-bin.000009
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
***
Exec_Master_Log_Pos: 654409041

***
Seconds_Behind_Master: 3296
***

这时候,SLAVE实际的延迟应该是:
mysql-bin.000009 这个binlog中的binlog position 1073742063 和 SLAVE上读取到的binlog position之间的差异延迟,即:

1073742063 - 654409041 = 419333022 个binlog event

并且还要加上 mysql-bin.000010这个binlog已经产生的107374193个binlog event,共

107374193 + 419333022 = 526707215 个binlog event

后记更新:

1、可以在MASTER上维护一个监控表,它只有一个字段,存储这最新最新时间戳(高版本可以采用event_scheduler来更新,低版本可以用cron结合自动循环脚本来更新),在SLAVE上读取该字段的时间,只要MASTER和SLAVE的系统时间一致,即可快速知道SLAVE和MASTER延迟差了多少。不过,在高并发的系统下,这个时间戳可以细化到毫秒,否则哪怕时间一致,也是有可能会延迟数千个binlog event的。
2、网友(李大玉,QQ:407361231)细心支出上面的计算延迟有误,应该是mysql-bin.000009的最大事件数减去已经被执行完的事件数,即1073742063 – 654409041= 419333022个binlog event,再加上mysql-bin.000010这个binlog已经产生的107374193个binlog event,共526707215 个binlog event。

[MySQL FAQ]系列 — 如何安全地关闭MySQL实例

本文分析了mysqld进程关闭的过程,以及如何安全、缓和地关闭MySQL实例,对这个过程不甚清楚的同学可以参考下。

关闭过程:

  • 1、发起shutdown,发出  SIGTERM信号
  • 2、有必要的话,新建一个关闭线程(shutdown thread)

如果是客户端发起的关闭,则会新建一个专用的关闭线程

如果是直接收到 SIGTERM 信号进行关闭的话,专门负责信号处理的线程就会负责关闭工作,或者新建一个独立的线程负责这个事

当无法创建独立的关闭线程时(例如内存不足),MySQL Server会发出类似下面的告警信息:

Error: Can’t create thread to kill server

  • 3、MySQL Server不再响应新的连接请求

关闭TCP/IP网络监听,关闭Unix Socket等渠道

  • 4、逐渐关闭当前的连接、事务

空闲连接,将立刻被终止;

当前还有事务、SQL活动的连接,会将其标识为 killed,并定期检查其状态,以便下次检查时将其关闭;(参考 KILL 语法)

当前有活跃事务的,该事物会被回滚,如果该事务中还修改了非事务表,则已经修改的数据无法回滚,可能只会完成部分变更;

如果是Master/Slave复制场景里的Master,则对复制线程的处理过程和普通线程也是一样的;

如果是Master/Slave复制场景里的Slave,则会依次关闭IO、SQL线程,如果这2个线程当前是活跃的,则也会加上 killed 标识,然后再关闭;

Slave服务器上,SQL线程是允许直接停止当前的SQL操作的(为了避免复制问题),然后再关闭该线程;

在MySQl 5.0.80及以前的版本里,如果SQL线程当时正好执行一个事务到中间,该事务会回滚;从5.0.81开始,则会等待所有的操作结束,除非用户发起KILL操作。

当Slave的SQL线程对非事务表执行操作时被强制 KILL了,可能会导致Master、Slave数据不一致;

  • 5、MySQL Server进程关闭所有线程,关闭所有存储引擎;

刷新所有表cache,关闭所有打开的表;

每个存储引擎各自负责相关的关闭操作,例如MyISAM会刷新所有等待写入的操作;InnoDB会将buffer pool刷新到磁盘中(从MySQL 5.0.5开始,如果innodb_fast_shutdown不设置为 2 的话),把当前的LSN记录到表空间中,然后关闭所有的内部线程。

  • 6、MySQL Server进程退出

关于KILL指令

从5.0开始,KILL 支持指定  CONNECTION | QUERY两种可选项:

  • KILL CONNECTION和原来的一样,停止回滚事务,关闭该线程连接,释放相关资源;
  • KILL QUERY则只停止线程当前提交执行的操作,其他的保持不变;

提交KILL操作后,该线程上会设置一个特殊的 kill标记位。通常需要一段时间后才能真正关闭线程,因为kill标记位只在特定的情况下才检查:

  • 1、执行SELECT查询时,在ORDER BY或GROUP BY循环中,每次读完一些行记录块后会检查 kill标记位,如果发现存在,该语句会终止;
  • 2、执行ALTER TABLE时,在从原始表中每读取一些行记录块后会检查 kill 标记位,如果发现存在,该语句会终止,删除临时表;
  • 3、执行UPDATE和DELETE时,每读取一些行记录块并且更新或删除后会检查 kill 标记位,如果发现存在,该语句会终止,回滚事务,若是在非事务表上的操作,则已发生变更的数据不会回滚;
  • 4、GET_LOCK() 函数返回NULL;
  • 5、INSERT DELAY线程会迅速内存中的新增记录,然后终止;
  • 6、如果当前线程持有表级锁,则会释放,并终止;
  • 7、如果线程的写操作调用在等待释放磁盘空间,则会直接抛出“磁盘空间满”错误,然后终止;
  • 8、当MyISAM表在执行REPAIR TABLE 或 OPTIMIZE TABLE 时被 KILL的话,会导致该表损坏不可用,指导再次修复完成。

安全关闭MySQL几点建议

想要安全关闭 mysqld 服务进程,建议按照下面的步骤来进行:

  • 0、用具有SUPER、ALL等最高权限的账号连接MySQL,最好是用 unix socket 方式连接;
  • 1、在5.0及以上版本,设置innodb_fast_shutdown = 1,允许快速关闭InnoDB(不进行full purge、insert buffer merge),如果是为了升级或者降级MySQL版本,则不要设置;
  • 2、设置innodb_max_dirty_pages_pct = 0,让InnoDB把所有脏页都刷新到磁盘中去;
  • 3、设置max_connections和max_user_connections为1,也就最后除了自己当前的连接外,不允许再有新的连接创建;
  • 4、关闭所有不活跃的线程,也就是状态为Sleep  且 Time 大于 1 的线程ID;
  • 5、执行 SHOW PROCESSLIST  确认是否还有活跃的线程,尤其是会产生表锁的线程,例如有大数据集的SELECT,或者大范围的UPDATE,或者执行DDL,都是要特别谨慎的;
  • 6、执行 SHOW ENGINE INNODB STATUS 确认History list length的值较低(一般要低于500),也就是未PURGE的事务很少,并且确认Log sequence number、Log flushed up to、Last checkpoint at三个状态的值一样,也就是所有的LSN都已经做过检查点了;
  • 7、然后执行FLUSH LOCKAL TABLES 操作,刷新所有 table cache,关闭已打开的表(LOCAL的作用是该操作不记录BINLOG);
  • 8、如果是SLAVE服务器,最好是先关闭 IO_THREAD,等待所有RELAY LOG都应用完后,再关闭 SQL_THREAD,避免 SQL_THREAD 在执行大事务被终止,耐心待其全部应用完毕,如果非要强制关闭的话,最好也等待大事务结束后再关闭SQL_THREAD;
  • 9、最后再执行 mysqladmin shutdown。
  • 10、紧急情况下,可以设置innodb_fast_shutdown = 1,然后直接执行 mysqladmin shutdown 即可,甚至直接在操作系统层调用 kill 或者 kill -9 杀掉 mysqld 进程(在innodb_flush_log_at_trx_commit = 0 的时候可能会丢失部分事务),不过mysqld进程再次启动时,会进行CRASH RECOVERY工作,需要有所权衡。

啰嗦那么多,其实正常情况下执行 mysqladmin shutdown 就够了,如果发生阻塞,再参考上面的内容进行分析和解决吧,哈哈:)