關於刪除MySQL Logs的問題記錄

五一前，一個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的輸出結果，只記錄相關的：

會發現HTTP://www.aliyun.com/zixun/aggregation/29914.html">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+）， 其背後做了什麼事情還需要找內核組的同事瞭解下。