#🔒 Profiling and timing stackframes (and its children) correctly within a callstack

92 messages · Page 1 of 1 (latest)

quiet osprey
#

Relevant code resides at; https://github.com/BruDriguezz/stackframe-tracer/tree/feature/implement-mvp
Relevant files are; _tracer.py
Issue; Timing logic seems to be incorrect, given it yields in incorrect (and sometimes negative) timing values for the inclusive and exclusive times of a stackframe.

graphviz4.png
vital edgeBOT
#

@quiet osprey

Python help channel opened

Remember to:

  • Ask your Python question, not if you can ask or if there's an expert who can help.
  • Show a code sample as text (rather than a screenshot) and the error message, if you've got one.
  • Explain what you expect to happen and what actually happens.

:warning: Do not pip install anything that isn't related to your question, especially if asked to over DMs.

Closes after a period of inactivity, or when you send !close.
quiet osprey
#

@lucid elm @silent surge

#

Actually, I should commit my latest changes for the sake of simplicity...

#

Hold,

#

Push done

#

Relevant file is now _tracer.py

lucid elm
#

You should explain what the problem is

quiet osprey
lucid elm
#

keep in mind: you are MUCH more familiar with what is happening here than anyone else.

lucid elm
silent surge
#

This goes right over my head
I'll try to help but I'm missing a lot of the domain knowledge here

quiet osprey
#

The exclusive time is the one which seems incorrect - more specifically, it either doesn't add up to the total runtime cost of the program, or it just goes negative entirely

#

Let me walk through how it calculates it real quick;

lucid elm
#

btw: you don't want Decimal here at all.

quiet osprey
# 
@dataclass
class Stackframe:
    name: str
    calls: int = 0
    average: Optional[Decimal] = None

    _start: Decimal = Decimal(0)
    _pause: Decimal = Decimal(0)
    _end: Decimal = Decimal(0)
    _times: list[Decimal] = field(default_factory=list)

    children: dict[str, Stackframe] = field(default_factory=dict)
    parent: Optional[Stackframe] = None

    exclusive_time: Decimal = Decimal(0)
    inclusive_time: Decimal = 0

    def start(self) -> None:
        self.calls += 1
        self._start = Decimal(perf_counter())
        if self.parent:
            self.parent.pause()

    def pause(self) -> None:
        self._pause = Decimal(perf_counter())
        elapsed = self._pause - self._start
        self._times.append(elapsed)
        self.inclusive_time += elapsed

    def resume(self) -> None:
        paused_duration = self._pause - self._start
        self._start = Decimal(perf_counter()) - paused_duration

    def stop(self) -> None:
        self._end = Decimal(perf_counter())
        elapsed = self._end - self._start
        self._times.append(elapsed)
        self.inclusive_time = sum(self._times)
        
        children_inclusive_time = sum(child.inclusive_time for child in self.children.values())
        self.exclusive_time = sum(self._times) / len(self._times) if self._times else Decimal(0)

        if self.parent:
            self.parent.inclusive_time += self.inclusive_time
            self.parent.resume()

        self.average = self.inclusive_time / self.calls if self.calls > 0 else Decimal(0)
quiet osprey
lucid elm
quiet osprey
#

Oh, welp. Should I use time.perf_counter_ns then?

lucid elm
#

to find the negative times, I would add some asserts: assert elapsed > 0 or whatever.

lucid elm
quiet osprey
lucid elm
quiet osprey
#

The exclusive time is calculated by subtracting the children's inclusive time with its own exclusive time

#

Okay, I'll write an assert and come back to you?

lucid elm
#

perf_counter_ns() would be fine also

quiet osprey
#

I have a suspicion that it may be caused by the stackframe's exclusive time being too small

#

Follow me for a second;

If a parent stackframe has the exclusive runtime of 0.2s and the cumulative time of all its descendants amount to far more, then it should go negative

#

But the exclusive time inherently counts the inclusive time because it's time is also spent waiting for its descendants to return

#

And therefore subtracting the exclusive time, which already counts the inclusive time initially, with their children's inclusive time should give a positive

#

And that cascades up

lucid elm
#

sounds plausible

quiet osprey
#

Running with your changes, I'll post results

lucid elm
#

also, remember the first rule of debugging: When In Doubt, Print More Out

quiet osprey
#

AssertionError: Negative elapsed time detected: -197988304 ns in test_function_d (/home/elkbyte/Dev/stackframe-tracer/src/stacktracer/_tracer.py:137)

Well shit.

#

I think I'll just fill the entire thing with prints.

#

And post results

#

So we can go through it

#

Oh wow what a dump.

#

Let me just redirect that to a file

#

Oh. Well.

#

I can't post it.

#

!paste

vital edgeBOT
#
Pasting large amounts of code

If your code is too long to fit in a codeblock in Discord, you can paste your code here:
https://paste.pythondiscord.com/

After pasting your code, save it by clicking the Paste! button in the bottom left, or by pressing CTRL + S. After doing that, you will be navigated to the new paste's page. Copy the URL and post it here so others can see it.

quiet osprey
#

There's thousands and thousands line more here, but they are mostly filler trash. I should tone it down and get more useful debugs.

