replace loggingcontexts with contextvars

[richvdh]

logcontexts are super confusing, and easy to mess up.

We should experiment with replacing the thread-local variable we currently use with a contextvar, which Twisted has first-class support for (twisted/twisted#1192), which could potentially save everyone who ever touches Synapse code a great deal of pain.

[richvdh]

It's worth noting that contextvars is new as of Python 3.7, but there is a backport.

It's also worth mentioning that twisted/twisted#1192 is new as of Twisted 21.2.0 (2021-02-28), so won't be in downstream distros for a while yet.

[richvdh]

Another fly in this ointment is that we rely on the fact that you have to manually switch into loggingcontexts to track CPU usage stats. (every time we switch loggingcontext, we record the CPU usage time). Currently I don't have any great ideas for solving that.

[callahad]

Python 3.6 goes EOL at the end of 2021; flagging this to re-review at the start of next year so we don't have the added complexity of a backport of contextvars

[richvdh]

Another fly in this ointment is that we rely on the fact that you have to manually switch into loggingcontexts to track CPU usage stats. (every time we switch loggingcontext, we record the CPU usage time). Currently I don't have any great ideas for solving that.

One idea: stick a shim high in the call stack which clocks a coroutine through manually, measuring CPU usage:

@types.coroutine
def measure_coro_rusage(coro, rusage) -> Generator:
    total_cpu_utime = 0
    val_to_send = None
    while True:
        start_cpu_utime = resource.getrusage().ru_utime
        try:
            try:
                result = coro.send(val_to_send)
            except StopIteration as e:
                return e.value
        finally:
            rusage.ru_utime += resource.getrusage().ru_utime - start_cpu_utime

        val_to_send = yield result

Probably needs more handling for edge cases, as well as sending exceptions back into the coroutine, but you get the general idea.

[richvdh]

bad news: as of current Twisted, contextvars support still appears broken: https://twistedmatrix.com/trac/ticket/10301

That said, it may well be possible to work around this by avoiding use of reset and tracking the "previous value" ourselves.

[richvdh]

One idea: stick a shim high in the call stack which clocks a coroutine through manually, measuring CPU usage:

incidentally, I think this might go some way to solving #8073: we currently do a lot of getrusage calls for entering/leaving nested logging contexts where we don't really care about the cpu usage stats.

[DMRobertson]

contextvars support still appears broken: twistedmatrix.com/trac/ticket/10301

Fixed in Twisted 22.8.0 (xref #14207).