AkkomaGang/akkoma
AkkomaGang/akkoma
16
67
Fork 103
Code Issues 168 Pull requests 13 Projects 2 Releases 19 Packages Wiki Activity

SQL: Outlier query information gathering #784

New issue
Open
opened 2024-05-27 00:58:34 +00:00 by floatingghost · 13 comments
floatingghost commented 2024-05-27 00:58:34 +00:00
Owner
Copy link

If you see this issue, go to

/phoenix/live_dashboard/ecto_stats?nav=outliers

and copy the outlier data here for query analysis to see if we can improve query design in any common places

template table


|  query | exec time | prop exec time | calls | sync IO time |
|--------|-----------|----------------|-------|--------------|
If you see this issue, go to `/phoenix/live_dashboard/ecto_stats?nav=outliers` and copy the outlier data here for query analysis to see if we can improve query design in any common places template table ``` | query | exec time | prop exec time | calls | sync IO time | |--------|-----------|----------------|-------|--------------| ```
floatingghost commented 2024-05-27 01:02:26 +00:00
Author
Owner
Copy link

Mine:

query exec time prop exec time calls sync IO time
SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE (to_jsonb(array(select jsonb_array_elements((o0."data")#>$2) ->> $3 where jsonb_typeof((o0."data")#>$4) = $5))::jsonb ?| ($1)) 1006476.661775 seconds 47.6 47976 0 seconds
SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) 251523.734009 seconds 11.9 112616 0 seconds
SELECT u1."id", u1."bio", u1."raw_bio", u1."email", u1."name", u1."nickname", u1."password_hash", u1."keys", u1."public_key", u1."ap_id", u1."avatar", u1."local", u1."follower_address", u1."following_address", u1."featured_address", u1."tags", u1."last_refreshed_at", u1."last_digest_emailed_at", u1."banner", u1."background", u1."note_count", u1."follower_count", u1."following_count", u1."is_locked", u1."is_confirmed", u1."password_reset_pending", u1."is_approved", u1."registration_reason", u1."confirmation_token", u1."default_scope", u1."domain_blocks", u1."is_active", u1."no_rich_text", u1."ap_enabled", u1."is_moderator", u1."is_admin", u1."show_role", u1."mastofe_settings", u1."uri", u1."hide_followers_count", u1."hide_follows_count", u1."hide_followers", u1."hide_follows", u1."hide_favorites", u1."email_notifications", u1."mascot", u1."emoji", u1."pleroma_settings_store", u1."fields", u1."raw_fields", u1."is_discoverable", u1."invisible", u1."allow_following_move", u1."skip_thread_containment", u1."actor_type", u1."also_known_as", u1."inbox", u1."shared_inbox", u1."last_active_at", u1."disclose_client", u1."pinned_objects", u1."is_suggested", u1."last_status_at", u1."language", u1."status_ttl_days", u1."accepts_direct_messages_from", u1."notification_settings", u1."multi_factor_authentication_settings", u1."inserted_at", u1."updated_at" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON u1."id" = f0."follower_id" WHERE (f0."state" = $1) AND (f0."following_id" = $2) AND (u1."is_active" = $3) 215632.590418 seconds 10.2 6981078 0 seconds
SELECT u1."id", u1."bio", u1."raw_bio", u1."email", u1."name", u1."nickname", u1."password_hash", u1."keys", u1."public_key", u1."ap_id", u1."avatar", u1."local", u1."follower_address", u1."following_address", u1."featured_address", u1."tags", u1."last_refreshed_at", u1."last_digest_emailed_at", u1."banner", u1."background", u1."note_count", u1."follower_count", u1."following_count", u1."is_locked", u1."is_confirmed", u1."password_reset_pending", u1."is_approved", u1."registration_reason", u1."confirmation_token", u1."default_scope", u1."domain_blocks", u1."is_active", u1."no_rich_text", u1."ap_enabled", u1."is_moderator", u1."is_admin", u1."show_role", u1."mastofe_settings", u1."uri", u1."hide_followers_count", u1."hide_follows_count", u1."hide_followers", u1."hide_follows", u1."hide_favorites", u1."email_notifications", u1."mascot", u1."emoji", u1."pleroma_settings_store", u1."fields", u1."raw_fields", u1."is_discoverable", u1."invisible", u1."allow_following_move", u1."skip_thread_containment", u1."actor_type", u1."also_known_as", u1."inbox", u1."shared_inbox", u1."last_active_at", u1."disclose_client", u1."pinned_objects", u1."is_suggested", u1."last_status_at", u1."language", u1."status_ttl_days", u1."permit_followback", u1."accepts_direct_messages_from", u1."notification_settings", u1."multi_factor_authentication_settings", u1."inserted_at", u1."updated_at" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON u1."id" = f0."follower_id" WHERE (f0."state" = $1) AND (f0."following_id" = $2) AND (u1."is_active" = $3) 105653.767247 seconds 5.0 2827509 0 seconds
SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) 65583.501187 seconds 3.1 33633706 0 seconds
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."priority" IN ($6,$7,$8,$9)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" 63982.806399 seconds 3.0 22013792 0 seconds
SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) 41508.531170 seconds 2.0 225232 0 seconds
SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) 33832.399275 seconds 1.6 14454187 0 seconds
Mine: | query | exec time | prop exec time | calls | sync IO time | |--------|----------|-----------------|-----|---------------| | SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE (to_jsonb(array(select jsonb_array_elements((o0."data")#>$2) ->> $3 where jsonb_typeof((o0."data")#>$4) = $5))::jsonb ?\| ($1)) | 1006476.661775 seconds | 47.6 | 47976 | 0 seconds | | SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) | 251523.734009 seconds | 11.9 |112616 | 0 seconds | | SELECT u1."id", u1."bio", u1."raw_bio", u1."email", u1."name", u1."nickname", u1."password_hash", u1."keys", u1."public_key", u1."ap_id", u1."avatar", u1."local", u1."follower_address", u1."following_address", u1."featured_address", u1."tags", u1."last_refreshed_at", u1."last_digest_emailed_at", u1."banner", u1."background", u1."note_count", u1."follower_count", u1."following_count", u1."is_locked", u1."is_confirmed", u1."password_reset_pending", u1."is_approved", u1."registration_reason", u1."confirmation_token", u1."default_scope", u1."domain_blocks", u1."is_active", u1."no_rich_text", u1."ap_enabled", u1."is_moderator", u1."is_admin", u1."show_role", u1."mastofe_settings", u1."uri", u1."hide_followers_count", u1."hide_follows_count", u1."hide_followers", u1."hide_follows", u1."hide_favorites", u1."email_notifications", u1."mascot", u1."emoji", u1."pleroma_settings_store", u1."fields", u1."raw_fields", u1."is_discoverable", u1."invisible", u1."allow_following_move", u1."skip_thread_containment", u1."actor_type", u1."also_known_as", u1."inbox", u1."shared_inbox", u1."last_active_at", u1."disclose_client", u1."pinned_objects", u1."is_suggested", u1."last_status_at", u1."language", u1."status_ttl_days", u1."accepts_direct_messages_from", u1."notification_settings", u1."multi_factor_authentication_settings", u1."inserted_at", u1."updated_at" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON u1."id" = f0."follower_id" WHERE (f0."state" = $1) AND (f0."following_id" = $2) AND (u1."is_active" = $3) | 215632.590418 seconds | 10.2 | 6981078 | 0 seconds | |SELECT u1."id", u1."bio", u1."raw_bio", u1."email", u1."name", u1."nickname", u1."password_hash", u1."keys", u1."public_key", u1."ap_id", u1."avatar", u1."local", u1."follower_address", u1."following_address", u1."featured_address", u1."tags", u1."last_refreshed_at", u1."last_digest_emailed_at", u1."banner", u1."background", u1."note_count", u1."follower_count", u1."following_count", u1."is_locked", u1."is_confirmed", u1."password_reset_pending", u1."is_approved", u1."registration_reason", u1."confirmation_token", u1."default_scope", u1."domain_blocks", u1."is_active", u1."no_rich_text", u1."ap_enabled", u1."is_moderator", u1."is_admin", u1."show_role", u1."mastofe_settings", u1."uri", u1."hide_followers_count", u1."hide_follows_count", u1."hide_followers", u1."hide_follows", u1."hide_favorites", u1."email_notifications", u1."mascot", u1."emoji", u1."pleroma_settings_store", u1."fields", u1."raw_fields", u1."is_discoverable", u1."invisible", u1."allow_following_move", u1."skip_thread_containment", u1."actor_type", u1."also_known_as", u1."inbox", u1."shared_inbox", u1."last_active_at", u1."disclose_client", u1."pinned_objects", u1."is_suggested", u1."last_status_at", u1."language", u1."status_ttl_days", u1."permit_followback", u1."accepts_direct_messages_from", u1."notification_settings", u1."multi_factor_authentication_settings", u1."inserted_at", u1."updated_at" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON u1."id" = f0."follower_id" WHERE (f0."state" = $1) AND (f0."following_id" = $2) AND (u1."is_active" = $3) | 105653.767247 seconds | 5.0 | 2827509 | 0 seconds | | SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) | 65583.501187 seconds | 3.1 | 33633706 | 0 seconds | | UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."priority" IN ($6,$7,$8,$9)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" | 63982.806399 seconds | 3.0 | 22013792 | 0 seconds | | SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) | 41508.531170 seconds | 2.0 | 225232 | 0 seconds | | SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) | 33832.399275 seconds | 1.6 | 14454187 | 0 seconds |
norm commented 2024-05-27 05:28:53 +00:00
Contributor
Copy link

Worth noting that the pg_stat_statements extension required for this data isn't enabled by default in Postgres.

To enable the extension, modify postgresql.conf with the following settings:

shared_preload_libraries = 'pg_stat_statements'
pg_stat_statements.track = all

Then restart Postgres. Next connect to the akkoma database with psql and run

CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

Steps copied from here.

Worth noting that the `pg_stat_statements` extension required for this data isn't enabled by default in Postgres. To enable the extension, modify `postgresql.conf` with the following settings: ``` shared_preload_libraries = 'pg_stat_statements' pg_stat_statements.track = all ``` Then restart Postgres. Next connect to the akkoma database with psql and run ```sql CREATE EXTENSION IF NOT EXISTS pg_stat_statements; ``` Steps copied from [here](https://www.bytebase.com/docs/slow-query/enable-pg-stat-statements-for-postgresql/).
YokaiRick commented 2024-05-27 15:35:38 +00:00
Contributor
Copy link

Hi, here are mine. I actived the PG extenstion 9 hours ago to let it collect some stats.
Ill can post a update in a few days again, if you want.

query exec time prop exec time calls sync IO time
SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) 102.813244 seconds 52.1 85 0 seconds
SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) 28.120333 seconds 14.2 170 0 seconds
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" 8.065643 seconds 4.1 25400 0 seconds
SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) 6.001011 seconds 3.0 25400 0 seconds
select installed_version from pg_available_extensions where name=$1 5.792762 seconds 2.9 5218 0 seconds
INSERT INTO "activities" ("data","local","recipients","actor","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 3.928702 seconds 2.0 3051 0 seconds
UPDATE "activities" AS a0 SET "recipients" = array_replace(a0."recipients",$1,$2) WHERE ($3 = ANY(a0."recipients")) 3.923397 seconds 2.0 2 0 seconds
SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) 3.484691 seconds 1.8 2208 0 seconds
SELECT u0."id", u0."bio", u0."raw_bio", u0."email", u0."name", u0."nickname", u0."password_hash", u0."keys", u0."public_key", u0."ap_id", u0."avatar", u0."local", u0."follower_address", u0."following_address", u0."featured_address", u0."tags", u0."last_refreshed_at", u0."last_digest_emailed_at", u0."banner", u0."background", u0."note_count", u0."follower_count", u0."following_count", u0."is_locked", u0."is_confirmed", u0."password_reset_pending", u0."is_approved", u0."registration_reason", u0."confirmation_token", u0."default_scope", u0."domain_blocks", u0."is_active", u0."no_rich_text", u0."ap_enabled", u0."is_moderator", u0."is_admin", u0."show_role", u0."mastofe_settings", u0."uri", u0."hide_followers_count", u0."hide_follows_count", u0."hide_followers", u0."hide_follows", u0."hide_favorites", u0."email_notifications", u0."mascot", u0."emoji", u0."pleroma_settings_store", u0."fields", u0."raw_fields", u0."is_discoverable", u0."invisible", u0."allow_following_move", u0."skip_thread_containment", u0."actor_type", u0."also_known_as", u0."inbox", u0."shared_inbox", u0."last_active_at", u0."disclose_client", u0."pinned_objects", u0."is_suggested", u0."last_status_at", u0."language", u0."status_ttl_days", u0."permit_followback", u0."accepts_direct_messages_from", u0."notification_settings", u0."multi_factor_authentication_settings", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (NOT (u0."nickname" IS NULL)) AND (NOT (u0."nickname" LIKE $5)) AND (u0."invisible" = $1) AND (u0."is_discoverable" = $2) ORDER BY u0."last_status_at" DESC NULLS LAST, u0."id" desc nulls last LIMIT $3 OFFSET $4 3.346299 seconds 1.7 7 0 seconds
WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" 2.877429 seconds 1.5 20916 0 seconds
Hi, here are mine. I actived the PG extenstion 9 hours ago to let it collect some stats. Ill can post a update in a few days again, if you want. | query | exec time | prop exec time | calls | sync IO time | |--------|-----------|----------------|-------|--------------| SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) | 102.813244 seconds | 52.1 |85 |0 seconds SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) | 28.120333 seconds | 14.2 | 170 | 0 seconds UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" | 8.065643 seconds | 4.1 | 25400 | 0 seconds SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) |6.001011 seconds |3.0 |25400 |0 seconds select installed_version from pg_available_extensions where name=$1 | 5.792762 seconds |2.9 |5218 |0 seconds INSERT INTO "activities" ("data","local","recipients","actor","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) | 3.928702 seconds |2.0 | 3051 | 0 seconds UPDATE "activities" AS a0 SET "recipients" = array_replace(a0."recipients",$1,$2) WHERE ($3 = ANY(a0."recipients")) |3.923397 seconds | 2.0 | 2 | 0 seconds SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) |3.484691 seconds |1.8 |2208 |0 seconds SELECT u0."id", u0."bio", u0."raw_bio", u0."email", u0."name", u0."nickname", u0."password_hash", u0."keys", u0."public_key", u0."ap_id", u0."avatar", u0."local", u0."follower_address", u0."following_address", u0."featured_address", u0."tags", u0."last_refreshed_at", u0."last_digest_emailed_at", u0."banner", u0."background", u0."note_count", u0."follower_count", u0."following_count", u0."is_locked", u0."is_confirmed", u0."password_reset_pending", u0."is_approved", u0."registration_reason", u0."confirmation_token", u0."default_scope", u0."domain_blocks", u0."is_active", u0."no_rich_text", u0."ap_enabled", u0."is_moderator", u0."is_admin", u0."show_role", u0."mastofe_settings", u0."uri", u0."hide_followers_count", u0."hide_follows_count", u0."hide_followers", u0."hide_follows", u0."hide_favorites", u0."email_notifications", u0."mascot", u0."emoji", u0."pleroma_settings_store", u0."fields", u0."raw_fields", u0."is_discoverable", u0."invisible", u0."allow_following_move", u0."skip_thread_containment", u0."actor_type", u0."also_known_as", u0."inbox", u0."shared_inbox", u0."last_active_at", u0."disclose_client", u0."pinned_objects", u0."is_suggested", u0."last_status_at", u0."language", u0."status_ttl_days", u0."permit_followback", u0."accepts_direct_messages_from", u0."notification_settings", u0."multi_factor_authentication_settings", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (NOT (u0."nickname" IS NULL)) AND (NOT (u0."nickname" LIKE $5)) AND (u0."invisible" = $1) AND (u0."is_discoverable" = $2) ORDER BY u0."last_status_at" DESC NULLS LAST, u0."id" desc nulls last LIMIT $3 OFFSET $4 | 3.346299 seconds |1.7 |7 |0 seconds WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" | 2.877429 seconds |1.5 |20916 |0 seconds
norm commented 2024-05-27 16:39:38 +00:00
Contributor
Copy link

