[issue19495] context manager for measuring duration of blocks of code

[Nick Coghlan]

Nick Coghlan  added the comment:

I think Caleb's "sample_before_and_after" idea hints that this may be an idea 
that could benefit from the ExitStack treatment where contextlib provides a 
building block that handles the interaction with the context management 
machinery, with the documentation shows recipes for particular use cases (such 
as implementing timers for blocks of code)

For example:

class ContextMonitor:
"""Invoke given sampling callbacks when a context is entered and 
exited, and optionally combine the sampling results

*on_entry*: zero-arg sampling function to call on context entry
*on_exit*: zero-arg sampling function to call on context exit
*combine_samples*: two-arg sample combination function. If not given, 
samples are combined as 2-tuples.
*keep_results*: whether to keep results for retrieval via 
``pop_combined_result()``

Instances of this context manager are reusable and reentrant.
"""
def __init__(self, on_entry=None, on_exit=None, combine_samples=None, 
*, keep_results = False):
self._on_entry = lambda:None if on_entry is None else on_entry
self._on_exit = lambda:None if on_exit is None else on_exit
self._combine_samples = lambda *args: args if combine_samples is 
None else combine_samples
self._entry_samples = []
self._keep_results = keep_results
self._combined_results = [] if keep_results else None

@classmethod
def sample(cls, on_event=None, check_results=None):
"""Context monitor that uses the same sampling callback on entry 
and exit"""
return cls(on_event, on_event, check_results)

def pop_combined_result(self):
"""Pops the last combined result. Raises RuntimeError if no results 
are available"""
results = self._combined_results
if not results:
raise RuntimeError("No sample results to report")
return self.checked_results.pop()

def __enter__(self):
self._entry_samples.append(self._on_entry())
return self

def __exit__(self, *args):
entry_sample = self._entry_samples.pop()
exit_sample = self._on_exit()
result = self._combine_samples(entry_sample, exit_sample)
if self._keep_results:
self._combined_results.append(result)
 
