Slow username auto-complete when writing Talk posts

[trouille]

See https://www.zooniverse.org/talk/17/2481806

The thread describes how it can take ~30 seconds the first time a person tries to find an @-username when writing a Talk post. In subsequent attempts that same day, the time is shorter. But then the time is long again the next day.

This is new behavior (ie., the moderator who posted about this issue has been w/ the Zooniverse for a long time and this appears to be new).

The people posting about experiencing this issue share the browser and OS they're using.
One is on Chrome 102 on Windows 10, 64bit. The other Safari on iOS (iPad).

[zwolf]

I'm not seeing this behavior either. Looking at some of the relevant code here, I wonder if this might not have to do with how many people that the affected users have messaged or mentioned. The query result might be cached in postgres, which could explain the faster subsequent queries. Then there's this bit here:

talk-api/lib/username_completion.rb

Lines 188 to 191 in db7810d

	def all_matching_users
	key = "username-completion-all-users-#{ @search }"
	Rails.cache.fetch(key, expires_in: 1.hour){ _all_matching_users }
	end

That method saves a list of "all matches" (to the current pattern) in the redis cache, but it expires in an hour. Seems like if this were the issue, though, it would be more widely impactful. The cache expiration makes it easy to want to blame, though.

The way that https://github.com/zooniverse/talk-api/blob/master/lib/username_completion.rb builds the SQL makes it difficult to tell how much work the intermediate queries like #matching_mentions, #matching_messages, and #matching_group_mentions are doing. For what it's worth, I tested this on the talk rails console with a user that described having issues in that talk thread and didn't see any significant delays.

@camallen do you have any insight here?

[camallen]

I'd say we can't reproduce this as it's related to the query on how much activity the logged in user has on a talk section (project). As you can see in the query sql the logged in user is used to search for

1. other mentioned users

   talk-api/lib/username_completion.rb

   Line 88 in db7810d

   mentions.user_id = #{ @current_user.id } and

2. other discussions participants the logged in user has been talking to on a section

   talk-api/lib/username_completion.rb

   Line 128 in db7810d

   participant_ids @> '{#{ @current_user.id }}'

I'd suggest you don't try to replicate this problem via the UI interface as your own accounts (i don't think it'll trigger the problematic behaviours). Instead you could try and debug / explain / run this query manually as the reporting users instead - this should trigger the problematic behaviours and from there we can debug why the query is slow (missing indexes etc)

[zwolf]

Instead you could try and debug / explain / run this query manually as the reporting users instead

I tested this on the talk rails console with a user that described having issues in that talk thread and didn't see any significant delays.

Yes, I used the console to build UsernameCompletion instances with a couple different users as @current_users:

talk-api/lib/username_completion.rb

Lines 7 to 13 in db7810d

	class UsernameCompletion
	def initialize(current_user, pattern, limit: 10)
	@current_user = current_user
	@pattern = pattern&.gsub /[^#{User::ALLOWED_LOGIN_CHARACTERS}]/, ''
	@emptyPattern = @pattern.blank?
	@limit = limit
	end

Running the various methods on those instances took a few seconds but were nothing like what's being described.

The problem with debugging the queries is that the some of those methods print out extremely unfriendly SQL in plain text.