Here's mine after about 12 hours (deleted the original since it wasn't run for long enough):

query exec time prop exec time calls sync IO time
SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE (to_jsonb(array(select jsonb_array_elements((o0."data")#>$2) ->> $3 where jsonb_typeof((o0."data")#>$4) = $5))::jsonb ?| ($1)) 5402.192327 seconds 83.1 185 0 seconds
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at", b2."id", b2."user_id", b2."activity_id", b2."inserted_at", b2."updated_at", NOT (t3."id" IS NULL) FROM "activities" AS a0 INNER JOIN "objects" AS o1 ON (o1."data"->>$21) = COALESCE(a0."data"->$22->>$23, a0."data"->>$24) LEFT OUTER JOIN "bookmarks" AS b2 ON (b2."user_id" = $1) AND (b2."activity_id" = a0."id") LEFT OUTER JOIN "thread_mutes" AS t3 ON (t3."user_id" = $2) AND (t3."context" = a0."data"->>$25) INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = $26) AS f4 ON $27 INNER JOIN "users" AS u5 ON (a0."actor" = u5."ap_id") AND (u5."invisible" = $28) WHERE (a0."id" > $3) AND (a0."data"->>$29 = $4) AND (not (a0."actor" = ANY($5))) AND (((not (a0."recipients" && $6)) or a0."actor" = $7)) AND ((recipients_contain_blocked_domains(a0."recipients", $8) = $30) or a0."actor" = $9) AND (not (a0."data"->>$31 = $32 and a0."data"->$33 ?| $10)) AND ((not (split_part(a0."actor", $34, $35) = ANY($11))) or a0."actor" = ANY($12)) AND ((not (split_part(o1."data"->>$36, $37, $38) = ANY($13))) or (o1."data"->>$39) = ANY($14)) AND (not ( a0."data"->>$40 = $41 and a0."actor" = ANY($15))) AND (not(o1."data"->>$42 = $43)) AND (a0."recipients" && $16 OR (a0."recipients" && $17 AND $18 = ANY(a0."recipients"))) AND (a0."id" > $19) ORDER BY a0."id" desc nulls last LIMIT $20 190.333149 seconds 2.9 1118 0 seconds
SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) 148.729416 seconds 2.3 133 0 seconds
SELECT o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) AND (o0."inserted_at" >= $2) AND ((o0."worker" = $3) AND ((o0."queue" = $4) AND ((o0."args" @> $5 AND o0."args" <@ $6) AND $7))) LIMIT $8 100.318536 seconds 1.5 139889 0 seconds
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at" FROM "activities" AS a0 INNER JOIN "objects" AS o1 ON (o1."data"->>$6) = COALESCE(a0."data"->$7->>$8, a0."data"->>$9) INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = $10) AS f2 ON $11 INNER JOIN "users" AS u3 ON (a0."actor" = u3."ap_id") AND (u3."invisible" = $12) WHERE ($1 && a0."recipients") AND (a0."actor" = $2) AND (a0."data"->>$13 = ANY($3)) AND (a0."data"->>$14 != $15) AND (not(o1."data"->>$16 = $17)) AND (a0."id" > $4) ORDER BY a0."id" asc nulls last LIMIT $5 59.240213 seconds 0.9 2621 0 seconds
SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) 51.662827 seconds 0.8 62745 0 seconds
INSERT INTO "activities" ("data","local","recipients","actor","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 48.560783 seconds 0.7 42695 0 seconds
SELECT u0."ap_id" FROM "users" AS u0 INNER JOIN "following_relationships" AS f1 ON (f1."following_id" = u0."id") AND (f1."follower_id" = $1) WHERE (NOT (u0."nickname" IS NULL)) AND (NOT (u0."nickname" LIKE $4)) AND (u0."is_active" = $5) AND (u0."id" != $2) AND (f1."state" = $3) 31.241961 seconds 0.5 121338 0 seconds
WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" 23.282083 seconds 0.4 251051 0 seconds
SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) 21.774968 seconds 0.3 266 0 seconds
Here's mine after about 12 hours (deleted the original since it wasn't run for long enough): | query | exec time | prop exec time | calls | sync IO time | |--------|-----------|----------------|-------|--------------| | SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE (to_jsonb(array(select jsonb_array_elements((o0."data")#>$2) ->> $3 where jsonb_typeof((o0."data")#>$4) = $5))::jsonb ?\| ($1)) | 5402.192327 seconds | 83.1 | 185 | 0 seconds| SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at", b2."id", b2."user_id", b2."activity_id", b2."inserted_at", b2."updated_at", NOT (t3."id" IS NULL) FROM "activities" AS a0 INNER JOIN "objects" AS o1 ON (o1."data"->>$21) = COALESCE(a0."data"->$22->>$23, a0."data"->>$24) LEFT OUTER JOIN "bookmarks" AS b2 ON (b2."user_id" = $1) AND (b2."activity_id" = a0."id") LEFT OUTER JOIN "thread_mutes" AS t3 ON (t3."user_id" = $2) AND (t3."context" = a0."data"->>$25) INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = $26) AS f4 ON $27 INNER JOIN "users" AS u5 ON (a0."actor" = u5."ap_id") AND (u5."invisible" = $28) WHERE (a0."id" > $3) AND (a0."data"->>$29 = $4) AND (not (a0."actor" = ANY($5))) AND (((not (a0."recipients" && $6)) or a0."actor" = $7)) AND ((recipients_contain_blocked_domains(a0."recipients", $8) = $30) or a0."actor" = $9) AND (not (a0."data"->>$31 = $32 and a0."data"->$33 ?\| $10)) AND ((not (split_part(a0."actor", $34, $35) = ANY($11))) or a0."actor" = ANY($12)) AND ((not (split_part(o1."data"->>$36, $37, $38) = ANY($13))) or (o1."data"->>$39) = ANY($14)) AND (not ( a0."data"->>$40 = $41 and a0."actor" = ANY($15))) AND (not(o1."data"->>$42 = $43)) AND (a0."recipients" && $16 OR (a0."recipients" && $17 AND $18 = ANY(a0."recipients"))) AND (a0."id" > $19) ORDER BY a0."id" desc nulls last LIMIT $20 | 190.333149 seconds | 2.9 | 1118 | 0 seconds| |SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) | 148.729416 seconds | 2.3 | 133 | 0 seconds| |SELECT o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) AND (o0."inserted_at" >= $2) AND ((o0."worker" = $3) AND ((o0."queue" = $4) AND ((o0."args" @> $5 AND o0."args" <@ $6) AND $7))) LIMIT $8 | 100.318536 seconds | 1.5 | 139889 | 0 seconds| |SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at" FROM "activities" AS a0 INNER JOIN "objects" AS o1 ON (o1."data"->>$6) = COALESCE(a0."data"->$7->>$8, a0."data"->>$9) INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = $10) AS f2 ON $11 INNER JOIN "users" AS u3 ON (a0."actor" = u3."ap_id") AND (u3."invisible" = $12) WHERE ($1 && a0."recipients") AND (a0."actor" = $2) AND (a0."data"->>$13 = ANY($3)) AND (a0."data"->>$14 != $15) AND (not(o1."data"->>$16 = $17)) AND (a0."id" > $4) ORDER BY a0."id" asc nulls last LIMIT $5 | 59.240213 seconds | 0.9 | 2621 | 0 seconds| |SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) | 51.662827 seconds | 0.8 | 62745 | 0 seconds| |INSERT INTO "activities" ("data","local","recipients","actor","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) | 48.560783 seconds | 0.7 | 42695 | 0 seconds| |SELECT u0."ap_id" FROM "users" AS u0 INNER JOIN "following_relationships" AS f1 ON (f1."following_id" = u0."id") AND (f1."follower_id" = $1) WHERE (NOT (u0."nickname" IS NULL)) AND (NOT (u0."nickname" LIKE $4)) AND (u0."is_active" = $5) AND (u0."id" != $2) AND (f1."state" = $3) | 31.241961 seconds | 0.5 | 121338 | 0 seconds| |WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" | 23.282083 seconds | 0.4 | 251051 | 0 seconds| |SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) | 21.774968 seconds | 0.3 | 266 | 0 seconds |
Oneric commented 2024-05-27 17:09:27 +00:00
Owner
Copy link

worth noting the top offender by far for ihba and akko is the query of the attachment cleanup worker; also see #765 for this one

@YokaiRick since it doesn’t show up at all on your instance, can you confirm whether :instance, :cleanup_attachments is set to false (the default)?

worth noting the top offender by far for ihba and akko is the query of the attachment cleanup worker; also see #765 for this one @YokaiRick since it doesn’t show up at all on your instance, can you confirm whether `:instance, :cleanup_attachments` is set to false *(the default)*?
YokaiRick commented 2024-05-27 18:00:38 +00:00
Contributor
Copy link

@Oneric nope, i didn't deactivate it: here is my instance part:

config :pleroma, :instance,
  name: "n0ids space",
  email: "rick@XXX.space",
  notify_email: "rick@XXX.space",
  limit: 5000,
  registrations_open: false,
  export_prometheus_metrics: true,
  public: true,
  max_pinned_statuses: 10

and i grepped for the default stuff also:

/opt/akkoma/releases/3.13.2-0-g050bc74/sys.config : {extended_nickname_format,true},{cleanup_attachments,false},{

i have a single user instance and tbh i can't remember when it was the last time i did delete a post.. maybe thats why?

@Oneric nope, i didn't deactivate it: here is my instance part: ``` config :pleroma, :instance, name: "n0ids space", email: "rick@XXX.space", notify_email: "rick@XXX.space", limit: 5000, registrations_open: false, export_prometheus_metrics: true, public: true, max_pinned_statuses: 10 ``` and i grepped for the default stuff also: ``` /opt/akkoma/releases/3.13.2-0-g050bc74/sys.config : {extended_nickname_format,true},{cleanup_attachments,false},{ ``` i have a single user instance and tbh i can't remember when it was the last time i did delete a post.. maybe thats why?
Oneric commented 2024-05-27 21:38:49 +00:00
Owner
Copy link

Yeah, if you didn’t set it at all it defaults to false; but never deleting posts would amount to the same effect; thanks!

Yeah, if you didn’t set it at all it defaults to `false`; but never deleting posts would amount to the same effect; thanks!
Oneric commented 2024-11-16 01:19:51 +00:00
Owner
Copy link

Here reports for a young, private instance with very few users. Outlier data gathering was turned on after a bit more than a month after creation and ran for about two (one) month. Prometheus is enabled (the default setting) and actively used. Attachment cleanup is turned on, but the still-not-merged optimisation patches are also applied locally explaining the absence of this query.

After ~2 months:

query exec time prop exec time calls sync IO time
SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) 1180.404619 seconds 31.3 14430 0 seconds
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" 681.908258 seconds 18.1 4306129 0 seconds
SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) 482.949110 seconds 12.8 28860 0 seconds
SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) 295.477402 seconds 7.8 4306009 0 seconds
WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" 111.632691 seconds 3.0 811222 0 seconds
INSERT INTO "activities" ("data","local","actor","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 111.281034 seconds 3.0 103563 0 seconds
SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload 84.501494 seconds 2.2 4888789 0 seconds
INSERT INTO "public"."oban_jobs" ("args","meta","state","max_attempts","queue","worker","errors","tags","attempt") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ON CONFLICT DO NOTHING RETURNING "id" 79.974538 seconds 2.1 285420 0 seconds
INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 40.555948 seconds 1.1 303523 0 seconds
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1, "scheduled_at" = $2, "errors" = array_append(o0."errors", $3) WHERE (o0."id" = $4) 38.076888 seconds 1.0 149192 0 seconds
A month prior
query exec time prop exec time calls sync IO time comment
SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) 709.823132 seconds 28.6 9458 0 seconds stat query; can be replaced with cheaper instance table query
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" 602.376685 seconds 24.3 2821512 0 seconds reduce unecessary job churn
SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) 295.784966 seconds 11.9 18916 0 seconds also pleroma/stats.ex, run twice for local and remote; combine into single query?
SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) 187.170853 seconds 7.5 2821392 0 seconds reduce unecessary job churn
INSERT INTO "activities" ("data","local","actor","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 67.182495 seconds 2.7 63141 0 seconds (nothing directly actionable; though cutting down on indexes might help, see #764)
WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" 65.859543 seconds 2.7 488066 0 seconds reduce unecessary job churn
SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload 54.175138 seconds 2.2 3188920 0 seconds also from Oban; reduce unecessary job churn
INSERT INTO "public"."oban_jobs" ("args","meta","state","max_attempts","queue","worker","errors","tags","attempt") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ON CONFLICT DO NOTHING RETURNING "id" 47.815033 seconds 1.9 173582 0 seconds reduce unecessary job churn
INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 26.374679 seconds 1.1 198884 0 seconds reduce unecessary job churn
SELECT o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) AND (o0."inserted_at" >= $2) AND ((o0."worker" = $3) AND ((o0."queue" = $4) AND ((o0."args" @> $5 AND o0."args" <@ $6) AND $7))) LIMIT $8 23.199854 seconds 0.9 143579 0 seconds reduce unecessary job churn

