Skip to content

Add query logging callbacks and context manager #1043

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 12 commits into from
Oct 9, 2023
Prev Previous commit
Next Next commit
Wrap timing in a context manager
  • Loading branch information
dcwatson committed Jul 7, 2023
commit f64a8eac4a1f0393e7c8987d77d3d9c9acc330e4
33 changes: 15 additions & 18 deletions asyncpg/connection.py
Original file line number Diff line number Diff line change
Expand Up @@ -339,10 +339,9 @@ async def execute(self, query: str, *args, timeout: float=None) -> str:
self._check_open()

if not args:
start = time.monotonic()
result = await self._protocol.query(query, timeout)
elapsed = time.monotonic() - start
self._log_query(query, args, timeout, elapsed)
with utils.timer() as t:
result = await self._protocol.query(query, timeout)
self._log_query(query, args, timeout, t.elapsed)
return result

_, status, _ = await self._execute(
Expand Down Expand Up @@ -1724,27 +1723,25 @@ async def __execute(
executor = lambda stmt, timeout: self._protocol.bind_execute(
stmt, args, '', limit, return_status, timeout)
timeout = self._protocol._get_timeout(timeout)
start = time.monotonic()
result, stmt = await self._do_execute(
query,
executor,
timeout,
record_class=record_class,
ignore_custom_codec=ignore_custom_codec,
)
elapsed = time.monotonic() - start
self._log_query(query, args, timeout, elapsed)
with utils.timer() as t:
result, stmt = await self._do_execute(
query,
executor,
timeout,
record_class=record_class,
ignore_custom_codec=ignore_custom_codec,
)
self._log_query(query, args, timeout, t.elapsed)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could go further and pull self._log_query into the context manager and that way you'll be able to log query errors too, e.g.

Suggested change
with utils.timer() as t:
result, stmt = await self._do_execute(
query,
executor,
timeout,
record_class=record_class,
ignore_custom_codec=ignore_custom_codec,
)
self._log_query(query, args, timeout, t.elapsed)
with self._time_and_log(query, args, timeout):
result, stmt = await self._do_execute(
query,
executor,
timeout,
record_class=record_class,
ignore_custom_codec=ignore_custom_codec,
)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great idea, I feel silly for not considering error logging as part of this.

return result, stmt

async def _executemany(self, query, args, timeout):
executor = lambda stmt, timeout: self._protocol.bind_execute_many(
stmt, args, '', timeout)
timeout = self._protocol._get_timeout(timeout)
with self._stmt_exclusive_section:
start = time.monotonic()
result, _ = await self._do_execute(query, executor, timeout)
elapsed = time.monotonic() - start
self._log_query(query, args, timeout, elapsed)
with utils.timer() as t:
result, _ = await self._do_execute(query, executor, timeout)
self._log_query(query, args, timeout, t.elapsed)
return result

async def _do_execute(
Expand Down
26 changes: 26 additions & 0 deletions asyncpg/utils.py
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@


import re
import time


def _quote_ident(ident):
Expand Down Expand Up @@ -43,3 +44,28 @@ async def _mogrify(conn, query, args):
# Finally, replace $n references with text values.
return re.sub(
r'\$(\d+)\b', lambda m: textified[int(m.group(1)) - 1], query)


class timer:
__slots__ = ('start', 'elapsed')

def __init__(self):
self.start = time.monotonic()
self.elapsed = None

@property
def current(self):
return time.monotonic() - self.start

def restart(self):
self.start = time.monotonic()

def stop(self):
self.elapsed = self.current

def __enter__(self):
self.restart()
return self

def __exit__(self, *exc):
self.stop()