vote_q: Track how long various parts of vote processing take.

r2/r2/lib/db/queries.py

@@ -35,6 +35,7 @@ from r2.models.query_cache import (cached_query, merged_cached_query,
 from r2.models.query_cache import UserQueryCache, SubredditQueryCache
 from r2.models.query_cache import ThingTupleComparator
 from r2.models.last_modified import LastModified
+from r2.lib.utils import SimpleSillyStub
 
 import cPickle as pickle
 
@@ -49,6 +50,7 @@ query_cache = g.permacache
 log = g.log
 make_lock = g.make_lock
 worker = amqp.worker
+stats = g.stats
 
 precompute_limit = 1000
 
@@ -796,10 +798,13 @@ def new_subreddit(sr):
     amqp.add_item('new_subreddit', sr._fullname)
 
 
-def new_vote(vote, foreground=False):
+def new_vote(vote, foreground=False, timer=None):
     user = vote._thing1
     item = vote._thing2
 
+    if timer is None:
+        timer = SimpleSillyStub()
+
     if not isinstance(item, (Link, Comment)):
         return
 
@@ -828,6 +833,8 @@ def new_vote(vote, foreground=False):
                     results.append(get_domain_links(domain, sort, "all"))
 
         add_queries(results, insert_items = item, foreground=foreground)
+
+    timer.intermediate("permacache")
     
     if isinstance(item, Link):
         # must update both because we don't know if it's a changed
@@ -1335,18 +1342,23 @@ def get_likes(user, items):
 
     return res
 
-def handle_vote(user, thing, dir, ip, organic, cheater=False, foreground=False):
+def handle_vote(user, thing, dir, ip, organic,
+                cheater=False, foreground=False, timer=None):
+    if timer is None:
+        timer = SimpleSillyStub()
+
     from r2.lib.db import tdb_sql
     from sqlalchemy.exc import IntegrityError
     try:
-        v = Vote.vote(user, thing, dir, ip, organic, cheater = cheater)
+        v = Vote.vote(user, thing, dir, ip, organic, cheater = cheater,
+                      timer=timer)
     except (tdb_sql.CreationError, IntegrityError):
         g.log.error("duplicate vote for: %s" % str((user, thing, dir)))
         return
 
     timestamps = []
     if isinstance(thing, Link):
-        new_vote(v, foreground=foreground)
+        new_vote(v, foreground=foreground, timer=timer)
 
         #update the modified flags
         if user._id == thing.author_id:
@@ -1369,9 +1381,12 @@ def handle_vote(user, thing, dir, ip, organic, cheater=False, foreground=False):
             #update sup listings
             sup.add_update(user, 'commented')
 
+    timer.intermediate("sup")
+
     for timestamp in timestamps:
         set_last_modified(user, timestamp.lower())
     LastModified.touch(user._fullname, timestamps)
+    timer.intermediate("last_modified")
 
 
 def process_votes(qname, limit=0):
@@ -1379,21 +1394,27 @@ def process_votes(qname, limit=0):
 
     @g.stats.amqp_processor(qname)
     def _handle_vote(msg):
+        timer = stats.get_timer("service_time." + qname)
+        timer.start()
+
         #assert(len(msgs) == 1)
         r = pickle.loads(msg.body)
 
         uid, tid, dir, ip, organic, cheater = r
         voter = Account._byID(uid, data=True)
         votee = Thing._by_fullname(tid, data = True)
+        timer.intermediate("preamble")
+
         if isinstance(votee, Comment):
             update_comment_votes([votee])
+            timer.intermediate("update_comment_votes")
 
         # I don't know how, but somebody is sneaking in votes
         # for subreddits
         if isinstance(votee, (Link, Comment)):
             print (voter, votee, dir, ip, organic, cheater)
             handle_vote(voter, votee, dir, ip, organic,
-                        cheater = cheater, foreground=True)
+                        cheater = cheater, foreground=True, timer=timer)
 
     amqp.consume_items(qname, _handle_vote, verbose = False)
 

r2/r2/models/vote.py

@@ -28,6 +28,7 @@ from r2.lib.db import tdb_cassandra
 from r2.lib.db.tdb_cassandra import TdbException, ASCII_TYPE, UTF8_TYPE
 from r2.lib.utils._utils import flatten
 from r2.lib.db.sorts import epoch_seconds
+from r2.lib.utils import SimpleSillyStub
 
 from account import Account
 from link import Link, Comment
@@ -239,11 +240,15 @@ class Vote(MultiRelation('vote',
     _defaults = {'organic': False}
 
     @classmethod
-    def vote(cls, sub, obj, dir, ip, organic = False, cheater = False):
+    def vote(cls, sub, obj, dir, ip, organic = False, cheater = False,
+             timer=None):
         from admintools import valid_user, valid_thing, update_score
         from r2.lib.count import incr_sr_count
         from r2.lib.db import queries
 
+        if timer is None:
+            timer = SimpleSillyStub()
+
         sr = obj.subreddit_slow
         kind = obj.__class__.__name__.lower()
         karma = sub.karma(kind, sr)
@@ -256,6 +261,8 @@ class Vote(MultiRelation('vote',
         oldvote = rel._fast_query(sub, obj, ['-1', '0', '1']).values()
         oldvote = filter(None, oldvote)
 
+        timer.intermediate("pg_read_vote")
+
         amount = 1 if dir is True else 0 if dir is None else -1
 
         is_new = False
@@ -286,6 +293,8 @@ class Vote(MultiRelation('vote',
 
         v._commit()
 
+        timer.intermediate("pg_write_vote")
+
         up_change, down_change = score_changes(amount, oldamount)
 
         if not (is_new and obj.author_id == sub._id and amount == 1):
@@ -293,22 +302,27 @@ class Vote(MultiRelation('vote',
             # vote, because we checked it in with _ups == 1
             update_score(obj, up_change, down_change,
                          v, old_valid_thing)
+            timer.intermediate("pg_update_score")
 
         if v.valid_user:
             author = Account._byID(obj.author_id, data=True)
             author.incr_karma(kind, sr, up_change - down_change)
+            timer.intermediate("pg_incr_karma")
 
         #update the sr's valid vote count
         if is_new and v.valid_thing and kind == 'link':
             if sub._id != obj.author_id:
                 incr_sr_count(sr)
+            timer.intermediate("incr_sr_counts")
 
         # now write it out to Cassandra. We'll write it out to both
         # this way for a while
         CassandraVote._copy_from(v)
         VotesByAccount.copy_from(v)
+        timer.intermediate("cassavotes")
 
         queries.changed(v._thing2, True)
+        timer.intermediate("changed")
 
         return v