From 3a5ad7dbd5a375023c96ee65c901f8be5ab02341 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 9 Feb 2015 17:55:56 +0000 Subject: Performance counters for database transaction names --- synapse/storage/_base.py | 32 +++++++++++++++++++++++++++++++- 1 file changed, 31 insertions(+), 1 deletion(-) (limited to 'synapse/storage/_base.py') diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 310ee0104c..bcb03cbdcb 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -39,6 +39,7 @@ class LoggingTransaction(object): passed to the constructor. Adds logging to the .execute() method.""" __slots__ = ["txn", "name"] + def __init__(self, txn, name): object.__setattr__(self, "txn", txn) object.__setattr__(self, "name", name) @@ -88,6 +89,8 @@ class SQLBaseStore(object): self._previous_txn_total_time = 0 self._current_txn_total_time = 0 self._previous_loop_ts = 0 + self._txn_perf_counters = {} + self._previous_txn_perf_counters = {} def start_profiling(self): self._previous_loop_ts = self._clock.time_msec() @@ -103,7 +106,29 @@ class SQLBaseStore(object): ratio = (curr - prev)/(time_now - time_then) - logger.info("Total database time: %.3f%%", ratio * 100) + txn_counters = [] + for name, (count, cum_time) in self._txn_perf_counters.items(): + prev_count, prev_time = self._previous_txn_perf_counters.get( + name, (0,0) + ) + txn_counters.append(( + (cum_time - prev_time) / (time_now - time_then), + count - prev_count, + name + )) + + self._previous_txn_perf_counters = dict(self._txn_perf_counters) + + txn_counters.sort(reverse=True) + top_three_counters = ", ".join( + "%s(%d): %.3f%%" % (name, count, 100 * ratio) + for ratio, count, name in txn_counters[:3] + ) + + logger.info( + "Total database time: %.3f%% {%s}", + ratio * 100, top_three_counters + ) self._clock.looping_call(loop, 10000) @@ -139,6 +164,11 @@ class SQLBaseStore(object): self._current_txn_total_time += end - start + count, cum_time = self._txn_perf_counters.get(name, (0,0)) + count += 1 + cum_time += end - start + self._txn_perf_counters[name] = (count, cum_time) + with PreserveLoggingContext(): result = yield self._db_pool.runInteraction( inner_func, *args, **kwargs -- cgit 1.4.1 From 347b497db0355fe4e26ae3a51967aa91bec090d3 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 9 Feb 2015 17:57:09 +0000 Subject: Formatting --- synapse/storage/_base.py | 1 - 1 file changed, 1 deletion(-) (limited to 'synapse/storage/_base.py') diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index bcb03cbdcb..45f4b994eb 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -39,7 +39,6 @@ class LoggingTransaction(object): passed to the constructor. Adds logging to the .execute() method.""" __slots__ = ["txn", "name"] - def __init__(self, txn, name): object.__setattr__(self, "txn", txn) object.__setattr__(self, "name", name) -- cgit 1.4.1 From 0c4536da8fe75a207052fb558414b4408aa857ec Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 9 Feb 2015 18:06:31 +0000 Subject: Use the transaction 'desc' rather than 'name', increment the txn_ids in txn names --- synapse/storage/_base.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'synapse/storage/_base.py') diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 45f4b994eb..5ddd410607 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -140,7 +140,7 @@ class SQLBaseStore(object): with LoggingContext("runInteraction") as context: current_context.copy_to(context) start = time.time() * 1000 - txn_id = SQLBaseStore._TXN_ID + txn_id = self._TXN_ID # We don't really need these to be unique, so lets stop it from # growing really large. @@ -163,10 +163,10 @@ class SQLBaseStore(object): self._current_txn_total_time += end - start - count, cum_time = self._txn_perf_counters.get(name, (0,0)) + count, cum_time = self._txn_perf_counters.get(desc, (0,0)) count += 1 cum_time += end - start - self._txn_perf_counters[name] = (count, cum_time) + self._txn_perf_counters[desc] = (count, cum_time) with PreserveLoggingContext(): result = yield self._db_pool.runInteraction( -- cgit 1.4.1 From d7c7efb691bd726ec3e8879e289546fbcfd7dabd Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 10 Feb 2015 14:50:53 +0000 Subject: Add performance counters for different stages of loading events --- synapse/storage/_base.py | 84 ++++++++++++++++++++++++++++++++++-------------- 1 file changed, 60 insertions(+), 24 deletions(-) (limited to 'synapse/storage/_base.py') diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 5ddd410607..c79399fe5e 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -77,6 +77,43 @@ class LoggingTransaction(object): sql_logger.debug("[SQL time] {%s} %f", self.name, end - start) +class PerformanceCounters(object): + def __init__(self): + self.current_counters = {} + self.previous_counters = {} + + def update(self, key, start_time, end_time=None): + if end_time is None: + end_time = time.time() * 1000; + duration = end_time - start_time + count, cum_time = self.current_counters.get(key, (0, 0)) + count += 1 + cum_time += duration + self.current_counters[key] = (count, cum_time) + return end_time + + def interval(self, interval_duration, limit=3): + counters = [] + for name, (count, cum_time) in self.current_counters.items(): + prev_count, prev_time = self.previous_counters.get(name, (0, 0)) + counters.append(( + (cum_time - prev_time) / interval_duration, + count - prev_count, + name + )) + + self.previous_counters = dict(self.current_counters) + + counters.sort(reverse=True) + + top_n_counters = ", ".join( + "%s(%d): %.3f%%" % (name, count, 100 * ratio) + for ratio, count, name in txn_counters[:limit] + ) + + return top_n_counters + + class SQLBaseStore(object): _TXN_ID = 0 @@ -88,8 +125,8 @@ class SQLBaseStore(object): self._previous_txn_total_time = 0 self._current_txn_total_time = 0 self._previous_loop_ts = 0 - self._txn_perf_counters = {} - self._previous_txn_perf_counters = {} + self._txn_perf_counters = PerformanceCounters() + self._get_event_counters = PerformanceCounters() def start_profiling(self): self._previous_loop_ts = self._clock.time_msec() @@ -105,23 +142,12 @@ class SQLBaseStore(object): ratio = (curr - prev)/(time_now - time_then) - txn_counters = [] - for name, (count, cum_time) in self._txn_perf_counters.items(): - prev_count, prev_time = self._previous_txn_perf_counters.get( - name, (0,0) - ) - txn_counters.append(( - (cum_time - prev_time) / (time_now - time_then), - count - prev_count, - name - )) - - self._previous_txn_perf_counters = dict(self._txn_perf_counters) - - txn_counters.sort(reverse=True) - top_three_counters = ", ".join( - "%s(%d): %.3f%%" % (name, count, 100 * ratio) - for ratio, count, name in txn_counters[:3] + top_three_counters = self._txn_perf_counters.interval( + time_now - time_then, limit=3 + ) + + top_3_event_counters = self._get_event_counters.interval( + time_now - time_then, limit=3 ) logger.info( @@ -162,11 +188,7 @@ class SQLBaseStore(object): ) self._current_txn_total_time += end - start - - count, cum_time = self._txn_perf_counters.get(desc, (0,0)) - count += 1 - cum_time += end - start - self._txn_perf_counters[desc] = (count, cum_time) + self._txn_perf_counters.update(desc, start, end) with PreserveLoggingContext(): result = yield self._db_pool.runInteraction( @@ -566,6 +588,8 @@ class SQLBaseStore(object): "LIMIT 1 " ) + start_time = time.time() * 1000; + txn.execute(sql, (event_id,)) res = txn.fetchone() @@ -575,6 +599,8 @@ class SQLBaseStore(object): internal_metadata, js, redacted, rejected_reason = res + self._get_event_counters.update("select_event", start_time) + if allow_rejected or not rejected_reason: return self._get_event_from_row_txn( txn, internal_metadata, js, redacted, @@ -586,10 +612,18 @@ class SQLBaseStore(object): def _get_event_from_row_txn(self, txn, internal_metadata, js, redacted, check_redacted=True, get_prev_content=False): + + start_time = time.time() * 1000; + update_counter = self._get_event_counters.update + d = json.loads(js) + start_time = update_counter("decode_json", start_time) + internal_metadata = json.loads(internal_metadata) + start_time = update_counter("decode_internal", start_time) ev = FrozenEvent(d, internal_metadata_dict=internal_metadata) + start_time = update_counter("build_frozen_event", start_time) if check_redacted and redacted: ev = prune_event(ev) @@ -605,6 +639,7 @@ class SQLBaseStore(object): if because: ev.unsigned["redacted_because"] = because + start_time = update_counter("redact_event", start_time) if get_prev_content and "replaces_state" in ev.unsigned: prev = self._get_event_txn( @@ -614,6 +649,7 @@ class SQLBaseStore(object): ) if prev: ev.unsigned["prev_content"] = prev.get_dict()["content"] + start_time = update_counter("get_prev_content", start_time) return ev -- cgit 1.4.1 From fda4422bc9d9f2974d7185011d6d905eea372b09 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 10 Feb 2015 14:54:07 +0000 Subject: Fix pyflakes --- synapse/storage/_base.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'synapse/storage/_base.py') diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index c79399fe5e..36455ef93c 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -108,7 +108,7 @@ class PerformanceCounters(object): top_n_counters = ", ".join( "%s(%d): %.3f%%" % (name, count, 100 * ratio) - for ratio, count, name in txn_counters[:limit] + for ratio, count, name in counters[:limit] ) return top_n_counters @@ -151,8 +151,8 @@ class SQLBaseStore(object): ) logger.info( - "Total database time: %.3f%% {%s}", - ratio * 100, top_three_counters + "Total database time: %.3f%% {%s} {%s}", + ratio * 100, top_three_counters, top_3_event_counters ) self._clock.looping_call(loop, 10000) -- cgit 1.4.1 From b085fac7353e1cd395b89f9334c8273a8e996f48 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Tue, 10 Feb 2015 16:30:48 +0000 Subject: Code-style fixes --- synapse/handlers/presence.py | 4 +++- synapse/handlers/register.py | 13 ++++++++----- synapse/push/__init__.py | 8 +++++--- synapse/push/baserules.py | 11 ++++++----- synapse/push/rulekinds.py | 12 ++++++------ synapse/python_dependencies.py | 6 ++++-- synapse/rest/client/v1/push_rule.py | 18 +++++++++++++----- synapse/rest/client/v1/pusher.py | 4 ++-- synapse/rest/media/v1/upload_resource.py | 7 ++++--- synapse/storage/_base.py | 6 +++--- synapse/storage/push_rule.py | 4 +++- 11 files changed, 57 insertions(+), 36 deletions(-) (limited to 'synapse/storage/_base.py') diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index cd0798c2b0..6a266ee0fe 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -658,7 +658,9 @@ class PresenceHandler(BaseHandler): observers = set(self._remote_recvmap.get(user, set())) if observers: - logger.debug(" | %d interested local observers %r", len(observers), observers) + logger.debug( + " | %d interested local observers %r", len(observers), observers + ) rm_handler = self.homeserver.get_handlers().room_member_handler room_ids = yield rm_handler.get_rooms_for_user(user) diff --git a/synapse/handlers/register.py b/synapse/handlers/register.py index 4f06c487b1..0247327eb9 100644 --- a/synapse/handlers/register.py +++ b/synapse/handlers/register.py @@ -105,17 +105,20 @@ class RegistrationHandler(BaseHandler): # do it here. try: auth_user = UserID.from_string(user_id) - identicon_resource = self.hs.get_resource_for_media_repository().getChildWithDefault("identicon", None) - upload_resource = self.hs.get_resource_for_media_repository().getChildWithDefault("upload", None) + media_repository = self.hs.get_resource_for_media_repository() + identicon_resource = media_repository.getChildWithDefault("identicon", None) + upload_resource = media_repository.getChildWithDefault("upload", None) identicon_bytes = identicon_resource.generate_identicon(user_id, 320, 320) content_uri = yield upload_resource.create_content( "image/png", None, identicon_bytes, len(identicon_bytes), auth_user ) profile_handler = self.hs.get_handlers().profile_handler - profile_handler.set_avatar_url(auth_user, auth_user, ("%s#auto" % content_uri)) + profile_handler.set_avatar_url( + auth_user, auth_user, ("%s#auto" % (content_uri,)) + ) except NotImplementedError: - pass # make tests pass without messing around creating default avatars - + pass # make tests pass without messing around creating default avatars + defer.returnValue((user_id, token)) @defer.inlineCallbacks diff --git a/synapse/push/__init__.py b/synapse/push/__init__.py index 6f143a5df9..418a348a58 100644 --- a/synapse/push/__init__.py +++ b/synapse/push/__init__.py @@ -140,7 +140,7 @@ class Pusher(object): lambda x: ('[%s%s]' % (x.group(1) and '^' or '', re.sub(r'\\\-', '-', x.group(2)))), r) return r - + def _event_fulfills_condition(self, ev, condition, display_name, room_member_count): if condition['kind'] == 'event_match': if 'pattern' not in condition: @@ -170,8 +170,10 @@ class Pusher(object): return False if not display_name: return False - return re.search("\b%s\b" % re.escape(display_name), - ev['content']['body'], flags=re.IGNORECASE) is not None + return re.search( + "\b%s\b" % re.escape(display_name), ev['content']['body'], + flags=re.IGNORECASE + ) is not None elif condition['kind'] == 'room_member_count': if 'is' not in condition: diff --git a/synapse/push/baserules.py b/synapse/push/baserules.py index 37878f1e0b..162d265f66 100644 --- a/synapse/push/baserules.py +++ b/synapse/push/baserules.py @@ -1,5 +1,6 @@ from synapse.push.rulekinds import PRIORITY_CLASS_MAP, PRIORITY_CLASS_INVERSE_MAP + def list_with_base_rules(rawrules, user_name): ruleslist = [] @@ -9,9 +10,9 @@ def list_with_base_rules(rawrules, user_name): if r['priority_class'] < current_prio_class: while r['priority_class'] < current_prio_class: ruleslist.extend(make_base_rules( - user_name, - PRIORITY_CLASS_INVERSE_MAP[current_prio_class]) - ) + user_name, + PRIORITY_CLASS_INVERSE_MAP[current_prio_class] + )) current_prio_class -= 1 ruleslist.append(r) @@ -19,8 +20,8 @@ def list_with_base_rules(rawrules, user_name): while current_prio_class > 0: ruleslist.extend(make_base_rules( user_name, - PRIORITY_CLASS_INVERSE_MAP[current_prio_class]) - ) + PRIORITY_CLASS_INVERSE_MAP[current_prio_class] + )) current_prio_class -= 1 return ruleslist diff --git a/synapse/push/rulekinds.py b/synapse/push/rulekinds.py index 763bdee58e..660aa4e10e 100644 --- a/synapse/push/rulekinds.py +++ b/synapse/push/rulekinds.py @@ -1,8 +1,8 @@ PRIORITY_CLASS_MAP = { - 'underride': 1, - 'sender': 2, - 'room': 3, - 'content': 4, - 'override': 5, - } + 'underride': 1, + 'sender': 2, + 'room': 3, + 'content': 4, + 'override': 5, +} PRIORITY_CLASS_INVERSE_MAP = {v: k for k, v in PRIORITY_CLASS_MAP.items()} diff --git a/synapse/python_dependencies.py b/synapse/python_dependencies.py index a89d618606..fd68da9dfb 100644 --- a/synapse/python_dependencies.py +++ b/synapse/python_dependencies.py @@ -19,10 +19,11 @@ REQUIREMENTS = { "pydenticon": ["pydenticon"], } + def github_link(project, version, egg): return "https://github.com/%s/tarball/%s/#egg=%s" % (project, version, egg) -DEPENDENCY_LINKS=[ +DEPENDENCY_LINKS = [ github_link( project="matrix-org/syutil", version="v0.0.2", @@ -101,6 +102,7 @@ def check_requirements(): % (dependency, file_path, version, required_version) ) + def list_requirements(): result = [] linked = [] @@ -111,7 +113,7 @@ def list_requirements(): for requirement in REQUIREMENTS: is_linked = False for link in linked: - if requirement.replace('-','_').startswith(link): + if requirement.replace('-', '_').startswith(link): is_linked = True if not is_linked: result.append(requirement) diff --git a/synapse/rest/client/v1/push_rule.py b/synapse/rest/client/v1/push_rule.py index d43ade39dd..c4e7dfcf0e 100644 --- a/synapse/rest/client/v1/push_rule.py +++ b/synapse/rest/client/v1/push_rule.py @@ -15,12 +15,17 @@ from twisted.internet import defer -from synapse.api.errors import SynapseError, Codes, UnrecognizedRequestError, NotFoundError, \ - StoreError +from synapse.api.errors import ( + SynapseError, Codes, UnrecognizedRequestError, NotFoundError, StoreError +) from .base import ClientV1RestServlet, client_path_pattern -from synapse.storage.push_rule import InconsistentRuleException, RuleNotFoundException +from synapse.storage.push_rule import ( + InconsistentRuleException, RuleNotFoundException +) import synapse.push.baserules as baserules -from synapse.push.rulekinds import PRIORITY_CLASS_MAP, PRIORITY_CLASS_INVERSE_MAP +from synapse.push.rulekinds import ( + PRIORITY_CLASS_MAP, PRIORITY_CLASS_INVERSE_MAP +) import json @@ -105,7 +110,9 @@ class PushRuleRestServlet(ClientV1RestServlet): # we build up the full structure and then decide which bits of it # to send which means doing unnecessary work sometimes but is # is probably not going to make a whole lot of difference - rawrules = yield self.hs.get_datastore().get_push_rules_for_user_name(user.to_string()) + rawrules = yield self.hs.get_datastore().get_push_rules_for_user_name( + user.to_string() + ) for r in rawrules: r["conditions"] = json.loads(r["conditions"]) @@ -383,6 +390,7 @@ def _namespaced_rule_id_from_spec(spec): def _rule_id_from_namespaced(in_rule_id): return in_rule_id.split('/')[-1] + class InvalidRuleException(Exception): pass diff --git a/synapse/rest/client/v1/pusher.py b/synapse/rest/client/v1/pusher.py index e10d2576d2..80e9939b79 100644 --- a/synapse/rest/client/v1/pusher.py +++ b/synapse/rest/client/v1/pusher.py @@ -34,8 +34,8 @@ class PusherRestServlet(ClientV1RestServlet): pusher_pool = self.hs.get_pusherpool() if ('pushkey' in content and 'app_id' in content - and 'kind' in content and - content['kind'] is None): + and 'kind' in content and + content['kind'] is None): yield pusher_pool.remove_pusher( content['app_id'], content['pushkey'] ) diff --git a/synapse/rest/media/v1/upload_resource.py b/synapse/rest/media/v1/upload_resource.py index 5b42782331..6df52ca434 100644 --- a/synapse/rest/media/v1/upload_resource.py +++ b/synapse/rest/media/v1/upload_resource.py @@ -38,9 +38,10 @@ class UploadResource(BaseMediaResource): def render_OPTIONS(self, request): respond_with_json(request, 200, {}, send_cors=True) return NOT_DONE_YET - + @defer.inlineCallbacks - def create_content(self, media_type, upload_name, content, content_length, auth_user): + def create_content(self, media_type, upload_name, content, content_length, + auth_user): media_id = random_string(24) fname = self.filepaths.local_media_filepath(media_id) @@ -65,7 +66,7 @@ class UploadResource(BaseMediaResource): } yield self._generate_local_thumbnails(media_id, media_info) - + defer.returnValue("mxc://%s/%s" % (self.server_name, media_id)) @defer.inlineCallbacks diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 36455ef93c..3e1ab0a159 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -84,7 +84,7 @@ class PerformanceCounters(object): def update(self, key, start_time, end_time=None): if end_time is None: - end_time = time.time() * 1000; + end_time = time.time() * 1000 duration = end_time - start_time count, cum_time = self.current_counters.get(key, (0, 0)) count += 1 @@ -588,7 +588,7 @@ class SQLBaseStore(object): "LIMIT 1 " ) - start_time = time.time() * 1000; + start_time = time.time() * 1000 txn.execute(sql, (event_id,)) @@ -613,7 +613,7 @@ class SQLBaseStore(object): def _get_event_from_row_txn(self, txn, internal_metadata, js, redacted, check_redacted=True, get_prev_content=False): - start_time = time.time() * 1000; + start_time = time.time() * 1000 update_counter = self._get_event_counters.update d = json.loads(js) diff --git a/synapse/storage/push_rule.py b/synapse/storage/push_rule.py index 30e23445d9..620de71398 100644 --- a/synapse/storage/push_rule.py +++ b/synapse/storage/push_rule.py @@ -91,7 +91,9 @@ class PushRuleStore(SQLBaseStore): txn.execute(sql, (user_name, relative_to_rule)) res = txn.fetchall() if not res: - raise RuleNotFoundException("before/after rule not found: %s" % (relative_to_rule)) + raise RuleNotFoundException( + "before/after rule not found: %s" % (relative_to_rule,) + ) priority_class, base_rule_priority = res[0] if 'priority_class' in kwargs and kwargs['priority_class'] != priority_class: -- cgit 1.4.1