Profile all function frames

3 files changed, 40 insertions, 30 deletions

diff --git a/nemesis/causal_event_loop.py b/nemesis/causal_event_loop.py
index 22ec65c..6d18dbc 100644
--- a/nemesis/causal_event_loop.py
+++ b/nemesis/causal_event_loop.py
@@ -103,16 +103,14 @@ class CausalEventLoop(asyncio.SelectorEventLoop):
     _time_entered_coro = None
     _ready_events = []
     # the time this experiment started
-    _start_time = None
+    _start_time = float("inf")
 
     def __init__(self) -> None:
         super().__init__()
 
     def set_speedup(self, speedup):
         # print(self._coro_intervals)
-        # we want to delay the start time if we are starting a new experiment
-        # during the old experiment's interval
-        self._start_time = self.time() if not self._time_entered_coro else None
+        self._start_time = self.time()
         self._speedup = speedup
 
         # reset experiment counters
@@ -142,10 +140,7 @@ class CausalEventLoop(asyncio.SelectorEventLoop):
         except AssertionError as e:
             print(f"Assertion failed: {e}")
             sys.exit(1)
-        if self._start_time:
-            self._coro_intervals.add((self._time_entered_coro, self.time()))
-        else:
-            self._start_time = self.time()
+        self._coro_intervals.add((self._time_entered_coro, self.time()))
         self._time_entered_coro = None
 
     def collect_ready_events(self, timeout=0):
@@ -275,16 +270,21 @@ class CausalEventLoop(asyncio.SelectorEventLoop):
                     logger.warning('Executing %s took %.3f seconds',
                                    _format_handle(handle), dt)
 
-                time_interval = (handle._when, process_start_time)
-                pause_time = self._get_pause_time(time_interval)
-                adjusted_start_time = process_start_time - pause_time
-                wait_time = adjusted_start_time - handle._when
-                try:
-                    assert wait_time >= -0.0001, f"wait time on {_format_handle(handle)} was found to be {wait_time:.4f}!"
-                except AssertionError as e:
-                    print(f"Assertion failed: {e}")
-                    sys.exit(1)
-                self._completed_coros.append((_format_handle(handle), wait_time))
+                # do not record coroutines which left I/O during the previous experiment
+                # the time held in the pause buffer would have also been incorrect for
+                # this experiment, but there is nothing we can do about it.
+                if handle._when > self._start_time:
+                    time_interval = (handle._when, process_start_time)
+                    pause_time = self._get_pause_time(time_interval)
+                    adjusted_start_time = process_start_time - pause_time
+                    wait_time = adjusted_start_time - handle._when
+                    try:
+                        assert wait_time >= -0.0001, f"wait time on {_format_handle(handle)} was found to be {wait_time:.4f}!"
+                    except AssertionError as e:
+                        print(f"Assertion failed: {e}")
+                        sys.exit(1)
+                    self._completed_coros.append((_format_handle(handle), wait_time))
+
             except Exception:
                 traceback.print_exc()
             finally:
diff --git a/nemesis/html_gen.py b/nemesis/html_gen.py
index 3c6fbef..89c62d4 100644
--- a/nemesis/html_gen.py
+++ b/nemesis/html_gen.py
@@ -3,7 +3,7 @@ from plotly.subplots import make_subplots
 import hashlib
 import math
 
-TRIM_PERCENT = 0.05
+TRIM_PERCENT = 0.10
 
 def get_color(name):
     hash_object = hashlib.md5(name.encode())
diff --git a/nemesis/nemesis.py b/nemesis/nemesis.py
index 5901801..7eed743 100755
--- a/nemesis/nemesis.py
+++ b/nemesis/nemesis.py
@@ -157,7 +157,7 @@ class Nemesis(object):
             loops = Nemesis.experiment_data.get_loops()
             exp_coro = Nemesis.experiment_coro
             for loop in loops:
-                coro = Nemesis._get_current_coro(loop)
+                coro = Nemesis._get_current_frame(loop)
                 prev_coro = Nemesis.prev_coro[loop]
                 if not prev_coro == coro:
                     if prev_coro == exp_coro:
@@ -173,15 +173,15 @@ class Nemesis(object):
                 Nemesis._stop_experiment()
 
         else:
-            coros = []
+            frames = []
             loops = Nemesis._get_event_loops()
             for loop in loops:
-                coro = Nemesis._get_current_coro(loop)
-                if coro is not None:
-                    coros.append(coro)
-                if coros:
-                    Nemesis._start_experiment(random.choice(coros),
-                                              Nemesis._select_speedup())
+                frame = Nemesis._get_current_frame(loop)
+                if frame is not None:
+                    frames.append(frame)
+            if frames:
+                Nemesis._start_experiment(random.choice(frames),
+                                          Nemesis._select_speedup())
 
     @staticmethod
     def _parse_handle(handle):
@@ -194,21 +194,31 @@ class Nemesis(object):
             return [str(type(handle).__name__), cb.__name__]
 
     @staticmethod
-    def _get_current_coro(loop):
+    def _get_current_frame(loop):
         tid = loop._thread_id
         assert tid, f"{loop} is not running, yet we attempted to sample it!"
 
         frame = sys._current_frames().get(tid)
         fname = frame.f_code.co_filename
+        if not fname:
+            # 'eval/compile' gives no f_code.co_filename.  We have
+            # to look back into the outer frame in order to check
+            # the co_filename.
+            back = frame.f_back
+            fname = back.f_code.co_filename
         while not Nemesis._should_trace(fname):
+            # Walk the stack backwards until we hit a frame that
+            # IS one we should trace (if there is one).  i.e., if
+            # it's in the code being profiled, and it is just
+            # calling stuff deep in libraries.
             if frame:
                 frame = frame.f_back
             else:
                 break
             if frame:
                 fname = frame.f_code.co_filename
-        if frame and frame.f_generator:
-            return frame.f_generator.cr_code.co_name
+        if frame:
+            return frame.f_code.co_name
         return None
 
     @staticmethod