Add elapsed time and elapsed_time format option.

[iory]

Thank you for your awesome debug tool!

This PR added a printing total elapsed time and elapsed_time format option. The test code is as follows.

import argparse
import time

import pysnooper

def test1(elapsed_time=False):
    with pysnooper.snoop(elapsed_time=elapsed_time):
        time.sleep(1.0)

def test2(elapsed_time=False):
    a = 1
    b = 2
    c = 3
    with pysnooper.snoop(elapsed_time=elapsed_time):
        tmp = a + b
        tmp2 = a - b

test1(elapsed_time=False)
print()
test1(elapsed_time=True)
print()
test2(elapsed_time=False)
print()
test2(elapsed_time=True)

The result is as follows.

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = False
22:14:11.952148 line         9         time.sleep(1.0)
Total elapsed time: 00:00:01.002691

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = True
00:00:00.000007 line         9         time.sleep(1.0)
Total elapsed time: 00:00:01.003509

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = False
New var:....... a = 1
New var:....... b = 2
New var:....... c = 3
22:14:13.959043 line        17         tmp = a + b
New var:....... tmp = 3
22:14:13.959235 line        18         tmp2 = a - b
Total elapsed time: 00:00:00.000334

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = True
New var:....... a = 1
New var:....... b = 2
New var:....... c = 3
00:00:00.000011 line        17         tmp = a + b
New var:....... tmp = 3
00:00:00.000295 line        18         tmp2 = a - b
Total elapsed time: 00:00:00.000409

[cool-RR]

Looks cool! I'll review it when I have time.

[cool-RR]

Looks good.

1. In the code you added to __exit__, you should do duration = datetime_module.datetime.now() - self.start_time. Then duration is a timedelta object. You should create a timedelta_format function in the pycompat module, where you could put the hack you've used in lines 313-314. Make sure there's a bit of testing for that hack.
2. Add tests for both the features you added.
3. Add documentation for relative_time similarly to the other flags.
4. Modify the example in the readme to show the duration like your new code shows.
5. Lines 362-366 are also hacky, but I'll fix them after you finish, so don't worry about that.

[alexmojaki]

There's just one start time being stored in the tracer. How does this handle the same tracer tracking multiple calls at the same time? You probably need a mapping from frames to times.

[cool-RR]

@alexmojaki Nice catch, I didn't think of that. Let's see what @iory comes up with.

@iory I'm happy to see these commits. When you're ready for me to review, let me know.

[iory]

@alexmojaki
Thank you for your comment. I would like to cope with that case. Could you let me know the test case?

@cool-RR I've fixed it based on your comments. Please review it.

[alexmojaki]

See for example reusing a tracer in https://github.com/cool-RR/PySnooper/blob/cba23d18a8809aef304718ddfec32d6249e12b34/tests/test_pysnooper.py#L900

Or have a test case with a recursive call.

Also try to test that the outputted time makes sense, e.g. put a sleep(0.1) somewhere and make sure the elapsed time is greater than that.

Are these tests passing? I don't see any normalising of the output for assert_sample_output.

[cool-RR]

@bittner Didn't we use to have tests running automatically on every PR? I thought we did but I'm not seeing them running now. Am I misremembering?

[cool-RR]

@iory I reviewed the code. There are a few problems, but I'll fix them when your PR is ready so don't worry about these. Address the 3 points that Alex raised and I think we'll be done.

[iory]

@alexmojaki Thank you for your reviews! I modified the code and coped with the recursive call case. (also I checked pytest passed.) Could you check the code?

The Test case's result is as follows

import time

import pysnooper

snoop = pysnooper.snoop(elapsed_time=True, depth=2)

def foo(x, depth):
    if x == 0:
        bar1(x, depth)
        qux()
        return

    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, depth + 1)
        bar2(x, depth)
        qux()
    int(4)
    bar3(9, depth)
    return x

@snoop
def bar1(_x, depth):
    qux()

@snoop
def bar2(_x, depth):
    qux()

@snoop
def bar3(_x, depth):
    qux()

def qux():
    time.sleep(1.0)
    return 9  # not traced, mustn't show up

result = foo(2, 1)

Source path:... <ipython-input-1-5287e53df31e>
New var:....... x = 2
New var:....... depth = 1
00:00:00.000019 line        18         foo(x - 1, depth + 1)
Starting var:.. x = 1
Starting var:.. depth = 2
00:00:00.000240 call         8 def foo(x, depth):
00:00:00.000307 line         9     if x == 0:
00:00:00.000367 line        14     with snoop:
00:00:00.000015 line        18         foo(x - 1, depth + 1)
    Starting var:.. x = 0
    Starting var:.. depth = 3
    00:00:00.000112 call         8 def foo(x, depth):
    00:00:00.000221 line         9     if x == 0:
    00:00:00.000290 line        10         bar1(x, depth)
        Starting var:.. _x = 0
        Starting var:.. depth = 3
        00:00:00.000011 call        27 def bar1(_x, depth):
        00:00:00.000119 line        28     qux()
            00:00:00.000188 call        41 def qux():
            00:00:00.000249 line        42     time.sleep(1.0)

            00:00:01.004509 line        43     return 9  # not traced, mustn't show up
            00:00:01.004653 return      43     return 9  # not traced, mustn't show up
            Return value:.. 9
        00:00:01.004749 return      28     qux()
        Return value:.. None
        Total elapsed time: 00:00:01.004881
    00:00:01.005316 line        11         qux()
    00:00:02.008273 line        12         return
    00:00:02.008526 return      12         return
    Return value:.. None
