你好,游客 登录 注册 搜索
背景:
阅读新闻

关于删除MySQL Logs的问题记录

[日期:2014-05-06] 来源:刘浩de技术博客  作者:刘浩 [字体: ]

  五一前,一个DBA同事反馈,在日常环境中删除一个大的slow log文件(假设文件大小10G以上吧),然后在MySQL中执行flush slow logs,会发现mysqld hang住。

  今天尝试着重现了此问题,这里简要分析下原因。

  重现步骤:

  1. 构造slow log (将long_query_time设成了0);

  2. 观察删rm slow log瞬间,tps/qps变化;

  3. 观察执行flush slow logs瞬间,tps/qps变化;

  4. 记录flush slow logs执行时, pstack打出的调用栈情况;

  第一步,没啥好说的。

  第二步,tps/qps没啥变化。

  第三步,会发现tps/qps瞬间跌0,如下所示:

  mysql命令行会发现,flush slow logs执行时间刚好为3s左右。

  第四步,我们看下pstack的输出结果,只记录相关的:

  会发现Thread 2在执行flush slow logs操作,其他的线程都在等待锁LOCK_log上边。

  背后的原因其实很简单,在shell中执行rm slow log操作时,由于mysqld仍有文件句柄打开此文件,所以实际上此时文件并未删除。执行flush logs操作,其实际执行的是1)close;2)open 操作(logger.flush_slow_log -> mysql_slow_log.reopen_file),在close操作执行时,文件系统真正删除文件,此时该线程占用着LOCK_log锁。

  删除时会执行刷脏(当然我构造这个场景很极端,基本所有slow log文件的内容都在文件系统缓存中),这个会很耗时间,比如我执行这个语句耗了3s。此时间段内,如果连接发来的语句需要记log(server层的log:slow log/binlog/general log共有LOCK_log这把锁)就会处于等待状态,那么系统对外的反应就是hang住了。

  flush slow logs中调用执行的close所需时间和文件大小、以及文件系统缓存中该文件脏页比例都有关系,比如我在执行flush slow logs前使用sysctl vm.drop_caches=3清空

  了文件系统缓存的话,同样大小的flush slow logs操作执行时间是0.42s,相应的阻塞时间也会减少不少。

  可以考虑在slow logs的文件句柄上执行posix_fadvise调用,促使不会缓存很大的log文件内容(slow log也没啥需要缓存的),这有篇霸爷的文章,可以参考下 posix_fadvise清除缓存的误解和改进措施 。

  另外,peter在07年就讨论过这个问题, Be careful rotating MySQL logs 其给出的建议是先mv file,然后flush logs,再执行删除文件的操作,让真正的删除行为由自己而不是mysqld完成。比较遗憾的是,七年过去了,LOCK_log这把锁的问题还没有完整的解决掉。

  PS:

  文章结尾记一点备忘,通过close/rm操作删除一个10G大小的文件,在执行sysctl vm.drop_caches=3清空缓存后,此操作的耗时仍在百毫秒量级(我的机器上是200ms+),其背后做了什么事情还需要找内核组的同事了解下。





收藏 推荐 打印 | 录入:elainebo | 阅读:
本文评论   查看全部评论 (0)
表情: 表情 姓名: 字数
点评:
       
评论声明
  • 尊重网上道德,遵守中华人民共和国的各项有关法律法规
  • 承担一切因您的行为而直接或间接导致的民事或刑事法律责任
  • 本站管理人员有权保留或删除其管辖留言中的任意内容
  • 本站有权在网站内转载或引用您的评论
  • 参与本评论即表明您已经阅读并接受上述条款