--> -->

skimemo

skimemo - 日記/2018-07-23/マストドンのLTLが遅くなってきたので解析して改善してみた のバックアップの現在との差分(No.2)

  • 追加された行はこの色です。
  • 削除された行はこの色です。
#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が行われている事が分かりました。~

~
 $ psql mastodon
 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: &#x5b;[[Linux>日記/Category/Linux]]&#x5d; - 13:26:37
----
RIGHT:&blog2trackback();
#comment(above)
#blog2navi()