diff --git a/common/lib/xmodule/xmodule/modulestore/split_mongo/mongo_connection.py b/common/lib/xmodule/xmodule/modulestore/split_mongo/mongo_connection.py index fc179c81ba..abe9fd1543 100644 --- a/common/lib/xmodule/xmodule/modulestore/split_mongo/mongo_connection.py +++ b/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