And then a recipe like the following (adapted from Caleb's example):

def log_if_slow(logger_name, msg, *args, threshold_sec=1.0, **kwargs):
Context manager that logs monitored blocks that take too long"""
logger = logging.getLogger(logger_name)
if not logger.isEnabledFor(logging.INFO):
# Avoid the timer overhead if the logger will never print anything
return nullcontext()
def _log_slow_blocks(start, end):
duration = end - start
if dt >= threshold_sec:
logger.info(msg, duration, *args, **kwargs)
return ContextMonitor.sample(time.perfcounter, _log_slow_blocks)

with log_if_slow(__name__, 'Took longer to run than expected: %.4g s'):
...


The question is whether anyone would actually find it easier to learn to use an 
API like ContextMonitor over just writing their own generator based context 
manager.

Depending on how familiar they are with the context management protocol, it's 
plausible that they would, as the construction API only asks a few questions:

* whether to use the same sampling function on entry and exit or different ones
* which sampling function(s) to use
* how to combine the two samples into a single result (defaulting to producing 
a two-tuple)
* whether to keep the results around for later retrieval (useful if you want to 
post-process the samples rather than dealing with them directly in the sample 
combination callback)

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[Caleb Hattingh]

Caleb Hattingh  added the comment:

Somehow I missed that there's been an open issue on this. Like others I've 
written a bunch of different incarnations of an "elapsed" context manager over 
the years.  Always for the more crude "how long did this take" reason like 
David mentioned, never the microbenchmarks scenario that timeit serves. The 
work is never quite substantial enough to make a Pypi package of it, but always 
annoying to have to do again the next time the need arises. 


The overall least fiddly scheme I've found is to just use a callback. It's the 
simplest option:


@contextmanager
def elapsed(cb: Callable[[float, float], None], counter=time.perf_counter):
t0 = counter()
try:
yield
finally:
t1 = counter()
cb(t0, t1)


The simple case, the one most people want when they just want a quick check of 
elapsed time on a chunk of code, is then quite easy:


with elapsed(lambda t0, t1: print(f'read_excel: {t1 - t0:.2f} s')):
# very large spreadsheet
df = pandas.read_excel(filename, dtype=str)


(I rarely need to use a timer decorator for functions, because the profiler 
tracks function calls. But within the scope of a function it can sometimes be 
difficult to get timing information, particularly if the calls made there are 
into native extensions)

One of the consequences of using a callback strategy is that an additional 
version might be required for async callbacks (I have used these in production 
also):


@asynccontextmanager
async def aioelapsed(acb: Callable[[float, float], Awaitable[None]],
 counter=time.perf_counter):
t0 = counter()
try:
yield
finally:
t1 = counter()
await acb(t0, t1)


So, the interesting thing here is that there is a general form for which an 
"elapsed" function is just a special case:


T = TypeVar('T')


@contextmanager
def sample_before_and_after(cb: Callable[[T, T], None], sample: Callable[[], 
T]):
before = sample()
try:
yield
finally:
after = sample()
cb(before, after)


The version of "elapsed" given further above is just this with kwarg 
sample=time.perf_counter.  So, it might be sufficient to cover the use-case of 
an "elapsed" context manager instead with something like the above instead, 
which is more general. However, I don't actually have any use cases for this 
more general thing above, other than "elapsed", but I thought it was 
interesting.


Whether any of this merits being in the stdlib or not is hard to say. These 
code snippets are all short and easy to write. But I've written them multiple 
times to make "elapsed".


---


Once the "elapsed" abstraction is available, other cool ideas become a little 
bit easier to think about. These would be things that are user code (not be in 
the stdlib), but which can make use of the "elapsed" cm; for example, a clever 
logger for slow code blocks (written a few of these too):


@contextmanager
def slow_code_logging(logger_name, msg, *args, threshold_sec=1.0, **kwargs):
logger = logging.getLogger(logger_name)

if logger.isEnabledFor(logging.INFO):
def cb(t0: float, t1: float) -> None:
dt = t1 - t0
if dt < threshold_sec:
# Change the logger level depending on threshold
logger.debug(msg, dt, *args, **kwargs)
else:
logger.info(msg, dt, *args, **kwargs)

cm = elapsed(cb)
else:
# Logger is not even enabled, do nothing.
cm = nullcontext()

with cm:
yield


with slow_code_logging(__name__, 'Took longer to run than expected: %.4g s'):
...


And a super-hacky timing histogram generator (which would be quite interesting 
to use for measuring latency in network calls, e.g. with asyncio code):


@contextmanager
def histobuilder(counter, bin_size):
def cb(t0, t1):
dt = t1 - t0
bucket = dt - dt % bin_size
counter[bucket, bucket + bin_size] += 1

with elapsed(cb, counter=time.perf_counter_ns):
yield

counter = Counter()

for i in range(100):
with histobuilder(counter, bin_size=int(5e4)):  # 50 us
time.sleep(0.01)  # 10 ms

for (a, b), v in sorted(counter.items(), key=lambda _: _[0][0]):
print(f'{a/1e6:6.2f} ms - {b/1e6:>6.2f} ms: {v:4} ' + '\u2588' * v)


output:


  9.85 ms -   9.90 ms:1 █
  9.90 ms -   9.95 ms:   10 ██
  9.95 ms -  10.00 ms:   17 █
 10.00 ms -  10.05 ms:8 
 10.05 ms -  10.10 ms:   12 
 10.10 ms -  10.15 ms:5 █
 10.15 ms -  10.20 ms:4 
 10.20 ms -  10.25 ms:4 
 10.25 ms -  10.30 ms:6 ██
 10.30 ms -  10.35 ms:9 █
 10.35 ms -  10.40 ms:3 ███
 10.40 ms -  10.45 ms:5 █
 10.45 ms -  10.50 ms:   12 
 10.50 ms -  10.55 ms:3 ███
 10.55 ms -  10.60 ms:1 █


Things like the histogram builder above become (for me) much simpler when 
"elapsed" is just a thing that 

[issue19495] context manager for measuring duration of blocks of code

[Xavier G. Domingo]

Change by Xavier G. Domingo :


--
nosy: +xgdomingo

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[R. David Murray]

R. David Murray  added the comment:

FWIW, we just ran in to the need for this on our project, and used 'Time' from 
the contexttimer package on pypi.  In our use case we want the number so we can 
log it, and what we care about is the actual elapsed time, not a precise 
measurement of the code block, because it for system monitoring and metrics, 
not hardcore performance analysis.  

Having this always print would indeed be sub-optimal :)

--
nosy: +r.david.murray
versions: +Python 3.8 -Python 3.5

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[Cheryl Sabella]

Cheryl Sabella  added the comment:

Hello everyone,

I was interested in similar functionality for timeit and found this discussion. 
 I know it's too late for 3.7, but I was wondering if it would be worth putting 
this on python-ideas or python-dev to try to get some consensus for a PEP or a 
patch?  With Barry's addition of breakpoint(), I would find something similar 
for timeit (that is, a simpler way to invoke it) would be quite helpful.

Thanks!

--
nosy: +csabella

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[Guido van Rossum]

Changes by Guido van Rossum :


--
nosy:  -gvanrossum

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[irdb]

Changes by irdb :


--
nosy: +irdb

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[Martin Panter]

Changes by Martin Panter vadmium...@gmail.com:


--
nosy: +vadmium

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue19495
___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue19495] context manager for measuring duration of blocks of code

[Robert Collins]

Changes by Robert Collins robe...@robertcollins.net:


--
nosy: +rbcollins
title: Enhancement for timeit: measure time to run blocks of code using 'with' 
- context manager for measuring duration of blocks of code

___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue19495
___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com