00:00:02.008684 line        19         bar2(x, depth)
    Starting var:.. _x = 1
    Starting var:.. depth = 2
    00:00:00.000010 call        32 def bar2(_x, depth):
    00:00:00.000160 line        33     qux()
        00:00:00.000247 call        41 def qux():
        00:00:00.000303 line        42     time.sleep(1.0)
        00:00:01.005015 line        43     return 9  # not traced, mustn't show up
        00:00:01.005159 return      43     return 9  # not traced, mustn't show up
        Return value:.. 9
    00:00:01.005244 return      33     qux()
    Return value:.. None
    Total elapsed time: 00:00:01.005352
00:00:03.014215 line        20         qux()
    00:00:03.014284 call        41 def qux():
    00:00:03.014337 line        42     time.sleep(1.0)
    00:00:04.015809 line        43     return 9  # not traced, mustn't show up
    00:00:04.015960 return      43     return 9  # not traced, mustn't show up
    Return value:.. 9
    Total elapsed time: 00:00:04.016078
New var:....... x = 1
New var:....... depth = 2
00:00:04.016723 line        21     int(4)
00:00:04.016810 line        22     bar3(9, depth)
    Starting var:.. _x = 9
    Starting var:.. depth = 2
    00:00:00.000007 call        37 def bar3(_x, depth):
    00:00:00.000085 line        38     qux()
        00:00:00.000232 call        41 def qux():
        00:00:00.000365 line        42     time.sleep(1.0)
        00:00:01.003332 line        43     return 9  # not traced, mustn't show up
        00:00:01.003537 return      43     return 9  # not traced, mustn't show up
        Return value:.. 9
    00:00:01.003692 return      38     qux()
    Return value:.. None
    Total elapsed time: 00:00:01.003856
00:00:05.020806 line        23     return x
00:00:05.020910 return      23     return x
Return value:.. 1
00:00:05.020978 line        19         bar2(x, depth)
Starting var:.. _x = 2
Starting var:.. depth = 1
00:00:00.000007 call        32 def bar2(_x, depth):
00:00:00.000084 line        33     qux()
    00:00:00.000143 call        41 def qux():
    00:00:00.000231 line        42     time.sleep(1.0)
    00:00:01.002687 line        43     return 9  # not traced, mustn't show up
    00:00:01.002878 return      43     return 9  # not traced, mustn't show up
    Return value:.. 9
00:00:01.002994 return      33     qux()
Return value:.. None
Total elapsed time: 00:00:01.003124
00:00:06.024215 line        20         qux()
00:00:06.024290 call        41 def qux():
00:00:06.024346 line        42     time.sleep(1.0)
00:00:07.025803 line        43     return 9  # not traced, mustn't show up
00:00:07.026055 return      43     return 9  # not traced, mustn't show up
Return value:.. 9
Total elapsed time: 00:00:07.026177
Starting var:.. _x = 9
Starting var:.. depth = 1
00:00:00.000009 call        37 def bar3(_x, depth):
00:00:00.000104 line        38     qux()
    00:00:00.000162 call        41 def qux():
    00:00:00.000208 line        42     time.sleep(1.0)
    00:00:01.001732 line        43     return 9  # not traced, mustn't show up
    00:00:01.001922 return      43     return 9  # not traced, mustn't show up
    Return value:.. 9
00:00:01.002199 return      38     qux()
Return value:.. None
Total elapsed time: 00:00:01.002651

[alexmojaki]

I see you've tested that the time after "Total elapsed time:" is correct, but there's no testing of the time that appears in every line.

[alexmojaki]

By the way, what's the use case for all this? Why not use a profiling tool specially designed for the task? Have you tried tools like:

• https://github.com/csurfer/pyheat
• https://github.com/uber-archive/pyflame or https://github.com/baverman/flameprof/
• https://docs.python.org/3.8/library/profile.html

[iory]

what's the use case for all this?

I want to know what the value is and how long it takes while debugging. Pysnooper is a poor man's debugger, you know? Is this feature not suitable for the pysnooper concept?

[alexmojaki]

Even assuming that it's suitable, it's good to think carefully about what exactly we want to achieve and then design the user interface around that.

[cool-RR]

I think that both features are good. Yes, there are dedicated profilers, but since PySnooper is already there and has the information, and it's dumping a big chunk of text anyway, it's helpful to include it.

[cool-RR]

I suggest that we freeze the review. I'll merge later today and add my fixes, and then both of you could reopen any discussions for another pr.

[alexmojaki]

Still need to track times per frame.

[cool-RR]

Right, so let's limit the discussion to this.

[iory]

Thank you for yours discussion. I modified start_frames like frame_to_local_reprs.

[bittner]

@bittner Didn't we use to have tests running automatically on every PR? I thought we did but I'm not seeing them running now. Am I misremembering?

The builds do run, but the integration with GitHub seems broken. Hence the green tick doesn't show next to commits and new PRs.

You may want to check the repository settings. It's probably that you withdrew permission for Travis CI unconsciously or by mistake.

[cool-RR]

@bittner Thanks, I fixed that now.

@iory , I fixed some of the issues, merged the commits and made a new release. Congrats on your contribution!

@iory @alexmojaki Feel free to look into my commit and see the changes I made. If any of them could be a problem, or you have a possible improvement, please open an issue/PR.

[iory]

Thank you!