User Card display performance

[DeanMarkTaylor (Dean Taylor)]

Thanks @zogstrip for this commit:
https://github.com/discourse/discourse/commit/e20078a9dc34ae4b03e33277a553e41af8066942

I had mentioned performance issues with this here:

@DeanMarkTaylor

For me I hate having to click a users avatar to PM - mainly because it takes ~3.5 seconds to load the user card after a click as an admin.

For me the general loading in user cards has gone from ~3.5 seconds to ~2 seconds…
… It may not seem like much - but it really helps - Thanks.

EDIT: I couldn’t think of a better category other than “bug” - feel free to re-categorise.

[zogstrip]

You’re welcome

Mind sharing the slowest queries? I’m guessing it’s other COUNT(*) queries…

[DeanMarkTaylor (Dean Taylor)]

No problem - here you are:

##Query 1
Executing action: show
T+34.8 ms
Reader
1284.2 ms

lib/sql_builder.rb:62:in `exec'
app/models/user_action.rb:74:in `stats'
app/serializers/user_serializer.rb:175:in `stats'
app/controllers/application_controller.rb:220:in `render_json_dump'
app/controllers/users_controller.rb:38:in `block (2 levels) in show'
app/controllers/users_controller.rb:31:in `show'
lib/middleware/anonymous_cache.rb:119:in `call'
lib/middleware/unicorn_oobgc.rb:95:in `process_client'

###SQL

SELECT action_type, COUNT(*) count
FROM user_actions a
JOIN topics t ON t.id = a.target_topic_id
LEFT JOIN posts p on p.id = a.target_post_id
JOIN posts p2 on p2.topic_id = a.target_topic_id and p2.post_number = 1
LEFT JOIN categories c ON c.id = t.category_id
WHERE (a.user_id = 12) AND (t.deleted_at is null)
GROUP BY action_type

##Query 2
Executing action: show
T+1481.2 ms
Reader
48.8 ms

app/models/user_action.rb:88:in `private_messages_stats'
app/serializers/user_serializer.rb:250:in `private_messages_stats'
app/controllers/application_controller.rb:220:in `render_json_dump'
app/controllers/users_controller.rb:38:in `block (2 levels) in show'
app/controllers/users_controller.rb:31:in `show'
lib/middleware/anonymous_cache.rb:119:in `call'
lib/middleware/unicorn_oobgc.rb:95:in `process_client'

SQL

SELECT COUNT(*) FROM "topics" LEFT OUTER JOIN topic_users AS tu ON (topics.id = tu.topic_id AND tu.user_id = 12) WHERE ("topics"."deleted_at" IS NULL) AND (topics.id IN (SELECT topic_id FROM topic_allowed_users WHERE user_id = 12)) AND "topics"."archetype" = 'private_message' AND (tu.last_read_post_number IS NULL OR tu.last_read_post_number < topics.highest_post_number) 

##Query 3
Although this one is not that big - it’s very simular to the one above and runs just before it

Executing action: show
T+1463.4 ms
Reader
14.6 ms

app/models/user_action.rb:87:in `private_messages_stats'
app/serializers/user_serializer.rb:250:in `private_messages_stats'
app/controllers/application_controller.rb:220:in `render_json_dump'
app/controllers/users_controller.rb:38:in `block (2 levels) in show'
app/controllers/users_controller.rb:31:in `show'
lib/middleware/anonymous_cache.rb:119:in `call'
lib/middleware/unicorn_oobgc.rb:95:in `process_client'

SQL

SELECT COUNT(*) FROM "topics" LEFT OUTER JOIN topic_users AS tu ON (topics.id = tu.topic_id AND tu.user_id = 12) WHERE ("topics"."deleted_at" IS NULL) AND (topics.id IN (SELECT topic_id FROM topic_allowed_users WHERE user_id = 12)) AND "topics"."archetype" = 'private_message' AND "topics"."user_id" = 12

[zogstrip]

We should definitely do something about query #1.

[riking (Kane York)]

Perhaps the user card could be broken into 2 requests, one for the data essential to display it and another for the admin-only extra data?

[zogstrip]

Unfortunately query #1 isn’t an admin-only request… It’s part of the “standard” user serializer.

[riking (Kane York)]

Wait, what the heck is that used for? It’s getting… user actions on the first post of all topics?

EDIT: That must be the ‘flagged topics’ count. That’s admin-only.

[sam (Sam Saffron)]

yeah we need to restructure the serializer.

[codinghorror (Jeff Atwood)]

This is slow enough to justify the bug label in my book… it is symptomatic of deeper issues.

[codinghorror (Jeff Atwood)]

@DeanMarkTaylor is this OK now?

[DeanMarkTaylor (Dean Taylor)]

I’m currently awaiting a couple of known bugs to be fixed before updating.
As soon as I see them resolved I will update and report back.

[DeanMarkTaylor (Dean Taylor)]

I can now report that the user card loading times…
Discourse 1.2.0.beta5 - https://github.com/discourse/discourse version 80d8b133d948c742275052123cad6ba753937ae0

The loading time is clearly linked to the number of topics / posts a user has.

Numbers from profiler.

When selecting an older user with 5540 posts the time is ~2045ms (feels like 2.8 seconds to display), with the slowest query:

When selecting an older user with 2668 posts the time is ~1726ms (feels like 2.5 seconds to display), with the slowest query:

When selecting an newer user with 12 posts the time is ~373ms (feels like 1 second to display), with the slowest query:

That same user 12 from the previous slow query had ~3803 posts - it appears I have clicked this user too many times and the cached time is ~617ms (feels like ~2 seconds).

[sam (Sam Saffron)]

This is now fixed via:

https://github.com/discourse/discourse/commit/e9c5e17fbe3e4d7730d523778d254c1c1d9bc181

and

https://github.com/discourse/discourse/commit/130dbf7358272da5c902e2e9afb8dfadcdd7497c

[DeanMarkTaylor (Dean Taylor)]

@sam

This is now fixed

Wooo - looks awesome and even better it feels soo much better as a user!

@DeanMarkTaylor

When selecting an older user with 5540 posts the time is ~2045ms (feels like 2.8 seconds to display)

Here are some times from clicking both old and new users with varying numbers of posts including that same user of with a 2 second+ load time:

So it looks like this has basically taken well over 1 second off of loading the User Card.

Another job well done @sam!