キャッシュを 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 種類に集中しています。中身はこれでした。
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 だと思って外したが、効かなかった
保持時間が長いなら通常のページはキャッシュから返るので、Worker は起動しないはずです。ではこれを呼んでいるのは誰か。
そのとき残っていた Worker 起動の多くが、存在しない URL へのアクセスでした。404 ページは共通レイアウトを使っていて、レイアウトにサイドバーが入っています。存在しない URL を返すためだけに毎回 2,000 行近く読んでいる、という筋書きが立ちました。
404 ページからだけウィジェットを外して、デプロイしました。
サイト別に前後を比べた結果がこれです。
- 外したサイト: 17% 減
- 外していないサイト: 77% 減、88% 減
- 外していないサイト: 47% 増、79% 増
外したサイトより、外していないサイトのほうが大きく動いていました。 これは対策の効果ではなく、時間帯によるアクセス量の変動を見ていただけでした。筋書きは外れていました。
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 つも無くなっています。先読みした結果は、そのままリクエストの終わりに捨てられていました。速度のための仕組みが、誰も開けないキャッシュを温めるために毎ページ数百行を読んでいたことになります。
同時に、これはサイドバーを外しても数字が下げ止まった理由でもありました。先読みが同じリクエスト内で集計を先に済ませてしまうため、後から呼ぶタームページ側は結果を共有します。タームページだけを直しても、読み取りは 1 行も減りません。
CMS 本体には手を入れず、パッケージマネージャの patch で先読みの一項目だけを無効化しました(EmDash で記事にタグを付けても本番に反映されない原因 では、同じ状況をアプリ側のミドルウェアで解いています)。あわせてタームページ側も、必要な 1 行だけを引く形に差し替えています。先読みが無くなった後は、そちらが唯一の呼び出し元になるからです。
デプロイ後、クエリ単位で見ると 8 サイトすべてからこの集計が消えました。5 分単位で区切ると、最後に実行されたのはデプロイ完了の直前のバケットでした。
どこで止まるか
見た目は変わります。カテゴリー名やタグ名の横の件数が消え、月別アーカイブが無くなります。件数に価値を置くなら、この方法は取れません。
先読みを止めたぶん、ターム一覧を EmDash 経由で取得するテンプレートを後から足すと、その分だけ往復が直列になります。手元では全サイトが自前実装なので影響が出ませんが、ウィジェットを使い続ける構成なら、止めるのは先読みではなく別の場所になります。
キャッシュが効いている間はそもそも Worker が起動しないので、閲覧者が多いページほどこの改善の効果は出ません。効くのは、キャッシュを抜けて届くアクセス、つまり機械的なクロールと初回アクセスに対してです。裏返すと、人がよく見るページだけを運用しているサイトでは、ここまでする必要はありません。
この構成で気をつけること
- 共通レイアウトやサイドバーに置いたクエリは全ページで走る。記事数に比例するクエリをそこに置くと、運用するほど重くなる。入れた直後は問題なく見える
- 「表示するかどうか」のプロパティは、取得を止めるとは限らない。実装を読んで確かめる
- 呼び出し元を消しても、フレームワークや CMS が先読みしていることがある。実行回数がリクエスト数を超えていたら、テンプレート以外の経路を疑う
- 同じリクエスト内で結果が共有される作りだと、後から呼ぶ側だけを直しても数字は動かない。先に走っているほうを止める
- 原因の切り分けには 1 リクエストあたりの読み取り行数を見る。起動数が増えたならアクセス増、1 起動あたりが増えたならコードの変更
- クエリ単位の集計は、キャッシュを壊した日のデータでも読める。合計値は再構築の波に埋もれるが、「どのクエリが何行読んだか」は埋もれない
- ログテーブルの累積カウントを、期間内のアクセス数として数えない。期間で絞っても過去のぶんが乗る
- 効果を測るときは同じ時間帯どうしで比べる。日単位だと時間帯によるアクセス量の差が乗る
読み取りが減らなかったとき、最初に疑ったのは保持時間の設定でした。次が 404、その次がサイドバーです。サイドバーは当たっていましたが、それで終わりではありませんでした。同じクエリを、フレームワーク側が「速くするため」に先回りして実行していた。消したい処理の呼び出し元を数えるとき、自分が書いた場所だけを数えていると届きません。