forked from MirrorHub/synapse
Merge pull request #57 from matrix-org/transaction_counters
Transaction counters
This commit is contained in:
commit
375eba6a18
1 changed files with 31 additions and 2 deletions
|
@ -88,6 +88,8 @@ class SQLBaseStore(object):
|
||||||
self._previous_txn_total_time = 0
|
self._previous_txn_total_time = 0
|
||||||
self._current_txn_total_time = 0
|
self._current_txn_total_time = 0
|
||||||
self._previous_loop_ts = 0
|
self._previous_loop_ts = 0
|
||||||
|
self._txn_perf_counters = {}
|
||||||
|
self._previous_txn_perf_counters = {}
|
||||||
|
|
||||||
def start_profiling(self):
|
def start_profiling(self):
|
||||||
self._previous_loop_ts = self._clock.time_msec()
|
self._previous_loop_ts = self._clock.time_msec()
|
||||||
|
@ -103,7 +105,29 @@ class SQLBaseStore(object):
|
||||||
|
|
||||||
ratio = (curr - prev)/(time_now - time_then)
|
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)
|
self._clock.looping_call(loop, 10000)
|
||||||
|
|
||||||
|
@ -116,7 +140,7 @@ class SQLBaseStore(object):
|
||||||
with LoggingContext("runInteraction") as context:
|
with LoggingContext("runInteraction") as context:
|
||||||
current_context.copy_to(context)
|
current_context.copy_to(context)
|
||||||
start = time.time() * 1000
|
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
|
# We don't really need these to be unique, so lets stop it from
|
||||||
# growing really large.
|
# growing really large.
|
||||||
|
@ -139,6 +163,11 @@ class SQLBaseStore(object):
|
||||||
|
|
||||||
self._current_txn_total_time += end - start
|
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)
|
||||||
|
|
||||||
with PreserveLoggingContext():
|
with PreserveLoggingContext():
|
||||||
result = yield self._db_pool.runInteraction(
|
result = yield self._db_pool.runInteraction(
|
||||||
inner_func, *args, **kwargs
|
inner_func, *args, **kwargs
|
||||||
|
|
Loading…
Reference in a new issue