【レポート】操作ログプラグイン「Logbook」がwp_postsに10万件溜め込んでいた（表示22秒→1秒）

保守を担当しているWordPressサイトで、管理画面の操作が多い時間帯に公開ページまで重くなり、表示に20秒以上かかる現象がありました。調べたところ、操作ログ用のプラグイン「Logbook」が、ログを投稿として wp_posts に10万件以上溜め込んでいました。

ログはログ用のテーブルに保存されるものだと思い込んでいたため、気付くのが遅れました。注意喚起と気付きとして残します。

背景

管理画面のアクセスが多いと、公開ページの表示も遅くなる。
PHPのデバッグログを有効にしていて、テーマ側の Warning がページ表示のたびに出ている状態だった。
Logbook は2018年3月から更新が止まっているプラグインで、有効インストール数は約1,000件。

Logbookの保存先

Logbook はログを独自テーブルではなく、カスタム投稿タイプ logbook として wp_posts に保存します。1件ごとに wp_postmeta にも4行書き込みます。

_logbook_label
_logbook_log_level
_logbook_ip
_logbook（ログの詳細を配列で保存）

本文には、エラー箇所のコードやアクセス元の情報がHTMLで入るため、1件あたりの容量も小さくありません。

公開ページでも書き込まれる

PHPのエラーを記録する機能（Last_Error）は、shutdown のタイミングで error_get_last() を確認し、エラーがあれば投稿を1件作成します。

public function log( $additional_args ) {
    $error = error_get_last();
    if ( $error ) {
        // ログの内容を組み立て、shutdown 時に wp_insert_post() で保存
    }
}

管理画面に限らず、公開ページのリクエストでも動きます。@ で抑制した警告も error_get_last() には残るため、記録の対象になります。

そのため、Warning や Deprecated がページ表示のたびに出ているサイトでは、アクセスのたびに wp_posts への書き込みが発生します。

古いログが削除されていなかった

Logbook には、1か月より古いログを削除する仕組みがあります。1時間ごとの cron（logbook_scheduled_event）で実行されます。

ただし、cron イベントの登録は、オプション logbook-scheduled-event が無いときにしか行われません。

function plugins_loaded() {
    if ( ! get_option( 'logbook-scheduled-event', false ) ) {
        wp_schedule_event( time(), 'hourly', 'logbook_scheduled_event' );
        update_option( 'logbook-scheduled-event', true );
    }
    // ...
}

何らかの理由で cron イベントだけが消えると、オプションは残ったままなので、イベントは再登録されません。今回のサイトでは、WP Crontrol で確認すると cron 一覧に logbook_scheduled_event が存在せず、削除処理が止まった状態でした。

件数の確認

投稿タイプごとの件数は、次のSQLで確認できます。

SELECT post_type, COUNT(*) FROM wp_posts GROUP BY post_type ORDER BY 2 DESC;

今回のサイトの結果です。

logbook の投稿: 101,316件
付随する wp_postmeta: 405,264行（1件につき4行）

ローカル環境のログでは1件あたり約3.9KB（本文と postmeta の合計）だったので、合計で約390MBになる計算です。サイト本来の投稿より、ログのほうがはるかに多い状態でした。

削除はSQLで行う

プラグインを削除すると uninstall.php でログも消えますが、この件数ではおすすめしません。

$posts = get_posts( array(
    'post_type' => 'logbook',
    'posts_per_page' => -1,
) );

foreach( $posts as $log ) {
    wp_delete_post( $log->ID, true );
}

全件を本文ごとメモリに読み込み、1件ずつ wp_delete_post() を呼ぶ作りです。10万件ではメモリ不足か実行時間の上限で止まり、中途半端な状態になる可能性が高いです。

ログの投稿には、タームやコメント、子投稿の紐づきがありません。そのため、本体と postmeta をSQLで消せば足ります。

手順です。

DBのバックアップを取得。
Logbook を無効化（この時点で新しいログの書き込みが止まる）。
アクセスの少ない時間帯に、次のSQLを上から順に実行。

DELETE pm FROM wp_postmeta pm JOIN wp_posts p ON p.ID = pm.post_id WHERE p.post_type = 'logbook';
DELETE FROM wp_posts WHERE post_type = 'logbook';

1行目で postmeta、2行目で投稿本体を削除します。順番を逆にすると、postmeta の削除条件に使う投稿が先に消えてしまうので注意してください。

削除後の確認。

SELECT COUNT(*) FROM wp_posts WHERE post_type = 'logbook';
SELECT COUNT(*) FROM wp_postmeta pm LEFT JOIN wp_posts p ON p.ID = pm.post_id WHERE p.ID IS NULL;

1つ目が0件になれば完了です。2つ目は、投稿が存在しない postmeta の件数です。削除前と同じ件数のままなら、取り残しは発生していません。

容量を回収。

OPTIMIZE TABLE wp_posts, wp_postmeta;

プラグインを削除（ログは0件なので、uninstall.php はすぐ終わる）。

結果

ログを削除した後、ページの表示速度は体感で約22秒から約1秒になりました（計測ツールでの比較ではありません）。

気付き

ログを保存するプラグインでも、専用テーブルではなく wp_posts を使うことがある。ログやフォームの送信データなど、件数が増え続けるデータを投稿タイプとして保存するプラグインは珍しくありません。
wp_posts はサイト全体で共有するテーブルなので、ログが膨らむと、記事や固定ページの表示に関わるクエリにも影響します。
定期削除が cron 任せの場合、cron イベントが消えると、誰にも気付かれずに溜まり続けます。
デバッグログを有効にしていると、エラーを記録する系のプラグインの書き込みも増えます。Warning を放置しないことが、結果的に負荷対策にもなります。

保守に入ったサイトでは、最初に投稿タイプごとの件数を確認しておくと、こうしたデータの溜まり方に早く気付けます。

以上です。

参考

Special Thanks

22秒の謎を一緒に追いかけてくれた先輩エンジニアと、10万件のログの海に一緒に潜ってくれたAIへ。おかげで、1秒の世界に帰ってこられました。