912484 - Can you cache this addons query?

Status: RESOLVED FIXED

(Marketplace Graveyard :: Code Quality, defect, P2)

Description

[Sheeri Cabral [:sheeri]]

as per https://bugzilla.mozilla.org/show_bug.cgi?id=862889#c11:

This query is looking for collections where the application_id is either NULL or 1, so it's looking for a special kind of application, very likely. Perhaps this query could be run once every 5 minutes and cached, and then a query once every 23 seconds could be run against the cache (whether the cache is a different db table, or in memcached or something?).

Recommendation: see if this query can be run less frequently. It currently runs about once every 23 seconds.

# Time range: 2013-08-19 14:50:57 to 19:54:39
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0     747
# Exec time      6   6262s      2s     42s      8s     26s      8s      5s
# Lock time      0    51ms    41us     1ms    68us    84us    53us    63us
# Rows sent      0     747       1       1       1       1       0       1
# Rows examine   7   1.14G   1.56M   1.56M   1.56M   1.53M       0   1.53M
# Query size     0 181.15k     246     253  248.32  246.02    3.50  246.02

 SELECT COUNT(*) FROM `collections` LEFT OUTER JOIN `applications` ON (`collections`.`application_id` = `applications`.`id`) WHERE ("pt-pt"="pt-pt" AND `collections`.`listed` = 1  AND (`collections`.`application_id` = 1  OR `applications`.`id` IS NULL))\G

The EXPLAIN uses the primary key on the applications table, but the "listed" key for the collections table. The "listed" key is used, which is appropriate because it's a clustered index so it has application_id within it. Unfortunately, it only lessens the filter to about half the table, because the split is about even:

MariaDB [addons_mozilla_org]> select count(*),listed from collections group by listed;
+----------+--------+
| count(*) | listed |
+----------+--------+
|  1558490 |      0 |
|  1519169 |      1 |
+----------+--------+
2 rows in set (1.10 sec)

Unfortunately this query is as good as it is going to get, without major changes (like, say, making a collections_listed and a collections_unlisted table and changing all the code to match that, and then this query can select from the appropriate table).

Comment 1

[Jeremy Orem [:oremj]]

This query has recently ramped up to 230+ calls per minute and is starting to affect full application performance. Can we look in to optimizing this?

Comment 2

[Jeremy Orem [:oremj]]

It looks like the only purpose of this query is to display "page x of y show x-y of z collections" at the bottom of the listing. I assume no one is paging through all 1 million+ collections, so we could:

1) Cache the count(*) query for 5+ minutes and not care about invalidation.
2) Do google style pagination i.e., no overall page count, just keep allowing the user to click next.

Comment 3

[Wil Clouser [:clouserw]]

Caching seems like an easy win.  Allen - what do you think?  We could get this in for the push tomorrow if it's a 1 line thing to cache

Comment 4

[Allen Short [:ashort]]

Since this is a COUNT() query, django-cache-machine should be caching this based on the CACHE_COUNT_TIMEOUT setting, which is set to 60 in lib.settings_base -- I'm having difficulty seeing how this could be running multiple times per second. Looking for ways around this currently.

Comment 5

[Allen Short [:ashort]]

https://github.com/mozilla/zamboni/commit/5107d66

Comment 6

[Sheeri Cabral [:sheeri]]

I gather from the commit that the django-cache-machine was not caching this before? 

Also, can you give a heads-up when this is pushed out? I'd like to check the db to make sure the query load has gone down.

Comment 7

[Allen Short [:ashort]]

django-cache-machine has a global setting for caching COUNT() queries, set to 60 seconds. Rather than change that, I added a separate explicit cache step for this particular query.

Comment 8

[Sheeri Cabral [:sheeri]]

OK, I see that you set it to 300 seconds, or 5 minutes. 

But how does that account for the fact that it was running multiple times per second when the cache time was 60 seconds? I'm unclear on why this would work, if the regular cache time of 60 seconds isn't working. :(