--> -->
#blog2navi() *マストドンのLTLが遅くなってきたので解析して改善してみた [#x4676fb9] HTL(Home Timeline)に比べてLTL(Local Timeline)の表示が異様に遅くなってきたので解析してみました。~ HTLは1秒以内程度で表示されるのですが、LTLは必ず10秒程度かかります。明らかにDBへのクエリーが遅くなっているようです。~ ~ まずはこの辺を読みながら、スロークエリの特定を行います。~ ~ ■スロークエリの分析~ [[https://lets.postgresql.jp/documents/technical/query_analysis/1]]~ ~ 私はlogを仕込む方法を採用しました。~ $ vi /etc/postgres/postgresql.conf log_min_duration_statement = 3s >$ vi /etc/postgres/postgresql.conf~ log_min_duration_statement = 3s < > # systemctl restart postgresql < ~ # systemctl restart postgresql ~ するとログに以下のような内容が出力されていました。~ $ tail /var/log/postgresql/postgresql-9.5-main.log 2018-07-23 12:32:03 JST [10141-1] mastodon@mastodon LOG: duration: 9523.376 ms execute <unnamed>: SELECT "statuses"."id", "statuses"."updated_at" FROM "statuses" LEFT OUTER JOIN "accounts" ON "accounts"."id" = "statuses"."account_id" WHERE ("statuses"."local" = $1 OR "statuses"."uri" IS NULL) AND "statuses"."visibility" = $2 AND (statuses.reblog_of_id IS NULL) AND (statuses.reply = FALSE OR statuses.in_reply_to_account_id = statuses.account_id) AND "statuses"."account_id" NOT IN ($3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15) AND "accounts"."silenced" = $16 ORDER BY "statuses"."id" DESC LIMIT $17 2018-07-23 12:32:03 JST [10141-2] mastodon@mastodon DETAIL: parameters: $1 = 't', $2 = '0', $3 = '....'(中略), $16 = 'f', $17 = '20' > $ tail /var/log/postgresql/postgresql-9.5-main.log~ 2018-07-23 12:32:03 JST [10141-1] mastodon@mastodon LOG: duration: 9523.376 ms execute <unnamed>: SELECT "statuses"."id", "statuses"."updated_at" FROM "statuses" LEFT OUTER JOIN "accounts" ON "accounts"."id" = "statuses"."account_id" WHERE ("statuses"."local" = $1 OR "statuses"."uri" IS NULL) AND "statuses"."visibility" = $2 AND (statuses.reblog_of_id IS NULL) AND (statuses.reply = FALSE OR statuses.in_reply_to_account_id = statuses.account_id) AND "statuses"."account_id" NOT IN ($3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15) AND "accounts"."silenced" = $16 ORDER BY "statuses"."id" DESC LIMIT $17~ 2018-07-23 12:32:03 JST [10141-2] mastodon@mastodon DETAIL: parameters: $1 = 't', $2 = '0', $3 = '....'(中略), $16 = 'f', $17 = '20' < ~ このクエリーを徐々に単純化しながらexplainしてみると、「"statuses"."local" = 't'」の条件で大きく絞り込まれるにも関わらず、indexを使用しておらずsequential scanが行われている事が分かりました。~ ~ mastodon=# explain select count(*) FROM "statuses" WHERE ("statuses"."local" = 't'); Aggregate (cost=202269.95..202269.96 rows=1 width=0) -> Seq Scan on statuses (cost=0.00..202269.95 rows=1 width=0) Filter: local ~ そこで、localにインデックスを張ってみます。~ create index index_statuses_only_local on statuses using btree(local); ~ これで再度explainしてみると、以下のようにコストが大幅に下がっていることが分かります。~ Aggregate (cost=33.05..33.06 rows=1 width=0) -> Index Only Scan using index_statuses_only_local on statuses (cost=0.43..30.97 rows=831 width=0) Index Cond: (local = true) Filter: local ~ 実際に元のクエリーを実行してみて、実行速度を確認、WEB UIからLTLを表示してみて実行速度を確認して終了です。~ でもこれ、小規模インスタンスには必須のインデックスにも思えるのですが、元々無いのでしょうか? それともupdateの途中で失敗してしまって無くなってしまったのか・・・。今まではこんなに遅いことは無く、途中から急に遅くなった気がするので、例えばインデックスが無くなったか、statusesテーブルがキャッシュに入らなくなったなど、何かの閾値を超えたために発生したように思います。~ ~ でもまあ、ひとまずは解決。。。 #htmlinsert(twitterbutton.html) ---- #htmlinsert(20180723_index.html) RIGHT:Category: [[[Linux>日記/Category/Linux]]] - 13:26:37 ---- RIGHT:&blog2trackback(); #comment(above) #blog2navi()