Add metrics to track /messages response time by room size

[MadLittleMods]

Add metrics to track /messages response time by room size

Follow-up to #13533

Part of #13356

Mentioned in internal doc

Dev notes

• https://stackoverflow.com/questions/59002918/type-hint-enum-classmethod-that-returns-enum-member

---

Discussion from #synapse-dev for reference:

<@DMRobertson:matrix.org> (surprised that's in synapse.metrics)

that's mostly because run_as_background_process isn't actually what you want, because that's all about reporting the CPU and DB usage metrics in the "background jobs" section of the grafana dashboard. If what you're looking for is doing things in parallel, and you're actually going to wait for the thing to complete at the end, then in theory what you want to do is to Deferred.fromCoroutine(get_number_joined_users_in_room()) (which gives you a Deferred which is much like a javascript Promise; it will run in the background and you can await it later).

However our logcontexts mess that up so actually you need more wrapping, so in practice the thing you actually want here is synapse.logging.context.run_in_background(get_number_joined_users_in_room())

and whether you use run_as_background_process or run_in_background, when you finally do the await at the end, you need to await make_deferred_yieldable(deferred), otherwise again logcontexts will get messed up if deferred isn't complete before you await it.

once more: the sooner we switch to proper contextvars rather than having to worry about the logcontext magic, the better

-- @richvdh, https://matrix.to/#/!vcyiEtMVHIhWXcJAfl:sw1v.org/$UdCC3RUwlnyyf1gJnxxXdXNIN7syssmJve9RzftD180?via=matrix.org&via=element.io&via=beeper.com

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)

[reivilibre]

Sensible idea otherwise.

[MadLittleMods]

I wish I could put the @trace on the outside but the cached stuff does not like getting wrapped. Same with the other caching decorators I've noticed (like @cachedList). It returns a DeferredCacheDescriptor/DeferredCacheListDescriptor instead of a wrapped function.

Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1030, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1007, in _find_and_load
  File "<frozen importlib._bootstrap>", line 986, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 680, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 850, in exec_module
  File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
  File "/Users/eric/Documents/github/element/synapse/synapse/app/homeserver.py", line 37, in <module>
    from synapse.app import _base
  File "/Users/eric/Documents/github/element/synapse/synapse/app/_base.py", line 61, in <module>
    from synapse.events.spamcheck import load_legacy_spam_checkers
  File "/Users/eric/Documents/github/element/synapse/synapse/events/spamcheck.py", line 35, in <module>
    from synapse.rest.media.v1._base import FileInfo
  File "/Users/eric/Documents/github/element/synapse/synapse/rest/__init__.py", line 18, in <module>
    from synapse.rest import admin
  File "/Users/eric/Documents/github/element/synapse/synapse/rest/admin/__init__.py", line 27, in <module>
    from synapse.rest.admin._base import admin_patterns, assert_requester_is_admin
  File "/Users/eric/Documents/github/element/synapse/synapse/rest/admin/_base.py", line 19, in <module>
    from synapse.api.auth import Auth
  File "/Users/eric/Documents/github/element/synapse/synapse/api/auth.py", line 22, in <module>
    from synapse import event_auth
  File "/Users/eric/Documents/github/element/synapse/synapse/event_auth.py", line 45, in <module>
    from synapse.storage.databases.main.events_worker import EventRedactBehaviour
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/__init__.py", line 34, in <module>
    from synapse.storage.databases import Databases
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/__init__.py", line 20, in <module>
    from synapse.storage.databases.main.events import PersistEventsStore
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/main/__init__.py", line 33, in <module>
    from .account_data import AccountDataStore
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/main/account_data.py", line 39, in <module>
    from synapse.storage.databases.main.push_rule import PushRulesWorkerStore
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/main/push_rule.py", line 41, in <module>
    from synapse.storage.databases.main.appservice import ApplicationServiceWorkerStore
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/main/appservice.py", line 35, in <module>
    from synapse.storage.databases.main.roommember import RoomMemberWorkerStore
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/main/roommember.py", line 82, in <module>
    class RoomMemberWorkerStore(EventsWorkerStore):
  File "/Users/eric/Documents/github/element/synapse/synapse/storage/databases/main/roommember.py", line 401, in RoomMemberWorkerStore
    async def get_number_joined_users_in_room(self, room_id: str) -> int:
  File "/Users/eric/Documents/github/element/synapse/synapse/logging/opentracing.py", line 954, in trace
    return trace_with_opname(func.__name__)(func)
AttributeError: 'DeferredCacheDescriptor' object has no attribute '__name__'

[reivilibre]

Maybe we can make DeferredCacheDescriptor have a __name__ field to make it compatible.

That said, is there any point in tracing the cached function from the outside? If it's a cache hit then it should take negligible time and it's probably not that interesting in your trace view.

[MadLittleMods]

Maybe we can make DeferredCacheDescriptor have a __name__ field to make it compatible.

I was exploring that option a few days ago but there is more to change to make it work.

That said, is there any point in tracing the cached function from the outside? If it's a cache hit then it should take negligible time and it's probably not that interesting in your trace view.

It's nice to have to so you know whether it's running. It's weird to just not see a call in the trace when you see it in the code.

[MadLittleMods]

It looks like this @trace call is messing up some of the tests (passes without it). The method still gives results so it's unclear to me why it would change things 🤔

https://github.com/matrix-org/synapse/runs/7891614050?check_suite_focus=true#step:7:3384

[FAIL]
Traceback (most recent call last):
  File "/home/runner/work/synapse/synapse/tests/rest/client/test_rooms.py", line 726, in test_post_room_initial_state
    self.assertEqual(50, channel.resource_usage.db_txn_count)
  File "/home/runner/.cache/pypoetry/virtualenvs/matrix-synapse-pswDeSvb-py3.9/lib/python3.9/site-packages/twisted/trial/_synctest.py", line 422, in assertEqual
    super().assertEqual(first, second, msg)
  File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/case.py", line 837, in assertEqual
    assertion_func(first, second, msg=msg)
  File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/case.py", line 830, in _baseAssertEqual
    raise self.failureException(msg)
twisted.trial.unittest.FailTest: 50 != 49

tests.rest.client.test_rooms.RoomsCreateTestCase.test_post_room_initial_state

[reivilibre]

Wonder if it's because the function being returned by trace always has the same __name__ and so just a guess, but these two get the same cache entries. Seems like a massive trap. I'll see if I can confirm.

@cached()
@trace
def fun1(): ...

@cached()
@trace
def fun2(): ...

edit: nope, the __name__ passes through @trace like you'd hope, so it's not that. It would be good to know why this is causing a test to fail :/

[MadLittleMods]

I'll re-introduce this in another PR if I get an inkling to have it again ⏩

[MadLittleMods]

Thanks for the review and help working out the details @reivilibre 🐫

Also thanks to @DMRobertson and @richvdh for the info to get background coroutines fully going 🦦