Slow queries
Using !3553 (merged) I'm finding some slow queries. Note that I have omitted Oban queries, so everything here is running as part of the request/response cycle pretty much.
Tracebacks are against this commit: https://gitlab.com/soapbox-pub/soapbox/-/tree/94eb61e8550c441afcfd293190b553373ae0b548
Home timeline:
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.429 request_id=Fr4zyQTR03rNmNkACO_j [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 353378.574ms
Dec 06 15:24:13 gleasonator mix[171487]: "SELECT a0.\"id\", a0.\"data\", a0.\"local\", a0.\"actor\", a0.\"recipients\", a0.\"inserted_at\", a0.\"updated_at\", b2.\"id\", b2.\"user_id\", b2.\"activity_id\", b2.\"inserted_at\", b2.\"updated_at\", o1.\"id\", o1.\"data\", o1.\"inserted_at\", o1.\"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') WHERE ((($3 && a0.\"recipients\")) OR (a0.\"actor\" = $4)) AND (a0.\"data\"->>'type' = ANY($5)) AND (not (a0.\"actor\" = ANY($6))) AND (((not (a0.\"recipients\" && $7)) or a0.\"actor\" = $8)) AND ((recipients_contain_blocked_domains(a0.\"recipients\", $9) = false) or a0.\"actor\" = $10) AND (not (a0.\"data\"->>'type' = 'Announce' and a0.\"data\"->'to' ?| $11)) AND ((not (split_part(a0.\"actor\", '/', 3) = ANY($12))) or a0.\"actor\" = ANY($13)) AND ((not (split_part(o1.\"data\"->>'actor', '/', 3) = ANY($14))) or (o1.\"data\"->>'actor') = ANY($15)) AND (not (a0.\"actor\" = ANY($16))) AND (not (a0.\"data\"->>'type' = 'Announce' and a0.\"data\"->'to' ?| $17)) AND (not (a0.\"actor\" = ANY($18))) AND (not (a0.\"data\"->'to' ?| $19) or a0.\"actor\" = $20) AND (t3.\"user_id\" IS NULL) AND (not ( a0.\"data\"->>'type' = 'Announce' and a0.\"actor\" = ANY($21))) AND (a0.\"data\"->>'type' != 'Announce' or o1.\"data\"->>'actor' != $22) AND (NOT (a0.\"actor\" = ANY($23))) AND (not(o1.\"data\"->>'type' = 'Answer')) AND (not(o1.\"data\"->>'type' = 'ChatMessage')) AND (NOT (a0.\"actor\" = ANY($24))) ORDER BY a0.\"id\" desc nulls last LIMIT $25"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Pagination, :fetch_paginated, 4,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/pagination.ex', line: 40]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.ActivityPub, :fetch_activities, 3,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/activity_pub.ex', line: 492]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :home, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 56
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :action, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :phoenix_controller_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :plug_builder_call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Home timeline again? This time in StatusView:
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.451 request_id=Fr4zyQTR03rNmNkACO_j [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 6723.929ms
Dec 06 15:24:13 gleasonator mix[171487]: "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\"->>'id') = COALESCE(a0.\"data\"->'object'->>'id', a0.\"data\"->>'object') WHERE (coalesce((a0.\"data\")->'object'->>'id', (a0.\"data\")->>'object') = ANY($1)) AND ((a0.\"data\")->>'type' = $2)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :get_replied_to_activities, 1,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 55]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 93]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :action, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :phoenix_controller_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :plug_builder_call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
More stuff in StatusView...
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 8229.138ms
Dec 06 15:24:13 gleasonator mix[171487]: "SELECT a0.\"id\", a0.\"data\", a0.\"local\", a0.\"actor\", a0.\"recipients\", a0.\"inserted_at\", a0.\"updated_at\", b2.\"id\", b2.\"user_id\", b2.\
"activity_id\", b2.\"inserted_at\", b2.\"updated_at\", o1.\"id\", o1.\"data\", o1.\"inserted_at\", o1.\"updated_at\", NOT (t3.\"id\" IS NULL) FROM \"activities\" AS a0 LEFT OUTER JOIN \"obje
cts\" 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') WHERE (coalesce((a0.\"data\")->'object'->>'id', (a0.\"data\")->>'objec
t') = ANY($3)) AND ((a0.\"data\")->>'type' = $4)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 103]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :action, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :phoenix_controller_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :plug_builder_call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Oh look, StatusView.
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 4183.351ms
Dec 06 15:24:13 gleasonator mix[171487]: "SELECT u0.\"relationship_type\", u0.\"source_id\", u0.\"target_id\" FROM \"user_relationships\" AS u0 WHERE ((source_id = ANY($1) AND target_id = ANY($2) AND relationship_type = ANY($3)) OR (source_id = ANY($4) AND target_id = ANY($5) AND relationship_type = ANY($6)))"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.UserRelationship, :view_relationships_option, 3,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/user_relationship.ex', line: 170]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 120]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :action, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :phoenix_controller_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :plug_builder_call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Endpoint, :call, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/endpoint.ex', line: 5]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Apparently instance favicons are very slow @lanodan
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.489 [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 16620.625ms
Dec 06 15:24:13 gleasonator mix[171487]: "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)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Federator, :perform, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/federator.ex', line: 81]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.494 request_id=Fr4zyQTR03rNmNkACO_j [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 1814.651ms
Dec 06 15:24:13 gleasonator mix[171487]: "SELECT i0.\"id\", i0.\"host\", i0.\"unreachable_since\", i0.\"favicon\", i0.\"favicon_updated_at\", i0.\"inserted_at\", i0.\"updated_at\" FROM \"instances\" AS i0 WHERE (i0.\"host\" = $1)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Instances.Instance, :get_or_update_favicon, 1,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/instances/instance.ex', line: 142]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.AccountView, :do_render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/account_view.ex', line: 230]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 343]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :safe_render, 3,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 6]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :safe_render_many, 4,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 6]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
StatusView & FollowingRelationship again:
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.502 request_id=Fr4zyQTR03rNmNkACO_j [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 4029.287ms
Dec 06 15:24:13 gleasonator mix[171487]: "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)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.FollowingRelationship, :following, 1,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/following_relationship.ex', line: 183]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Visibility, :visible_for_user?, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/visibility.ex', line: 85]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 382]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :safe_render, 3,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 6]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :safe_render_many, 4,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 6]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.TimelineController, :action, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: file: 'lib/pleroma/web/mastodon_api/controllers/timeline_controller.ex',
Dec 06 15:24:13 gleasonator mix[171487]: line: 5
Dec 06 15:24:13 gleasonator mix[171487]: ]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
SideEffects:
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.504 [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 1943.692ms
Dec 06 15:24:13 gleasonator mix[171487]: "SELECT o0.\"id\", o0.\"data\", o0.\"inserted_at\", o0.\"updated_at\" FROM \"objects\" AS o0 WHERE ((o0.\"data\")->>'id' = $1)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.SideEffects, :handle, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/side_effects.ex', line: 269]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Pipeline, :do_common_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/pipeline.ex', line: 50]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Pipeline, :common_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/pipeline.ex', line: 28]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Transmogrifier, :handle_incoming, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/transmogrifier.ex', line: 476]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Federator, :perform, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/federator.ex', line: 84]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Notifications:
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 4561.205ms
Dec 06 15:24:13 gleasonator mix[171487]: "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.\"accepts_chat_messages\", u0.\"last_active_at\", u0.\"disclose_client\", u0.\"accepts_email_list\", u0.\"pinned_objects\", u0.\"is_suggested\", u0.\"notification_settings\", u0.\"blocks\", u0.\"mutes\", u0.\"muted_reblogs\", u0.\"muted_notifications\", u0.\"subscribers\", u0.\"multi_factor_authentication_settings\", u0.\"inserted_at\", u0.\"updated_at\" FROM \"users\" AS u0 WHERE (u0.\"ap_id\" = ANY($1)) AND (NOT (u0.\"nickname\" IS NULL)) AND (NOT (u0.\"nickname\" LIKE 'internal.%')) AND (u0.\"local\" = $2)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Notification, :get_notified_from_activity, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/notification.ex', line: 512]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Notification, :do_create_notifications, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/notification.ex', line: 389]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.SideEffects, :handle, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/side_effects.ex', line: 272]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Pipeline, :do_common_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/pipeline.ex', line: 50]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Pipeline, :common_pipeline, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/pipeline.ex', line: 28]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Transmogrifier, :handle_incoming, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/transmogrifier.ex', line: 476]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Federator, :perform, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/federator.ex', line: 84]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Did somebody say StatusView?
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.605 request_id=Fr4zyQTR03rNmNkACO_j [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 4256.109ms
Dec 06 15:24:13 gleasonator mix[171487]: "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.\"accepts_chat_messages\", u0.\"last_active_at\", u0.\"disclose_client\", u0.\"accepts_email_list\", u0.\"pinned_objects\", u0.\"is_suggested\", u0.\"notification_settings\", u0.\"blocks\", u0.\"mutes\", u0.\"muted_reblogs\", u0.\"muted_notifications\", u0.\"subscribers\", u0.\"multi_factor_authentication_settings\", u0.\"inserted_at\", u0.\"updated_at\" FROM \"users\" AS u0 WHERE (u0.\"ap_id\" = $1)"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.User, :get_cached_by_ap_id, 1,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/user.ex', line: 1126]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :render, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 162]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :safe_render, 3,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 6]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.MastodonAPI.StatusView, :safe_render_many, 4,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/mastodon_api/views/status_view.ex', line: 6]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
Ah, here is the query mentioned in #2792 (closed), !3554 (merged) ... WTF??? Over 1 minute...
Dec 06 15:24:13 gleasonator mix[171487]: 15:24:13.817 [warn] Query took longer than 500ms!
Dec 06 15:24:13 gleasonator mix[171487]: Total time: 77559.285ms
Dec 06 15:24:13 gleasonator mix[171487]: "SELECT u0.\"ap_id\" FROM \"users\" AS u0 WHERE (u0.\"is_active\" = FALSE) AND (NOT (u0.\"nickname\" IS NULL)) AND (NOT (u0.\"nickname\" LIKE 'internal.%'))"
Dec 06 15:24:13 gleasonator mix[171487]: [
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Activity, :restrict_deactivated_users, 1,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/activity.ex', line: 367]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Activity, :get_create_by_object_ap_id, 1,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/activity.ex', line: 255]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Transmogrifier, :fix_in_reply_to, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/transmogrifier.ex', line: 153]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.ActivityPub.Transmogrifier, :handle_incoming, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/activity_pub/transmogrifier.ex', line: 457]},
Dec 06 15:24:13 gleasonator mix[171487]: {Pleroma.Web.Federator, :perform, 2,
Dec 06 15:24:13 gleasonator mix[171487]: [file: 'lib/pleroma/web/federator.ex', line: 84]}
Dec 06 15:24:13 gleasonator mix[171487]: ]
I'm still identifying, but I would say we should probably look into StatusView.