`relative_time` fails with generator

cool-RR commented 4 years ago

I found a bug with relative_time when used with a generator. The times shown seem to be reset at some point. I don't know whether this bug could also happen without generators.

@iory Can you take a look at this bug?

@alexmojaki I suspect that this has something to do with the start_times dict you suggested.

Sample:

import pysnooper
import time

def g():
    time.sleep(0.1)
    yield 8
    time.sleep(0.1)

@pysnooper.snoop(relative_time=True)
def f():
    time.sleep(0.1)
    yield from g()
    time.sleep(0.1)

tuple(f())

Output:

Source path:... C:\Users\Administrator\Desktop\fuck.py
00:00:00.000000 call        10 def f():
00:00:00.000000 line        11     time.sleep(0.1)
00:00:00.100000 line        12     yield from g()
00:00:00.200000 return      12     yield from g()
Return value:.. 8
Elapsed time: 00:00:00.200000
00:00:00.000000 call        12     yield from g()
00:00:00.100000 exception   12     yield from g()
StopIteration
00:00:00.100000 line        13     time.sleep(0.1)
00:00:00.207002 return      13     time.sleep(0.1)
Return value:.. None
Elapsed time: 00:00:00.207002

alexmojaki commented 4 years ago

Well I see a call in the middle, so I think that's just how PySnooper interprets generators resuming execution, like what I mentioned here: https://github.com/alexmojaki/snoop/wiki/Comparison-to-PySnooper#generators

cool-RR commented 4 years ago

Hmm, interesting. Do you think that if I were to cherry-pick that feature out of snoop, this bug would be solved without any changes to the start_times logic?

alexmojaki commented 4 years ago

I don't think it would be that simple, but I think the process of extracting that feature would probably make it pretty easy to understand and fix this bug.

I'm guessing the reset happens here https://github.com/cool-RR/PySnooper/blob/master/pysnooper/tracer.py#L381

cool-RR commented 4 years ago

Awesome, thanks for the information. I'll check it out.

On Mon, May 4, 2020 at 6:54 PM Alex Hall notifications@github.com wrote:

I don't think it would be that simple, but I think the process of extracting that feature would probably make it pretty easy to understand and fix this bug.

I'm guessing the reset happens here https://github.com/cool-RR/PySnooper/blob/master/pysnooper/tracer.py#L381

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/cool-RR/PySnooper/issues/182#issuecomment-623548134, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAN3SUXYWLKHVD7FZCOWNDRP3QLTANCNFSM4MY3EIIQ .

cool-RR commented 4 years ago

God damn it, this is complicated.

I made a failing test, but figuring out how to fix the behavior is hard. @iory , @alexmojaki if any of you could be interested in trying this bug, feel free.

cool-RR / PySnooper

`relative_time` fails with generator #182