Top offender here is the query used to get the list and count of remote isntaces used in prometheus stat reporting, the peers mastodon API and possibly some other pleroma API. This was also a high offender in previous reports, but got overshadowed by the awful attachment cleanup perf.
This can be replaced with a query of the instances table which EXPLAIN suggests is much cheaper. Results don’t match exactly, but nothing to worry about imho.

Third-highest offender is again a stat query counting local and remtote users. Note how it’s run exactly twice as often as the instance query; this i because remote and local users are counted individually; combining this query should half the perf cost; both do a full table scan.

Insertion of activites also shows up; there’s nothing we can do directly, though cutting down on unecessary indices (see #764) might help — and in particular the counter_cache table (which is populated by an insertion trigger) and it’s related indexes could be dropped; it’s only used to report non-critical stats in some Pleroma Admin API, but I suspect it of being relatively costly on activity operations.

Everything else is Oban related; we currently create way too many jobs known to be noops; cutting down on this might help here too (i have a half-finished patch, but no ETA) (this also helps with PostgreSQL bloat from deleted rows)

Here reports for a young, private instance with very few users. Outlier data gathering was turned on after a bit more than a month after creation and ran for about two (one) month. Prometheus is enabled *(the default setting)* and actively used. Attachment cleanup is turned on, but the still-not-merged optimisation patches are also applied locally explaining the absence of this query. **After ~2 months**: | query | exec time | prop exec time | calls | sync IO time | |--------|-----------|----------------|-------|--------------|-| | SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) | 1180.404619 seconds | 31.3 | 14430 | 0 seconds | | UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" | 681.908258 seconds | 18.1 | 4306129 | 0 seconds | | SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) | 482.949110 seconds | 12.8 | 28860 | 0 seconds | | SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) | 295.477402 seconds | 7.8 | 4306009 | 0 seconds | | WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" | 111.632691 seconds | 3.0 | 811222 | 0 seconds | | INSERT INTO "activities" ("data","local","actor","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) | 111.281034 seconds | 3.0 | 103563 | 0 seconds | | SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload | 84.501494 seconds | 2.2 | 4888789 | 0 seconds | | INSERT INTO "public"."oban_jobs" ("args","meta","state","max_attempts","queue","worker","errors","tags","attempt") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ON CONFLICT DO NOTHING RETURNING "id" | 79.974538 seconds | 2.1 | 285420 | 0 seconds | | INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 | 40.555948 seconds | 1.1 | 303523 | 0 seconds | | UPDATE "public"."oban_jobs" AS o0 SET "state" = $1, "scheduled_at" = $2, "errors" = array_append(o0."errors", $3) WHERE (o0."id" = $4) | 38.076888 seconds | 1.0 | 149192 | 0 seconds | <details> <summary>A month prior</summary> | query | exec time | prop exec time | calls | sync IO time | | comment | |--------|-----------|----------------|-------|--------------|-|---------| | SELECT distinct split_part(u0."nickname", $2, $3) FROM "users" AS u0 WHERE (u0."local" != $1) | 709.823132 seconds | 28.6 | 9458 | 0 seconds | | stat query; can be replaced with cheaper instance table query | | UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ($4,$5)) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" | 602.376685 seconds | 24.3 | 2821512 | 0 seconds | | reduce unecessary job churn | | SELECT count(u0."id") FROM "users" AS u0 WHERE (u0."is_active" = $1) AND (u0."local" = $2) AND (NOT (u0."nickname" IS NULL)) AND (NOT (u0."invisible")) | 295.784966 seconds | 11.9 | 18916 | 0 seconds | | also `pleroma/stats.ex`, run twice for local and remote; combine into single query? | | SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = $1) AND (NOT (o0."queue" IS NULL)) | 187.170853 seconds | 7.5 | 2821392 | 0 seconds | | reduce unecessary job churn | | INSERT INTO "activities" ("data","local","actor","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) | 67.182495 seconds | 2.7 | 63141 | 0 seconds | | *(nothing directly actionable; though cutting down on indexes might help, see #764)* | | WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" | 65.859543 seconds | 2.7 | 488066 | 0 seconds | | reduce unecessary job churn | | SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload | 54.175138 seconds | 2.2 | 3188920 | 0 seconds | | also from Oban; reduce unecessary job churn | | INSERT INTO "public"."oban_jobs" ("args","meta","state","max_attempts","queue","worker","errors","tags","attempt") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ON CONFLICT DO NOTHING RETURNING "id" | 47.815033 seconds | 1.9 | 173582 | 0 seconds | | reduce unecessary job churn | | INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 | 26.374679 seconds | 1.1 | 198884 | 0 seconds | | reduce unecessary job churn | | SELECT o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) AND (o0."inserted_at" >= $2) AND ((o0."worker" = $3) AND ((o0."queue" = $4) AND ((o0."args" @> $5 AND o0."args" <@ $6) AND $7))) LIMIT $8 | 23.199854 seconds | 0.9 | 143579 | 0 seconds | | reduce unecessary job churn | </details> Top offender here is the query used to get the list and count of remote isntaces used in prometheus stat reporting, the `peers` mastodon API and possibly some other pleroma API. This was also a high offender in previous reports, but got overshadowed by the awful attachment cleanup perf. This can be replaced with a query of the instances table which `EXPLAIN` suggests is _much_ cheaper. Results don’t match exactly, but nothing to worry about imho. Third-highest offender is again a stat query counting local and remtote users. Note how it’s run exactly twice as often as the instance query; this i because remote and local users are counted individually; combining this query should half the perf cost; both do a full table scan. Insertion of activites also shows up; there’s nothing we can do directly, though cutting down on unecessary indices (see #764) might help — and in particular the `counter_cache` table (which is populated by an insertion trigger) and it’s related indexes could be dropped; it’s only used to report non-critical stats in some Pleroma Admin API, but I suspect it of being relatively costly on activity operations. Everything else is Oban related; we currently create way too many jobs known to be noops; cutting down on this might help here too *(i have a half-finished patch, but no ETA)* *(this also helps with PostgreSQL bloat from deleted rows)*
Oneric commented 2025-03-03 01:49:32 +00:00
Owner
Copy link

With the attachment cleanup alleviation and perf changes which made it into 3.15.x the profile changed quit e a bit and it’d be good to take another look at this for various instance sizes and settings.

First up, upgrade to the newest release if you haven’t already and then run the following as the db superuser (postgres) to reset your statement statistics:

SELECT pg_stat_statements_reset('<akkoma user oid>'::regclass::oid, '<akkoma database oid>'::regclass::oid);
-- or to just reset stats for all users and databases:
-- SELECT pg_stat_statements_reset();

Then wait at least a week and report your results.

Additionally it’d be nice if you could take a look at your individually most costly queries. Adapt the execution count threshold to a sufficient value to exclude e.g. db prune queries and other stuff you ran manually:

psql -U akkoma -d akkoma -c "COPY (
    SELECT
        interval '1 millisecond' * (total_exec_time/calls) AS avg_exec_time,
        calls,
        interval '1 millisecond' * total_exec_time AS exec_time,
        (total_exec_time/sum(total_exec_time) OVER()) AS prop_exec_time,
        query AS query
    FROM pg_stat_statements
    WHERE userid = (SELECT usesysid FROM pg_user WHERE usename = current_user LIMIT 1)
          AND query NOT LIKE '/* ECTO_PSQL_EXTRAS:%'
          --- excluding db prunes and occasional manual queries
          AND calls>15
    ORDER BY avg_exec_time DESC
    LIMIT 25
) TO STDOUT WITH NULL AS '<null>'" > most_costly_queries.tsv
With the attachment cleanup alleviation and perf changes which made it into 3.15.x the profile changed quit e a bit and it’d be good to take another look at this for various instance sizes and settings. First up, upgrade to the newest release if you haven’t already and then run the following as the db superuser (`postgres`) to reset your statement statistics: ```sql SELECT pg_stat_statements_reset('<akkoma user oid>'::regclass::oid, '<akkoma database oid>'::regclass::oid); -- or to just reset stats for all users and databases: -- SELECT pg_stat_statements_reset(); ``` Then wait at least a week and report your results. Additionally it’d be nice if you could take a look at your _individually_ most costly queries. Adapt the execution count threshold to a sufficient value to exclude e.g. db prune queries and other stuff you ran manually: ``` psql -U akkoma -d akkoma -c "COPY ( SELECT interval '1 millisecond' * (total_exec_time/calls) AS avg_exec_time, calls, interval '1 millisecond' * total_exec_time AS exec_time, (total_exec_time/sum(total_exec_time) OVER()) AS prop_exec_time, query AS query FROM pg_stat_statements WHERE userid = (SELECT usesysid FROM pg_user WHERE usename = current_user LIMIT 1) AND query NOT LIKE '/* ECTO_PSQL_EXTRAS:%' --- excluding db prunes and occasional manual queries AND calls>15 ORDER BY avg_exec_time DESC LIMIT 25 ) TO STDOUT WITH NULL AS '<null>'" > most_costly_queries.tsv ```
Oneric commented 2025-03-03 02:14:22 +00:00
Owner
Copy link

