Postgresql performance

#1

Hello.
After upgrading to Mastodon 3.0.0 Postgres consumes 100% of CPU while generating Local and Public timelines.
I’ve stopped services, dumped the DB and re-created it from dump, but i still have very slow queries. For example:

 2019-10-07 20:15:36.241 PDT [29298] mastodon@mastodon_production LOG:  duration: 7458.818 ms  execute a12: SELECT  "statuses".* FROM "statuses" WHERE "statuses"."deleted_at" IS NULL AND "statuses"."account_id" = $1 AND "statuses"."
reblog_of_id" = $2 ORDER BY "statuses"."id" DESC LIMIT $3
2019-10-07 20:15:36.241 PDT [29298] mastodon@mastodon_production DETAIL:  parameters: $1 = '48', $2 = '102924583513975602', $3 = '1'
2019-10-07 20:15:38.937 PDT [30375] mastodon@mastodon_production LOG:  duration: 92863.952 ms  execute <unnamed>: SELECT  "statuses"."id", "statuses"."updated_at" FROM "statuses" LEFT OUTER JOIN "accounts" ON "accounts"."id" = "sta
tuses"."account_id" WHERE "statuses"."visibility" = $1 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 ($2, $3, $4, $5, $6
, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22, $23, $24, $25, $26, $27, $28, $29, $30, $31, $32, $33, $34, $35, $36, $37, $38, $39, $40, $41, $42, $43, $44, $45, $46, $47, $48, $49, $50, $51, $52, $5
3, $54, $55, $56, $57, $58, $59, $60, $61, $62, $63) AND (accounts.domain IS NULL OR accounts.domain NOT IN ('pawoo.net','baraag.net','mstdn.foxfam.club')) AND ("statuses"."language" IS NULL OR "statuses"."language" = $64) AND "sta
tuses"."deleted_at" IS NULL AND "accounts"."silenced_at" IS NULL AND "statuses"."id" < 102924270400802132 ORDER BY "statuses"."id" DESC, "statuses"."id" DESC LIMIT $65
2019-10-07 20:15:38.937 PDT [30375] mastodon@mastodon_production DETAIL:  parameters: $1 = '0', $2 = '45785', $3 = '35891', $4 = '114', $5 = '95', $6 = '34', $7 = '57310', $8 = '52161', $9 = '50551', $10 = '11957', $11 = '5687', $1
2 = '19414', $13 = '2044', $14 = '26026', $15 = '33101', $16 = '5393', $17 = '931', $18 = '2294', $19 = '2351', $20 = '821', $21 = '23502', $22 = '41470', $23 = '42569', $24 = '41477', $25 = '42575', $26 = '4191', $27 = '4840', $28
 = '87', $29 = '36928', $30 = '41471', $31 = '14790', $32 = '31390', $33 = '41487', $34 = '42610', $35 = '41484', $36 = '41481', $37 = '42559', $38 = '42868', $39 = '7488', $40 = '3314', $41 = '3610', $42 = '3250', $43 = '3113', $4
4 = '2898', $45 = '7522', $46 = '3496', $47 = '7655', $48 = '4538', $49 = '28068', $50 = '5100', $51 = '29443', $52 = '7734', $53 = '23193', $54 = '34642', $55 = '34277', $56 = '13193', $57 = '1384', $58 = '28942', $59 = '11178', $
60 = '2041', $61 = '1401', $62 = '3121', $63 = '1132', $64 = 'ru', $65 = '20'
2019-10-07 20:15:49.053 PDT [29347] mastodon@mastodon_production LOG:  duration: 6908.775 ms  execute a15: SELECT  "statuses".* FROM "statuses" WHERE "statuses"."deleted_at" IS NULL AND "statuses"."account_id" = $1 AND "statuses"."
reblog_of_id" = $2 ORDER BY "statuses"."id" DESC LIMIT $3

Reindexing did not solve the issue. What else can I try to do?

#2

I am not sure yet if we are talking about the same problem, however, i have much ioload since the update and it seems to come from postgres - on a quite beefy machine, it can even slow it down so heavy that mastodon becomes completly unresponsive for a while.

I was hoping it was just the forgotten jemalloc thingie, but as of now it doesn’t seem to be the case (it’s mainly the memory cache that’s going wild due to the huge operations anyway)

#3

can anyone affected take problematic query(ies) and run EXPLAIN ANALYZE .... on them? Preferably post results to https://explain.depesz.com/

#4

Smth like this:
https://explain.depesz.com/s/Jc7C

Log says it takes a lot of time (mostly 1-3 seconds). One of the last records was 20540.235 ms

#5 
LOG:  duration: 20540.235 ms  execute a21: SELECT  "statuses".* FROM "statuses" WHERE "statuses"."deleted_at" IS NULL AND "statuses"."account_id" = $1 AND "statuses"."reblog_of_id" = $2 ORDER BY "statuses"."id" DESC LIMIT $3
#6

thanks, for staters, i caught this one at 26594.960 ms just now.

edit: nvm i think this one (orig. 270055.359 ms) is more interesting. for now… at least.

edit2: or this one (orig. 424626.718 ms)

execute <unnamed>: SELECT  DISTINCT "statuses"."id", "statuses"."updated_at" FROM "statuses" INNER JOIN "statuses_tags" ON "statuses_tags"."status_id" = "statuses"."id" LEFT OUTER JOIN "accounts" ON "accounts"."id" = "statuses"."account_id" WHERE "statuses"."visibility" = 0 AND (statuses.reblog_of_id IS NULL) AND "statuses_tags"."tag_id" = 84 AND 1=1 AND "statuses"."deleted_at" IS NULL AND "accounts"."silenced_at" IS NULL ORDER BY "statuses"."id" DESC, "statuses"."id" DESC LIMIT 30
#7

I’ve spotted very slow queries when building timeline for hashtags, my SQL explain looks very similar with above posted ones.

I’ve tried to make it faster (but I don’t think it’s fully resolved though) by:

  1. Create an extra index to speed up the query a little

    CREATE INDEX index_statuses_20191002 ON public.statuses USING btree (id DESC, updated_at, account_id) WHERE (visibility = 0) AND (deleted_at IS NULL);

  2. Delete unnecessary toots to reduce total amount of data to be queried (this takes VERY long time)

    RAILS_ENV=production /home/mastodon/live/bin/tootctl statuses remove

Hope this info helps.

1 Like
#9

Small hint: one can include the query as well when pasting to explain.depesz.com - it will be visible in the “TEXT” tab. You may want to remove some user identifiable stuff, but do not use obfuscation - our schema is public.

I never really understood why we have queries full of NOT IN (long list of something) instead of using joins. First we could issue one query instead of two and second we could really give a database a chance to do its work properly…

#10

Thanks a lot, it helps — it’s still slow, bot at least I can see Public timeline now.

P.S.: AFAIK, there are planned optimizations in Mastodon 3.0.1, hope this will happen soon :slight_smile:

1 Like