Added notion of tottime and cumtime

kernel/modelverse_jit/tree_ir.py

@@ -30,7 +30,7 @@
 
 import modelverse_jit.source_map as source_map
 
-PROFILING = True
+PROFILING = False
 
 NOP_LITERAL = None
 """A literal that results in a nop during which execution may be interrupted
@@ -458,7 +458,7 @@ class ReturnInstruction(VoidInstruction):
         if self.value.has_definition():
             self.value.generate_python_def(code_generator)
         if PROFILING:
-            code_generator.append_line("print('%s : %s' % (___profiling[1], time.time() - ___profiling[0]))")
+            code_generator.append_line("print('%s : %s : %s' % (___profiling[0], time.time() - ___profiling[1], time.time() - ___profiling[1] - ___profiling[2]))")
         code_generator.append_line(
             'raise PrimitiveFinished(' +
             self.value.generate_python_use(code_generator) +
@@ -1009,7 +1009,11 @@ class StateInstruction(Instruction):
             if arg_i.has_definition():
                 arg_i.generate_python_def(code_generator)
 
+        if PROFILING and "CALL" in self.get_opcode():
+            code_generator.append_line("___profiling_start = time.time()")
         code_generator.append_state_definition(self, self.get_opcode(), args)
+        if PROFILING and "CALL" in self.get_opcode():
+            code_generator.append_line("___profiling[2] += (time.time() - ___profiling_start)")
 
     def __repr__(self):
         return "StateInstruction(%s)" % ', '.join(map(repr, self.get_arguments()))
@@ -1244,7 +1248,7 @@ class DefineFunctionInstruction(VariableInstruction):
         code_generator.increase_indentation()
         if PROFILING:
             code_generator.append_line("import time")
-            code_generator.append_line("___profiling = (time.time(), '%s')" % self.name)
+            code_generator.append_line("___profiling = ['%s', time.time(), 0.0]" % self.name)
         self.body.generate_python_def(code_generator)
         code_generator.decrease_indentation()
 

sum_times.py

@@ -1,20 +1,23 @@
 import sys
 
-counters = {}
+tottimes = {}
+cumtimes = {}
 
 for l in open(sys.argv[1], "r"):
-        r = l.rsplit(" : ", 1)
-        if len(r) == 2:
-            func, time = r
-            time = float(time)
-            counters[func] = counters.get(func, 0.0) + time
+        r = l.rsplit(" : ", 2)
+        if len(r) == 3:
+            func, cumtime, tottime = r
+            cumtime = float(cumtime)
+            tottime = float(tottime)
+            tottimes[func] = tottimes.get(func, 0.0) + tottime
+            cumtimes[func] = cumtimes.get(func, 0.0) + cumtime
 
 c = 0
-for time, func in reversed(sorted([(counters[k], k) for k in counters])):
+for time, func in reversed(sorted([(tottimes[k], k) for k in tottimes])):
     if func.startswith("jit"):
         continue
     else:
-        print("%s = %s" % (func, time))
+        print("%s = %s (%s)" % (func, time, cumtimes[func]))
         c += 1
         if c > 30:
             break