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

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

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

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

610Thread5(Thread0x2afdc4101700(LWP30762)):
611#00x0000003c6e40a7d6inpthread_rwlock_rdlock()from/lib64/libpthread.so.0
612#10x0000000000825135ininline_mysql_rwlock_rdlock()
613#20x0000000000838004inLOGGER::lock_shared()()
614#30x00000000008283bfinLOGGER::slow_log_print(THD*,charconst*,unsignedint,unsignedlonglong)()
615#40x0000000000832b30inslow_log_print(THD*,charconst*,unsignedint,unsignedlonglong)()
616#50x0000000000609f23inlog_slow_statement(THD*)()
617#60x00000000006099d1indispatch_command(enum_server_command,THD*,char*,unsignedint)()
618#70x0000000000606e02indo_command(THD*)()
619#80x00000000006f070findo_handle_one_connection(THD*)()
620#90x00000000006f020dinhandle_one_connection()
621#100x0000003c6e4077f1instart_thread()from/lib64/libpthread.so.0
622#110x0000003c6e0e570dinclone()from/lib64/libc.so.6
623Thread4(Thread0x2afdd0080700(LWP30763)):
624#00x0000003c6e40a7d6inpthread_rwlock_rdlock()from/lib64/libpthread.so.0
625#10x0000000000825135ininline_mysql_rwlock_rdlock()
626#20x0000000000838004inLOGGER::lock_shared()()
627#30x00000000008283bfinLOGGER::slow_log_print(THD*,charconst*,unsignedint,unsignedlonglong)()
628#40x0000000000832b30inslow_log_print(THD*,charconst*,unsignedint,unsignedlonglong)()
629#50x0000000000609f23inlog_slow_statement(THD*)()
630#60x00000000006099d1indispatch_command(enum_server_command,THD*,char*,unsignedint)()
631#70x0000000000606e02indo_command(THD*)()
632#80x00000000006f070findo_handle_one_connection(THD*)()
633#90x00000000006f020dinhandle_one_connection()
634#100x0000003c6e4077f1instart_thread()from/lib64/libpthread.so.0
635#110x0000003c6e0e570dinclone()from/lib64/libc.so.6
636Thread3(Thread0x2afdd0101700(LWP30764)):
637#00x0000003c6e40a7d6inpthread_rwlock_rdlock()from/lib64/libpthread.so.0
638#10x0000000000825135ininline_mysql_rwlock_rdlock()
639#20x0000000000838004inLOGGER::lock_shared()()
640#30x00000000008283bfinLOGGER::slow_log_print(THD*,charconst*,unsignedint,unsignedlonglong)()
641#40x0000000000832b30inslow_log_print(THD*,charconst*,unsignedint,unsignedlonglong)()
642#50x0000000000609f23inlog_slow_statement(THD*)()
643#60x00000000006099d1indispatch_command(enum_server_command,THD*,char*,unsignedint)()
644#70x0000000000606e02indo_command(THD*)()
645#80x00000000006f070findo_handle_one_connection(THD*)()
646#90x00000000006f020dinhandle_one_connection()
647#100x0000003c6e4077f1instart_thread()from/lib64/libpthread.so.0
648#110x0000003c6e0e570dinclone()from/lib64/libc.so.6
649Thread2(Thread0x2afe18080700(LWP30855)):
650#00x0000003c6e40e54dinclose()from/lib64/libpthread.so.0
651#10x00000000008f56edinmy_close()
652#20x0000000000825c16ininline_mysql_file_close()
653#30x000000000082b305inMYSQL_LOG::close(unsignedint)()
654#40x000000000082b634inMYSQL_QUERY_LOG::reopen_file()()
655#50x0000000000828283inLOGGER::flush_slow_log()()
656#60x000000000071d8fcinreload_acl_and_cache(THD*,unsignedlong,TABLE_LIST*,int*)()
657#70x0000000000610200inmysql_execute_command(THD*)()
658#80x000000000061534dinmysql_parse(THD*,char*,unsignedint,Parser_state*)()
659#90x00000000006086a0indispatch_command(enum_server_command,THD*,char*,unsignedint)()
660#100x0000000000606e02indo_command(THD*)()
661#110x00000000006f070findo_handle_one_connection(THD*)()
662#120x00000000006f020dinhandle_one_connection()
663#130x0000003c6e4077f1instart_thread()from/lib64/libpthread.so.0
664#140x0000003c6e0e570dinclone()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+），其背后做了什么事情还需要找内核组的同事了解下。