キャッシュを 30 日にしても D1 の読み取りが減らない原因
Cloudflare 上で動かしている Astro 製の CMS「EmDash」 のサイト群で、データベースの読み取りが多すぎました。エッジキャッシュの保持時間を 5 分から 30 日へ延ばしたところ、読み取りは 55.6% 減りましたが、目標の 2 倍を超えたままでした。
残っていた読み取りを分解したら、7 割がサイドバーの「(12)」を出すためのクエリでした。そしてサイドバーを消しても、そのクエリは止まりませんでした。
8 サイト全体でどこにコストが乗っていたかは Cloudflare D1 の読み取りが 1 日 2,100 万行になった原因 に書きました。この記事は、その中でいちばん時間がかかった切り分けの記録です。
キャッシュは効いているのに読み取りが減らない
時間帯によってアクセス量が違い、日単位だと差が出すぎるので、延ばす前と後を同じ時間帯どうしで比べました。
- 延ばす前 7 日間の平均(09:00–22:00 UTC): 14,895,070 行
- 延ばした後の同じ時間帯: 6,606,157 行
キャッシュ自体は働いていて、同じ URL を叩くと age が伸び続けたまま返ってきます。
$ curl -s -D- -o /dev/null https://example.com/ | grep -iE 'cf-cache-status|^age:'
cf-cache-status: HIT
age: 5247414 時間以上前に作った HTML がそのまま返っていて、保持時間が 5 分だった頃なら 300 秒で切れていました。キャッシュから返っているのに、読み取りは減っていませんでした。
残りの 7 割が 1 種類のクエリだった
D1 の GraphQL Analytics はクエリ単位で読み取り行数を出せます。保持時間を延ばした後の時間帯だけを切り出して、種類別に足しました。
- タクソノミーの件数集計: 4,926,570 行(68%)
- コンテンツ取得: 731,077 行(10%)
- タクソノミー参照: 448,007 行(6%)
- マイグレーション確認: 261,991 行(4%)
- リダイレクト読み込み: 252,921 行(3%)
- 404 ログ: 139,443 行(2%)
7 割が 1 種類のクエリに集中していて、中身は次の SQL でした。
SELECT taxonomy_id, SUM(count) AS count
FROM (
SELECT ct.taxonomy_id AS taxonomy_id, COUNT(*) AS count
FROM content_taxonomies AS ct
INNER JOIN ec_posts AS e ON e.id = ct.entry_id
WHERE ct.collection = ?
AND ct.taxonomy_id IN (SELECT translation_group FROM taxonomies WHERE name = ?)
GROUP BY ct.taxonomy_id
) AS per_collection
GROUP BY taxonomy_idサイドバーのカテゴリー一覧で、名前の横に出る「(12)」を数えるクエリです。
原因を 404 だと見て 404 ページのサイドバーを外したが、効果は無かった
保持時間が長いなら通常のページはキャッシュから返るので、Worker は起動しないはずです。では、このクエリを呼んでいるのは何か。
そのとき残っていた Worker 起動の多くが、存在しない URL へのアクセスでした。404 ページは共通レイアウトを使っていて、レイアウトにサイドバーが入っています。存在しない URL を返すためだけに毎回 2,000 行近く読んでいるという筋書きが立ちました。
404 ページからだけウィジェットを外して、デプロイしました。
サイト別に前後を比べた結果がこれです。
- 外したサイト: 17% 減
- 外していないサイト: 77% 減、88% 減
- 外していないサイト: 47% 増、79% 増
外したサイトより、外していないサイトのほうが大きく動いていました。 これは対策の効果ではなく、時間帯によるアクセス量の変動を見ていただけで、404 が原因という筋書きは外れていました。
404 は主因ではなかった
切り分け直すのに 404 のログテーブルを使いました。このテーブルにはパスごとに初めて記録した時刻と最後に見た時刻が入っていて、「新しく出現したパス」と「既知のパスへの再訪」を分けられます。
5.4 時間ぶんを数えると、404 になったのは 384 パス(新規 28、再訪 356)。同じ期間の Worker 起動は 9,744 回でした。404 は起動の数パーセントにすぎません。新規パスは 1 日換算で 120 個で、初見の URL が無尽蔵に来る状況でもありませんでした。
前の見立てでは、404 ログの累積ヒット数を期間内のアクセス数として数えていました。このテーブルはパスごとにヒット数を積算するので、期間で絞っても過去のヒット数が含まれ、404 を過大に見積もっていました。
残りの 9,000 回超は、キャッシュを抜けて届いた通常ページへのアクセスでした。サイドバーのクエリは、この通常ページで呼ばれていました。
1 起動あたりの読み取り行数を見ると分かった
サイト別に「1 回の Worker 起動で何行読んでいるか」を出すと、40 倍の開きがありました。
- 記事 339 件のサイト: 684 行
- 記事 253 件のサイト: 468 行
- 記事 129 件のサイト: 291 行
- 記事 16 件のサイト: 16 行
記事数ときれいに比例しています。最後のサイトも同じコードで同じウィジェットを描画していますが、紐付けが 25 行しかないので軽く済んでいます。このサイトが軽いのは、まだ記事が少ないからでした。 このクエリは記事とタグの紐付け数に比例するので、運用するほど重くなります。
アクセス数ではなく 1 起動あたりの行数を見たことで、切り分けができました。起動数が増えたならアクセス増、1 起動あたりが増えたならコードの変更と原因を分けられます。
件数の表示を消しても集計は止まらない
ウィジェットには件数を出すかどうかのプロパティがあります。false にすれば集計も止まると考えましたが、実装はそうなっていませんでした。
const { showCount = true, hierarchical = true } = Astro.props;
const categories = await getTaxonomyTerms("category");showCount に関係なく取得しに行き、プロパティは取得した件数を表示するかどうかだけを決めています。取得側にも分岐はありません。
const [rows, counts] = await Promise.all([
termsQuery.execute(),
getVisibleTermCounts(def.name, def.collections),
]);ウィジェットを使う限り、この集計は避けられませんでした。
ウィジェットをやめてタームの一覧だけを自分で引いた
管理画面からサイドバーの並びを入れ替える運用はしていなかったので、ウィジェットの仕組みごと外して、必要なものだけを描画するコンポーネントに差し替えました。
const rows = await db
.selectFrom("taxonomies")
.select(["slug", "label"])
.where("name", "=", taxonomyName)
.orderBy("label", "asc")
.execute();同じ本番データに対して両方を実行し、返ってくる rows_read を比べました。
- 件数を数える方: 1,273 行
- 一覧だけ引く方: 59 行
読む行数はターム数で頭打ちになり、記事が増えても変わりません。
月別アーカイブのウィジェットも外しました。こちらは月ごとに集計するために、件数の指定なしで全記事を取得していました。記事 253 件のサイトではそのまま 253 行になります。月別に遡る導線より、毎リクエスト全記事を読むコストのほうが上回ると判断しました。カテゴリー・タグ・最近の記事からは辿れます。
置き換えた直後の 1 時間あたりの読み取り行数です。サイドバーを共通レイアウトに置いていたサイト(全ページで実行される)のものです。
01:00 50,932
02:00 276,952
03:00 114,808
04:00 45,243
05:00 25,754
06:00 54,954 ← デプロイ
07:00 1,209 ← 置き換え後置き換え前 5 時間の平均が 102,738 行、後が 1,209 行。クエリ単体の比較(1,273 → 59 行)より減り幅が大きいのは、サイドバーが全ページで走っていたぶん、ページ全体では重複して呼ばれていたからです。
ここで解決したと思っていました。
消したはずのクエリがまだ動いていた
翌日、別のサイトを含めて全体を測り直すと、目標の 2.4 倍のままでした。クエリ単位で見ると、タクソノミーの件数集計がまだ 1 位に居ます。
- サイト A: 1,225,636 行 / 1,937 回
- サイト B: 532,220 行 / 614 回
- サイト C: 496,644 行 / 1,657 回
- サイト D: 444,264 行 / 1,524 回
- サイト E: 366,680 行 / 2,512 回
サイドバーはもうこの集計を呼んでいないので、残る呼び出し元は、1 件のタームを引く関数が内部で同じ集計を走らせるカテゴリーページとタグページのはずでした。
ただ、実行回数が多すぎました。 サイト A は同じ時間帯の Worker 起動が 1,000 回ほどで、集計は 1,937 回。タームページの表示回数にしては多く、しかも「起動数のちょうど 2 倍」という比率が、サイトを変えても続いていました。
2 という数字に心当たりがありました。このサイトのタクソノミーは category と tag の 2 つです。
集計は誰も読まない先読みのために走っていた
EmDash の配布物を追うと、ミドルウェアに先読みの処理がありました。
async function prefetchTaxonomyTerms() {
const defs = await getTaxonomyDefs();
await Promise.allSettled(defs.map((def) => getTaxonomyTerms(def.name)));
}公開ページのレンダリングが始まる時点で、レイアウトが使う共通データ(サイト設定・メニュー・ウィジェットエリア・タクソノミーのターム一覧)をまとめて先に取りに行く仕組みでした。個別のコンポーネントがそれぞれ await すると往復が直列になるので、本来はその往復を 1 回にまとめて表示を速くするための機能です。
タクソノミーの数だけループするので、実行回数が起動数の 2 倍になっていた理由もこれで説明が付きます。
問題は、そのデータをもう誰も読んでいなかったことでした。サイドバーを自前実装に置き換えた時点で、ターム一覧を EmDash 経由で取得するテンプレートは 1 つも無くなっています。先読みした結果は、そのままリクエストの終わりに捨てられていました。表示を速くするための先読みが、誰も使わない結果のために毎ページ数百行を読んでいたことになります。
この先読みは、サイドバーを外しても読み取りが下げ止まった理由でもありました。先読みが同じリクエスト内で集計を先に済ませてしまうため、後から呼ぶタームページ側は結果を共有します(リクエスト内キャッシュの重複排除は D1 の無駄なクエリを削ったらクエリ数が増えた原因 に書きました)。タームページだけを直しても、読み取りは 1 行も減りません。
CMS 本体には手を入れず、パッケージマネージャの patch で先読みの一項目だけを無効化しました(EmDash で記事にタグを付けても本番に反映されない原因 では、同じ状況をアプリ側のミドルウェアで解いています)。あわせてタームページ側も、必要な 1 行だけを引く形に差し替えています。先読みが無くなった後は、タームページが唯一の呼び出し元になるからです。
デプロイ後、クエリ単位で見ると 8 サイトすべてからこの集計が消えました。5 分単位で区切ると、最後に実行されたのはデプロイ完了の直前のバケットでした。
件数表示を失い、効果はキャッシュを抜けるアクセスにだけ出る
カテゴリー名やタグ名の横の件数が消え、月別アーカイブが無くなるので、見た目は変わります。件数に価値を置くなら、この方法は取れません。
先読みを止めたぶん、ターム一覧を EmDash 経由で取得するテンプレートを後から足すと、その分だけ往復が直列になります。手元では全サイトが自前実装なので影響が出ませんが、ウィジェットを使い続ける構成なら、止めるのは先読みではなく別の場所になります。
キャッシュが効いている間はそもそも Worker が起動しないので、閲覧者が多いページほどこの改善の効果は出ず、効果が出るのはキャッシュを抜けて届くアクセス、つまり機械的なクロールと初回アクセスです。裏返すと、人がよく見るページだけを運用しているサイトでは、ここまでする必要はありません。
読み取りが減らないときは全ページで走るクエリと先読みを疑う
- 共通レイアウトやサイドバーに置いたクエリは全ページで走る。記事数に比例するクエリをそこに置くと、入れた直後は問題なく見えても運用するほど重くなる
- 「表示するかどうか」のプロパティは、取得を止めるとは限らない。実装を読んで確かめる
- 呼び出し元を消しても、フレームワークや CMS が先読みしていることがある。実行回数がリクエスト数を超えていたら、テンプレート以外の経路を疑う
- 同じリクエスト内で結果が共有される作りだと、後から呼ぶ側だけを直しても数字は動かない。先に走っているほうを止める
- 原因の切り分けには 1 リクエストあたりの読み取り行数を見る。起動数が増えたならアクセス増、1 起動あたりが増えたならコードの変更
- クエリ単位の集計は、キャッシュを壊した日のデータでも読める。合計値はキャッシュの再構築による増加に埋もれるが、「どのクエリが何行読んだか」は埋もれない
- ログテーブルの累積カウントを、期間内のアクセス数として数えない。期間で絞っても過去のぶんが乗る
- 効果を測るときは同じ時間帯どうしで比べる。日単位だと時間帯によるアクセス量の差が乗る
読み取りが減らなかったとき、最初に疑ったのは保持時間の設定でした。次が 404、その次がサイドバーです。サイドバーは当たっていましたが、同じクエリをフレームワーク側が「速くするため」に先回りして実行していました。消したい処理の呼び出し元を数えるとき、自分が書いた場所だけを数えていると先読みのような経路を見落とします。