Partial solution to tracing all lines (coroutines calling methods)

3 files changed, 62 insertions, 11 deletions

diff --git a/aergia/aergia.py b/aergia/aergia.py
index 28e8d7a..b2ed74b 100755
--- a/aergia/aergia.py
+++ b/aergia/aergia.py
@@ -53,6 +53,8 @@ import sys
 import threading
 import time
 import traceback
+import gc
+import inspect
 
 
 orig_thread_join = threading.Thread.join
@@ -134,7 +136,7 @@ class Aergia(object):
     def print_samples():
         '''Pretty-print profiling results.'''
         if Aergia.total_samples > 0:
-            print("FILE\tFUNC\tPERC\t(ACTUAL -> SECONDS)")
+            print(f"{'FILE':<19} {'FUNC':<30} {'PERC':<8} {'(ACTUAL -> SEC)':<10}")
             for key in Aergia._sort_samples(Aergia.samples):
                 Aergia.print_sample(key)
         else:
@@ -146,10 +148,8 @@ class Aergia(object):
         '''Pretty-print a single sample.'''
         sig_intv = Aergia.signal_interval
         value = Aergia.samples[key]
-        print(f"{Aergia._tuple_to_string(key)} :"
-              f"\t\t{value * 100 / Aergia.total_samples:.3f}%"
-              f"\t({value:.3f} ->"
-              f" {value*sig_intv:.6f} seconds)")
+        print(f"{Aergia._tuple_to_string(key)} {value * 100 / Aergia.total_samples:.3f}% "
+              f" ({value:.3f} -> {value*sig_intv:.6f})")
 
     @staticmethod
     def _idle_signal_handler(sig, frame):
@@ -223,7 +223,8 @@ class Aergia(object):
     def _tuple_to_string(sample):
         '''Given a namedtuple corresponding to a sample key,
         pretty-prints a frame as a function/file name and a line number.'''
-        return sample.file + ':' + str(sample.line) + '\t' + sample.func
+        filename = (sample.file if len(sample.file) <= 30 else sample.file[-30:])
+        return f"{sample.file}:{sample.line}".ljust(20)  + f"{sample.func:30}"
 
     @staticmethod
     def _sort_samples(sample_dict):
@@ -257,13 +258,48 @@ class Aergia(object):
     @staticmethod
     def _get_deepest_traceable_frame(coro):
         curr = coro
-        ret = None
+        deepest_frame = None
         while curr:
             frame = getattr(curr, 'cr_frame', None)
             if frame and Aergia._should_trace(frame.f_code.co_filename):
-                ret = frame
+                deepest_frame = frame
             curr = getattr(curr, 'cr_await', None)
-        return ret
+
+        # we are not awaiting anything.
+        # either: we did a standard call to a non-coroutine
+        #     or: we are awaiting an async generator (handled very differently)
+        #     or: we are awaiting or called a library function which we do not
+        #   care to profile.
+        #
+        # first case:
+        # second case: we'd like to trace that frame down as far as possible.
+        #              unless it leads to another task's coroutine, in which
+        #              case we'll politely decline to count it twice.
+        # third case:  we'd like to return the current value of deepest_frame.
+
+        previous_frame = None
+        while previous_frame is not deepest_frame:
+            previous_frame = deepest_frame
+            refs = gc.get_referrers(deepest_frame)
+            print('-' * 60)
+            print('--- Frame Information for ---')
+            print(previous_frame)
+            print(f"{'Frame':<10} {'Filename':<30} {'Function':<30} {'Line':<10}")
+            index = 0
+            for r in refs:
+                if inspect.isframe(r) and \
+                   Aergia._should_trace(r.f_code.co_filename):
+                    deepest_frame = r
+                    co = r.f_code
+                    func_name = co.co_name
+                    filename = co.co_filename
+                    filename = (filename if len(filename) <= 30 else filename[-30:])
+                    line_no = r.f_lineno
+                    print(f"{index:<10} {filename:<30} {func_name:<30} {line_no:<10}")
+                    index +=1
+            print('--- End of Frame Information ---')
+            print(f'finished with {deepest_frame}')
+        return deepest_frame
 
     @staticmethod
     def _should_trace(filename):
@@ -276,8 +312,8 @@ class Aergia(object):
             return False
         if filename[0] == '<':
             return False
-        # if 'aergia' in filename:
-        #     return False
+        if 'aergia.py' in filename:
+            return False
         return True
 
     @staticmethod
diff --git a/t/test_yappi_adaptations.py b/t/test_yappi_adaptations.py
index 7f034ef..a8b4212 100644
--- a/t/test_yappi_adaptations.py
+++ b/t/test_yappi_adaptations.py
@@ -15,6 +15,7 @@ class YappiTests(utils.AergiaUnitTestCase):
             if n <= 0:
                 return
             await asyncio.sleep(delay)
+            utils.burn_cpu(0.1)
             await a(n - 1)
             await a(n - 2)
 
diff --git a/t/utils.py b/t/utils.py
index 4dde466..ee9478d 100644
--- a/t/utils.py
+++ b/t/utils.py
@@ -1,5 +1,6 @@
 from aergia.aergia import Aergia
 import yappi
+import time
 import unittest
 
 
@@ -63,3 +64,16 @@ class AergiaUnitTestCase(unittest.TestCase):
         for s in stats:
             if s.name == func_name:
                 return s.ttot
+
+
+def burn_cpu(sec):
+    t0 = Aergia._gettime()
+    elapsed = 0
+    while (elapsed < sec):
+        for _ in range(1000):
+            pass
+        elapsed = Aergia._gettime() - t0
+
+
+def burn_io(sec):
+    time.sleep(sec)