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!`
This commit is contained in:
Eric Eastwood
2025-09-02 15:11:04 -05:00
parent 93044f4c5b
commit 6ce2f3e59d
2 changed files with 7 additions and 7 deletions

View File

@@ -601,6 +601,12 @@ async def start(hs: "HomeServer") -> None:
hs.get_datastores().main.db_pool.start_profiling() hs.get_datastores().main.db_pool.start_profiling()
hs.get_pusherpool().start() 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. # Log when we start the shut down process.
hs.get_reactor().addSystemEventTrigger( hs.get_reactor().addSystemEventTrigger(
"before", "shutdown", logger.info, "Shutting down..." "before", "shutdown", logger.info, "Shutting down..."

View File

@@ -366,12 +366,6 @@ class HomeServer(metaclass=abc.ABCMeta):
self.datastores = Databases(self.DATASTORE_CLASS, self) self.datastores = Databases(self.DATASTORE_CLASS, self)
logger.info("Finished setting up.") 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: def __del__(self) -> None:
""" """
Called when an the homeserver is garbage collected. Called when an the homeserver is garbage collected.
@@ -410,7 +404,7 @@ class HomeServer(metaclass=abc.ABCMeta):
appropriate listeners. appropriate listeners.
""" """
def setup_background_tasks(self) -> None: def start_background_tasks(self) -> None:
""" """
Some handlers have side effects on instantiation (like registering Some handlers have side effects on instantiation (like registering
background updates). This function causes them to be fetched, and background updates). This function causes them to be fetched, and