标签归档:FAQ

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 就够了,如果发生阻塞,再参考上面的内容进行分析和解决吧,哈哈:)

[MySQL FAQ]系列 — slow log中出现大量的binlog dump记录

线上有个数据库,在slow log中,存在大量类似下面的记录:

# Time: 130823 13:56:08
# User@Host: repl[repl] @ slave [10.x.x.x]
# Query_time: 9.000833 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1377237368;
# administrator command: Binlog Dump;

每完成一次binlog dump都会被记录下来,看着非常不爽(我有强迫症,O(∩_∩)O哈哈~),得想着法子搞掉。
经过排查,最后确认是特定版本存在这个现象,目前发现官方 5.1.49 存在,估计整个官方 5.1.x 都会有这个现象。

解决方法:
修改 my.cnf 配置文件,增加或修改下面这个选项:

log-slow-admin-statements = 0

比较坑人的是,这个选项在5.1无法在线修改,需要重启mysqld。
手册上关于这个选项的解释如下:

Include slow administrative statements in the statements written to the slow query log. Administrative statements include ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE.

手册也有不靠谱的时候啊,还是实践出真知。