关于删除MySQL Logs的问题记录

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

五一前,一个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,如下所示:

  1. [ 639s] threads: 32, tps: 1121.00, reads/s: 15843.98, writes/s: 4490.99 
  2. [ 640s] threads: 32, tps: 792.99, reads/s: 10803.89, writes/s: 3150.97 
  3. [ 641s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 0.00 
  4. [ 642s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 0.00 
  5. [ 643s] threads: 32, tps: 471.01, reads/s: 6860.08, writes/s: 1908.02 

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

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

  1. 610 Thread 5 (Thread 0x2afdc4101700 (LWP 30762)): 
  2. 611 #0  0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0 
  3. 612 #1  0x0000000000825135 in inline_mysql_rwlock_rdlock () 
  4. 613 #2  0x0000000000838004 in LOGGER::lock_shared() () 
  5. 614 #3  0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) () 
  6. 615 #4  0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) () 
  7. 616 #5  0x0000000000609f23 in log_slow_statement(THD*) () 
  8. 617 #6  0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) () 
  9. 618 #7  0x0000000000606e02 in do_command(THD*) () 
  10. 619 #8  0x00000000006f070f in do_handle_one_connection(THD*) () 
  11. 620 #9  0x00000000006f020d in handle_one_connection () 
  12. 621 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0 
  13. 622 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6 
  14. 623 Thread 4 (Thread 0x2afdd0080700 (LWP 30763)): 
  15. 624 #0  0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0 
  16. 625 #1  0x0000000000825135 in inline_mysql_rwlock_rdlock () 
  17. 626 #2  0x0000000000838004 in LOGGER::lock_shared() () 
  18. 627 #3  0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) () 
  19. 628 #4  0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) () 
  20. 629 #5  0x0000000000609f23 in log_slow_statement(THD*) () 
  21. 630 #6  0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) () 
  22. 631 #7  0x0000000000606e02 in do_command(THD*) () 
  23. 632 #8  0x00000000006f070f in do_handle_one_connection(THD*) () 
  24. 633 #9  0x00000000006f020d in handle_one_connection () 
  25. 634 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0 
  26. 635 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6 
  27. 636 Thread 3 (Thread 0x2afdd0101700 (LWP 30764)): 
  28. 637 #0  0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0 
  29. 638 #1  0x0000000000825135 in inline_mysql_rwlock_rdlock () 
  30. 639 #2  0x0000000000838004 in LOGGER::lock_shared() () 
  31. 640 #3  0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) () 
  32. 641 #4  0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) () 
  33. 642 #5  0x0000000000609f23 in log_slow_statement(THD*) () 
  34. 643 #6  0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) () 
  35. 644 #7  0x0000000000606e02 in do_command(THD*) () 
  36. 645 #8  0x00000000006f070f in do_handle_one_connection(THD*) () 
  37. 646 #9  0x00000000006f020d in handle_one_connection () 
  38. 647 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0 
  39. 648 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6 
  40. 649 Thread 2 (Thread 0x2afe18080700 (LWP 30855)): 
  41. 650 #0  0x0000003c6e40e54d in close () from /lib64/libpthread.so.0 
  42. 651 #1  0x00000000008f56ed in my_close () 
  43. 652 #2  0x0000000000825c16 in inline_mysql_file_close () 
  44. 653 #3  0x000000000082b305 in MYSQL_LOG::close(unsigned int) () 
  45. 654 #4  0x000000000082b634 in MYSQL_QUERY_LOG::reopen_file() () 
  46. 655 #5  0x0000000000828283 in LOGGER::flush_slow_log() () 
  47. 656 #6  0x000000000071d8fc in reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) () 
  48. 657 #7  0x0000000000610200 in mysql_execute_command(THD*) () 
  49. 658 #8  0x000000000061534d in mysql_parse(THD*, char*, unsigned int, Parser_state*) () 
  50. 659 #9  0x00000000006086a0 in dispatch_command(enum_server_command, THD*, char*, unsigned int) () 
  51. 660 #10 0x0000000000606e02 in do_command(THD*) () 
  52. 661 #11 0x00000000006f070f in do_handle_one_connection(THD*) () 
  53. 662 #12 0x00000000006f020d in handle_one_connection () 
  54. 663 #13 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0 
  55. 664 #14 0x0000003c6e0e570d in clone () from /lib64/libc.so.6 

会发现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+),其背后做了什么事情还需要找内核组的同事了解下。

责任编辑:黄丹 来源: 刘浩de技术博客
相关推荐

2017-06-12 16:10:05

MySQL表名

2015-07-15 10:37:10

IOS用户行为统计代码

2012-05-03 10:13:56

FlexSSHJava

2009-06-17 10:47:36

Hibernate级联级联删除

2010-10-13 17:07:46

MySQL删除重复记录

2011-05-18 15:08:03

mysql删除修改数据

2010-11-23 14:26:02

MySQL删除重复记录

2017-11-06 16:00:05

iOS安卓发送原图

2011-10-28 13:26:09

Win7

2020-09-30 06:49:25

MySQL查询删除

2009-12-23 10:02:46

ADO数据库

2009-09-14 10:29:02

LINQ删除记录

2022-07-08 17:13:32

MySQL数据死锁

2009-09-14 16:12:57

LINQ删除记录

2010-11-23 14:40:04

MySQL多表删除

2010-10-15 15:02:37

Mysql多表删除

2010-05-11 10:43:10

Unix awk

2010-10-27 16:49:23

Oracle删除重复记

2010-09-08 10:00:34

SQL删除记录

2011-07-29 11:20:51

MySQL数据库字段重复
点赞
收藏

51CTO技术栈公众号