diff --git a/app/adapters/database.py b/app/adapters/database.py index c5e40b43..404aa1c6 100644 --- a/app/adapters/database.py +++ b/app/adapters/database.py @@ -11,6 +11,7 @@ from app import settings from app.logging import log +from app.timer import Timer class MySQLDialect(MySQLDialect_mysqldb): @@ -49,11 +50,18 @@ async def fetch_one( if isinstance(query, ClauseElement): query, params = self._compile(query) - row = await self._database.fetch_one(query, params) + with Timer() as timer: + row = await self._database.fetch_one(query, params) + if settings.DEBUG: + time_elapsed = timer.elapsed() log( - f"Executed SQL query: {query} {params}", - extra={"query": query, "params": params}, + f"Executed SQL query: {query} {params} in {time_elapsed:.2f} seconds.", + extra={ + "query": query, + "params": params, + "time_elapsed": time_elapsed, + }, ) return dict(row._mapping) if row is not None else None @@ -66,7 +74,20 @@ async def fetch_all( if isinstance(query, ClauseElement): query, params = self._compile(query) - rows = await self._database.fetch_all(query, params) + with Timer() as timer: + rows = await self._database.fetch_all(query, params) + + if settings.DEBUG: + time_elapsed = timer.elapsed() + log( + f"Executed SQL query: {query} {params} in {time_elapsed:.2f} seconds.", + extra={ + "query": query, + "params": params, + "time_elapsed": time_elapsed, + }, + ) + return [dict(row._mapping) for row in rows] async def fetch_val( @@ -78,14 +99,40 @@ async def fetch_val( if isinstance(query, ClauseElement): query, params = self._compile(query) - val = await self._database.fetch_val(query, params, column) + with Timer() as timer: + val = await self._database.fetch_val(query, params, column) + + if settings.DEBUG: + time_elapsed = timer.elapsed() + log( + f"Executed SQL query: {query} {params} in {time_elapsed:.2f} seconds.", + extra={ + "query": query, + "params": params, + "time_elapsed": time_elapsed, + }, + ) + return val async def execute(self, query: MySQLQuery, params: MySQLParams = None) -> int: if isinstance(query, ClauseElement): query, params = self._compile(query) - rec_id = await self._database.execute(query, params) + with Timer() as timer: + rec_id = await self._database.execute(query, params) + + if settings.DEBUG: + time_elapsed = timer.elapsed() + log( + f"Executed SQL query: {query} {params} in {time_elapsed:.2f} seconds.", + extra={ + "query": query, + "params": params, + "time_elapsed": time_elapsed, + }, + ) + return cast(int, rec_id) # NOTE: this accepts str since current execute_many uses are not using alchemy. @@ -94,7 +141,19 @@ async def execute_many(self, query: str, params: list[MySQLParams]) -> None: if isinstance(query, ClauseElement): query, _ = self._compile(query) - await self._database.execute_many(query, params) + with Timer() as timer: + await self._database.execute_many(query, params) + + if settings.DEBUG: + time_elapsed = timer.elapsed() + log( + f"Executed SQL query: {query} {params} in {time_elapsed:.2f} seconds.", + extra={ + "query": query, + "params": params, + "time_elapsed": time_elapsed, + }, + ) def transaction( self, diff --git a/app/timer.py b/app/timer.py new file mode 100644 index 00000000..35892683 --- /dev/null +++ b/app/timer.py @@ -0,0 +1,27 @@ +from __future__ import annotations + +import time +from types import TracebackType + + +class Timer: + def __init__(self) -> None: + self.start_time: float | None = None + self.end_time: float | None = None + + def __enter__(self) -> Timer: + self.start_time = time.time() + return self + + def __exit__( + self, + exc_type: type[BaseException] | None, + exc: BaseException | None, + traceback: TracebackType | None, + ) -> None: + self.end_time = time.time() + + def elapsed(self) -> float: + if self.start_time is None or self.end_time is None: + raise ValueError("Timer has not been started or stopped.") + return self.end_time - self.start_time