SpamChecker metrics

[jesopo]

EDIT by @reivilibre:

This PR makes SpamChecker callbacks show up in the 'Per-block Metrics' section of a typical Synapse dashboard.

---

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Pull request includes a sign off
• Code style is correct
  (run the linters)

[jesopo]

docstring is missing Added in Synapse v1.2.3. but I wasn't sure what's meant to go there for this one

[jesopo]

an obvious consideration is whether ModuleApi wants to superimpose the module's name in to the Measure's name

[clokep]

From discussion on Matrix the goal of this is to be able to measure the amount of time a callback takes -- I wonder if it would make more sense to wrap some (or all) of the spots we call into modules with Measure blocks, tagging them with some sort of sensible name?

[jesopo]

I think that's a good idea so long as the performance impact of Measures are negligible

[clokep]

From discussion on Matrix the goal of this is to be able to measure the amount of time a callback takes -- I wonder if it would make more sense to wrap some (or all) of the spots we call into modules with Measure blocks, tagging them with some sort of sensible name?

There seemed to be general consensus in #synapse-dev that this makes sense to do.

[anoadragon453]

I'm taking the above as this PR requires further changes, and thus have added the Awaiting Changes label and am removing the request for review. But please re-request review it if that's incorrect!

[jesopo]

From discussion on Matrix the goal of this is to be able to measure the amount of time a callback takes -- I wonder if it would make more sense to wrap some (or all) of the spots we call into modules with Measure blocks, tagging them with some sort of sensible name?

given the callbacks here are handled in SpamChecker, do I want to be putting the measurements in SpamChecker or in the things calling SpamChecker, or?

[DMRobertson]

From discussion on Matrix the goal of this is to be able to measure the amount of time a callback takes -- I wonder if it would make more sense to wrap some (or all) of the spots we call into modules with Measure blocks, tagging them with some sort of sensible name?

given the callbacks here are handled in SpamChecker, do I want to be putting the measurements in SpamChecker or in the things calling SpamChecker, or?

I'm not fully sure how SpamChecker relates to the module API, but given the choice I'd vote for putting them in the SpamChecker methods themselves.

[richvdh]

given the callbacks here are handled in SpamChecker, do I want to be putting the measurements in SpamChecker or in the things calling SpamChecker, or?

The SpamChecker in question appears to be https://github.com/matrix-org/synapse/blob/v1.57.1/synapse/events/spamcheck.py#L164. (By the way: context like that is always appreciated - it makes answering questions like this much easier!)

Anyway I'd agree with @DMRobertson. We ought to be adding the Measure calls at the transition between the core Synapse code and the module, which in this case is SpamChecker (eg here)

[squahtx]

Do feel free to re-request review from matrix-org/synapse-core if you need more feedback!

[jesopo]

trying to think of a way to give each callback its own reasonable name to log the measurement under...

>>> repr(A().a)
'<bound method A.a of <__main__.A object at 0x7fb1af964d00>>'

is bad but this feels worse:

>>> A().a.__self__.__class__.__name__
'A'
>>> A().a.__name__
'a'

but I also don't think that SpamChecker has access to the names modules were loaded under, so that'll, I assume, want something like an additional name param for SpamChecker.register_callbacks

[squahtx]

trying to think of a way to give each callback its own reasonable name to log the measurement under...

>>> repr(A().a)
'<bound method A.a of <__main__.A object at 0x7fb1af964d00>>'

is bad but this feels worse:

>>> A().a.__self__.__class__.__name__
'A'
>>> A().a.__name__
'a'

but I also don't think that SpamChecker has access to the names modules were loaded under, so that'll, I assume, want something like an additional name param for SpamChecker.register_callbacks

You could try f"{method.__module__}.{method.__qualname__}" ?

>>> class SomeClass:
...      def instance_method(self):
...          pass
...
>>> SomeClass().instance_method.__qualname__
'SomeClass.instance_method'

>>> from synapse.util import log_failure
>>> log_failure.__module__
'synapse.util'
>>> log_failure.__qualname__
'log_failure'

[jesopo]

only bit I'm unsure of now is whether we need each Measure here to explicitly say what event it was handling, but that ought to be evident from the __module__.__qualname__s, so feels perhaps unnecessary

[reivilibre]

only bit I'm unsure of now is whether we need each Measure here to explicitly say what event it was handling, but that ought to be evident from the module.__qualname__s, so feels perhaps unnecessary

I agree — I don't think module authors are likely to reuse the same methods for different kinds of events so seems good to me!

[reivilibre]

I'd just be tempted to make this a bit more comprehensible to an administrator (I don't know if it's clear what a Measure block is to anyone except Synapse devs)..

Suggested change

	Insert Measure blocks throughout SpamChecker to collect metrics.
	Measure the time taken in spam checker callbacks and expose them as per-block metrics in Prometheus.

I'm no expert but I think that assumes a bit less Synapse code knowledge?

[jesopo]

i went a bit freestyle, but does the new version look OK?

[reivilibre]

Ya, works for me!