From 38b67ca04cb1bdfd479ed6addbde5dd75fbd99a2 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 2 Sep 2025 15:11:04 -0500 Subject: [PATCH 1/9] 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 48989540bb2..d91eeb15c57 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -601,6 +601,12 @@ def run_sighup(*args: Any, **kwargs: Any) -> 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 3eac271c907..3fb29a78176 100644 --- a/synapse/server.py +++ b/synapse/server.py @@ -366,12 +366,6 @@ def setup(self) -> None: 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 @@ def start_listening(self) -> None: # noqa: B027 (no-op by design) 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 From e39a2196bd7d0e964004c42f2ac83138da5a4668 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Sep 2025 11:32:18 -0500 Subject: [PATCH 2/9] Add context --- synapse/app/_base.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index d91eeb15c57..ff81ec575de 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -604,6 +604,15 @@ def run_sighup(*args: Any, **kwargs: Any) -> None: # 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. + # + # While we could "start" these before the reactor runs, nothing will happen + # until the reactor is running, so we may as well do it here in `start`. + # + # Additionally, this means we also start them after we daemonize and fork the + # process which means we can avoid any potential problems with cputime metrics getting + # 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. if hs.config.worker.run_background_tasks: hs.start_background_tasks() From 313da3e21ccf5572296efe0112354ab809b67fd7 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Sep 2025 11:32:42 -0500 Subject: [PATCH 3/9] Add changelog --- changelog.d/18871.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/18871.misc diff --git a/changelog.d/18871.misc b/changelog.d/18871.misc new file mode 100644 index 00000000000..d0d32e59abb --- /dev/null +++ b/changelog.d/18871.misc @@ -0,0 +1 @@ +Start background tasks after we fork the process (daemonize). From ee290306cead1f53a01f7faceb89db4ef24a03f3 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Sep 2025 11:43:36 -0500 Subject: [PATCH 4/9] Use correct changelog number --- changelog.d/{18871.misc => 18886.misc} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename changelog.d/{18871.misc => 18886.misc} (100%) diff --git a/changelog.d/18871.misc b/changelog.d/18886.misc similarity index 100% rename from changelog.d/18871.misc rename to changelog.d/18886.misc From 2f235e31a56e8b067da19cda26183eecdca35d84 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Sep 2025 13:40:43 -0500 Subject: [PATCH 5/9] `start_background_tasks` where we start other background tasks See https://github.com/element-hq/synapse/pull/18886#discussion_r2325789462 --- synapse/app/_base.py | 37 ++++++++++++++++++++----------------- 1 file changed, 20 insertions(+), 17 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index ff81ec575de..bce6f4d82f3 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -601,21 +601,6 @@ def run_sighup(*args: Any, **kwargs: Any) -> 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. - # - # While we could "start" these before the reactor runs, nothing will happen - # until the reactor is running, so we may as well do it here in `start`. - # - # Additionally, this means we also start them after we daemonize and fork the - # process which means we can avoid any potential problems with cputime metrics getting - # 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. - 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..." @@ -624,10 +609,28 @@ def run_sighup(*args: Any, **kwargs: Any) -> None: setup_sentry(hs) setup_sdnotify(hs) - # If background tasks are running on the main process or this is the worker in - # charge of them, start collecting the phone home stats and shared usage metrics. + # 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. + # + # While we could "start" these before the reactor runs, nothing will happen until + # the reactor is running, so we may as well do it here in `start`. + # + # Additionally, this means we also start them after we daemonize and fork the + # process which means we can avoid any potential problems with cputime metrics + # getting 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. if hs.config.worker.run_background_tasks: + hs.start_background_tasks() + + # TODO: This should be moved to same pattern we use for other background tasks: + # Add to `REQUIRED_ON_BACKGROUND_TASK_STARTUP` and rely on + # `start_background_tasks` to start it. await hs.get_common_usage_metrics_manager().setup() + + # TODO: This feels like another pattern that should refactored as one of the + # `REQUIRED_ON_BACKGROUND_TASK_STARTUP` start_phone_stats_home(hs) # We now freeze all allocated objects in the hopes that (almost) From 99b99c2f6f021e85df4f1479d78a72c56941dd54 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 5 Sep 2025 13:46:07 -0500 Subject: [PATCH 6/9] `start_background_tasks` in tests --- tests/server.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/tests/server.py b/tests/server.py index ebff8b04b34..7432db1ac85 100644 --- a/tests/server.py +++ b/tests/server.py @@ -1160,6 +1160,16 @@ def setup_test_homeserver( with patch("synapse.storage.database.make_pool", side_effect=make_fake_db_pool): hs.setup() + # 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. + # + # Since, we don't have to worry about `daemonize` (forking the process) in tests, we + # can just start the background tasks straight away after `hs.setup`. (compare this + # with where we call `hs.start_background_tasks()` outside of the test environment). + if hs.config.worker.run_background_tasks: + hs.start_background_tasks() + # Since we've changed the databases to run DB transactions on the same # thread, we need to stop the event fetcher hogging that one thread. hs.get_datastores().main.USE_DEDICATED_DB_THREADS_FOR_EVENT_FETCHING = False From 11c39c5d97521208340f4582c7de0cfc8339b000 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 8 Sep 2025 23:21:25 -0500 Subject: [PATCH 7/9] Try `start_background_tasks` in `synapse/_scripts/update_synapse_database.py` so portdb can maybe finish See https://github.com/element-hq/synapse/pull/18886#discussion_r2331969841 --- synapse/_scripts/update_synapse_database.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/synapse/_scripts/update_synapse_database.py b/synapse/_scripts/update_synapse_database.py index 70e55984184..d376b7f7b72 100644 --- a/synapse/_scripts/update_synapse_database.py +++ b/synapse/_scripts/update_synapse_database.py @@ -120,6 +120,10 @@ def main() -> None: # DB. hs.setup() + # TODO: Why do we need this here? + if hs.config.worker.run_background_tasks: + hs.start_background_tasks() + if args.run_background_updates: run_background_updates(hs) From ed42696f70eba9d40f9158955a0353034bb64bd8 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 8 Sep 2025 23:33:07 -0500 Subject: [PATCH 8/9] Revert "Try `start_background_tasks` in `synapse/_scripts/update_synapse_database.py` so portdb can maybe finish" This reverts commit 11c39c5d97521208340f4582c7de0cfc8339b000. --- synapse/_scripts/update_synapse_database.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/synapse/_scripts/update_synapse_database.py b/synapse/_scripts/update_synapse_database.py index d376b7f7b72..70e55984184 100644 --- a/synapse/_scripts/update_synapse_database.py +++ b/synapse/_scripts/update_synapse_database.py @@ -120,10 +120,6 @@ def main() -> None: # DB. hs.setup() - # TODO: Why do we need this here? - if hs.config.worker.run_background_tasks: - hs.start_background_tasks() - if args.run_background_updates: run_background_updates(hs) From 74cd02d2e21423e2d1beec1063de53362adf9f31 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 8 Sep 2025 23:55:56 -0500 Subject: [PATCH 9/9] Ensure storage classes are instantiated so the background updates are registered are available --- synapse/_scripts/update_synapse_database.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/synapse/_scripts/update_synapse_database.py b/synapse/_scripts/update_synapse_database.py index 70e55984184..3624db3544e 100644 --- a/synapse/_scripts/update_synapse_database.py +++ b/synapse/_scripts/update_synapse_database.py @@ -120,6 +120,13 @@ def main() -> None: # DB. hs.setup() + # This will cause all of the relevant storage classes to be instantiated and call + # `register_background_update_handler(...)`, + # `register_background_index_update(...)`, + # `register_background_validate_constraint(...)`, etc so they are available to use + # if we are asked to run those background updates. + hs.get_storage_controllers() + if args.run_background_updates: run_background_updates(hs)