My results, from the dashboard which evidently includes the cost of db pruning:

Almost everything is now just oban job handling, except:

  • updates to the imho wholly unecessary counter_cache i complained about before
  • activity inserts are now proportionally speaking worse and the counter_cache likely contributes to this (the rest are other indices)
  • generating the peers list for instance stats and masto API takes up 2.3% of DB time; ideally it’d be less but it seems acceptable. If we want we could reduce the frequency at which those stats are refreshed to cut down the cost proportionally
query exec time prop exec time calls sync IO time
SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = 'available') AND (NOT (o0."queue" IS NULL)) 545.330043 seconds 19.1 6119459 0 seconds
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ('scheduled','retryable')) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" 248.152905 seconds 8.7 6119459 0 seconds
delete from public.activities where id in ( select a.id from public.activities a left join public.objects o on a.data ->> $1 = o.data ->> $2 left join public.activities a2 on a.data ->> $3 = a2.data ->> $4 left join public.users u on a.data ->> $5 = u.ap_id where not a.local and jsonb_typeof(a."data" -> $6) = $7 and o.id is null and a2.id is null and u.id is null ) 235.734905 seconds 8.3 3 0 seconds
INSERT INTO "activities" ("data","local","actor","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 173.935229 seconds 6.1 160395 0 seconds
UPDATE "counter_cache" SET unlisted = greatest("counter_cache".unlisted - $2, $3) WHERE "instance" = $1 134.464931 seconds 4.7 213715 0 seconds
SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload 121.414660 seconds 4.3 6799795 0 seconds
SELECT i0."host" FROM "instances" AS i0 64.530873 seconds 2.3 20525 0 seconds
INSERT INTO "public"."oban_jobs" ("args","meta","state","max_attempts","queue","worker","errors","tags","attempt") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ON CONFLICT DO NOTHING RETURNING "id" 64.113283 seconds 2.2 218240 0 seconds
INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 57.624981 seconds 2.0 431278 0 seconds
WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" 55.529206 seconds 1.9 354893 0 seconds

As for noteworthy things from the individually most costly queries:

  • two user search is the top contender with on average 76ms and 70ms
    • this query is awfully convoluted and can probably be simplified
  • note search is next up with about half the cost: 35ms on average
    • akkoma-fe also always searches all categories, but the API supports only searching specific categories.
      The frontend could be improved to be more selective here to avoid unecessary queries being made.
  • two queries later: object and activities DELETEs with 23 and 19ms
    • again: without large sacle db changes, cutting down on indices and triggers like the counter_cache stuff is the only thing which helps here
  • mere object SELECTs by id also take a whole 7ms
My results, from the dashboard which evidently includes the cost of db pruning: Almost everything is now just oban job handling, except: - updates to the imho wholly unecessary `counter_cache` i complained about before - activity inserts are now proportionally speaking worse and the `counter_cache` likely contributes to this *(the rest are other indices)* - generating the peers list for instance stats and masto API takes up 2.3% of DB time; ideally it’d be less but it seems acceptable. If we want we could reduce the frequency at which those stats are refreshed to cut down the cost proportionally | query | exec time | prop exec time | calls | sync IO time | |--------|-----------|----------------|-------|--------------| | SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = 'available') AND (NOT (o0."queue" IS NULL)) | 545.330043 seconds | 19.1 | 6119459 | 0 seconds | | UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ('scheduled','retryable')) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" | 248.152905 seconds | 8.7 | 6119459 | 0 seconds | | delete from public.activities where id in ( select a.id from public.activities a left join public.objects o on a.data ->> $1 = o.data ->> $2 left join public.activities a2 on a.data ->> $3 = a2.data ->> $4 left join public.users u on a.data ->> $5 = u.ap_id where not a.local and jsonb_typeof(a."data" -> $6) = $7 and o.id is null and a2.id is null and u.id is null ) | 235.734905 seconds | 8.3 | 3 | 0 seconds | | INSERT INTO "activities" ("data","local","actor","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) | 173.935229 seconds | 6.1 | 160395 | 0 seconds | | UPDATE "counter_cache" SET unlisted = greatest("counter_cache".unlisted - $2, $3) WHERE "instance" = $1 | 134.464931 seconds | 4.7 | 213715 | 0 seconds | | SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload | 121.414660 seconds | 4.3 | 6799795 | 0 seconds | | SELECT i0."host" FROM "instances" AS i0 | 64.530873 seconds | 2.3 | 20525 | 0 seconds | | INSERT INTO "public"."oban_jobs" ("args","meta","state","max_attempts","queue","worker","errors","tags","attempt") VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ON CONFLICT DO NOTHING RETURNING "id" | 64.113283 seconds | 2.2 | 218240 | 0 seconds | | INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 | 57.624981 seconds | 2.0 | 431278 | 0 seconds | | WITH "subset" AS MATERIALIZED(SELECT so0."id" AS "id" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" = $7) AND (so0."queue" = $1) ORDER BY so0."priority", so0."scheduled_at", so0."id" LIMIT $2 FOR UPDATE SKIP LOCKED) UPDATE "public"."oban_jobs" AS o0 SET "state" = $3, "attempted_at" = $4, "attempted_by" = $5, "attempt" = o0."attempt" + $6 FROM "subset" AS f1 WHERE (o0."id" = f1."id") AND (o0."attempt" < o0."max_attempts") RETURNING o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" | 55.529206 seconds | 1.9 | 354893 | 0 seconds | As for noteworthy things from the individually most costly queries: - two user search is the top contender with on average 76ms and 70ms - this query is awfully convoluted and can probably be simplified - note search is next up with about half the cost: 35ms on average - akkoma-fe also always searches all categories, but the API supports only searching specific categories. The frontend could be improved to be more selective here to avoid unecessary queries being made. - two queries later: object and activities DELETEs with 23 and 19ms - again: without large sacle db changes, cutting down on indices and triggers like the counter_cache stuff is the only thing which helps here - mere object SELECTs by id also take a whole 7ms
norm commented 2025-03-13 03:26:58 +00:00
Contributor
Copy link

Here's my updated outliers list:

(note: Sync IO time is omitted because the columns for those stats got changed in pg 17 and phoenix live dashboard doesn't support using those yet)

Query Exec time Prop exec time Calls
SELECT o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) AND (o0."inserted_at" >= $2) AND ((o0."worker" = $3) AND ((o0."queue" = $4) AND ((o0."args" @> $5 AND o0."args" <@ $6) AND $7))) LIMIT $8 1337.857472 seconds 8.7 2115704
SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) 1040.815957 seconds 6.7 1127704
SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE (to_jsonb(array(select jsonb_array_elements((o0."data")#>$2) ->> $3 where jsonb_typeof((o0."data")#>$4) = $5))::jsonb ?| ($1)) 1029.247545 seconds 6.7 54
INSERT INTO "activities" ("actor","data","local","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 1014.950256 seconds 6.6 922190
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at" FROM "activities" AS a0 LEFT OUTER JOIN "objects" AS o1 ON (o1."data"->>'id') = COALESCE(a0."data"->'object'->>'id', a0."data"->>'object') WHERE ((a0."data")->>'id' = $1) 682.735781 seconds 4.4 1189143
SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE ((o0."data")->>'id' = $1) 610.000494 seconds 4.0 2431559
SELECT o0."state", o0."queue", count(o0."id") FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) GROUP BY o0."state", o0."queue" 608.734979 seconds 3.9 863226
COPY public.objects (id, data, inserted_at, updated_at) TO stdout 506.708485 seconds 3.3 10
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at" FROM "activities" AS a0 INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = TRUE) AS f1 ON TRUE WHERE (coalesce((a0."data")->'object'->>'id', (a0."data")->>'object') = $1) AND ((a0."data")->>'type' = $2) 453.856337 seconds 2.9 2223375
COPY public.activities (id, data, inserted_at, updated_at, local, actor, recipients) TO stdout 431.621097 seconds 2.8 10
Here's my updated outliers list: (note: Sync IO time is omitted because the columns for those stats got changed in pg 17 and phoenix live dashboard doesn't support using those yet) |Query | Exec time | Prop exec time | Calls | | ---------|----------------- |-------------------------|-------- | |SELECT o0."id", o0."state", o0."queue", o0."worker", o0."args", o0."meta", o0."tags", o0."errors", o0."attempt", o0."attempted_by", o0."max_attempts", o0."priority", o0."attempted_at", o0."cancelled_at", o0."completed_at", o0."discarded_at", o0."inserted_at", o0."scheduled_at" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) AND (o0."inserted_at" >= $2) AND ((o0."worker" = $3) AND ((o0."queue" = $4) AND ((o0."args" @> $5 AND o0."args" <@ $6) AND $7))) LIMIT $8 | 1337.857472 seconds | 8.7 | 2115704 | |SELECT u1."follower_address" FROM "following_relationships" AS f0 INNER JOIN "users" AS u1 ON f0."following_id" = u1."id" WHERE (f0."follower_id" = $1) AND (f0."state" = $2) | 1040.815957 seconds | 6.7 | 1127704 | |SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE (to_jsonb(array(select jsonb_array_elements((o0."data")#>$2) ->> $3 where jsonb_typeof((o0."data")#>$4) = $5))::jsonb ?\| ($1)) | 1029.247545 seconds | 6.7 | 54 | |INSERT INTO "activities" ("actor","data","local","recipients","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) |1014.950256 seconds | 6.6 | 922190 | |SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at" FROM "activities" AS a0 LEFT OUTER JOIN "objects" AS o1 ON (o1."data"->>'id') = COALESCE(a0."data"->'object'->>'id', a0."data"->>'object') WHERE ((a0."data")->>'id' = $1) | 682.735781 seconds |4.4 |1189143 | |SELECT o0."id", o0."data", o0."inserted_at", o0."updated_at" FROM "objects" AS o0 WHERE ((o0."data")->>'id' = $1) |610.000494 seconds |4.0 |2431559 | |SELECT o0."state", o0."queue", count(o0."id") FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = ANY($1)) GROUP BY o0."state", o0."queue" |608.734979 seconds |3.9 |863226 | |COPY public.objects (id, data, inserted_at, updated_at) TO stdout |506.708485 seconds |3.3| 10| |SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at" FROM "activities" AS a0 INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = TRUE) AS f1 ON TRUE WHERE (coalesce((a0."data")->'object'->>'id', (a0."data")->>'object') = $1) AND ((a0."data")->>'type' = $2) |453.856337 seconds |2.9 |2223375 | |COPY public.activities (id, data, inserted_at, updated_at, local, actor, recipients) TO stdout |431.621097 seconds |2.8 | 10|
❤️ 1
Oneric commented 2025-03-25 23:46:28 +00:00
Owner
Copy link

After upgrading to PostgreSQL 17 and recollecting stats for some weeks during which users were more active than on average and no db pruning, here are my renewed outlier stats:

query exec time prop exec time calls comment
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at" FROM "activities" AS a0 INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = TRUE) AS f1 ON TRUE WHERE (coalesce((a0."data")->'object'->>'id', (a0."data")->>'object') = $1) AND ((a0."data")->>'type' = $2) 210.397852 seconds 20.0 54150 Activity.(get_|get_all_|)create_by_object_id/1
SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = 'available') AND (NOT (o0."queue" IS NULL)) 169.309471 seconds 16.1 1889265
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at", b2."id", b2."user_id", b2."activity_id", b2."inserted_at", b2."updated_at", NOT (t3."id" IS NULL) FROM "activities" AS a0 INNER JOIN "objects" AS o1 ON (o1."data"->>'id') = COALESCE(a0."data"->'object'->>'id', a0."data"->>'object') LEFT OUTER JOIN "bookmarks" AS b2 ON (b2."user_id" = $1) AND (b2."activity_id" = a0."id") LEFT OUTER JOIN "thread_mutes" AS t3 ON (t3."user_id" = $2) AND (t3."context" = a0."data"->>'context') INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = TRUE) AS f4 ON TRUE INNER JOIN "users" AS u5 ON (a0."actor" = u5."ap_id") AND (u5."invisible" = FALSE) WHERE ((($3 && a0."recipients")) OR (a0."actor" = $4)) AND (a0."id" > $5) AND (a0."data"->>'type' = ANY($6)) AND (not (a0."actor" = ANY($7))) AND (((not (a0."recipients" && $8)) or a0."actor" = $9)) AND ((recipients_contain_blocked_domains(a0."recipients", $10) = false) or a0."actor" = $11) AND (not (a0."data"->>'type' = 'Announce' and a0."data"->'to' ?| $12)) AND ((not (split_part(a0."actor", '/', 3) = ANY($13))) or a0."actor" = ANY($14)) AND ((not (split_part(o1."data"->>'actor', '/', 3) = ANY($15))) or (o1."data"->>'actor') = ANY($16)) AND (not (a0."actor" = ANY($17))) AND (not (a0."data"->'to' ?| $18) or a0."actor" = $19) AND (t3."user_id" IS NULL) AND (not ( a0."data"->>'type' = 'Announce' and a0."actor" = ANY($20))) AND (a0."data"->>'type' != 'Announce' or o1."data"->>'actor' != $21) AND (not(o1."data"->>'type' = 'Answer')) AND (a0."id" > $22) ORDER BY a0."id" desc nulls last LIMIT $23 96.544907 seconds 9.2 28236
UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ('scheduled','retryable')) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" 80.151989 seconds 7.6 1889265 home TL
SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload 43.273205 seconds 4.1 2312456
SELECT i0."host" FROM "instances" AS i0 26.559587 seconds 2.5 6339 stats
INSERT INTO "activities" ("data","local","recipients","actor","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) 24.594452 seconds 2.3 25435
INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 19.506537 seconds 1.9 133189
SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at" FROM "activities" AS a0 WHERE (a0."actor" = $1) AND (coalesce((a0."data")->$4->>$5, (a0."data")->>$6) = $2) AND ((a0."data")->>$7 = $3) LIMIT $8 18.269952 seconds 1.7 10231 appears to only be ActivityPub.Utils.get_existing_announce/2? Kinda a lot of calls then though...
COPY public.objects (id, data, inserted_at, updated_at) TO stdout 16.578686 seconds 1.6 4 manual db backups
After upgrading to PostgreSQL 17 and recollecting stats for some weeks during which users were more active than on average and no db pruning, here are my renewed outlier stats: | query | exec time | prop exec time | calls | comment | |--------|-----------|----------------|-------|--------------| | SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at" FROM "activities" AS a0 INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = TRUE) AS f1 ON TRUE WHERE (coalesce((a0."data")->'object'->>'id', (a0."data")->>'object') = $1) AND ((a0."data")->>'type' = $2) | 210.397852 seconds | 20.0 | 54150 | `Activity.(get_\|get_all_\|)create_by_object_id/1` | | SELECT DISTINCT o0."queue" FROM "public"."oban_jobs" AS o0 WHERE (o0."state" = 'available') AND (NOT (o0."queue" IS NULL)) | 169.309471 seconds | 16.1 | 1889265 | | | SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at", o1."id", o1."data", o1."inserted_at", o1."updated_at", b2."id", b2."user_id", b2."activity_id", b2."inserted_at", b2."updated_at", NOT (t3."id" IS NULL) FROM "activities" AS a0 INNER JOIN "objects" AS o1 ON (o1."data"->>'id') = COALESCE(a0."data"->'object'->>'id', a0."data"->>'object') LEFT OUTER JOIN "bookmarks" AS b2 ON (b2."user_id" = $1) AND (b2."activity_id" = a0."id") LEFT OUTER JOIN "thread_mutes" AS t3 ON (t3."user_id" = $2) AND (t3."context" = a0."data"->>'context') INNER JOIN LATERAL (SELECT is_active from users WHERE ap_id = a0."actor" AND is_active = TRUE) AS f4 ON TRUE INNER JOIN "users" AS u5 ON (a0."actor" = u5."ap_id") AND (u5."invisible" = FALSE) WHERE ((($3 && a0."recipients")) OR (a0."actor" = $4)) AND (a0."id" > $5) AND (a0."data"->>'type' = ANY($6)) AND (not (a0."actor" = ANY($7))) AND (((not (a0."recipients" && $8)) or a0."actor" = $9)) AND ((recipients_contain_blocked_domains(a0."recipients", $10) = false) or a0."actor" = $11) AND (not (a0."data"->>'type' = 'Announce' and a0."data"->'to' ?\| $12)) AND ((not (split_part(a0."actor", '/', 3) = ANY($13))) or a0."actor" = ANY($14)) AND ((not (split_part(o1."data"->>'actor', '/', 3) = ANY($15))) or (o1."data"->>'actor') = ANY($16)) AND (not (a0."actor" = ANY($17))) AND (not (a0."data"->'to' ?\| $18) or a0."actor" = $19) AND (t3."user_id" IS NULL) AND (not ( a0."data"->>'type' = 'Announce' and a0."actor" = ANY($20))) AND (a0."data"->>'type' != 'Announce' or o1."data"->>'actor' != $21) AND (not(o1."data"->>'type' = 'Answer')) AND (a0."id" > $22) ORDER BY a0."id" desc nulls last LIMIT $23 | 96.544907 seconds | 9.2 | 28236 | | | UPDATE "public"."oban_jobs" AS o0 SET "state" = $1 FROM (SELECT so0."id" AS "id", so0."state" AS "state" FROM "public"."oban_jobs" AS so0 WHERE (so0."state" IN ('scheduled','retryable')) AND (NOT (so0."queue" IS NULL)) AND (so0."scheduled_at" <= $2) LIMIT $3) AS s1 WHERE (o0."id" = s1."id") RETURNING o0."id", o0."queue", s1."state" | 80.151989 seconds | 7.6 | 1889265 | home TL | | SELECT pg_notify($1, payload) FROM json_array_elements_text($2::json) AS payload | 43.273205 seconds | 4.1 | 2312456 | | | SELECT i0."host" FROM "instances" AS i0 | 26.559587 seconds | 2.5 | 6339 | stats | | INSERT INTO "activities" ("data","local","recipients","actor","id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) | 24.594452 seconds | 2.3 | 25435 | | | INSERT INTO "public"."oban_peers" AS o0 ("name","node","started_at","expires_at") VALUES ($1,$2,$3,$4) ON CONFLICT ("name") DO UPDATE SET "expires_at" = $5 | 19.506537 seconds | 1.9 | 133189 | | | SELECT a0."id", a0."data", a0."local", a0."actor", a0."recipients", a0."inserted_at", a0."updated_at" FROM "activities" AS a0 WHERE (a0."actor" = $1) AND (coalesce((a0."data")->$4->>$5, (a0."data")->>$6) = $2) AND ((a0."data")->>$7 = $3) LIMIT $8 | 18.269952 seconds | 1.7 | 10231 | appears to only be `ActivityPub.Utils.get_existing_announce/2`? Kinda a lot of calls then though... | | COPY public.objects (id, data, inserted_at, updated_at) TO stdout | 16.578686 seconds | 1.6 | 4 | manual db backups |
Oneric commented 2025-03-26 00:23:42 +00:00
Owner
Copy link

Observations from norm’s and my refreshed stats:

  • norm’s query costs are now much more evenly spread out; all of the top 10 queries now sum up to 50% of total db time; before just attachment deletion alone took up 83% of total db time. The new top10’s 50% are made up of
    • 12.6% Oban stuff
    • 7.3% selecting activities by their ID or by object id (the result is not cached-elixir side; it be good to remember this when possible instead of rerequesting it during successive processing steps)
    • 6.7% attachment cleanup (still too much; can eventually be fixed once there’s a decision on #818 and i have time again)
    • 6.7% selecting follower addresses; which is used e.g. as an input for timeline queries (cannot be improved really without a large-scale db overhaul which would allow joining over foreign key user ids instead)
    • surprisingly 0% of timeline queries themselves?
    • 6.6% inserting into activities (reduce indexes and drop counter_cache)
    • 6.1% manual DB backups
    • 4.0% querying objects by their AP ID (this query result should already be cached so eventhough it’d make sense to remember the result during incoming object processing instead of rerequesting it over and over, this is unlikely to affect the DB-side of things)
  • for me the sum of the top 10 also reduced, even if in the refreshed stats only a bit but that’s due to higher activity ig. Using the refreshed result which i suppose is more interesting as a higher-load scenario, the top 10 sums up to 67% made up of:
    • 29.7% Oban stuff
    • 20% querying activities by their object ID (yes the query already uses indexes for everything; still takes this much time)
    • 9.2% home TL query (the update version with a min_id; the version without a mn_id is individually more costly but rarer)
    • 2.5% instance stats
    • 2.3% inserting into activities
    • 1.7% processing announces/boosts(?)
    • 1.6% manual DB backups

There’s no obvious big common outlier to tackle, but good steps (including observations from my previous results) appear to be:

  • migrate to a new attachment db scheme to mostly get rid of attachment cleanup costs (and enable other future attachment feature improvements; blocked on authorative decision on #818)
  • get rid of some heavy activities indexes and triggers which don't bring much benefit; imho counter_cache and it’s associated admin-fe feature should be purged
  • to a lesser degree the same for the objects table
  • user search is both overly costly and gives poor results; we can most likely improve things here
  • it’d be good if we’d remember activity (and also object) lookup results during processing instead of reerequesting it over and over. While elixir-side caches might also cut down on performance, they bring their own share of pain and potential mystery bugs since e.g. cache updates from a failing transaction can poison the cache with data not in sync with the actual DB state
  • maybe cut down instance stats update refresh period from the current 5min to 15min or 30min
Observations from norm’s and my refreshed stats: - norm’s query costs are now _much_ more evenly spread out; all of the top 10 queries now sum up to 50% of total db time; before just attachment deletion alone took up 83% of total db time. The new top10’s 50% are made up of - 12.6% Oban stuff - 7.3% selecting activities by their ID or by object id *(the result is not cached-elixir side; it be good to remember this when possible instead of rerequesting it during successive processing steps)* - 6.7% attachment cleanup *(still too much; can eventually be fixed once there’s a decision on #818 and i have time again)* - 6.7% selecting follower addresses; which is used e.g. as an input for timeline queries *(cannot be improved really without a large-scale db overhaul which would allow joining over foreign key user ids instead)* - surprisingly 0% of timeline queries themselves? - 6.6% inserting into activities *(reduce indexes and drop counter_cache)* - 6.1% manual DB backups - 4.0% querying objects by their AP ID *(this query result should already be cached so eventhough it’d make sense to remember the result during incoming object processing instead of rerequesting it over and over, this is unlikely to affect the DB-side of things)* - for me the sum of the top 10 also reduced, even if in the refreshed stats only a bit but that’s due to higher activity ig. Using the refreshed result which i suppose is more interesting as a higher-load scenario, the top 10 sums up to 67% made up of: - 29.7% Oban stuff - 20% querying activities by their object ID *(yes the query already uses indexes for everything; still takes this much time)* - 9.2% home TL query *(the update version with a `min_id`; the version without a mn_id is individually more costly but rarer)* - 2.5% instance stats - 2.3% inserting into activities - 1.7% processing announces/boosts(?) - 1.6% manual DB backups There’s no obvious big common outlier to tackle, but good steps (including observations from my previous results) appear to be: - migrate to a new attachment db scheme to mostly get rid of attachment cleanup costs (and enable other future attachment feature improvements; blocked on authorative decision on #818) - get rid of some heavy `activities` indexes and triggers which don't bring much benefit; imho `counter_cache` and it’s associated admin-fe feature should be purged - to a lesser degree the same for the `objects` table - user search is both overly costly and gives poor results; we can most likely improve things here - it’d be good if we’d remember activity (and also object) lookup results during processing instead of reerequesting it over and over. While elixir-side caches might also cut down on performance, they bring their own share of pain and potential mystery bugs since e.g. cache updates from a failing transaction can poison the cache with data not in sync with the actual DB state - maybe cut down instance stats update refresh period from the current 5min to 15min or 30min
❤️ 1
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
develop
backfill-expiry
stable
db-prune-beastmode-level-aggression
better-stats
translations
customizable-docker-db
static-adminfe
bad-uploader-config-warning
docker
user-expiry-backfill
config-db-keys
ensure-scrubbers-loaded
otp26
code-shaking-does-not-go-brr
elixir1.15
circleci
backup-fixes
mod-task
policy
mrf-coolness
frontend-switcher-9000
contentMap
language-on-posts
rabbit
credo-on-pr
unify-http
normalise-markup-by-default
buildx
v3.15.2
v3.15.1
v3.15.0
v3.14.1
v3.14.0
v2.8.0
v2.7.1
v3.13.3
v2.7.0
v3.13.2
v2.6.3
v3.13.1
v3.13.0
snac-3.12.1.2
v3.12.2
snac-3.12.1.1
v3.12.1
v3.12.0
v3.11.0
v2.6.2
v2.6.1
2.6.1
v2.6.0
v2.5.5
v3.10.4
v3.10.3
v3.10.2
v3.10.1
v3.10.0
v2.5.4
v2.5.3
v3.9.3
v3.9.2
v3.9.1
V3.9.0
2023.05
v3.8.0
v3.7.1
v3.7.0
v3.6.0
v3.5.0
v2.4.5
v3.4.0
v3.3.1
v2.4.4
v3.3.0
v3.2.3
v3.2.2
v3.2.1
stable-202209
v3.2.0
v3.1.0
stable-2022.07
v3.0.0
v0.0.1
v2.5.2-6
v2.5.2-5
v2.5.2-4
v2.5.2-3
v2.5.2-2
v2.5.2-1
v2.5.2
v2.5.1
v2.5.0-8
v2.5.0-7
v2.5.0-6
v2.5.0-5
v2.5.0-4
v2.5.0-3
v2.5.0-2
v2.5.0-1
v2.5.0
v2.4.3
pre-rebase
v2.4.2
v2.4.1
v2.4.0
soapbox-v1.1.1
soapbox-v1.1.0
soapbox-v1.0.0
v2.3.0
v2.2.2
v2.2.1
v2.2.0
v2.1.2
v2.1.1
v2.1.0
v2.0.7
v2.0.6
v2.0.5
v2.0.4
v2.0.3
v2.0.2
v2.0.1
v2.0.0
v1.1.9
v1.1.8
v1.1.7
v1.1.6
v1.1.5
v1.1.4
v1.1.3
v1.1.2
v1.1.1
v1.1.0
v1.0.91
v1.0.90
v1.0.7
v1.0.6
v1.0.5
v1.0.4
v1.0.3
v1.0.2
v1.0.1
v1.0.0
v0.9.0
Labels
Clear labels   
approved, awaiting change

   
bug

Something is not working

  
configuration

This requires config changes

  
documentation

This is about human-readable docs

  
duplicate

This issue or pull request already exists

  
enhancement

New feature

  
extremely low priority

   
feature request

Something new?

  
Fix it yourself

Support has been attempted

  
help wanted

Need some help

  
invalid

Something is wrong

  
mastodon_api

   
needs change/feedback

Issue or PR is stalled on response from the author or a third party

  
needs docs

   
needs tests

   
not a bug

   
planned

   
pleroma_api

   
privacy

   
question

More information is needed

  
static_fe

   
triage

   
wontfix

This won't be fixed

No labels
approved, awaiting change
bug
configuration
documentation
duplicate
enhancement
extremely low priority
feature request
Fix it yourself
help wanted
invalid
mastodon_api
needs change/feedback
needs docs
needs tests
not a bug
planned
pleroma_api
privacy
question
static_fe
triage
wontfix
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
4 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: AkkomaGang/akkoma#784
No description provided.
Delete branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?