Add basic benchmarking script (#83)

* add basic benchmarking script

* add results class, collect more information, and fix check for no args

* fix indentation

* we don't have logger here

* use argv[0] for name of program

* allow dumping of stats from the API and use .format()

* add ProfilingResults class

* bugfixes

manticore/core/executor.py

@@ -6,6 +6,7 @@ import cPickle
 import cProfile
 import random
 import logging
+import pstats
 import traceback
 import signal
 import weakref
@@ -68,6 +69,24 @@ def sync(f):
             self._lock.release()
     return newFunction
 
+class ProfilingResults(object):
+    def __init__(self, raw_stats, instructions_executed):
+        self.raw_stats = raw_stats
+        self.instructions_executed = instructions_executed
+
+        self.time_elapsed = raw_stats.total_tt
+
+        self.loading_time = 0
+        self.saving_time = 0
+        self.solver_time = 0
+        for (func_file, _, func_name), (_, _, _, func_time, _) in raw_stats.stats.iteritems():
+            if func_name == '_getState':
+                self.loading_time += func_time
+            elif func_name == '_putState':
+                self.saving_time += func_time
+            elif func_file.endswith('solver.py') and 'setstate' not in func_name and 'getstate' not in func_name and 'ckl' not in func_name:
+                self.solver_time += func_time
+
 class Executor(object):
 
     def shutdown(self):
@@ -173,26 +192,14 @@ class Executor(object):
                 How long it actually took (tottime: excludes the times of other functions) - 
                 What functions it called (callers) - 
                 What functions called it (callees)'''
+            results = ProfilingResults(ps, self.count)
 
-            getstate_time = 0.0
+            logger.info("Total profiled time: %f", results.time_elapsed)
-            putstate_time = 0.0
+            logger.info("Loading state time: %f", results.loading_time)
-            solver_time = 0.0
+            logger.info("Saving state time: %f", results.saving_time)
-
+            logger.info("Solver time: %f", results.solver_time)
-            for (func_file, func_line, func_name), (cc, nc, tt, ct, callers) in ps.stats.iteritems():
+            logger.info("Other time: %f", results.time_elapsed - (results.loading_time + results.saving_time + results.solver_time))
-                #This if tries to sum only independient stuff
+            return results
-                if func_name == '_getState':
-                    getstate_time += ct
-                elif func_name == '_putState':
-                    putstate_time += ct
-                elif func_file.endswith('solver.py') and 'setstate' not in func_name and 'getstate' not in func_name and 'ckl' not in func_name:
-                    solver_time += ct
-                #print (func_file, func_line, func_name), (cc, nc, tt, ct)
-
-            logger.info("Total profiled time: %f", ps.total_tt)
-            logger.info("Loading state time: %f", getstate_time)
-            logger.info("Saving state time: %f", putstate_time)
-            logger.info("Solver time: %f", solver_time)
-            logger.info("Other time: %f", ps.total_tt - (getstate_time+putstate_time+solver_time))
 
     def _getFilename(self, filename):
         return os.path.join(self.workspace, filename)

scripts/benchmark.py

@@ -0,0 +1,48 @@
+from manticore import Manticore
+from sys import argv, exit
+
+def display(results):
+    print "  Total time: {} seconds".format(results.time_elapsed)
+    print "  Total instructions executed: {}".format(results.instructions_executed)
+    print "  Average instructions per second: {}".format(results.instructions_executed / results.time_elapsed)
+    print "  Time spent loading states: {} seconds".format(results.loading_time)
+    print "  Time spent saving states: {} seconds".format(results.saving_time)
+    print "  Time spent in solver: {} seconds".format(results.solver_time)
+
+def benchmark(program):
+    print "[*] Benchmarking program \"{}\"".format(program)
+
+    m = Manticore(program)
+    m.should_profile = True
+    m.run()
+
+    results = m._executor.dump_stats()
+    if results is None:
+        print "[*] Failed to collect stats for program {}".format(program)
+        return
+
+    display(results)
+    return results
+
+if __name__ == "__main__":
+    args = argv[1:]
+
+    if len(args) == 0:
+        print "usage: python {} PROGRAM1 PROGRAM2...".format(argv[0])
+        exit()
+
+    first_program = args[0]
+    other_programs = args[1:]
+    overall_results = benchmark(first_program)
+
+    if other_programs:
+        for program in other_programs:
+            results = benchmark(program)
+            overall_results.time_elapsed += results.time_elapsed
+            overall_results.instructions_executed += results.instructions_executed
+            overall_results.solver_time += results.solver_time
+            overall_results.loading_time += results.loading_time
+            overall_results.saving_time += results.saving_time
+            
+        print "Overall:"
+        display(overall_results)