Research why loading nearbyPeople Srch API is so slow to load

[nstjean]

In our maps we are now loading data from https://publiclab.org/api/srch/nearbyPeople?nwlat=10.0&selat=0.0&nwlng=0.0&selng=10.0
This code is located here: https://github.com/publiclab/plots2/blob/master/app/api/srch/search.rb#L333

Accessing this API takes a lot longer than it should. For example, it takes 19.43s to load:

Meanwhile another API we use in our map layers has far more results in only 83ms!

Some of our other Search API requests perform much better than nearbyPeople. Why is that particular one so slow? In order for our maps to be useful we can't have such a long delay in loading every time we refresh or move the map.

[nstjean]

I suspect that we are going to have to use less search params in order to get the speeds we want. The problem is I'm not sure how we can test those params without pushing and merging the changes to the live site, and that's going to be a really slow iteration. Anyone want to look into this?

[dburugupalli]

@nstjean i could like to try this one. I think the issue could be because of the greater number of parameters to be processed. Due to which, it takes a larger amount of time to load and process the data.

[nstjean]

@dburugupalli Go for it!

[sagarpreet-chadha]

Yes we need to decrease the time taken by that query. Thanks!

[jywarren]

@dburugupalli my first suggestion is to try adding a limit to this. we should try to trace the query -- adding more info here:

plots2/app/services/search_service.rb

Lines 187 to 190 in 783fbe2

	uids = User.joins(:user_tags)
	.where('user_tags.value = ?', tag)
	.where(id: user_locations.select("rusers.id"))
	.collect(&:id).uniq || []

This is the query, which i suspect runs real slow on the whole huge users table. We can limit with an additional:

.where(status: 1)

which will help a lot. We could also join the nodes table and insist that the user has a node which has node.status == 1 too. That'd help a lot too.

Yes, here is the Skylight report on this query:

Full report here: https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1583245980/6h/endpoints/Srch::Search%20%5BGET%5D%20srch%2FnearbyPeople

That actually says the slow query is the user tags query...

So maybe when we run this, it is running on a TON of records:

plots2/app/services/search_service.rb

Lines 203 to 208 in 783fbe2

	# selects the items whose node_tags don't have the location:blurred tag
	items.select do |item|
	item.user_tags.none? do |user_tag|
	user_tag.name == "location:blurred"
	end
	end

We could limit it to 100

Also, are we re-running a user_tag query on each instance, on this line?

      item.user_tags.none? do |user_tag|

If so, we could optimize this.

[jywarren]

I think this'll take a little experimentation but if that is a nested query on item.user_tags.none? we should be able to speed this up a LOT by a) limiting the results and b) not nesting the query, but, inspecting the item and seeing what we can do to test if it has any tags without generating a new nested query.

[jywarren]

Looking at whether we need to add an index, or reduce recursion in query nesting...

[jywarren]

Hmm. user_tags has no indices:

plots2/db/schema.rb.example

Lines 417 to 422 in 15589c9

	create_table "user_tags", force: true do |t|
	t.integer "uid"
	t.string "value"
	t.datetime "created_at", null: false
	t.datetime "updated_at", null: false
	t.text "data"

Not sure if it needs them? Checking # of records now.

[jywarren]

Primary key ought to auto-index...

So, i ran it in the production console and it's really fast: UserTag.find_by(uid: 1)

So, i think it's the nesting - i bet we are running it on a ton of users.

[SidharthBansal]

plots2/app/services/search_service.rb

Line 197 in 783fbe2

items = User.where('rusers.status <> 0')

and

plots2/app/services/search_service.rb

Line 176 in 783fbe2

user_locations = User.where('rusers.status <> 0')

have
User.where('rusers.status <> 0') .joins(:user_tags)
same statements running twice! Can we optimize here by storing them ?

[SidharthBansal]

shouldn't there be status<>0 clause at user in

plots2/app/services/search_service.rb

Line 187 in 783fbe2

uids = User.joins(:user_tags)

