From 487fa5317e7f9a0f9bd9dd1abe0fd473610266f4 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Fri, 29 Nov 2019 23:55:33 +0200 Subject: [PATCH 01/75] Split readme to 2 files, fix #146 --- ADVANCED_USAGE.md | 89 +++++++++++++++++++++++++++++++++++++++++++++ README.md | 91 +---------------------------------------------- 2 files changed, 90 insertions(+), 90 deletions(-) create mode 100644 ADVANCED_USAGE.md diff --git a/ADVANCED_USAGE.md b/ADVANCED_USAGE.md new file mode 100644 index 0000000..5a95899 --- /dev/null +++ b/ADVANCED_USAGE.md @@ -0,0 +1,89 @@ +# Advanced Usage # + +Use `watch_explode` to expand values to see all their attributes or items of lists/dictionaries: + +```python +@pysnooper.snoop(watch_explode=('foo', 'self')) +``` + +`watch_explode` will automatically guess how to expand the expression passed to it based on its class. You can be more specific by using one of the following classes: + +```python +import pysnooper + +@pysnooper.snoop(watch=( + pysnooper.Attrs('x'), # attributes + pysnooper.Keys('y'), # mapping (e.g. dict) items + pysnooper.Indices('z'), # sequence (e.g. list/tuple) items +)) +``` + +Exclude specific keys/attributes/indices with the `exclude` parameter, e.g. `Attrs('x', exclude=('_foo', '_bar'))`. + +Add a slice after `Indices` to only see the values within that slice, e.g. `Indices('z')[-3:]`. + +```console +$ export PYSNOOPER_DISABLED=1 # This makes PySnooper not do any snooping +``` + +This will output lines like: + +``` +Modified var:.. foo[2] = 'whatever' +New var:....... self.baz = 8 +``` + +Start all snoop lines with a prefix, to grep for them easily: + +```python +@pysnooper.snoop(prefix='ZZZ ') +``` + +Remove all machine-related data (paths, timestamps, memory addresses) to compare with other traces easily: + +```python +@pysnooper.snoop(normalize=True) +``` + +On multi-threaded apps identify which thread are snooped in output: + +```python +@pysnooper.snoop(thread_info=True) +``` + +PySnooper supports decorating generators. + +If you decorate a class with `snoop`, it'll automatically apply the decorator to all the methods. (Not including properties and other special cases.) + +You can also customize the repr of an object: + +```python +def large(l): + return isinstance(l, list) and len(l) > 5 + +def print_list_size(l): + return 'list(size={})'.format(len(l)) + +def print_ndarray(a): + return 'ndarray(shape={}, dtype={})'.format(a.shape, a.dtype) + +@pysnooper.snoop(custom_repr=((large, print_list_size), (numpy.ndarray, print_ndarray))) +def sum_to_x(x): + l = list(range(x)) + a = numpy.zeros((10,10)) + return sum(l) + +sum_to_x(10000) +``` + +You will get `l = list(size=10000)` for the list, and `a = ndarray(shape=(10, 10), dtype=float64)` for the ndarray. +The `custom_repr` are matched in order, if one condition matches, no further conditions will be checked. + +Variables and exceptions get truncated to 100 characters by default. You +can customize that: + +```python + @pysnooper.snoop(max_variable_length=200) +``` + +You can also use `max_variable_length=None` to never truncate them. \ No newline at end of file diff --git a/README.md b/README.md index d5fb417..12686e8 100644 --- a/README.md +++ b/README.md @@ -117,81 +117,13 @@ See values of some expressions that aren't local variables: @pysnooper.snoop(watch=('foo.bar', 'self.x["whatever"]')) ``` -Expand values to see all their attributes or items of lists/dictionaries: - -```python -@pysnooper.snoop(watch_explode=('foo', 'self')) -``` - -This will output lines like: - -``` -Modified var:.. foo[2] = 'whatever' -New var:....... self.baz = 8 -``` - -(see [Advanced Usage](#advanced-usage) for more control) - Show snoop lines for functions that your function calls: ```python @pysnooper.snoop(depth=2) ``` -Start all snoop lines with a prefix, to grep for them easily: - -```python -@pysnooper.snoop(prefix='ZZZ ') -``` - -Remove all machine-related data (paths, timestamps, memory addresses) to compare with other traces easily: - -```python -@pysnooper.snoop(normalize=True) -``` - -On multi-threaded apps identify which thread are snooped in output: - -```python -@pysnooper.snoop(thread_info=True) -``` - -PySnooper supports decorating generators. - -If you decorate a class with `snoop`, it'll automatically apply the decorator to all the methods. (Not including properties and other special cases.) - -You can also customize the repr of an object: - -```python -def large(l): - return isinstance(l, list) and len(l) > 5 - -def print_list_size(l): - return 'list(size={})'.format(len(l)) - -def print_ndarray(a): - return 'ndarray(shape={}, dtype={})'.format(a.shape, a.dtype) - -@pysnooper.snoop(custom_repr=((large, print_list_size), (numpy.ndarray, print_ndarray))) -def sum_to_x(x): - l = list(range(x)) - a = numpy.zeros((10,10)) - return sum(l) - -sum_to_x(10000) -``` - -You will get `l = list(size=10000)` for the list, and `a = ndarray(shape=(10, 10), dtype=float64)` for the ndarray. -The `custom_repr` are matched in order, if one condition matches, no further conditions will be checked. - -Variables and exceptions get truncated to 100 characters by default. You -can customize that: - -```python - @pysnooper.snoop(max_variable_length=200) -``` - -You can also use `max_variable_length=None` to never truncate them. +**See [Advanced Usage](https://github.com/cool-RR/PySnooper/blob/master/ADVANCED_USAGE.md) for more options.** <------ # Installation # @@ -208,27 +140,6 @@ $ pip install pysnooper $ conda install -c conda-forge pysnooper ``` -# Advanced Usage # - -`watch_explode` will automatically guess how to expand the expression passed to it based on its class. You can be more specific by using one of the following classes: - -```python -import pysnooper - -@pysnooper.snoop(watch=( - pysnooper.Attrs('x'), # attributes - pysnooper.Keys('y'), # mapping (e.g. dict) items - pysnooper.Indices('z'), # sequence (e.g. list/tuple) items -)) -``` - -Exclude specific keys/attributes/indices with the `exclude` parameter, e.g. `Attrs('x', exclude=('_foo', '_bar'))`. - -Add a slice after `Indices` to only see the values within that slice, e.g. `Indices('z')[-3:]`. - -```console -$ export PYSNOOPER_DISABLED=1 # This makes PySnooper not do any snooping -``` # License # From 6416a11d390b8975644363a54ca9484aec244a60 Mon Sep 17 00:00:00 2001 From: iory Date: Thu, 16 Apr 2020 04:27:36 +0900 Subject: [PATCH 02/75] Add total elapsed time --- pysnooper/tracer.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index be177bf..4c51553 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -296,6 +296,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) + self.start_time = datetime_module.datetime.now() sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -307,6 +308,11 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) + now = (datetime_module.datetime.min + ( + datetime_module.datetime.now() - self.start_time)).time() + now_string = pycompat.time_isoformat(now, timespec='microseconds') + self.write('Total elapsed time: {now_string}'.format(**locals())) + def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename From f822104feb84c14dbd88c1329ef43ee80f0f89ab Mon Sep 17 00:00:00 2001 From: iory Date: Thu, 16 Apr 2020 04:27:56 +0900 Subject: [PATCH 03/75] Add relative_time format --- pysnooper/tracer.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 4c51553..e43b5bf 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -201,7 +201,8 @@ class Tracer: ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), - max_variable_length=100, normalize=False): + max_variable_length=100, normalize=False, + relative_time=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -227,6 +228,7 @@ class Tracer: self.last_source_path = None self.max_variable_length = max_variable_length self.normalize = normalize + self.relative_time = relative_time def __call__(self, function_or_class): if DISABLED: @@ -357,7 +359,11 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - now = datetime_module.datetime.now().time() + if self.relative_time: + now = (datetime_module.datetime.min + + (datetime_module.datetime.now() - self.start_time)).time() + else: + now = datetime_module.datetime.now().time() now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) From caf1e1a63a2538fee519625f9095c3ab72854dbf Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 17:01:56 +0900 Subject: [PATCH 04/75] Add timedelta_isoformat --- pysnooper/pycompat.py | 6 ++++++ pysnooper/tracer.py | 12 ++++++------ 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index 5b9a481..c6b1bf7 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -80,3 +80,9 @@ else: return result +def timedelta_isoformat(timedelta, timespec='microseconds'): + assert isinstance(timedelta, datetime_module.timedelta) + if timespec != 'microseconds': + raise NotImplementedError + time = (datetime_module.datetime.min + timedelta).time() + return time_isoformat(time, timespec) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index e43b5bf..7dbd748 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -310,9 +310,8 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - now = (datetime_module.datetime.min + ( - datetime_module.datetime.now() - self.start_time)).time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') + duration = datetime_module.datetime.now() - self.start_time + now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') self.write('Total elapsed time: {now_string}'.format(**locals())) def _is_internal_frame(self, frame): @@ -360,11 +359,12 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.relative_time: - now = (datetime_module.datetime.min + - (datetime_module.datetime.now() - self.start_time)).time() + duration = datetime_module.datetime.now() - self.start_time + now_string = pycompat.timedelta_isoformat( + duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: now = datetime_module.datetime.now().time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 + now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) source_path = source_path if not self.normalize else os.path.basename(source_path) From c39a68760d555e625fe202afdfbd4009c5a250bf Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 18:29:21 +0900 Subject: [PATCH 05/75] Add depth case --- pysnooper/tracer.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 7dbd748..c02153c 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -310,9 +310,10 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - duration = datetime_module.datetime.now() - self.start_time - now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') - self.write('Total elapsed time: {now_string}'.format(**locals())) + if thread_global.depth == -1: + duration = datetime_module.datetime.now() - self.start_time + now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') + self.write('Total elapsed time: {now_string}'.format(**locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename From 32183e0489c37518d0d4453f39a2ced14570c349 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 18:30:43 +0900 Subject: [PATCH 06/75] Add BasePrintEntry and ElapsedPrintEntry --- tests/utils.py | 40 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/tests/utils.py b/tests/utils.py index 48e98cc..169d184 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -77,6 +77,31 @@ class _BaseValueEntry(_BaseEntry): self._check_content(content)) +class _BasePrintEntry(_BaseEntry): + def __init__(self, prefix=''): + _BaseEntry.__init__(self, prefix=prefix) + self.line_pattern = re.compile( + r"""^%s(?P(?: {4})*)(?P[^:]*):""" + r""" (?P.*)$""" % (re.escape(self.prefix),) + ) + + @abc.abstractmethod + def _check_preamble(self, preamble): + pass + + @abc.abstractmethod + def _check_content(self, preamble): + pass + + def check(self, s): + match = self.line_pattern.match(s) + if not match: + return False + _, preamble, content = match.groups() + return (self._check_preamble(preamble) and + self._check_content(content)) + + class VariableEntry(_BaseValueEntry): def __init__(self, name=None, value=None, stage=None, prefix='', name_regex=None, value_regex=None): @@ -195,6 +220,21 @@ class SourcePathEntry(_BaseValueEntry): return True +class ElapsedTimeEntry(_BasePrintEntry): + def __init__(self, prefix=''): + _BasePrintEntry.__init__(self, prefix=prefix) + + _preamble_pattern = re.compile( + r"""^Total elapsed time$""" + ) + + def _check_preamble(self, preamble): + return bool(self._preamble_pattern.match(preamble)) + + def _check_content(self, content): + return True + + class _BaseEventEntry(_BaseEntry): def __init__(self, source=None, source_regex=None, thread_info=None, thread_info_regex=None, prefix=''): From 57cec2b9af96b9234bdfdf9fe0f07a1df6bb525d Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 18:31:12 +0900 Subject: [PATCH 07/75] Fixed test for elapsed time --- tests/samples/exception.py | 1 + tests/samples/indentation.py | 1 + tests/samples/recursion.py | 1 + tests/test_chinese.py | 6 ++- tests/test_pysnooper.py | 71 +++++++++++++++++++++++++++++++----- 5 files changed, 68 insertions(+), 12 deletions(-) diff --git a/tests/samples/exception.py b/tests/samples/exception.py index aa663de..87642c8 100644 --- a/tests/samples/exception.py +++ b/tests/samples/exception.py @@ -46,4 +46,5 @@ TypeError: bad 12:18:08.018787 line 21 pass 12:18:08.018813 return 21 pass Return value:.. None +Total elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/indentation.py b/tests/samples/indentation.py index 9ea0318..65cb7b4 100644 --- a/tests/samples/indentation.py +++ b/tests/samples/indentation.py @@ -42,4 +42,5 @@ Source path:... Whatever Return value:.. None 21:10:42.299627 return 6 f2() Return value:.. None +Total elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/recursion.py b/tests/samples/recursion.py index 1570d1a..7edbaac 100644 --- a/tests/samples/recursion.py +++ b/tests/samples/recursion.py @@ -59,4 +59,5 @@ Starting var:.. x = 4 Return value:.. 24 20:28:17.876646 return 8 return mul(x, factorial(x - 1)) Return value:.. 24 +Total elapsed time: 00:00:00.000651 ''' diff --git a/tests/test_chinese.py b/tests/test_chinese.py index 828ad1c..90e52aa 100644 --- a/tests/test_chinese.py +++ b/tests/test_chinese.py @@ -16,7 +16,8 @@ from pysnooper import pycompat from pysnooper.variables import needs_parentheses from .utils import (assert_output, assert_sample_output, VariableEntry, CallEntry, LineEntry, ReturnEntry, OpcodeEntry, - ReturnValueEntry, ExceptionEntry, SourcePathEntry) + ReturnValueEntry, ExceptionEntry, SourcePathEntry, + ElapsedTimeEntry) from . import mini_toolbox @@ -44,6 +45,7 @@ def test_chinese(): VariableEntry(u'x', (u"'失败'" if pycompat.PY3 else None)), LineEntry(), ReturnEntry(), - ReturnValueEntry('7') + ReturnValueEntry('7'), + ElapsedTimeEntry(), ), ) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 44852f4..b321d95 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -15,7 +15,8 @@ import pysnooper from pysnooper.variables import needs_parentheses from .utils import (assert_output, assert_sample_output, VariableEntry, CallEntry, LineEntry, ReturnEntry, OpcodeEntry, - ReturnValueEntry, ExceptionEntry, SourcePathEntry) + ReturnValueEntry, ExceptionEntry, SourcePathEntry, + ElapsedTimeEntry) from . import mini_toolbox @@ -44,6 +45,7 @@ def test_string_io(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -74,6 +76,7 @@ def test_thread_info(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -125,6 +128,7 @@ def test_multi_thread_info(): name="MainThread")), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('foo', value_regex="u?'bubu'"), CallEntry('def my_function(foo):', thread_info_regex=thread_info_regex.format( @@ -142,6 +146,7 @@ def test_multi_thread_info(): name="test123")), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('foo', value_regex="u?'bibi'"), CallEntry('def my_function(foo):', thread_info_regex=thread_info_regex.format(name='bibi')), @@ -155,6 +160,7 @@ def test_multi_thread_info(): thread_info_regex=thread_info_regex.format(name='bibi')), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -188,6 +194,7 @@ def test_callable(normalize): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -240,7 +247,8 @@ def test_watch(normalize): VariableEntry('len(foo.__dict__["x"] * "abc")', '48'), LineEntry(), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -291,7 +299,8 @@ def test_watch_explode(normalize): VariableEntry('(lst + [])[3]', '10'), VariableEntry('lst + []'), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -342,7 +351,8 @@ def test_variables_classes(normalize): VariableEntry('_lst[998]', '998'), VariableEntry('_lst[999]', '999'), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -384,7 +394,8 @@ def test_single_watch_no_comma(normalize): LineEntry(), LineEntry(), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -412,7 +423,8 @@ def test_long_variable(normalize): VariableEntry('foo', value_regex=regex), LineEntry(), ReturnEntry(), - ReturnValueEntry(value_regex=regex) + ReturnValueEntry(value_regex=regex), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -440,7 +452,8 @@ def test_long_variable_with_custom_max_variable_length(normalize): VariableEntry('foo', value_regex=regex), LineEntry(), ReturnEntry(), - ReturnValueEntry(value_regex=regex) + ReturnValueEntry(value_regex=regex), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -468,7 +481,8 @@ def test_long_variable_with_infinite_max_variable_length(normalize): VariableEntry('foo', value_regex=regex), LineEntry(), ReturnEntry(), - ReturnValueEntry(value_regex=regex) + ReturnValueEntry(value_regex=regex), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -498,7 +512,8 @@ def test_repr_exception(normalize): LineEntry('bad = Bad()'), VariableEntry('bad', value='REPR FAILED'), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -561,6 +576,7 @@ def test_depth(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('20'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -600,6 +616,7 @@ def test_method_and_prefix(normalize): LineEntry(prefix='ZZZ'), ReturnEntry(prefix='ZZZ'), ReturnValueEntry(prefix='ZZZ'), + ElapsedTimeEntry(prefix='ZZZ'), ), prefix='ZZZ', normalize=normalize, @@ -634,6 +651,7 @@ def test_file_output(normalize): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -679,6 +697,7 @@ def test_confusing_decorator_lines(normalize): # back in my_function ReturnEntry(), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -700,6 +719,7 @@ def test_lambda(normalize): LineEntry(source_regex='^my_function = pysnooper.*'), ReturnEntry(source_regex='^my_function = pysnooper.*'), ReturnValueEntry('49'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -734,6 +754,7 @@ def test_unavailable_source(): LineEntry('SOURCE IS UNAVAILABLE'), ReturnEntry('SOURCE IS UNAVAILABLE'), ReturnValueEntry('7'), + ElapsedTimeEntry(), ) ) @@ -767,6 +788,7 @@ def test_no_overwrite_by_default(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -800,6 +822,7 @@ def test_overwrite(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('foo', value_regex="u?'baba'"), CallEntry('def my_function(foo):'), @@ -810,6 +833,7 @@ def test_overwrite(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -914,6 +938,7 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # In with in recursive call LineEntry('bar2(x)'), @@ -925,9 +950,11 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # In with in recursive call LineEntry('qux()'), + ElapsedTimeEntry(), # Call to bar3 from after with VariableEntry('_x', '9'), @@ -936,6 +963,7 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # -- Similar to previous few sections, # -- but from first call to foo @@ -950,9 +978,11 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # In with in first call LineEntry('qux()'), + ElapsedTimeEntry(), # Call to bar3 from after with VariableEntry('_x', '9'), @@ -961,6 +991,7 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1020,6 +1051,7 @@ def test_with_block_depth(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('20'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1086,6 +1118,7 @@ def test_cellvars(normalize): ReturnValueEntry(), ReturnEntry(), ReturnValueEntry(), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1133,6 +1166,7 @@ def test_var_order(normalize): VariableEntry("seven", "7"), ReturnEntry(), ReturnValueEntry(), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1207,6 +1241,7 @@ def test_generator(): LineEntry(), ReturnEntry(), ReturnValueEntry('0'), + ElapsedTimeEntry(), # Pause and resume: @@ -1223,6 +1258,7 @@ def test_generator(): LineEntry(), ReturnEntry(), ReturnValueEntry('2'), + ElapsedTimeEntry(), # Pause and resume: @@ -1238,7 +1274,7 @@ def test_generator(): LineEntry(), ReturnEntry(), ReturnValueEntry(None), - + ElapsedTimeEntry(), ) ) @@ -1285,6 +1321,7 @@ def test_custom_repr(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('49995000'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1313,6 +1350,7 @@ def test_custom_repr_single(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('7'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1363,6 +1401,7 @@ def test_class(normalize): LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), + ElapsedTimeEntry(), VariableEntry('self', value_regex="u?.+MyClass object"), VariableEntry('foo', value_regex="u?'baba'"), CallEntry('def my_method(self, foo):'), @@ -1371,6 +1410,7 @@ def test_class(normalize): LineEntry('return y + self.x'), ReturnEntry('return y + self.x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1409,6 +1449,7 @@ def test_class_with_decorated_method(normalize): LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), + ElapsedTimeEntry(), VariableEntry('args', value_regex=r"\(<.+>, 'baba'\)"), VariableEntry('kwargs', value_regex=r"\{\}"), VariableEntry('function', value_regex="u?.+my_method"), @@ -1418,6 +1459,7 @@ def test_class_with_decorated_method(normalize): LineEntry('return result'), ReturnEntry('return result'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1457,6 +1499,7 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), + ElapsedTimeEntry(), VariableEntry('args', value_regex=r"u?\(<.+>, 'baba'\)"), VariableEntry('kwargs', value_regex=r"u?\{\}"), VariableEntry('function', value_regex="u?.*my_method"), @@ -1475,6 +1518,7 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): LineEntry('return result'), ReturnEntry('return result'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1531,6 +1575,7 @@ def test_class_with_property(normalize): LineEntry('self._x = 0'), ReturnEntry('self._x = 0'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # Called from getter VariableEntry('self', value_regex="u?.*MyClass object"), @@ -1538,6 +1583,7 @@ def test_class_with_property(normalize): LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # Called from setter VariableEntry('self', value_regex="u?.*MyClass object"), @@ -1545,6 +1591,7 @@ def test_class_with_property(normalize): LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # Called from deleter VariableEntry('self', value_regex="u?.*MyClass object"), @@ -1552,6 +1599,7 @@ def test_class_with_property(normalize): LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1589,6 +1637,7 @@ def test_snooping_on_class_does_not_cause_base_class_to_be_snooped(normalize): LineEntry('self.method_on_base_class()'), ReturnEntry('self.method_on_base_class()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1625,6 +1674,7 @@ def test_normalize(): LineEntry('return res'), ReturnEntry('return res'), ReturnValueEntry('41'), + ElapsedTimeEntry(), ) ) @@ -1661,6 +1711,7 @@ def test_normalize_prefix(): LineEntry('return res', prefix=_prefix), ReturnEntry('return res', prefix=_prefix), ReturnValueEntry('41', prefix=_prefix), + ElapsedTimeEntry(prefix=_prefix), ) ) From ee7be80b449474ca1d3731574a73c006aeba6b89 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 19:29:21 +0900 Subject: [PATCH 08/75] Add test for relative_time --- tests/test_pysnooper.py | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index b321d95..a4219fc 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -50,6 +50,36 @@ def test_string_io(): ) +def test_relative_time(): + string_io = io.StringIO() + + @pysnooper.snoop(string_io, relative_time=True) + def my_function(foo): + x = 7 + y = 8 + return y + x + + result = my_function('baba') + assert result == 15 + output = string_io.getvalue() + assert_output( + output, + ( + SourcePathEntry(), + VariableEntry('foo', value_regex="u?'baba'"), + CallEntry('def my_function(foo):'), + LineEntry('x = 7'), + VariableEntry('x', '7'), + LineEntry('y = 8'), + VariableEntry('y', '8'), + LineEntry('return y + x'), + ReturnEntry('return y + x'), + ReturnValueEntry('15'), + ElapsedTimeEntry(), + ) + ) + + def test_thread_info(): @pysnooper.snoop(thread_info=True) From 73c2816121470925daf708700ca749d2668a36f3 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 20:04:18 +0900 Subject: [PATCH 09/75] Add README.md for relative_time --- README.md | 27 ++++++++++++++++++++++++--- 1 file changed, 24 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 12686e8..4f948f6 100644 --- a/README.md +++ b/README.md @@ -72,18 +72,18 @@ Or if you don't want to trace an entire function, you can wrap the relevant part import pysnooper import random -def foo(): +def foo(relative_time=False): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(): + with pysnooper.snoop(relative_time=relative_time): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 print(lower, mid, upper) -foo() +foo(False) ``` which outputs something like: @@ -99,6 +99,27 @@ New var:....... upper = 832 74 453.0 832 New var:....... mid = 453.0 09:37:35.882486 line 13 print(lower, mid, upper) +Total elapsed time: 00:00:00.000344 +``` + +If `relative_time` is `True`, print time format will be relative. + +```python +import pysnooper +import random + +def foo(relative_time=False): + lst = [] + for i in range(10): + lst.append(random.randrange(1, 1000)) + + with pysnooper.snoop(relative_time=relative_time): + lower = min(lst) + upper = max(lst) + mid = (lower + upper) / 2 + print(lower, mid, upper) + +foo(True) ``` # Features # From d94b0214f9ffe5e9a2097b85e39b69649f158582 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 22:04:45 +0900 Subject: [PATCH 10/75] Rename relative_time to elapsed_time --- README.md | 10 +++++----- pysnooper/tracer.py | 10 +++++++--- tests/test_pysnooper.py | 4 ++-- 3 files changed, 14 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index 4f948f6..a008b56 100644 --- a/README.md +++ b/README.md @@ -72,12 +72,12 @@ Or if you don't want to trace an entire function, you can wrap the relevant part import pysnooper import random -def foo(relative_time=False): +def foo(elapsed_time=False): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(relative_time=relative_time): + with pysnooper.snoop(elapsed_time=elapsed_time): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 @@ -102,18 +102,18 @@ New var:....... mid = 453.0 Total elapsed time: 00:00:00.000344 ``` -If `relative_time` is `True`, print time format will be relative. +If `elapsed_time` is `True`, print elapsed time format. ```python import pysnooper import random -def foo(relative_time=False): +def foo(elapsed_time=False): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(relative_time=relative_time): + with pysnooper.snoop(elapsed_time=elapsed_time): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index c02153c..8d303ae 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -198,11 +198,15 @@ class Tracer: You can also use `max_variable_length=None` to never truncate them. + Print time in elapsed time format:: + + @pysnooper.snoop(elapsed_time=True) + ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), max_variable_length=100, normalize=False, - relative_time=False): + elapsed_time=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -228,7 +232,7 @@ class Tracer: self.last_source_path = None self.max_variable_length = max_variable_length self.normalize = normalize - self.relative_time = relative_time + self.elapsed_time = elapsed_time def __call__(self, function_or_class): if DISABLED: @@ -359,7 +363,7 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - if self.relative_time: + if self.elapsed_time: duration = datetime_module.datetime.now() - self.start_time now_string = pycompat.timedelta_isoformat( duration, timespec='microseconds') if not self.normalize else ' ' * 15 diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index a4219fc..2140ca5 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -50,10 +50,10 @@ def test_string_io(): ) -def test_relative_time(): +def test_elapsed_time(): string_io = io.StringIO() - @pysnooper.snoop(string_io, relative_time=True) + @pysnooper.snoop(string_io, elapsed_time=True) def my_function(foo): x = 7 y = 8 From b886f2b504c4b0ce89df6199e4deb8b3150fe04d Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 09:12:44 +0900 Subject: [PATCH 11/75] Enable multi call --- pysnooper/tracer.py | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 8d303ae..8530589 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -217,6 +217,7 @@ class Tracer: for v in utils.ensure_tuple(watch_explode) ] self.frame_to_local_reprs = {} + self.start_times = {} self.depth = depth self.prefix = prefix self.thread_info = thread_info @@ -302,7 +303,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) - self.start_time = datetime_module.datetime.now() + self.start_times[id(calling_frame)] = datetime_module.datetime.now() sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -314,10 +315,10 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - if thread_global.depth == -1: - duration = datetime_module.datetime.now() - self.start_time - now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') - self.write('Total elapsed time: {now_string}'.format(**locals())) + start_time = self.start_times.pop(id(calling_frame)) + duration = datetime_module.datetime.now() - start_time + now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') + self.write('Total elapsed time: {now_string}'.format(**locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename @@ -364,7 +365,9 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.elapsed_time: - duration = datetime_module.datetime.now() - self.start_time + calling_frame = frame.f_back + duration = datetime_module.datetime.now() - self.start_times[ + id(calling_frame)] now_string = pycompat.timedelta_isoformat( duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: From 4779aebbe45f1326484b7a799ac519d4fd1b5d7e Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 09:28:33 +0900 Subject: [PATCH 12/75] Add indent of elapsed time --- pysnooper/tracer.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 8530589..cf957b7 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -318,7 +318,9 @@ class Tracer: start_time = self.start_times.pop(id(calling_frame)) duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') - self.write('Total elapsed time: {now_string}'.format(**locals())) + indent = ' ' * 4 * (thread_global.depth + 1) + self.write('{indent}Total elapsed time: {now_string}'.format( + **locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename From 2ac382f8563452ce982665a39c8abd99106cc9ac Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 09:35:07 +0900 Subject: [PATCH 13/75] Fixed test for elapsed time entry --- tests/samples/indentation.py | 1 + tests/samples/recursion.py | 55 ++++++++++--------- .../test_multiple_files.py | 4 +- tests/test_pysnooper.py | 1 + 4 files changed, 34 insertions(+), 27 deletions(-) diff --git a/tests/samples/indentation.py b/tests/samples/indentation.py index 65cb7b4..60f073b 100644 --- a/tests/samples/indentation.py +++ b/tests/samples/indentation.py @@ -38,6 +38,7 @@ Source path:... Whatever Return value:.. None 21:10:42.299509 return 19 f5() Return value:.. None + Total elapsed time: 00:00:00.000134 21:10:42.299577 return 10 f3() Return value:.. None 21:10:42.299627 return 6 f2() diff --git a/tests/samples/recursion.py b/tests/samples/recursion.py index 7edbaac..f1529ed 100644 --- a/tests/samples/recursion.py +++ b/tests/samples/recursion.py @@ -18,46 +18,49 @@ def main(): expected_output = ''' Source path:... Whatever Starting var:.. x = 4 -20:28:17.875295 call 5 def factorial(x): -20:28:17.875509 line 6 if x <= 1: -20:28:17.875550 line 8 return mul(x, factorial(x - 1)) +09:31:32.691599 call 5 def factorial(x): +09:31:32.691722 line 6 if x <= 1: +09:31:32.691746 line 8 return mul(x, factorial(x - 1)) Starting var:.. x = 3 - 20:28:17.875624 call 5 def factorial(x): - 20:28:17.875668 line 6 if x <= 1: - 20:28:17.875703 line 8 return mul(x, factorial(x - 1)) + 09:31:32.691781 call 5 def factorial(x): + 09:31:32.691806 line 6 if x <= 1: + 09:31:32.691823 line 8 return mul(x, factorial(x - 1)) Starting var:.. x = 2 - 20:28:17.875771 call 5 def factorial(x): - 20:28:17.875813 line 6 if x <= 1: - 20:28:17.875849 line 8 return mul(x, factorial(x - 1)) + 09:31:32.691852 call 5 def factorial(x): + 09:31:32.691875 line 6 if x <= 1: + 09:31:32.691892 line 8 return mul(x, factorial(x - 1)) Starting var:.. x = 1 - 20:28:17.875913 call 5 def factorial(x): - 20:28:17.875953 line 6 if x <= 1: - 20:28:17.875987 line 7 return 1 - 20:28:17.876021 return 7 return 1 + 09:31:32.691918 call 5 def factorial(x): + 09:31:32.691941 line 6 if x <= 1: + 09:31:32.691961 line 7 return 1 + 09:31:32.691978 return 7 return 1 Return value:.. 1 + Total elapsed time: 00:00:00.000092 Starting var:.. a = 2 Starting var:.. b = 1 - 20:28:17.876111 call 11 def mul(a, b): - 20:28:17.876151 line 12 return a * b - 20:28:17.876190 return 12 return a * b + 09:31:32.692025 call 11 def mul(a, b): + 09:31:32.692055 line 12 return a * b + 09:31:32.692075 return 12 return a * b Return value:.. 2 - 20:28:17.876235 return 8 return mul(x, factorial(x - 1)) + 09:31:32.692102 return 8 return mul(x, factorial(x - 1)) Return value:.. 2 + Total elapsed time: 00:00:00.000283 Starting var:.. a = 3 Starting var:.. b = 2 - 20:28:17.876320 call 11 def mul(a, b): - 20:28:17.876359 line 12 return a * b - 20:28:17.876397 return 12 return a * b + 09:31:32.692147 call 11 def mul(a, b): + 09:31:32.692174 line 12 return a * b + 09:31:32.692193 return 12 return a * b Return value:.. 6 - 20:28:17.876442 return 8 return mul(x, factorial(x - 1)) + 09:31:32.692216 return 8 return mul(x, factorial(x - 1)) Return value:.. 6 + Total elapsed time: 00:00:00.000468 Starting var:.. a = 4 Starting var:.. b = 6 - 20:28:17.876525 call 11 def mul(a, b): - 20:28:17.876563 line 12 return a * b - 20:28:17.876601 return 12 return a * b + 09:31:32.692259 call 11 def mul(a, b): + 09:31:32.692285 line 12 return a * b + 09:31:32.692304 return 12 return a * b Return value:.. 24 -20:28:17.876646 return 8 return mul(x, factorial(x - 1)) +09:31:32.692326 return 8 return mul(x, factorial(x - 1)) Return value:.. 24 -Total elapsed time: 00:00:00.000651 +Total elapsed time: 00:00:00.000760 ''' diff --git a/tests/test_multiple_files/test_multiple_files.py b/tests/test_multiple_files/test_multiple_files.py index 5bd233a..e217ce4 100644 --- a/tests/test_multiple_files/test_multiple_files.py +++ b/tests/test_multiple_files/test_multiple_files.py @@ -15,7 +15,8 @@ import pysnooper from pysnooper.variables import needs_parentheses from ..utils import (assert_output, assert_sample_output, VariableEntry, CallEntry, LineEntry, ReturnEntry, OpcodeEntry, - ReturnValueEntry, ExceptionEntry, SourcePathEntry) + ReturnValueEntry, ExceptionEntry, SourcePathEntry, + ElapsedTimeEntry) from .. import mini_toolbox from .multiple_files import foo @@ -45,6 +46,7 @@ def test_multiple_files(): LineEntry(), ReturnEntry(), ReturnValueEntry(), + ElapsedTimeEntry(), ) ) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 2140ca5..d4dd5f4 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -1544,6 +1544,7 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): LineEntry('return y + self.x'), ReturnEntry('return y + self.x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('result', '15'), LineEntry('return result'), ReturnEntry('return result'), From 828ffb1d3c6eb7efd58f655d7a221030ff96a889 Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 15:17:40 +0900 Subject: [PATCH 14/75] Add time_fromisoformat --- pysnooper/pycompat.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index c6b1bf7..1899ff8 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -80,6 +80,16 @@ else: return result +if sys.version_info[:2] >= (3, 7): + time_fromisoformat = datetime_module.time.fromisoformat +else: + def time_fromisoformat(isoformat_str): + hour, minute, second, microsecond = map( + int, + isoformat_str.replace('.', ':').split(':')) + return datetime_module.time(hour, minute, second, microsecond) + + def timedelta_isoformat(timedelta, timespec='microseconds'): assert isinstance(timedelta, datetime_module.timedelta) if timespec != 'microseconds': From 0c018d868e60949592b360519e6ca2be2d34883d Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 15:19:38 +0900 Subject: [PATCH 15/75] Fixed elapsed_time --- pysnooper/tracer.py | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index cf957b7..887277e 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -217,7 +217,7 @@ class Tracer: for v in utils.ensure_tuple(watch_explode) ] self.frame_to_local_reprs = {} - self.start_times = {} + self.start_times = [] self.depth = depth self.prefix = prefix self.thread_info = thread_info @@ -303,7 +303,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) - self.start_times[id(calling_frame)] = datetime_module.datetime.now() + self.start_times.append(datetime_module.datetime.now()) sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -315,7 +315,7 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - start_time = self.start_times.pop(id(calling_frame)) + start_time = self.start_times.pop(-1) duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') indent = ' ' * 4 * (thread_global.depth + 1) @@ -332,7 +332,6 @@ class Tracer: return thread_info.ljust(self.thread_info_padding) def trace(self, frame, event, arg): - ### Checking whether we should trace this line: ####################### # # # We should trace this line either if it's in the decorated function, @@ -367,9 +366,7 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.elapsed_time: - calling_frame = frame.f_back - duration = datetime_module.datetime.now() - self.start_times[ - id(calling_frame)] + duration = datetime_module.datetime.now() - self.start_times[-1] now_string = pycompat.timedelta_isoformat( duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: From 612e6ebed710f617d0da006080882c24a5e298dd Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 15:19:55 +0900 Subject: [PATCH 16/75] Add elapsed_time check for test --- tests/test_pysnooper.py | 141 ++++++++++++++++++++++++++++++++++------ tests/utils.py | 15 ++++- 2 files changed, 134 insertions(+), 22 deletions(-) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index d4dd5f4..4cdbee5 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -4,6 +4,7 @@ import io import textwrap import threading +import time import types import os import sys @@ -51,32 +52,132 @@ def test_string_io(): def test_elapsed_time(): - string_io = io.StringIO() + snoop = pysnooper.snoop(elapsed_time=True) - @pysnooper.snoop(string_io, elapsed_time=True) - def my_function(foo): - x = 7 - y = 8 - return y + x + def foo(x): + if x == 0: + bar1(x) + qux() + return - result = my_function('baba') - assert result == 15 - output = string_io.getvalue() + with snoop: + # There should be line entries for these three lines, + # no line entries for anything else in this function, + # but calls to all bar functions should be traced + foo(x - 1) + bar2(x) + qux() + int(4) + bar3(9) + return x + + @snoop + def bar1(_x): + qux() + + @snoop + def bar2(_x): + qux() + + @snoop + def bar3(_x): + qux() + + def qux(): + time.sleep(0.1) + return 9 # not traced, mustn't show up + + with mini_toolbox.OutputCapturer(stdout=False, + stderr=True) as output_capturer: + result = foo(2) + assert result == 2 + output = output_capturer.string_io.getvalue() assert_output( output, ( + # In first with SourcePathEntry(), - VariableEntry('foo', value_regex="u?'baba'"), - CallEntry('def my_function(foo):'), - LineEntry('x = 7'), - VariableEntry('x', '7'), - LineEntry('y = 8'), - VariableEntry('y', '8'), - LineEntry('return y + x'), - ReturnEntry('return y + x'), - ReturnValueEntry('15'), - ElapsedTimeEntry(), - ) + VariableEntry('x', '2'), + VariableEntry('bar1'), + VariableEntry('bar2'), + VariableEntry('bar3'), + VariableEntry('foo'), + VariableEntry('qux'), + VariableEntry('snoop'), + LineEntry('foo(x - 1)'), + + # In with in recursive call + VariableEntry('x', '1'), + VariableEntry('bar1'), + VariableEntry('bar2'), + VariableEntry('bar3'), + VariableEntry('foo'), + VariableEntry('qux'), + VariableEntry('snoop'), + LineEntry('foo(x - 1)'), + + # Call to bar1 from if block outside with + VariableEntry('_x', '0'), + VariableEntry('qux'), + CallEntry('def bar1(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # In with in recursive call + LineEntry('bar2(x)'), + + # Call to bar2 from within with + VariableEntry('_x', '1'), + VariableEntry('qux'), + CallEntry('def bar2(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # In with in recursive call + LineEntry('qux()'), + ElapsedTimeEntry(0.4), + + # Call to bar3 from after with + VariableEntry('_x', '9'), + VariableEntry('qux'), + CallEntry('def bar3(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # -- Similar to previous few sections, + # -- but from first call to foo + + # In with in first call + LineEntry('bar2(x)'), + + # Call to bar2 from within with + VariableEntry('_x', '2'), + VariableEntry('qux'), + CallEntry('def bar2(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # In with in first call + LineEntry('qux()'), + ElapsedTimeEntry(0.7), + + # Call to bar3 from after with + VariableEntry('_x', '9'), + VariableEntry('qux'), + CallEntry('def bar3(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + ), ) diff --git a/tests/utils.py b/tests/utils.py index 169d184..2b73555 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -221,8 +221,13 @@ class SourcePathEntry(_BaseValueEntry): class ElapsedTimeEntry(_BasePrintEntry): - def __init__(self, prefix=''): + + def __init__(self, elapsed_time_value=None, + tolerance=0.05, + prefix=''): _BasePrintEntry.__init__(self, prefix=prefix) + self.elapsed_time_value = elapsed_time_value + self.tolerance = tolerance _preamble_pattern = re.compile( r"""^Total elapsed time$""" @@ -232,7 +237,13 @@ class ElapsedTimeEntry(_BasePrintEntry): return bool(self._preamble_pattern.match(preamble)) def _check_content(self, content): - return True + if self.elapsed_time_value: + time = pysnooper.pycompat.time_fromisoformat(content) + sec = (time.hour * 60 + time.minute) * 60 + time.second + \ + time.microsecond * (10 ** -6) + return abs(sec - self.elapsed_time_value) <= self.tolerance + else: + return True class _BaseEventEntry(_BaseEntry): From 35d3bc2db165aecbc4fafa1fd3ed6bd0ced30059 Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 18:00:29 +0900 Subject: [PATCH 17/75] Delete default value of timedelta_isoformat --- pysnooper/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 887277e..c7d6e49 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -317,7 +317,7 @@ class Tracer: start_time = self.start_times.pop(-1) duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') + now_string = pycompat.timedelta_isoformat(duration) indent = ' ' * 4 * (thread_global.depth + 1) self.write('{indent}Total elapsed time: {now_string}'.format( **locals())) From 444ea173147534e8c03b44eaf55c29f7bc026c8c Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 18:24:57 +0900 Subject: [PATCH 18/75] Refactor the timedelta_isoformat --- pysnooper/pycompat.py | 7 ++----- pysnooper/tracer.py | 2 +- 2 files changed, 3 insertions(+), 6 deletions(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index 1899ff8..c6b23b3 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -90,9 +90,6 @@ else: return datetime_module.time(hour, minute, second, microsecond) -def timedelta_isoformat(timedelta, timespec='microseconds'): - assert isinstance(timedelta, datetime_module.timedelta) - if timespec != 'microseconds': - raise NotImplementedError +def timedelta_isoformat(timedelta): time = (datetime_module.datetime.min + timedelta).time() - return time_isoformat(time, timespec) + return time_isoformat(time) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index c7d6e49..1c9103b 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -368,7 +368,7 @@ class Tracer: if self.elapsed_time: duration = datetime_module.datetime.now() - self.start_times[-1] now_string = pycompat.timedelta_isoformat( - duration, timespec='microseconds') if not self.normalize else ' ' * 15 + duration) if not self.normalize else ' ' * 15 else: now = datetime_module.datetime.now().time() now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 From 0cb6df1f7b5bab9ca98b6afd5442dd9306328282 Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 23:22:46 +0900 Subject: [PATCH 19/75] Fixed multi thread case of elapsed_time --- pysnooper/tracer.py | 26 +++++++++++++++++--------- 1 file changed, 17 insertions(+), 9 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 1c9103b..e6a4a65 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -217,7 +217,7 @@ class Tracer: for v in utils.ensure_tuple(watch_explode) ] self.frame_to_local_reprs = {} - self.start_times = [] + self.start_times = {} self.depth = depth self.prefix = prefix self.thread_info = thread_info @@ -303,7 +303,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) - self.start_times.append(datetime_module.datetime.now()) + self.start_times[calling_frame] = datetime_module.datetime.now() sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -315,12 +315,14 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - start_time = self.start_times.pop(-1) - duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat(duration) - indent = ' ' * 4 * (thread_global.depth + 1) - self.write('{indent}Total elapsed time: {now_string}'.format( - **locals())) + start_time = self.start_times.pop(calling_frame, None) + # TODO(Fix case of start_time is None) + if start_time: + duration = datetime_module.datetime.now() - start_time + now_string = pycompat.timedelta_isoformat(duration) + indent = ' ' * 4 * (thread_global.depth + 1) + self.write('{indent}Total elapsed time: {now_string}'.format( + **locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename @@ -366,7 +368,11 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.elapsed_time: - duration = datetime_module.datetime.now() - self.start_times[-1] + if frame not in self.start_times: + self.start_times[frame] = start_time = datetime_module.datetime.now() + else: + start_time = self.start_times[frame] + duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat( duration) if not self.normalize else ' ' * 15 else: @@ -458,6 +464,8 @@ class Tracer: if event == 'return': del self.frame_to_local_reprs[frame] + if self.elapsed_time: + del self.start_times[frame] thread_global.depth -= 1 if not ended_by_exception: From 48cc9d94cdb102064fb6b3248c1d2b8f288cb96f Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 23:37:03 +0900 Subject: [PATCH 20/75] Fixed timedelta_isoformat --- pysnooper/pycompat.py | 4 ++-- pysnooper/tracer.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index c6b23b3..fedb3a5 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -90,6 +90,6 @@ else: return datetime_module.time(hour, minute, second, microsecond) -def timedelta_isoformat(timedelta): +def timedelta_isoformat(timedelta, timespec='microseconds'): time = (datetime_module.datetime.min + timedelta).time() - return time_isoformat(time) + return time_isoformat(time, timespec) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index e6a4a65..7a56d3b 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -374,7 +374,7 @@ class Tracer: start_time = self.start_times[frame] duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat( - duration) if not self.normalize else ' ' * 15 + duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: now = datetime_module.datetime.now().time() now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 From 43ed249e8cff6c630d5664321cc4f95c06a61998 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Tue, 21 Apr 2020 14:17:29 +0300 Subject: [PATCH 21/75] Massaging some code --- ADVANCED_USAGE.md | 5 ++- AUTHORS | 1 + README.md | 29 +++-------------- pysnooper/pycompat.py | 24 +++++++------- pysnooper/tracer.py | 61 +++++++++++++++++++++--------------- tests/samples/exception.py | 2 +- tests/samples/indentation.py | 4 +-- tests/samples/recursion.py | 8 ++--- tests/test_pysnooper.py | 4 +-- tests/utils.py | 55 +++++++++----------------------- 10 files changed, 81 insertions(+), 112 deletions(-) diff --git a/ADVANCED_USAGE.md b/ADVANCED_USAGE.md index 5a95899..aa63618 100644 --- a/ADVANCED_USAGE.md +++ b/ADVANCED_USAGE.md @@ -86,4 +86,7 @@ can customize that: @pysnooper.snoop(max_variable_length=200) ``` -You can also use `max_variable_length=None` to never truncate them. \ No newline at end of file +You can also use `max_variable_length=None` to never truncate them. + +Use `relative_time=True` to show timestamps relative to start time rather than +wall time. \ No newline at end of file diff --git a/AUTHORS b/AUTHORS index 1066728..0035467 100644 --- a/AUTHORS +++ b/AUTHORS @@ -21,3 +21,4 @@ pikez Jonathan Reichelt Gjertsen Guoqiang Ding Itamar.Raviv +iory diff --git a/README.md b/README.md index a008b56..627a757 100644 --- a/README.md +++ b/README.md @@ -64,6 +64,7 @@ Modified var:.. bits = [1, 1, 0] 15:29:11.327032 line 10 return bits 15:29:11.327032 return 10 return bits Return value:.. [1, 1, 0] +Elapsed time: 00:00:00.000001 ``` Or if you don't want to trace an entire function, you can wrap the relevant part in a `with` block: @@ -72,18 +73,18 @@ Or if you don't want to trace an entire function, you can wrap the relevant part import pysnooper import random -def foo(elapsed_time=False): +def foo(): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(elapsed_time=elapsed_time): + with pysnooper.snoop(): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 print(lower, mid, upper) -foo(False) +foo() ``` which outputs something like: @@ -99,27 +100,7 @@ New var:....... upper = 832 74 453.0 832 New var:....... mid = 453.0 09:37:35.882486 line 13 print(lower, mid, upper) -Total elapsed time: 00:00:00.000344 -``` - -If `elapsed_time` is `True`, print elapsed time format. - -```python -import pysnooper -import random - -def foo(elapsed_time=False): - lst = [] - for i in range(10): - lst.append(random.randrange(1, 1000)) - - with pysnooper.snoop(elapsed_time=elapsed_time): - lower = min(lst) - upper = max(lst) - mid = (lower + upper) / 2 - print(lower, mid, upper) - -foo(True) +Elapsed time: 00:00:00.000344 ``` # Features # diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index fedb3a5..247dbde 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -80,16 +80,16 @@ else: return result -if sys.version_info[:2] >= (3, 7): - time_fromisoformat = datetime_module.time.fromisoformat -else: - def time_fromisoformat(isoformat_str): - hour, minute, second, microsecond = map( - int, - isoformat_str.replace('.', ':').split(':')) - return datetime_module.time(hour, minute, second, microsecond) - - -def timedelta_isoformat(timedelta, timespec='microseconds'): +def timedelta_format(timedelta): time = (datetime_module.datetime.min + timedelta).time() - return time_isoformat(time, timespec) + return time_isoformat(time, timespec='microseconds') + +def timedelta_parse(s): + hours, minutes, seconds, microseconds = map( + int, + s.replace('.', ':').split(':') + ) + return datetime_module.timedelta(hours=hours, minutes=minutes, + seconds=seconds, + microseconds=microseconds) + diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 7a56d3b..4b4ac05 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -198,15 +198,14 @@ class Tracer: You can also use `max_variable_length=None` to never truncate them. - Print time in elapsed time format:: + Show timestamps relative to start time rather than wall time:: - @pysnooper.snoop(elapsed_time=True) + @pysnooper.snoop(relative_time=True) ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), - max_variable_length=100, normalize=False, - elapsed_time=False): + max_variable_length=100, normalize=False, relative_time=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -233,7 +232,7 @@ class Tracer: self.last_source_path = None self.max_variable_length = max_variable_length self.normalize = normalize - self.elapsed_time = elapsed_time + self.relative_time = relative_time def __call__(self, function_or_class): if DISABLED: @@ -315,14 +314,17 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - start_time = self.start_times.pop(calling_frame, None) - # TODO(Fix case of start_time is None) - if start_time: - duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat(duration) - indent = ' ' * 4 * (thread_global.depth + 1) - self.write('{indent}Total elapsed time: {now_string}'.format( - **locals())) + ### Writing elapsed time: ############################################# + # # + start_time = self.start_times.pop(calling_frame) + duration = datetime_module.datetime.now() - start_time + elapsed_time_string = pycompat.timedelta_format(duration) + indent = ' ' * 4 * (thread_global.depth + 1) + self.write( + '{indent}Elapsed time: {elapsed_time_string}'.format(**locals()) + ) + # # + ### Finished writing elapsed time. #################################### def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename @@ -334,6 +336,7 @@ class Tracer: return thread_info.ljust(self.thread_info_padding) def trace(self, frame, event, arg): + ### Checking whether we should trace this line: ####################### # # # We should trace this line either if it's in the decorated function, @@ -367,17 +370,26 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - if self.elapsed_time: - if frame not in self.start_times: - self.start_times[frame] = start_time = datetime_module.datetime.now() - else: + ### Making timestamp: ################################################# + # # + if self.normalize: + timestamp = ' ' * 15 + elif self.relative_time: + try: start_time = self.start_times[frame] + except KeyError: + start_time = self.start_times[frame] = \ + datetime_module.datetime.now() duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat( - duration, timespec='microseconds') if not self.normalize else ' ' * 15 + timestamp = pycompat.timedelta_format(duration) else: - now = datetime_module.datetime.now().time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 + timestamp = pycompat.time_isoformat( + datetime_module.datetime.now().time(), + timespec='microseconds' + ) + # # + ### Finished making timestamp. ######################################## + line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) source_path = source_path if not self.normalize else os.path.basename(source_path) @@ -459,13 +471,12 @@ class Tracer: self.write('{indent}Call ended by exception'. format(**locals())) else: - self.write(u'{indent}{now_string} {thread_info}{event:9} ' + self.write(u'{indent}{timestamp} {thread_info}{event:9} ' u'{line_no:4} {source_line}'.format(**locals())) if event == 'return': - del self.frame_to_local_reprs[frame] - if self.elapsed_time: - del self.start_times[frame] + self.frame_to_local_reprs.pop(frame, None) + self.start_times.pop(frame, None) thread_global.depth -= 1 if not ended_by_exception: diff --git a/tests/samples/exception.py b/tests/samples/exception.py index 87642c8..bf6196f 100644 --- a/tests/samples/exception.py +++ b/tests/samples/exception.py @@ -46,5 +46,5 @@ TypeError: bad 12:18:08.018787 line 21 pass 12:18:08.018813 return 21 pass Return value:.. None -Total elapsed time: 00:00:00.000885 +Elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/indentation.py b/tests/samples/indentation.py index 60f073b..651dfce 100644 --- a/tests/samples/indentation.py +++ b/tests/samples/indentation.py @@ -38,10 +38,10 @@ Source path:... Whatever Return value:.. None 21:10:42.299509 return 19 f5() Return value:.. None - Total elapsed time: 00:00:00.000134 + Elapsed time: 00:00:00.000134 21:10:42.299577 return 10 f3() Return value:.. None 21:10:42.299627 return 6 f2() Return value:.. None -Total elapsed time: 00:00:00.000885 +Elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/recursion.py b/tests/samples/recursion.py index f1529ed..825f511 100644 --- a/tests/samples/recursion.py +++ b/tests/samples/recursion.py @@ -35,7 +35,7 @@ Starting var:.. x = 4 09:31:32.691961 line 7 return 1 09:31:32.691978 return 7 return 1 Return value:.. 1 - Total elapsed time: 00:00:00.000092 + Elapsed time: 00:00:00.000092 Starting var:.. a = 2 Starting var:.. b = 1 09:31:32.692025 call 11 def mul(a, b): @@ -44,7 +44,7 @@ Starting var:.. x = 4 Return value:.. 2 09:31:32.692102 return 8 return mul(x, factorial(x - 1)) Return value:.. 2 - Total elapsed time: 00:00:00.000283 + Elapsed time: 00:00:00.000283 Starting var:.. a = 3 Starting var:.. b = 2 09:31:32.692147 call 11 def mul(a, b): @@ -53,7 +53,7 @@ Starting var:.. x = 4 Return value:.. 6 09:31:32.692216 return 8 return mul(x, factorial(x - 1)) Return value:.. 6 - Total elapsed time: 00:00:00.000468 + Elapsed time: 00:00:00.000468 Starting var:.. a = 4 Starting var:.. b = 6 09:31:32.692259 call 11 def mul(a, b): @@ -62,5 +62,5 @@ Starting var:.. x = 4 Return value:.. 24 09:31:32.692326 return 8 return mul(x, factorial(x - 1)) Return value:.. 24 -Total elapsed time: 00:00:00.000760 +Elapsed time: 00:00:00.000760 ''' diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 4cdbee5..2623f35 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -51,8 +51,8 @@ def test_string_io(): ) -def test_elapsed_time(): - snoop = pysnooper.snoop(elapsed_time=True) +def test_relative_time(): + snoop = pysnooper.snoop(relative_time=True) def foo(x): if x == 0: diff --git a/tests/utils.py b/tests/utils.py index 2b73555..10fd249 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -77,29 +77,28 @@ class _BaseValueEntry(_BaseEntry): self._check_content(content)) -class _BasePrintEntry(_BaseEntry): - def __init__(self, prefix=''): +class ElapsedTimeEntry(_BaseEntry): + def __init__(self, elapsed_time_value=None, tolerance=0.2, prefix=''): _BaseEntry.__init__(self, prefix=prefix) self.line_pattern = re.compile( - r"""^%s(?P(?: {4})*)(?P[^:]*):""" - r""" (?P.*)$""" % (re.escape(self.prefix),) + r"""^%s(?P(?: {4})*)Elapsed time: (?P