mirror of
https://github.com/element-hq/synapse
synced 2024-09-12 09:25:11 +00:00
Add logging
This commit is contained in:
parent
5e56736313
commit
37153a5478
2 changed files with 16 additions and 1 deletions
|
@ -11,12 +11,15 @@
|
||||||
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||||
# See the License for the specific language governing permissions and
|
# See the License for the specific language governing permissions and
|
||||||
# limitations under the License.
|
# limitations under the License.
|
||||||
|
import logging
|
||||||
import os
|
import os
|
||||||
import time
|
import time
|
||||||
from typing import Any, Callable, Dict, Optional
|
from typing import Any, Callable, Dict, Optional
|
||||||
|
|
||||||
from scalene import scalene_profiler
|
from scalene import scalene_profiler
|
||||||
|
|
||||||
|
logger = logging.getLogger(__name__)
|
||||||
|
|
||||||
|
|
||||||
class ProfilingDecider:
|
class ProfilingDecider:
|
||||||
INSTANCES: Dict[str, "ProfilingDecider"] = {}
|
INSTANCES: Dict[str, "ProfilingDecider"] = {}
|
||||||
|
@ -24,16 +27,20 @@ class ProfilingDecider:
|
||||||
def __init__(self, name: str, cond: Callable[[], bool]) -> None:
|
def __init__(self, name: str, cond: Callable[[], bool]) -> None:
|
||||||
ProfilingDecider.INSTANCES[name] = self
|
ProfilingDecider.INSTANCES[name] = self
|
||||||
|
|
||||||
|
logger.warning("Setting up profiler %r", name)
|
||||||
|
|
||||||
# Default to being armed if SCALENE is available as an env var.
|
# Default to being armed if SCALENE is available as an env var.
|
||||||
self.armed = b"SCALENE" in os.environb
|
self.armed = b"SCALENE" in os.environb
|
||||||
|
|
||||||
self._cond = cond
|
self._cond = cond
|
||||||
|
|
||||||
def decide(self) -> bool:
|
def decide(self) -> bool:
|
||||||
|
logger.warning("Decide? Armed? %r", self.armed)
|
||||||
if not self.armed:
|
if not self.armed:
|
||||||
return False
|
return False
|
||||||
|
|
||||||
if not self._cond():
|
if not self._cond():
|
||||||
|
logger.warning("Cond fail")
|
||||||
return False
|
return False
|
||||||
|
|
||||||
self.armed = False
|
self.armed = False
|
||||||
|
@ -62,6 +69,7 @@ class CpuUtimeTracker:
|
||||||
wall = time.time()
|
wall = time.time()
|
||||||
elapsed = wall - self._last_wall
|
elapsed = wall - self._last_wall
|
||||||
if elapsed < self.min_elapse:
|
if elapsed < self.min_elapse:
|
||||||
|
logger.warning("Not enough elapsed %r", elapsed)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
last_utime = self._last_utime
|
last_utime = self._last_utime
|
||||||
|
@ -71,9 +79,11 @@ class CpuUtimeTracker:
|
||||||
|
|
||||||
if elapsed > self.max_elapse:
|
if elapsed > self.max_elapse:
|
||||||
# the average will be a bit skewy if so much time has elapsed. Ignore.
|
# the average will be a bit skewy if so much time has elapsed. Ignore.
|
||||||
|
logger.warning("Too much elapsed %r", elapsed)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
usage = (self._last_utime - last_utime) / (self._last_elapsed - last_elapsed)
|
usage = (self._last_utime - last_utime) / (self._last_elapsed - last_elapsed)
|
||||||
|
logger.info("Usage %r", usage)
|
||||||
return usage
|
return usage
|
||||||
|
|
||||||
|
|
||||||
|
@ -81,6 +91,7 @@ class SelectiveProfiling:
|
||||||
def __init__(self, decider: ProfilingDecider, enable: bool = False):
|
def __init__(self, decider: ProfilingDecider, enable: bool = False):
|
||||||
self._decider = decider
|
self._decider = decider
|
||||||
self._enable = enable
|
self._enable = enable
|
||||||
|
logger.info("selective enable %r", enable)
|
||||||
|
|
||||||
def __enter__(self) -> None:
|
def __enter__(self) -> None:
|
||||||
if not self._enable:
|
if not self._enable:
|
||||||
|
@ -88,8 +99,11 @@ class SelectiveProfiling:
|
||||||
if not self._decider.decide():
|
if not self._decider.decide():
|
||||||
self._enable = False
|
self._enable = False
|
||||||
return
|
return
|
||||||
|
logger.info("STARTING")
|
||||||
scalene_profiler.start()
|
scalene_profiler.start()
|
||||||
|
|
||||||
def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None:
|
def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None:
|
||||||
if not self._enable:
|
if not self._enable:
|
||||||
scalene_profiler.stop()
|
return
|
||||||
|
scalene_profiler.stop()
|
||||||
|
logger.info("STOPPED")
|
||||||
|
|
|
@ -351,6 +351,7 @@ class RoomSendEventRestServlet(TransactionRestServlet):
|
||||||
txn_id: Optional[str] = None,
|
txn_id: Optional[str] = None,
|
||||||
) -> Tuple[int, JsonDict]:
|
) -> Tuple[int, JsonDict]:
|
||||||
requester = await self.auth.get_user_by_req(request, allow_guest=True)
|
requester = await self.auth.get_user_by_req(request, allow_guest=True)
|
||||||
|
logger.info("SP!!!")
|
||||||
with SelectiveProfiling(
|
with SelectiveProfiling(
|
||||||
send_event_profiler,
|
send_event_profiler,
|
||||||
enable=requester.user.to_string() == "@reivilibre.element:librepush.net",
|
enable=requester.user.to_string() == "@reivilibre.element:librepush.net",
|
||||||
|
|
Loading…
Reference in a new issue