?
I think there should be !

[SidharthBansal]

Two possible ways to reduce time are short circuiting if possible, AND rearrangement of statements so that the first clause eliminates more cases then the upcoming clauses in sql statements.

[jywarren]

I think the first and second referenced in your comment are the latitude and longitude calcs I want to combine.

https://blog.nrowegt.com/rails-pg-ambiguous-column-reference/

[jywarren]

OK, i was able to get this to work:

u = User.where('rusers.status <> 0').joins(:user_tags).where('user_tags.value LIKE ?', 'lat%').where('REPLACE(user_tags.value, "lat:", "") BETWEEN 44 AND 44.1').joins('INNER JOIN `user_tags` AS `lontags` ON lontags.uid = rusers.id').where('lontags.value LIKE ?', 'lon%').where('REPLACE(lontags.value, "lon:", "") BETWEEN 20 AND 80')

Formatted:

u = User.where('rusers.status <> 0')
.joins(:user_tags)
.where('user_tags.value LIKE ?', 'lat%')
.where('REPLACE(user_tags.value, "lat:", "") BETWEEN 44 AND 44.1')
.joins('INNER JOIN `user_tags` AS `lontags` ON lontags.uid = rusers.id')
.where('lontags.value LIKE ?', 'lon%')
.where('REPLACE(lontags.value, "lon:", "") BETWEEN 20 AND 80')

[jywarren]

Hmm. @cesswairimu actually the block I'm still not sure about is:

      item.user_tags.none? do |user_tag|
        user_tag.name == "location:blurred"
      end

What's going on here?

[jywarren]

i think i found that the block is used to evaluate all items of the array and the whole thing returns true only if none of the array members return true? https://ruby-doc.org/core-2.7.0/Enumerable.html#method-i-none-3F

[jywarren]

OK, i added .limit(limit) in a couple places too. I hope this helps!!!

[SidharthBansal]

#7556 (comment)

