Quantify the time we're spending doing background permacache mutations

In the permacachezlib patch we want to be able to time how long we're spending
doing the compression and serialisation. There are times that we use the
permacache in the AMQP worker thread, which can't get to g, so it can't get to
g.stats. The solution is probably to just stop using the permacache in this way,
but first we'll want to know what it would cost us to start doing these
operations in the foreground.

Most permacache mutations occur in queue processes where it shouldn't matter,
but there are cases like deletions and inboxes where they occur in-request. So
knowing the costs of foregrounding them is important.

Note that this causes the timers to occur in the worker thread. That has known
to be safe in the past, but it's been a while since the support was used.

r2/r2/lib/db/queries.py

@@ -51,6 +51,7 @@ from r2.lib.utils import in_chunks, is_subdomain, SimpleSillyStub
 import cPickle as pickle
 
 from datetime import datetime
+from functools import partial
 from time import mktime
 import pytz
 import itertools
@@ -945,19 +946,31 @@ def add_queries(queries, insert_items=None, delete_items=None, foreground=False)
     """Adds multiple queries to the query queue. If insert_items or
        delete_items is specified, the query may not need to be
        recomputed against the database."""
+
+    # we want to time how long background permacache mutations take, so we need
+    # to wrap g.stats up so that we can use it on the other thread
+    def mutation_timer(stats, timer_name, fn, *a):
+        def _fn():
+            with stats.get_timer(timer_name):
+                return fn(*a)
+        return _fn
+    mutation_timer = partial(mutation_timer, g.stats)
+
     for q in queries:
         if insert_items and q.can_insert():
             log.debug("Inserting %s into query %s" % (insert_items, q))
             if foreground:
                 q.insert(insert_items)
             else:
-                worker.do(q.insert, insert_items)
+                worker.do(mutation_timer('permacache.background.insert',
+                                         q.insert, insert_items))
         elif delete_items and q.can_delete():
             log.debug("Deleting %s from query %s" % (delete_items, q))
             if foreground:
                 q.delete(delete_items)
             else:
-                worker.do(q.delete, delete_items)
+                worker.do(mutation_timer('permacache.background.delete',
+                                         q.delete, delete_items))
         else:
             raise Exception("Cannot update query %r!" % (q,))