From 6ce2f3e59d6dcd8a798552a087414cf137d0ddad Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 2 Sep 2025 15:11:04 -0500 Subject: [PATCH] Fix CPU time going backwards when `daemonize` When we `daemonize`, we fork the process and cputime metrics get confused about the per-thread resource usage appearing to go backwards because we're comparing the resource usage (`rusage`) from the original process to the forked process. We now kick off the background tasks (`run_as_background_process`) after we have forked the process so the `rusage` we record when we `start` is in the same thread when we `stop`. Bad log examples from before: ``` synapse.logging.context - ERROR - _schedule_next_expiry-0 - utime went backwards! 0.050467 < 0.886526 synapse.logging.context - ERROR - _schedule_db_events-0 - stime went backwards! 0.009941 < 0.155106 synapse.logging.context - ERROR - wake_destinations_needing_catchup-0 - stime went backwards! 0.010175 < 0.130923 synapse.logging.context - ERROR - resume_sync_partial_state_room-0 - utime went backwards! 0.052898 < 0.886526 ``` Testing strategy: 1. Run with `daemonize: true` in your `homeserver.yaml` 1. `poetry run synapse_homeserver --config-path homeserver.yaml` 1. Shutdown the server 1. Look for any bad log entries in your homeserver logs: - `Expected logging context sentinel but found main` - `Expected logging context main was lost` - `utime went backwards!`/`stime went backwards!` --- synapse/app/_base.py | 6 ++++++ synapse/server.py | 8 +------- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 48989540bb..d91eeb15c5 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -601,6 +601,12 @@ async def start(hs: "HomeServer") -> None: hs.get_datastores().main.db_pool.start_profiling() hs.get_pusherpool().start() + # Register background tasks required by this server. This must be done + # somewhat manually due to the background tasks not being registered + # unless handlers are instantiated. + if hs.config.worker.run_background_tasks: + hs.start_background_tasks() + # Log when we start the shut down process. hs.get_reactor().addSystemEventTrigger( "before", "shutdown", logger.info, "Shutting down..." diff --git a/synapse/server.py b/synapse/server.py index 3eac271c90..3fb29a7817 100644 --- a/synapse/server.py +++ b/synapse/server.py @@ -366,12 +366,6 @@ class HomeServer(metaclass=abc.ABCMeta): self.datastores = Databases(self.DATASTORE_CLASS, self) logger.info("Finished setting up.") - # Register background tasks required by this server. This must be done - # somewhat manually due to the background tasks not being registered - # unless handlers are instantiated. - if self.config.worker.run_background_tasks: - self.setup_background_tasks() - def __del__(self) -> None: """ Called when an the homeserver is garbage collected. @@ -410,7 +404,7 @@ class HomeServer(metaclass=abc.ABCMeta): appropriate listeners. """ - def setup_background_tasks(self) -> None: + def start_background_tasks(self) -> None: """ Some handlers have side effects on instantiation (like registering background updates). This function causes them to be fetched, and