5月1日以前、DBAの同僚は、デイリー環境で大きなスローログファイルを削除し、MySQLでフラッシュスローログを実行すると、mysqldがライブでハングするというフィードバックをくれました。
今日、この問題を再現してみました。
手順を再現します：
1.スローログの構築
2.rmスローログを削除した瞬間のtps/qpsの変化を観察してください；
3.フラッシュスローログが実行された瞬間のtps/qpsの変化を観察してください；
4.フラッシュスローログが実行されたときに、pstackがヒットしたコールスタックを記録します；
*** 特に言うことはありません。
ステップ2、tps/qpsはあまり変わりませんでした。
3番目のステップでは、下図のように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の実行に約3秒かかることがわかります。
ステップ4では、pstackの出力を見て、関連するものだけを記録します：
610 Thread 5 (Thread 0x2afdc4101700 (LWP 30762)):
611 #0 0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
612 #1 0x0000000000825135 in inline_mysql_rwlock_rdlock ()
613 #2 0x0000000000838004 in LOGGER::lock_shared() ()
614 #3 0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
615 #4 0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
616 #5 0x0000000000609f23 in log_slow_statement(THD*) ()
617 #6 0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
618 #7 0x0000000000606e02 in do_command(THD*) ()
619 #8 0x00000000006f070f in do_handle_one_connection(THD*) ()
620 #9 0x00000000006f020d in handle_one_connection ()
621 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
622 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6
623 Thread 4 (Thread 0x2afdd0080700 (LWP 30763)):
624 #0 0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
625 #1 0x0000000000825135 in inline_mysql_rwlock_rdlock ()
626 #2 0x0000000000838004 in LOGGER::lock_shared() ()
627 #3 0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
628 #4 0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
629 #5 0x0000000000609f23 in log_slow_statement(THD*) ()
630 #6 0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
631 #7 0x0000000000606e02 in do_command(THD*) ()
632 #8 0x00000000006f070f in do_handle_one_connection(THD*) ()
633 #9 0x00000000006f020d in handle_one_connection ()
634 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
635 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6
636 Thread 3 (Thread 0x2afdd0101700 (LWP 30764)):
637 #0 0x0000003c6e40a7d6 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
638 #1 0x0000000000825135 in inline_mysql_rwlock_rdlock ()
639 #2 0x0000000000838004 in LOGGER::lock_shared() ()
640 #3 0x00000000008283bf in LOGGER::slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
641 #4 0x0000000000832b30 in slow_log_print(THD*, char const*, unsigned int, unsigned long long) ()
642 #5 0x0000000000609f23 in log_slow_statement(THD*) ()
643 #6 0x00000000006099d1 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
644 #7 0x0000000000606e02 in do_command(THD*) ()
645 #8 0x00000000006f070f in do_handle_one_connection(THD*) ()
646 #9 0x00000000006f020d in handle_one_connection ()
647 #10 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
648 #11 0x0000003c6e0e570d in clone () from /lib64/libc.so.6
649 Thread 2 (Thread 0x2afe18080700 (LWP 30855)):
650 #0 0x0000003c6e40e54d in close () from /lib64/libpthread.so.0
651 #1 0x00000000008f56ed in my_close ()
652 #2 0x0000000000825c16 in inline_mysql_file_close ()
653 #3 0x000000000082b305 in MYSQL_LOG::close(unsigned int) ()
654 #4 0x000000000082b634 in MYSQL_QUERY_LOG::reopen_file() ()
655 #5 0x0000000000828283 in LOGGER::flush_slow_log() ()
656 #6 0x000000000071d8fc in reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) ()
657 #7 0x0000000000610200 in mysql_execute_command(THD*) ()
658 #8 0x000000000061534d in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()
659 #9 0x00000000006086a0 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
660 #10 0x0000000000606e02 in do_command(THD*) ()
661 #11 0x00000000006f070f in do_handle_one_connection(THD*) ()
662 #12 0x00000000006f020d in handle_one_connection ()
663 #13 0x0000003c6e4077f1 in start_thread () from /lib64/libpthread.so.0
664 #14 0x0000003c6e0e570d in clone () from /lib64/libc.so.6
スレッド2が低速ログのフラッシュ操作を行っており、他のスレッドはロックLOCK_logが上がるのを待っていることがわかります。
背後にある理由は、実際には非常に簡単です、シェルでrmの遅いログ操作を実行するために、mysqldはまだファイルを開くには、ファイルハンドルを持っているので、実際にはこの時点でファイルが削除されません。フラッシュログ操作を実行すると、実際の実行は1）クローズされ、2）オープン操作は、クローズ操作の実行では、ファイルシステムが実際にファイルを削除し、この時点でスレッドがLOCK_logロックを占有します。
削除する際、ダーティフラッシュを実行しますが、これには多くの時間がかかります。例えば、このステートメントを実行するのに3秒かかりました。この間、接続からのステートメントをログに記録する必要がある場合、待機状態になり、システムの外部応答は "hang on "となります。
フラッシュスローログのクローズコールの実行にかかる時間は、ファイルサイズとファイルシステムキャッシュのダーティページの割合に関係します。例えば、私はフラッシュスローログを実行する前に、sysctl vm.drop_caches=3を使ってクリアします。
ファイルシステムキャッシュを使用すると、同じサイズのフラッシュスローログ操作の実行時間は0.42秒になり、対応するブロック時間は大幅に短縮されます。
そのアドバイスでは、ファイルを mv してからログをフラッシュし、ファイルを削除することで、実際の削除は mysqld ではなく自分自身で行われるようにしています。残念ながら、7 年経った今でも LOCK_log ロックの問題は完全には解決されていません。
PS：
少しメモを覚えて記事の終わりは、10Gサイズのファイルを削除するには、close / rmの操作を介して、キャッシュのクリア後にsysctlのvm.drop_caches = 3の実装では、操作時間の消費はまだ桁のミリ秒の数百であり、行われているものの背面はまた、次について学ぶために同僚のカーネルグループを見つける必要があります。
