暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

MYSQL 5.7 DDL CRASHES问题分析

数元技术 2017-12-06
1780

最近有几个执行DDL变更导致MySQL崩溃的情况。 在其中一个奔溃案例中,是由于迅速连续的DROP多个数据表而引起的。 在此之前,我们升级到了MySQL 5.7,这个问题是我们使用mysql_upgrade在2.2Tb表上运行ALTER TABLE FORCE的是时候发生的,该操作以便我们将其转换为新的支持微秒精度的数据格式。

这个问题发生在中间表已经完全写入全部数据之后,当MySQL将中间表和现有表换出时发生的。 经过一段时间MySQL崩溃后,我们在错误日志中发现了以下InnoDB输出:

2017-11-19T00:22:44.070363Z 7 [ERROR] InnoDB: The age of the last checkpoint is 379157140, which exceeds the log group capacity 377483674.

InnoDB: ###### Diagnostic info printed to the standard error stream

2017-11-19T00:22:57.447115Z 0 [Warning] InnoDB: A long semaphore wait:

–Thread 140690671367936 has waited at srv0srv.cc line 1982 for 921.00 seconds the semaphore:

X-lock on RW-latch at 0x750a368 created in file dict0dict.cc line 1184

a writer (thread id 140690645923584) has reserved it in mode exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0purge.cc line 862

Last time write locked in file build/mysql-5.7-RrA758/mysql-5.7-5.7.20/storage/innobase/row/row0mysql.cc line 4305

2017-11-19T00:22:57.447181Z 0 [Warning] InnoDB: A long semaphore wait:

–Thread 140690535433984 has waited at buf0flu.cc line 1209 for 660.00 seconds the semaphore:

SX-lock on RW-latch at 0x7ff5d4a5eaa0 created in file buf0buf.cc line 1460

a writer (thread id 140690645923584) has reserved it in mode exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0sel.cc line 1335

Last time write locked in file build/mysql-5.7-RrA758/mysql-5.7-5.7.20/storage/innobase/row/row0upd.cc line 2856

2017-11-19T00:22:57.447210Z 0 [Warning] InnoDB: A long semaphore wait:

–Thread 140690654582528 has waited at row0purge.cc line 862 for 923.00 seconds the semaphore:

S-lock on RW-latch at 0x750a368 created in file dict0dict.cc line 1184

a writer (thread id 140690645923584) has reserved it in mode exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0purge.cc line 862

Last time write locked in file build/mysql-5.7-RrA758/mysql-5.7-5.7.20/storage/innobase/row/row0mysql.cc line 4305

InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

InnoDB: Pending preads 0, pwrites 0

…..

—————————-

END OF INNODB MONITOR OUTPUT

============================

InnoDB: ###### Diagnostic info printed to the standard error stream

2017-11-19T00:23:27.448900Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to 10364 be hung.

2017-11-18 19:23:27 0x7ff51a7d9700 InnoDB: Assertion failure in thread 140690688153344 in file ut0ut.cc line 916



这里要注意的关键信息在是数据字典(dict0dict.cc)上有一个purge event清除事件(row0purge.cc),它形成了一个持续时间超过600秒的信号量。如果信号量等待时间超过600秒,MySQL将会自行崩溃。

在输出中我们注意到了一些其他的东西,特别是有一个警告,即上一个检查点超出了重做日志文件的阈值,这表明重做日志的积累超过了InnoDB刷新磁盘的能力,这绝对是造成问题的瓶颈。

为了解决这个问题,我们将重做日志空间增加到了8G,因为一些测试表明在2.2Tb大小的表上ALTER TABLE FORCE进程期间将有多少数据写入重做日志。同时我们也增加内存和缓冲池大小,以加快ALTER TABLE FORCE进程。

另外一个关键的变更是,我们相信解决这个问题是需要将变量innodb_purge_threads从5.7的默认值4设置为1. 如果你检查MySQL的参考文档,你会看到有一个注释说明需要保持这个设置比较低为低,以便线程不会相互竞争访问繁忙的表。通过一些Google搜索,你也可以找到像这样的bug报告,其中提出了将该变量设置为1的类似问题。

结论:

从这里得出的结论仅仅是建议如果你正在运行MySQL 5.7,你需要考虑将变量innodb_purge_threads从它的新默认值4改为5.6的默认值1,以避免清除线程争用。 也就是说,除非你有强烈的需要运行多个清除线程,建议将这个值设置为1,因为它可以被认为是不安全的设置。大家有没有使用5.7的同学,是否有这个问题,innodb_purge_threads是如何设置的,欢迎留言讨论。


文章转载自数元技术,如果涉嫌侵权,请发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论