Repository: joerick/pyinstrument

Issue:
pstats renderer total time
The sum of `tottime` for all functions from the pstats output correctly matches the total time displayed in the header of `print_stats()` when using the `pstats` module. However, this does not match the duration shown in the HTML output (it is about twice longer). Is this expected? How much should I trust `tottime` in a pstats output? I tested with both async mode on and off.


Discussion:

Patch:
diff --git a/pyinstrument/renderers/pstatsrenderer.py b/pyinstrument/renderers/pstatsrenderer.py
index 2bb8157..35428b3 100644
--- a/pyinstrument/renderers/pstatsrenderer.py
+++ b/pyinstrument/renderers/pstatsrenderer.py
@@ -71,7 +71,7 @@ class PstatsRenderer(FrameRenderer):
         stats[key] = (call_time, number_calls, total_time, cumulative_time, callers)
 
         for child in frame.children:
-            if not frame.is_synthetic:
+            if not child.is_synthetic:
                 self.render_frame(child, stats)
 
     def render(self, session: Session):


Test patch:
diff --git a/test/test_profiler_async.py b/test/test_profiler_async.py
index 48cb793..fd67375 100644
--- a/test/test_profiler_async.py
+++ b/test/test_profiler_async.py
@@ -144,10 +144,10 @@ def test_profiler_task_isolation(engine):
                 )
                 nursery.start_soon(
                     partial(async_wait, sync_time=0.1, async_time=0.3, engine="trio")
-                )
+                )  # pyright: ignore
                 nursery.start_soon(
                     partial(async_wait, sync_time=0.1, async_time=0.3, engine="trio")
-                )
+                )  # pyright: ignore
 
         with fake_time_trio() as fake_clock:
             trio.run(multi_task, clock=fake_clock.trio_clock)
diff --git a/test/test_pstats_renderer.py b/test/test_pstats_renderer.py
index 909d5c0..697b76d 100644
--- a/test/test_pstats_renderer.py
+++ b/test/test_pstats_renderer.py
@@ -2,7 +2,7 @@ import os
 import time
 from pathlib import Path
 from pstats import Stats
-from test.fake_time_util import fake_time
+from test.fake_time_util import FakeClock, fake_time
 from typing import Any
 
 import pytest
@@ -99,3 +99,32 @@ def test_round_trip_encoding_of_binary_data(tmp_path: Path):
 
     assert data_blob == data_blob_string.encode(encoding="utf-8", errors="surrogateescape")
     assert data_blob == file.read_bytes()
+
+
+def sleep_and_busy_wait(clock: FakeClock):
+    time.sleep(1.0)
+    # this looks like a busy wait to the profiler
+    clock.time += 1.0
+
+
+def test_sum_of_tottime(tmp_path):
+    # Check that the sum of the tottime of all the functions is equal to the
+    # total time of the profile
+
+    with fake_time() as clock:
+        profiler = Profiler()
+        profiler.start()
+
+        sleep_and_busy_wait(clock)
+
+        profiler.stop()
+        profiler_session = profiler.last_session
+
+    assert profiler_session
+
+    pstats_data = PstatsRenderer().render(profiler_session)
+    fname = tmp_path / "test.pstats"
+    with open(fname, "wb") as fid:
+        fid.write(pstats_data.encode(encoding="utf-8", errors="surrogateescape"))
+    stats: Any = Stats(str(fname))
+    assert stats.total_tt == pytest.approx(2)