Merge pull request #8678 from cpennington/improve-structure-cache-metrics

Improve structure cache metrics

common/lib/xmodule/xmodule/modulestore/split_mongo/mongo_connection.py

@@ -21,7 +21,6 @@ from mongodb_proxy import autoretry_read, MongoProxy
 from xmodule.exceptions import HeartbeatFailure
 from xmodule.modulestore import BlockData
 from xmodule.modulestore.split_mongo import BlockKey
-import dogstats_wrapper as dog_stats_api
 
 
 new_contract('BlockData', BlockData)
@@ -42,9 +41,10 @@ class Tagger(object):
     An object used by :class:`QueryTimer` to allow timed code blocks
     to add measurements and tags to the timer.
     """
-    def __init__(self):
+    def __init__(self, default_sample_rate):
         self.added_tags = []
         self.measures = []
+        self.sample_rate = default_sample_rate
 
     def measure(self, name, size):
         """
@@ -109,7 +109,7 @@ class QueryTimer(object):
             metric_name: The name used to aggregate all of these metrics.
             course_context: The course which the query is being made for.
         """
-        tagger = Tagger()
+        tagger = Tagger(self._sample_rate)
         metric_name = "{}.{}".format(self._metric_base, metric_name)
 
         start = time()
@@ -125,24 +125,24 @@ class QueryTimer(object):
                     size,
                     timestamp=end,
                     tags=[tag for tag in tags if not tag.startswith('{}:'.format(metric_name))],
-                    sample_rate=self._sample_rate,
+                    sample_rate=tagger.sample_rate,
                 )
             dog_stats_api.histogram(
                 '{}.duration'.format(metric_name),
                 end - start,
                 timestamp=end,
                 tags=tags,
-                sample_rate=self._sample_rate,
+                sample_rate=tagger.sample_rate,
             )
             dog_stats_api.increment(
                 metric_name,
                 timestamp=end,
                 tags=tags,
-                sample_rate=self._sample_rate,
+                sample_rate=tagger.sample_rate,
             )
 
 
-TIMER = QueryTimer(__name__, 0.001)
+TIMER = QueryTimer(__name__, 0.01)
 
 
 def structure_from_mongo(structure, course_context=None):
@@ -222,33 +222,42 @@ class CourseStructureCache(object):
         except InvalidCacheBackendError:
             self.no_cache_found = True
 
-    def get(self, key):
+    def get(self, key, course_context=None):
         """Pull the compressed, pickled struct data from cache and deserialize."""
         if self.no_cache_found:
             return None
 
-        compressed_pickled_data = self.cache.get(key)
-        if compressed_pickled_data is None:
-            return None
-        return pickle.loads(zlib.decompress(compressed_pickled_data))
+        with TIMER.timer("CourseStructureCache.get", course_context) as tagger:
+            compressed_pickled_data = self.cache.get(key)
+            tagger.tag(from_cache=str(compressed_pickled_data is not None).lower())
 
-    def set(self, key, structure):
+            if compressed_pickled_data is None:
+                # Always log cache misses, because they are unexpected
+                tagger.sample_rate = 1
+                return None
+
+            tagger.measure('compressed_size', len(compressed_pickled_data))
+
+            pickled_data = zlib.decompress(compressed_pickled_data)
+            tagger.measure('uncompressed_size', len(pickled_data))
+
+            return pickle.loads(pickled_data)
+
+    def set(self, key, structure, course_context=None):
         """Given a structure, will pickle, compress, and write to cache."""
         if self.no_cache_found:
             return None
 
-        pickled_data = pickle.dumps(structure, pickle.HIGHEST_PROTOCOL)
-        # 1 = Fastest (slightly larger results)
-        compressed_pickled_data = zlib.compress(pickled_data, 1)
+        with TIMER.timer("CourseStructureCache.set", course_context) as tagger:
+            pickled_data = pickle.dumps(structure, pickle.HIGHEST_PROTOCOL)
+            tagger.measure('uncompressed_size', len(pickled_data))
 
-        # record compressed course structure sizes
-        dog_stats_api.histogram(
-            'compressed_course_structure.size',
-            len(compressed_pickled_data),
-            tags=[key]
-        )
-        # Stuctures are immutable, so we set a timeout of "never"
-        self.cache.set(key, compressed_pickled_data, None)
+            # 1 = Fastest (slightly larger results)
+            compressed_pickled_data = zlib.compress(pickled_data, 1)
+            tagger.measure('compressed_size', len(compressed_pickled_data))
+
+            # Stuctures are immutable, so we set a timeout of "never"
+            self.cache.set(key, compressed_pickled_data, None)
 
 
 class MongoConnection(object):
@@ -311,14 +320,19 @@ class MongoConnection(object):
         with TIMER.timer("get_structure", course_context) as tagger_get_structure:
             cache = CourseStructureCache()
 
-            structure = cache.get(key)
-            tagger_get_structure.tag(from_cache='true' if structure else 'false')
+            structure = cache.get(key, course_context)
+            tagger_get_structure.tag(from_cache=str(bool(structure)).lower())
             if not structure:
+                # Always log cache misses, because they are unexpected
+                tagger_get_structure.sample_rate = 1
+
                 with TIMER.timer("get_structure.find_one", course_context) as tagger_find_one:
                     doc = self.structures.find_one({'_id': key})
                     tagger_find_one.measure("blocks", len(doc['blocks']))
                     structure = structure_from_mongo(doc, course_context)
-                cache.set(key, structure)
+                    tagger_find_one.sample_rate = 1
+
+                cache.set(key, structure, course_context)
 
             return structure