Could the replace statements move towards end?
After sorting, we will have lesser number of rows so replacing at last step can improve(I don't have full context, so it may be wrong)

[jywarren]

#7795 is now merged, although one of the .limit() statements had to be removed. We should re-test this after today's live site republication and see if performance improved?

Current:

https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1586809440/1d/endpoints/Srch::Search%20%5BGET%5D%20srch%2FnearbyPeople

[jywarren]

Now not seeing much more than 8s, much better than 60!!!

https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1586902080/30m/endpoints/Srch::Search%20%5BGET%5D%20srch%2FnearbyPeople

but needs more testing.

[jywarren]

Test it out at this zoom level: https://publiclab.org/map#9/40.71372914097432/-73.47581131383778

cc zoom level optimizations: #7822

[jywarren]

OK, so i'm not seeing a huge difference between before and after April 14; both are averaging around 17 seconds or so, and both have outliers up to more than a minute of load time, so not good. But even before the 14th, the "what time is spent on" chart is quite different for different periods.

We just don't have a huge amount of traffic so statistics aren't great, but I'll screenshot a few "moments" so we can look at different possible sources of inefficiency:

https://oss.skylight.io/app/applications/GZDPChmcfm1Q/1586919420/1d/endpoints/Srch::Search%20%5BGET%5D%20srch%2FnearbyPeople

this has 3 queries:

SELECT DISTINCT `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON `user_tags`.`uid` = `rusers`.`id` WHERE (rusers.status <> ?) AND (value LIKE ?) AND (REPLACE(value, ?, ?) BETWEEN ? AND ?)

SELECT `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON `user_tags`.`uid` = `rusers`.`id` WHERE (rusers.status <> ?) AND (rusers.id IN ?) AND (user_tags.value LIKE ?) AND (REPLACE(user_tags.value, ?, ?) BETWEEN ? AND ?)

SELECT  `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON `user_tags`.`uid` = `rusers`.`id` WHERE (rusers.status <> ?) AND (rusers.id IN ?) AND (user_tags.value LIKE ?) AND (REPLACE(user_tags.value, ?, ?) BETWEEN ? AND ?) ORDER BY created_at DESC LIMIT ?

That was all just one query, for the period of time before the April 14th optimization.

This next one was after the optimization:

The query was more simple:

SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = ?

It does seem that most slowness after April 14th was to do with user_tags for a single user... that's weird.

Could it be that for large sets of users, this is just these lines running over and over?

plots2/app/services/search_service.rb

Lines 204 to 206 in c6aabd6

	item.user_tags.none? do |user_tag|
	user_tag.name == "location:blurred"
	end

If true (and we should be able to test that on the console?) we should be able to do this filtering a different way, as we should already have loaded the user tags and be able to additionally sort by them. But maybe we haven't eager-loaded the associations?

Could we a) do this in 2 batches, one for users with a location:blurred tag and once without, and/or b) eager-load the user tags so we can filter without doing individual queries for each user?

[emilyashley]

Also, pssst @Tlazypanda the staff and I were talking about this today and I thought you may also want to put eyes on it since it is performance related! :)

[Tlazypanda]

@emilyashley Yeah sure! Would need a bit of context on this first though 😅 Will look into it 😄

[daemon1024]

So the next step would be to try eager loading. This should help in our performance significantly I believe.

I think we'll probably have to try a few different measures to reduce the load time.

Agreed. Will look into further improvements after improving this.

[daemon1024]

The performance now seems to be regressed back to normal.
I think it's not the right way to eager load the query. Will have to look into how to do it the correct way. Any inputs appreciated!

[daemon1024]

So we have a similar construct in nearbyNodes too.

plots2/app/services/search_service.rb

Lines 144 to 148 in b70cbef

	items.select do |item|
	item.node_tags.none? do |node_tag|
	node_tag.name == "location:blurred"
	end
	end

And that uses eager loading too.

plots2/app/services/search_service.rb

Line 137 in b70cbef

items = Node.includes(:tag)

History for this points to #1987.

[daemon1024]

Reverted this commit since it broke things 😅

[Tlazypanda]

Hey @daemon1024 just noting here https://github.com/flyerhzm/bullet you can set this gem up locally to test whether the n+1 problem is getting resolved or not ✌️ This really helped me a lot to figure out the exact traceback of the n+1 query issue and change my code accordingly. Once the issue is resolved it will also stop generating the warning for n+1

[jywarren]

Hi @daemon1024 can you link us to the PR you're working in? Sorry if I missed that!

[daemon1024]

@jywarren There's no PR for now 😅. Most of my testing has been in local or directly on unstable. Will make a PR once I have something concrete. Rest noted my observations above.

Thanks @Tlazypanda for the gem, looks very helpful and will get back to you after trying it out 🙌

[jywarren]

Ah i see no problem! - still, good for us to be able to see your code so far, so don't be afraid to share even rough early code!

[17sushmita]

Hi @daemon1024

So the problematic queries are still the same

SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = ?

This one is due to the looping over on every node by the user to check if it has location: blurred.

plots2/app/services/search_service.rb

Lines 202 to 207 in b70cbef

	# selects the items whose node_tags don't have the location:blurred tag
	items.select do |item|
	item.user_tags.none? do |user_tag|
	user_tag.name == "location:blurred"
	end
	end

So can be resolved by using a simpler rails query

    items = items.where('user_tags.value <> "location:blurred"')

Second query still needs to be debugged

and

SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = ? AND (value LIKE ?)

[17sushmita]

I'm not really sure about the second query but I observed that when the limit is 5 it performs 20 such queries - 4 query for each record and the 4 queries are in following pattern-

  UserTag Load (29.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'lat:%')
  UserTag Load (29.1ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'lon:%')
  UserTag Exists (15.0ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (39.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'location:%')

First one for loading tag like 'lat:%' second for loading tag like 'lon:%' and third one for checking if 'location:%' exists or not and fourth for loading the tag like 'location:%' on the same user.

We are only using LIKE 'lat%' and LIKE 'lon%' queries in this rails query-

plots2/app/services/search_service.rb

Lines 176 to 183 in b70cbef

	user_locations = User.where('rusers.status <> 0')
	.joins(:user_tags)
	.where('user_tags.value LIKE ?', 'lat%')
	.where('REPLACE(user_tags.value, "lat:", "") BETWEEN ' + coordinates["selat"].to_s + ' AND ' + coordinates["nwlat"].to_s)
	.joins('INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id')
	.where('lontags.value LIKE ?', 'lon%')
	.where('REPLACE(lontags.value, "lon:", "") BETWEEN ' + coordinates["nwlng"].to_s + ' AND ' + coordinates["selng"].to_s)
	.distinct

and checking if location: blurred exists in this query-

plots2/app/services/search_service.rb

Lines 202 to 207 in b70cbef

	# selects the items whose node_tags don't have the location:blurred tag
	items.select do |item|
	item.user_tags.none? do |user_tag|
	user_tag.name == "location:blurred"
	end
	end

which after optimizing will look like-

    items = items.where('user_tags.value <> "location:blurred"')

So, I think these queries are automatically performed by rails ORM to verify if returned records have these attributes or not.

Complete trace of queries executed for the following parameters - http://publiclab.org/api/srch/nearbyPeople?nwlat=55.3791104480105&selat=23.40276490540795&nwlng=-128.67187500000003&selng=178.76953125
are (placed dummy user ids in place of original ones) -

  UserTag Load (29.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'lat:%')
  UserTag Load (29.1ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'lon:%')
  UserTag Exists (15.0ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (39.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'location:%')
  UserTag Load (42.6ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'lat:%')
  UserTag Load (47.8ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'lon:%')
  UserTag Exists (14.7ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (43.4ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'location:%')
  UserTag Load (39.3ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'lat:%')
  UserTag Load (43.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'lon:%')
  UserTag Exists (12.0ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (47.6ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'location:%')
  UserTag Load (42.4ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'lat:%')
  UserTag Load (40.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'lon:%')
  UserTag Exists (14.2ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (41.4ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'location:%')
  UserTag Load (38.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'lat:%')
  UserTag Load (41.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'lon:%')
  UserTag Exists (13.7ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (45.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'location:%')

These are some stack overflow questions that I found had some similar issues like us (Not sure)-
https://stackoverflow.com/questions/50483971/why-is-ruby-on-rails-executing-select-1-as-one-queries
https://stackoverflow.com/questions/53125413/page-loads-unnecessary-queries-ruby-on-rails

[daemon1024]

Details

Order of execution of things I see in skylight.

1. The first query:

   SELECT DISTINCT `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON `user_tags`.`uid` = `rusers`.`id` INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id WHERE (rusers.status <> ?) AND (user_tags.value LIKE ?) AND (REPLACE(user_tags.value, ?, ?) BETWEEN ? AND ?) AND (lontags.value LIKE ?) AND (REPLACE(lontags.value, ?, ?) BETWEEN ? AND ?)

   which I believe translates from
   

   plots2/app/services/search_service.rb

   Lines 176 to 183 in b70cbef

   	user_locations = User.where('rusers.status <> 0')
   	.joins(:user_tags)
   	.where('user_tags.value LIKE ?', 'lat%')
   	.where('REPLACE(user_tags.value, "lat:", "") BETWEEN ' + coordinates["selat"].to_s + ' AND ' + coordinates["nwlat"].to_s)
   	.joins('INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id')
   	.where('lontags.value LIKE ?', 'lon%')
   	.where('REPLACE(lontags.value, "lon:", "") BETWEEN ' + coordinates["nwlng"].to_s + ' AND ' + coordinates["selng"].to_s)
   	.distinct

2. The second query:

   SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = ?

   which is already fixed in Reduced response time in nearby People search API #9940 🥳

3. The third query:

   SELECT  DISTINCT `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON `user_tags`.`uid` = `rusers`.`id` INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id WHERE (rusers.status <> ?) AND (user_tags.value LIKE ?) AND (REPLACE(user_tags.value, ?, ?) BETWEEN ? AND ?) AND (lontags.value LIKE ?) AND (REPLACE(lontags.value, ?, ?) BETWEEN ? AND ?) ORDER BY created_at DESC LIMIT ?

   This is where things get interesting. We are kind of repeating our query. with some additional params)(ORDER BY created_at DESC LIMIT ?). And I believe this is caused by
   

   plots2/app/services/search_service.rb

   Lines 232 to 234 in b70cbef

   	items.order("created_at #{order_direction}")
   	.limit(limit)
   	end

   So we need to debug our recency sort code?

4. The consequent queries

   SELECT  ? AS one FROM `user_tags` WHERE `user_tags`.`uid` = ? AND (value LIKE ?) LIMIT ?

   and

   SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = ? AND (value LIKE ?)

   ( the problematic one )

[daemon1024]

So, I think these queries are automatically performed by rails ORM to verify if returned records have these attributes or not.

Agreed, rails is probably is running it to verify against something we have triggered.
I believe it's the ordering code

plots2/app/services/search_service.rb

Lines 220 to 235 in b70cbef

	if sort_by == "recent"
	items.joins(:revisions).where("node_revisions.status = 1")\
	.order("node_revisions.timestamp #{order_direction}")
	.distinct
	elsif sort_by == "content"
	ids = items.collect(&:id).uniq || []
	User.select('`rusers`.*, count(`node`.uid) AS ord')
	.joins(:node)
	.where('rusers.id IN (?)', ids)
	.group('`node`.`uid`')
	.order("ord #{order_direction}")
	else
	items.order("created_at #{order_direction}")
	.limit(limit)
	end
	end

What do you think @17sushmita ?

Also can you provide me a full stack trace? Like fuller than you share :P which includes all the queries triggered by this service ( like select distinct ones )

Thank you.

[17sushmita]

There were 4 types of queries executed by this service -

• First one is the whole rails query above looping
• Second query is the problematic one which is fixed now Reduced response time in nearby People search API #9940
• Third is again same first rails query with all the additional queries after looping.
• Fourth is the queries triggered by rails automatically.

Basically the looping part is breaking our whole single rails query into multiple and so adding redundancy because after looping the previous query is executed again with all the additional queries after the looping.

Full stack trace of original queries triggered by this service before fixing(I have placed ? in place of actual user ids and in the last type of queries to maintain the pattern of 4 queries on the same user I have placed dummy user ids in place of original ones)-
https://gist.github.com/17sushmita/54fbb31b064d9f643fe58ddc41d616c4
(pretty long so sharing as gist)

After the change in #9940, the second query is fixed and we have a single query for first, second(fixed one) and third so now we have only two types of queries-

• First one being the whole rails query executed by us in code.
• Second one is the 4 query on each user triggered by rails automatically which I mentioned above-

This is the full stack trace of queries executed by the service after making the change. (I have placed some dummy user ids in place of actual user ids.)

  User Load (3763.5ms)  SELECT  DISTINCT `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON `user_tags`.`uid` = 
 `rusers`.`id` INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id WHERE (rusers.status <> 0) AND (user_tags.value 
  LIKE 'lat%') AND (REPLACE(user_tags.value, "lat:", "") BETWEEN 23.40276490540795 AND 55.3791104480105) AND 
  (lontags.value LIKE 'lon%') AND (REPLACE(lontags.value, "lon:", "") BETWEEN -128.67187500000003 AND 178.76953125) 
  AND (user_tags.value <> "location:blurred") ORDER BY created_at DESC LIMIT 5
  
  UserTag Load (260.6ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'lat:%')
  UserTag Load (50.4ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'lon:%')
  UserTag Exists (26.5ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (63.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1000 AND (value LIKE 'location:%')
  UserTag Load (50.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'lat:%')
  UserTag Load (55.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'lon:%')
  UserTag Exists (24.3ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (52.8ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1001 AND (value LIKE 'location:%')
  UserTag Load (45.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'lat:%')
  UserTag Load (54.7ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'lon:%')
  UserTag Exists (22.6ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (61.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1002 AND (value LIKE 'location:%')
  UserTag Load (53.7ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'lat:%')
  UserTag Load (52.1ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'lon:%')
  UserTag Exists (22.8ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (53.6ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1003 AND (value LIKE 'location:%')
  UserTag Load (52.9ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'lat:%')
  UserTag Load (57.9ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'lon:%')
  UserTag Exists (19.2ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (63.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 1004 AND (value LIKE 'location:%')

[daemon1024]

Are you sure about

This is the full stack trace of queries executed by the service after making the change. (I have placed some dummy user ids in place of actual user ids.)

the trace below this being full?

I think there should be a few other relevant queries above it.
Since the trace you are sharing starts with ORDER BY created_at DESC LIMIT 5 and I believe it shouldn't be triggered until the end of the function.

Let me know if I am in the wrong.

Rest, I have understood your point regarding looping.

[daemon1024]

To confirm my hypothesis, maybe we can comment out

plots2/app/services/search_service.rb

Lines 218 to 235 in b70cbef

	# sort users by their recent activities if the sort_by==recent
	if sort_by == "recent"
	items.joins(:revisions).where("node_revisions.status = 1")\
	.order("node_revisions.timestamp #{order_direction}")
	.distinct
	elsif sort_by == "content"
	ids = items.collect(&:id).uniq || []
	User.select('`rusers`.*, count(`node`.uid) AS ord')
	.joins(:node)
	.where('rusers.id IN (?)', ids)
	.group('`node`.`uid`')
	.order("ord #{order_direction}")
	else
	items.order("created_at #{order_direction}")
	.limit(limit)
	end
	end

this part and check the query logs again.

[17sushmita]

the trace below this being full?

Yes, for the parameters in this URL - http://publiclab.org/api/srch/nearbyPeople?nwlat=55.3791104480105&selat=23.40276490540795&nwlng=-128.67187500000003&selng=178.76953125 we are not passing any order direction so it goes to the default i.e else case -

plots2/app/services/search_service.rb

Lines 231 to 234 in b70cbef

	else
	items.order("created_at #{order_direction}")
	.limit(limit)
	end

and I also tried printing the order_direction, it was DESC by default this is why we have ORDER BY created_at DESC

I tried commenting out the sorting part and the current code looks like this -

  def tagNearbyPeople(coordinates, tag, field, period = nil, sort_by = nil, order_direction = nil, limit = 10)
    raise("Must contain all four coordinates") if coordinates["nwlat"].nil?
    raise("Must contain all four coordinates") if coordinates["nwlng"].nil?
    raise("Must contain all four coordinates") if coordinates["selat"].nil?
    raise("Must contain all four coordinates") if coordinates["selng"].nil?

    raise("Must be a float") unless coordinates["nwlat"].is_a? Float
    raise("Must be a float") unless coordinates["nwlng"].is_a? Float
    raise("Must be a float") unless coordinates["selat"].is_a? Float
    raise("Must be a float") unless coordinates["selng"].is_a? Float

    raise("If 'from' is not null, must contain date") if period["from"] && !(period["from"].is_a? Date)
    raise("If 'to' is not null, must contain date") if period["to"] && !(period["to"].is_a? Date)

    user_locations = User.where('rusers.status <> 0')
                         .joins(:user_tags)
                         .where('user_tags.value LIKE ?', 'lat%')
                         .where('REPLACE(user_tags.value, "lat:", "") BETWEEN ' + coordinates["selat"].to_s + ' AND ' + coordinates["nwlat"].to_s)
                         .joins('INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id')
                         .where('lontags.value LIKE ?', 'lon%')
                         .where('REPLACE(lontags.value, "lon:", "") BETWEEN ' + coordinates["nwlng"].to_s + ' AND ' + coordinates["selng"].to_s)
                         .distinct

    if tag.present?
      if field.present? && field == 'node_tag'
        tids = Tag.where("term_data.name = ?", tag).collect(&:tid).uniq || []
        uids = TagSelection.where('tag_selections.tid IN (?)', tids).collect(&:user_id).uniq || []
      else
        uids = User.where('rusers.status <> 0')
                   .joins(:user_tags)
                   .where('user_tags.value = ?', tag)
                   .where(id: user_locations.select("rusers.id"))
                   .limit(limit)
                   .collect(&:id).uniq || []
      end
      user_locations = user_locations.where('rusers.id IN (?)', uids).distinct
    end

    items = user_locations

    # selects the items whose node_tags don't have the location:blurred tag
    items = items.where('user_tags.value <> "location:blurred"')

    # Here we use period["from"] and period["to"] in the query only if they have been specified,
    # so we avoid to join revision table
    if !period["from"].nil? || !period["to"].nil?
      items = items.joins(:revisions).where("node_revisions.status = 1")\
                   .distinct
      items = items.where('node_revisions.timestamp > ' + period["from"].to_time.to_i.to_s) unless period["from"].nil?
      items = items.where('node_revisions.timestamp < ' + period["to"].to_time.to_i.to_s) unless period["to"].nil?
    # ----------------------Modified Code-----------------------------------#
    # # # # added else to return the result and limit to limit the result    
    else
      items.order('created_at DESC').limit(limit)
    end

    # sort users by their recent activities if the sort_by==recent

    # if sort_by == "recent"
    #   items.joins(:revisions).where("node_revisions.status = 1")\
    #        .order("node_revisions.timestamp #{order_direction}")
    #        .distinct
    # elsif sort_by == "content"
    #   ids = items.collect(&:id).uniq || []
    #   User.select('`rusers`.*, count(`node`.uid) AS ord')
    #       .joins(:node)
    #       .where('rusers.id IN (?)', ids)
    #       .group('`node`.`uid`')
    #       .order("ord #{order_direction}")
    # else
    #   items.order("created_at #{order_direction}")
    #         .limit(limit)
    # end
    # ---------------------- End of Modified Code-----------------------------------#

  end

I added the else block because it wasn't returning any data as it didn't go to the if case and we didn't have a default case. Also, without the limit query it resulted all the users from the resulting query (which were too many) so took a really long time (because of the automatic 4 queries on each user).
Also, after limiting, resulting users were different from previous ones because we don't have any sorting so the results were in random order

Following is the full query stack trace of the above code-

  User Load (7.9ms)  SELECT  DISTINCT `rusers`.* FROM `rusers` INNER JOIN `user_tags` ON 
  `user_tags`.`uid` = `rusers`.`id` INNER JOIN user_tags AS lontags ON lontags.uid = rusers.id 
  WHERE (rusers.status <> 0) AND (user_tags.value LIKE 'lat%') AND (REPLACE(user_tags.value, 
  "lat:", "") BETWEEN 23.40276490540795 AND 55.3791104480105) AND (lontags.value LIKE 'lon%') 
  AND (REPLACE(lontags.value, "lon:", "") BETWEEN -128.67187500000003 AND 178.76953125) AND 
  (user_tags.value <> "location:blurred") LIMIT 5
  
  UserTag Load (38.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2000 AND (value LIKE 'lat:%')
  UserTag Load (45.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2000 AND (value LIKE 'lon:%')
  UserTag Exists (0.4ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 2000 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (41.1ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2000 AND (value LIKE 'location:%')
  UserTag Load (43.9ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2001 AND (value LIKE 'lat:%')
  UserTag Load (33.7ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2001 AND (value LIKE 'lon:%')
  UserTag Exists (1.1ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 2001 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (47.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2001 AND (value LIKE 'location:%')
  UserTag Load (38.3ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2002 AND (value LIKE 'lat:%')
  UserTag Load (43.2ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2002 AND (value LIKE 'lon:%')
  UserTag Exists (0.7ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 2002 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (38.1ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2002 AND (value LIKE 'location:%')
  UserTag Load (34.9ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2003 AND (value LIKE 'lat:%')
  UserTag Load (37.4ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2003 AND (value LIKE 'lon:%')
  UserTag Exists (0.9ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 2003 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (47.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2003 AND (value LIKE 'location:%')
  UserTag Load (48.0ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2004 AND (value LIKE 'lat:%')
  UserTag Load (37.9ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2004 AND (value LIKE 'lon:%')
  UserTag Exists (0.8ms)  SELECT  1 AS one FROM `user_tags` WHERE `user_tags`.`uid` = 2004 AND (value LIKE 'location:%') LIMIT 1
  UserTag Load (43.5ms)  SELECT `user_tags`.* FROM `user_tags` WHERE `user_tags`.`uid` = 2004 AND (value LIKE 'location:%')

[daemon1024]

Ohh. Thank You. That makes sense. I will try to look into it once more.

[17sushmita]

I think there should be a few other relevant queries above it.
Since the trace you are sharing starts with ORDER BY created_at DESC LIMIT 5 and I believe it shouldn't be triggered until the end of the function.

Addressing this concern,
Rails’ ActiveRecord, have lazy loading built-in which allows to defer querying associations until the moment they’re needed.
Before fixing, the looping part needed the result of our first query that is why all the queries above looping were executed first.
Then the whole query was needed at the time of returning the records from the function, so it was executed once again and this time it had some additional queries(ordering etc)

[daemon1024]

Interesting. This is first time me diving into ruby this deep so these things are quite fascinating to me 🚀

Thanks for following up 🙌

[Tlazypanda]

Hey @daemon1024 and @17sushmita whoaa that's some awesome collaborative detective work right there 🕵️‍♀️ 🔥 I see @17sushmita you have already opened a PR for making one of the queries faster which looks greatt! I will revert on it as soon as I can get some more idea on this issue and checkout the queries ✌️

I am trying to check this endpoint out locally but don't have datapoints for this @jywarren can I get a sql dump from unstable with the query datapoints to test out or any other testing strategy that @17sushmita you followed that might be helpful?

Thank you all! ❤️ ❤️ Some amazing work right here!!

[17sushmita]

Hi @Tlazypanda, I imported only few tables from the db - rusers and user_tags and tested the endpoint. The db is really huuuuge 😮 so it was taking really long. While importing, I used this tool - https://www.ivarch.com/programs/pv.shtml to track the progress of how much data has been imported and how much time is remaining coz it was taking really long 😅 .

And also, before importing, I was testing by creating a few users with nearby location and then querying with parameters around those location.

[jywarren]

Re-opening, it's a LOT faster now! about 1-2 seconds:

https://publiclab.org/map#14/40.7110947680185/-73.96068613976242

generates: https://publiclab.org/api/srch/nearbyPeople?nwlat=40.73652850646351&selat=40.68565131103966&nwlng=-74.00051157921554&selng=-73.92086070030929

returns:

{"items":[{"doc_id":742836,"doc_type":"PLACES","doc_url":"/profile/LESBreathe","doc_title":"LESBreathe","doc_score":null,"doc_author":null,"doc_image_url":"/public/system/users/photos/000/742/836/thumb/lesbreath_logo.png","latitude":"40.71","longitude":"-73.97","blurred":true,"category":"PLACES","place_name":null,"created_at":"2021-03-01T22:41:48.000Z","time_since":null,"comment_count":null}],"srchParams":{"query":null,"seq":null,"tag":null,"nwlat":40.73652850646351,"nwlng":-74.00051157921554,"selat":40.68565131103966,"selng":-73.92086070030929}}

(for example)

But I don't see this user displayed. Do you know why?

[daemon1024]

Cz blurred being true?

---

simplescreenrecorder-2021-07-28_02.57.58.mp4

Observed a weird thing. The user here has blurred set to true, but we can see them at some particular zoom level 🤔