Cleanup output format, simplify sample data structure

1 files changed, 56 insertions, 52 deletions

diff --git a/aergia b/aergia
index 4578d24..54c86cb 100755
--- a/aergia
+++ b/aergia
@@ -46,10 +46,10 @@ from types import FrameType
 from typing import cast, List, Tuple
 import argparse
 import asyncio
+import atexit
 import selectors
 import signal
 import sys
-import threading
 import time
 import traceback
 
@@ -85,83 +85,77 @@ class Aergia(object):
     # a key-value pair where keys represent frame metadata (see
     # Aergia.frame_to_string) and values represent number of times
     # sampled.
-    cpu_samples = defaultdict(lambda: 0)
-    cpu_samples_c = defaultdict(lambda: 0)
+    samples = defaultdict(lambda: [0, 0])
     # number of times samples have been collected
-    total_cpu_samples = 0
+    total_samples = 0
 
-    # the time, in seconds, between samples
-    signal_interval = 0.01
     # the timestamp recorded last signal
     last_signal_time = 0.0
 
-
-    def __init__(self):
+    def __init__(self, signal_interval):
         signal.signal(signal.SIGPROF,
                       self.cpu_signal_handler)
         signal.setitimer(signal.ITIMER_PROF,
-                         self.signal_interval,
-                         self.signal_interval)
-
-    @staticmethod
-    def gettime():
-        '''get the wallclock time'''
-        return time.time()
+                         signal_interval,
+                         signal_interval)
 
     @staticmethod
-    def start(profile_async):
+    def start():
+        atexit.register(Aergia.exit_handler)
         Aergia.last_signal_time = Aergia.gettime()
 
     @staticmethod
-    def stop():
-        '''Turn off profiling signals'''
+    def exit_handler():
+        Aergia.print_samples()
         Aergia.disable_signals()
-        Aergia.exit_handler()
 
     @staticmethod
-    def exit_handler():
+    def print_samples():
         '''Pretty-print profiling information.'''
-        # If we've collected any samples, dump them.
-        print("CPU usage (Python):")
-        if Aergia.total_cpu_samples > 0:
-            for key in Aergia.sort_samples(Aergia.cpu_samples):
-                print(f"{key} : "
-                      f"{Aergia.cpu_samples[key] * 100 / Aergia.total_cpu_samples:.3f} % "
-                      f"({Aergia.cpu_samples[key]:.1f} total samples)")
-            print("CPU usage (Native):")
-            for key in Aergia.sort_samples(Aergia.cpu_samples_c):
-                print(f"{key} : "
-                      f"{Aergia.cpu_samples_c[key] * 100 / Aergia.total_cpu_samples:.3f} % "
-                      f"({Aergia.cpu_samples_c[key]:.1f} total samples)")
+        if Aergia.total_samples > 0:
+            print("Results")
+            print("FILE\tFUNC\tPERC\tACTUAL+CALCULATED=SECONDS")
+            for key in Aergia.sort_samples(Aergia.samples):
+                Aergia.print_sample(key)
         else:
-            print("(Bug) The program did not run long enough to profile, or a one-time error occured.")
+            print("No samples were gathered. This is likely a bug.")
+
+    @staticmethod
+    def print_sample(key):
+        '''Pretty-print a single sample.'''
+        sig_intv = Aergia.get_sampling_interval()
+        value = Aergia.samples[key]
+        tot = Aergia.sum_sample(value)
+        print(f"{key} :\t{tot * 100 / Aergia.total_samples:.3f}%"
+              f"\t({value[0]:.3f} + {value[1]:.3f} ="
+              f" {tot*sig_intv:.6f} seconds)")
 
     @staticmethod
     def disable_signals():
         signal.signal(signal.ITIMER_PROF, signal.SIG_IGN)
-        signal.signal(signal.SIGVTALRM, signal.SIG_IGN)
         signal.setitimer(signal.ITIMER_PROF, 0)
 
     @staticmethod
     def cpu_signal_handler(sig, frame):
