2c4057bf93
Be mindful that it's possible to run Synapse multiple times in the same Python process. So we only need to do some part of the logging setup once. - We only need to setup the global log record factory and context filter once - We only need to redirect Twisted logging once ### Background As part of Element's plan to support a light form of vhosting (virtual host) (multiple instances of Synapse in the same Python process), we're currently diving into the details and implications of running multiple instances of Synapse in the same Python process. "Per-tenant logging" tracked internally by https://github.com/element-hq/synapse-small-hosts/issues/48
155 lines
4.6 KiB
Python
155 lines
4.6 KiB
Python
#
|
|
# This file is licensed under the Affero General Public License (AGPL) version 3.
|
|
#
|
|
# Copyright 2019 The Matrix.org Foundation C.I.C.
|
|
# Copyright (C) 2023 New Vector, Ltd
|
|
#
|
|
# This program is free software: you can redistribute it and/or modify
|
|
# it under the terms of the GNU Affero General Public License as
|
|
# published by the Free Software Foundation, either version 3 of the
|
|
# License, or (at your option) any later version.
|
|
#
|
|
# See the GNU Affero General Public License for more details:
|
|
# <https://www.gnu.org/licenses/agpl-3.0.html>.
|
|
#
|
|
# Originally licensed under the Apache License, Version 2.0:
|
|
# <http://www.apache.org/licenses/LICENSE-2.0>.
|
|
#
|
|
# [This file includes modifications made by New Vector Limited]
|
|
#
|
|
#
|
|
import logging
|
|
import logging.config
|
|
import warnings
|
|
from io import StringIO
|
|
from typing import Optional
|
|
from unittest.mock import Mock
|
|
|
|
from pyperf import perf_counter
|
|
|
|
from twisted.internet.address import IPv4Address, IPv6Address
|
|
from twisted.internet.defer import Deferred
|
|
from twisted.internet.protocol import ServerFactory
|
|
from twisted.logger import LogBeginner, LogPublisher
|
|
from twisted.protocols.basic import LineOnlyReceiver
|
|
|
|
from synapse.config.logger import _setup_stdlib_logging, one_time_logging_setup
|
|
from synapse.logging import RemoteHandler
|
|
from synapse.synapse_rust import reset_logging_config
|
|
from synapse.types import ISynapseReactor
|
|
from synapse.util.clock import Clock
|
|
|
|
|
|
class LineCounter(LineOnlyReceiver):
|
|
delimiter = b"\n"
|
|
count = 0
|
|
|
|
def lineReceived(self, line: bytes) -> None:
|
|
self.count += 1
|
|
|
|
assert isinstance(self.factory, Factory)
|
|
|
|
if self.count >= self.factory.wait_for and self.factory.on_done:
|
|
on_done = self.factory.on_done
|
|
self.factory.on_done = None
|
|
on_done.callback(True)
|
|
|
|
|
|
class Factory(ServerFactory):
|
|
protocol = LineCounter
|
|
wait_for: int
|
|
on_done: Optional[Deferred]
|
|
|
|
|
|
async def main(reactor: ISynapseReactor, loops: int) -> float:
|
|
"""
|
|
Benchmark how long it takes to send `loops` messages.
|
|
"""
|
|
|
|
logger_factory = Factory()
|
|
logger_factory.wait_for = loops
|
|
logger_factory.on_done = Deferred()
|
|
port = reactor.listenTCP(0, logger_factory, backlog=50, interface="127.0.0.1")
|
|
|
|
# A fake homeserver config.
|
|
class Config:
|
|
class server:
|
|
server_name = "synmark-" + str(loops)
|
|
|
|
# This odd construct is to avoid mypy thinking that logging escapes the
|
|
# scope of Config.
|
|
class _logging:
|
|
no_redirect_stdio = True
|
|
|
|
logging = _logging
|
|
|
|
hs_config = Config()
|
|
|
|
# To be able to sleep.
|
|
# Ignore linter error here since we are running outside of the context of a
|
|
# Synapse `HomeServer`.
|
|
clock = Clock(reactor, server_name=hs_config.server.server_name) # type: ignore[multiple-internal-clocks]
|
|
|
|
errors = StringIO()
|
|
publisher = LogPublisher()
|
|
mock_sys = Mock()
|
|
beginner = LogBeginner(
|
|
publisher, errors, mock_sys, warnings, initialBufferSize=loops
|
|
)
|
|
|
|
address = port.getHost()
|
|
assert isinstance(address, (IPv4Address, IPv6Address))
|
|
log_config = {
|
|
"version": 1,
|
|
"loggers": {"synapse": {"level": "DEBUG", "handlers": ["remote"]}},
|
|
"formatters": {"tersejson": {"class": "synapse.logging.TerseJsonFormatter"}},
|
|
"handlers": {
|
|
"remote": {
|
|
"class": "synapse.logging.RemoteHandler",
|
|
"formatter": "tersejson",
|
|
"host": address.host,
|
|
"port": address.port,
|
|
"maximum_buffer": 100,
|
|
}
|
|
},
|
|
}
|
|
|
|
logger = logging.getLogger("synapse")
|
|
one_time_logging_setup(logBeginner=beginner)
|
|
_setup_stdlib_logging(
|
|
hs_config, # type: ignore[arg-type]
|
|
None,
|
|
)
|
|
|
|
# Force a new logging config without having to load it from a file.
|
|
logging.config.dictConfig(log_config)
|
|
reset_logging_config()
|
|
|
|
# Wait for it to connect...
|
|
for handler in logging.getLogger("synapse").handlers:
|
|
if isinstance(handler, RemoteHandler):
|
|
break
|
|
else:
|
|
raise RuntimeError("Improperly configured: no RemoteHandler found.")
|
|
|
|
await handler._service.whenConnected(failAfterFailures=10)
|
|
|
|
start = perf_counter()
|
|
|
|
# Send a bunch of useful messages
|
|
for i in range(loops):
|
|
logger.info("test message %s", i)
|
|
|
|
if len(handler._buffer) == handler.maximum_buffer:
|
|
while len(handler._buffer) > handler.maximum_buffer / 2:
|
|
await clock.sleep(0.01)
|
|
|
|
await logger_factory.on_done
|
|
|
|
end = perf_counter() - start
|
|
|
|
handler.close()
|
|
port.stopListening()
|
|
|
|
return end
|