#

But from that small snippet, we can see the negative behavior still.

#

Is it because of pprint, perhaps that it's messing everything up...?

#

Here, a lot more useful.

#

I'll take a second and read into what's useful information to extract, and what's odd behavior.

#

[DEBUG] Pause time: 837105381852 ns, Elapsed: -199596867 ns in test_function_d.
[DEBUG] End time: 837909394336 ns, Elapsed: -1001417998 ns in test_function_d.

#

[DEBUG] Inclusive time after stop: -198843932 ns in test_function_d

#

[DEBUG] Inclusive time after stop: -17737167835 ns in test_function_b.

#

I can't tell the relationship between those callframes. I'll have to print them out

#

Then I'll try to piece a chronological timeline of a callstack and its calculations.

#

...Well, this is nice.

#

Can I just straight up throw this to GPT...?

#

Have him do his reading stuff.

#

Turns out, I can! Crisis averted!

#

Well, thank you very much GPT.

#

Cause reading through 900 lines worth of logs was NOT IT.

#

[DEBUG] Starting frame: test_function_a (/path/to/script.py:142)
[INFO] Parent: None
[DEBUG] Start time: 1538511322255 ns

[DEBUG] Starting frame: test_function_b (/path/to/script.py:148)
[INFO] Parent: test_function_a
[DEBUG] Start time: 1539011744746 ns

[DEBUG] Pausing frame: test_function_a
[DEBUG] Pause time: 1539011765680 ns, Elapsed: 500443425 ns
[DEBUG] Inclusive time after pause: 500443425 ns

[DEBUG] Starting frame: test_function_d (/path/to/script.py:158)
[INFO] Parent: test_function_b
[DEBUG] Start time: 1539312410343 ns

[DEBUG] Pausing frame: test_function_b
[DEBUG] Pause time: 1539312433995 ns, Elapsed: 300689249 ns
[DEBUG] Inclusive time after pause: 300689249 ns

[DEBUG] Starting frame: test_function_f (/path/to/script.py:168)
[INFO] Parent: test_function_d
[DEBUG] Start time: 1539913224208 ns

[DEBUG] Pausing frame: test_function_d
[DEBUG] Pause time: 1539913250603 ns, Elapsed: 600840260 ns
[DEBUG] Inclusive time after pause: 600840260 ns

[DEBUG] Stopping frame: test_function_f
[DEBUG] End time: 1540713673977 ns, Elapsed: 800449769 ns
[DEBUG] Inclusive time after stop: 800449769 ns
[DEBUG] Exclusive time: 800449769 ns

[DEBUG] Resuming frame: test_function_d
[DEBUG] New start time: 1540113007308 ns

[DEBUG] Pausing frame: test_function_d
[DEBUG] Pause time: 1540714594983 ns, Elapsed: -199262942 ns
Warning: Negative elapsed time detected: -199262942 ns in test_function_d

[DEBUG] Pausing frame: test_function_d
[DEBUG] Pause time: 1540714799889 ns, Elapsed: -199058036 ns
Warning: Negative elapsed time detected: -199058036 ns in test_function_d

[DEBUG] Stopping frame: test_function_d
[DEBUG] End time: 1541515807406 ns, Elapsed: -999711065 ns
Warning: Negative elapsed time detected: -999711065 ns in test_function_d
[DEBUG] Inclusive time after stop: -196220462 ns

#

@lucid elm Aaaand that's all of useful that I've managed to log and narrow it down.

#

Elapsed times are the key negatives to bringing the whole calculation down

# 
def stop(self) -> None:
        self._end = Decimal(perf_counter())
        elapsed = self._end - self._start
        self._times.append(elapsed)
        self.inclusive_time = sum(self._times)
        
        children_inclusive_time = sum(child.inclusive_time for child in self.children.values())
        self.exclusive_time = sum(self._times) / len(self._times) if self._times else Decimal(0)

        if self.parent:
            self.parent.inclusive_time += self.inclusive_time
            self.parent.resume()

        self.average = self.inclusive_time / self.calls if self.calls > 0 else Decimal(0)

But like, why?

# 
def resume(self) -> None:
      paused_duration = self._pause - self._start
      self._start = Decimal(perf_counter()) - paused_duration

Could be that resume itself is being calculated incorrectly.

#

@silent surge Thoughts?

#

a wild guess?

silent surge
#

✈️

🐕‍🦺

quiet osprey
#

🗿

#

I'm just as clueless as you are

#

Oh my God.

silent surge
#

You found the tiny bug?

quiet osprey
#

No

#

I wish

#

I have no clue why it is wrong.

#

Can you like, whack my head? And help me magically figure out the solution?

#

Man, I think I'm just dumb. There's no way.

silent surge
#

did it work?

quiet osprey
#

It did not.

#

Man...

#

I have one last ditch theory though.

#

@normal otter

quiet osprey
#

I concede defeat for today.

#

I will come back tomorrow, stronger

vital edgeBOT
#
Python help channel closed

This help channel has been closed and it's no longer possible to send messages here. If your question wasn't answered, feel free to create a new post in #1035199133436354600. To maximize your chances of getting a response, check out this guide on asking good questions.