+        sig_intv = Aergia.get_sampling_interval()
         elapsed_since_last_signal = Aergia.gettime() - \
             Aergia.last_signal_time
-        c_time_norm = (elapsed_since_last_signal -
-                       Aergia.signal_interval) / \
-            Aergia.signal_interval
+        c_time_norm = (elapsed_since_last_signal - sig_intv) / \
+            sig_intv
 
         keys = Aergia.compute_frames_to_record()
         for key in keys:
-            Aergia.cpu_samples[Aergia.frame_to_string(key)] += 1
-            Aergia.cpu_samples_c[Aergia.frame_to_string(
-                key)] += c_time_norm
-            Aergia.total_cpu_samples += elapsed_since_last_signal / \
-                Aergia.signal_interval
+            Aergia.samples[Aergia.frame_to_string(key)][0] += \
+                elapsed_since_last_signal
+            Aergia.samples[Aergia.frame_to_string(key)][1] += c_time_norm
+            Aergia.total_samples += elapsed_since_last_signal / \
+                sig_intv
         Aergia.last_signal_time = Aergia.gettime()
 
     @staticmethod
     def compute_frames_to_record():
         '''Collects all stack frames that Aergia actually processes.'''
+        frames = []
         if Aergia.is_event_loop_running():
             frames = [task.get_coro().cr_frame for task in asyncio.all_tasks()]
 
@@ -195,17 +189,19 @@ class Aergia(object):
     @staticmethod
     def frame_to_string(frame):
         '''Pretty-prints a frame as a function/file name and a line number.
-        Additionally used a key for tallying lines.'''
+        Additionally used as a key for tallying lines.'''
         co = frame.f_code
         func_name = co.co_name
         line_no = frame.f_lineno
         filename = co.co_filename
-        return filename + '\t' + func_name + '\t' + str(line_no)
+        return filename + ':' + str(line_no) + '\t' + func_name
 
     @staticmethod
     def should_trace(filename):
         '''Returns FALSE if filename is uninteresting to the user.'''
         # FIXME Assume GuixSD. Makes filtering easy
+        if '/gnu/store' in filename:
+            return False
         if 'site-packages' in filename:
             return False
         if filename[0] == '<':
@@ -224,7 +220,7 @@ class Aergia(object):
     def sort_samples(sample_dict):
         '''Returns SAMPLE_DICT in descending order by number of samples.'''
         return {k: v for k, v in sorted(sample_dict.items(),
-                                        key=lambda item: item[1],
+                                        key=lambda item: Aergia.sum_sample(item[1]),
                                         reverse=True)}
 
     @staticmethod
@@ -245,6 +241,20 @@ class Aergia(object):
             print(f"WARN: Duplicate frame found: {dup}", file=sys.stderr)
         return list(s)
 
+    @staticmethod
+    def sum_sample(sample):
+        return sample[0] + sample[1]
+
+    @staticmethod
+    def gettime():
+        '''returns the wallclock time'''
+        return time.time()
+
+    @staticmethod
+    def get_sampling_interval():
+        '''returns the current sampling interval'''
+        return signal.getitimer(signal.ITIMER_PROF)[-1]
+
 
 the_globals = {
     '__name__': '__main__',
@@ -265,11 +275,6 @@ def parse_arguments():
         usage='%(prog)s [args] script [args]'
     )
 
-    parser.add_argument('-a', '--async_off',
-                        action='store_false',
-                        help='Turn off experimental async profiling.',
-                        default=True)
-
     parser.add_argument('-i', '--interval',
                         help='The minimum amount of time inbetween \
                         samples in seconds.',
@@ -289,9 +294,8 @@ def main():
     try:
         with open(args.script, 'rb') as fp:
             code = compile(fp.read(), args.script, "exec")
-            Aergia().start(args.async_off)
+            Aergia(args.interval).start()
             exec(code, the_globals)
-            Aergia().stop()
     except Exception:
         traceback.print_exc()