diff --git a/synapse/hacks/selective_scalene_profiling.py b/synapse/hacks/selective_scalene_profiling.py index 41829c3094..15fc4642d1 100644 --- a/synapse/hacks/selective_scalene_profiling.py +++ b/synapse/hacks/selective_scalene_profiling.py @@ -11,12 +11,15 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. +import logging import os import time from typing import Any, Callable, Dict, Optional from scalene import scalene_profiler +logger = logging.getLogger(__name__) + class ProfilingDecider: INSTANCES: Dict[str, "ProfilingDecider"] = {} @@ -24,16 +27,20 @@ class ProfilingDecider: def __init__(self, name: str, cond: Callable[[], bool]) -> None: ProfilingDecider.INSTANCES[name] = self + logger.warning("Setting up profiler %r", name) + # Default to being armed if SCALENE is available as an env var. self.armed = b"SCALENE" in os.environb self._cond = cond def decide(self) -> bool: + logger.warning("Decide? Armed? %r", self.armed) if not self.armed: return False if not self._cond(): + logger.warning("Cond fail") return False self.armed = False @@ -62,6 +69,7 @@ class CpuUtimeTracker: wall = time.time() elapsed = wall - self._last_wall if elapsed < self.min_elapse: + logger.warning("Not enough elapsed %r", elapsed) return None last_utime = self._last_utime @@ -71,9 +79,11 @@ class CpuUtimeTracker: if elapsed > self.max_elapse: # the average will be a bit skewy if so much time has elapsed. Ignore. + logger.warning("Too much elapsed %r", elapsed) return None usage = (self._last_utime - last_utime) / (self._last_elapsed - last_elapsed) + logger.info("Usage %r", usage) return usage @@ -81,6 +91,7 @@ class SelectiveProfiling: def __init__(self, decider: ProfilingDecider, enable: bool = False): self._decider = decider self._enable = enable + logger.info("selective enable %r", enable) def __enter__(self) -> None: if not self._enable: @@ -88,8 +99,11 @@ class SelectiveProfiling: if not self._decider.decide(): self._enable = False return + logger.info("STARTING") scalene_profiler.start() def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None: if not self._enable: - scalene_profiler.stop() + return + scalene_profiler.stop() + logger.info("STOPPED") diff --git a/synapse/rest/client/room.py b/synapse/rest/client/room.py index 6d8421a523..57dbab5ae1 100644 --- a/synapse/rest/client/room.py +++ b/synapse/rest/client/room.py @@ -351,6 +351,7 @@ class RoomSendEventRestServlet(TransactionRestServlet): txn_id: Optional[str] = None, ) -> Tuple[int, JsonDict]: requester = await self.auth.get_user_by_req(request, allow_guest=True) + logger.info("SP!!!") with SelectiveProfiling( send_event_profiler, enable=requester.user.to_string() == "@reivilibre.element:librepush.net",