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