profiling option

src/jsifier.js

@@ -431,6 +431,15 @@ function JSify(data, functionsOnly, givenFunctions, givenGlobalVariables) {
 
       func.JS = '\nfunction ' + func.ident + '(' + func.paramIdents.join(', ') + ') {\n';
 
+      if (PROFILE) {
+        func.JS += '  if (PROFILING) { '
+                +      'var __parentProfilingNode__ = PROFILING_NODE; PROFILING_NODE = PROFILING_NODE.children["' + func.ident + '"]; '
+                +      'if (!PROFILING_NODE) __parentProfilingNode__.children["' + func.ident + '"] = PROFILING_NODE = { time: 0, children: {}, calls: 0 };'
+                +      'PROFILING_NODE.calls++; '
+                +      'var __profilingStartTime__ = Date.now() '
+                +    '}\n';
+      }
+
       func.JS += '  ' + RuntimeGenerator.stackEnter(func.initialStack) + ';\n';
 
       if (LABEL_DEBUG) func.JS += "  print(INDENT + ' Entering: " + func.ident + "'); INDENT += '  ';\n";
@@ -723,6 +732,12 @@ function JSify(data, functionsOnly, givenFunctions, givenGlobalVariables) {
   });
   makeFuncLineActor('return', function(item) {
     var ret = RuntimeGenerator.stackExit(item.funcData.initialStack) + ';\n';
+    if (PROFILE) {
+      ret += 'if (PROFILING) { '
+          +    'PROFILING_NODE.time += Date.now() - __profilingStartTime__; '
+          +    'PROFILING_NODE = __parentProfilingNode__ '
+          +  '}\n';
+    }
     if (LABEL_DEBUG) {
       ret += "print(INDENT + 'Exiting: " + item.funcData.ident + "');\n"
           +  "INDENT = INDENT.substr(0, INDENT.length-2);\n";

src/preamble.js

@@ -274,6 +274,36 @@ var INDENT = '';
 var START_TIME = Date.now();
 #endif
 
+#if PROFILE
+var PROFILING = 0;
+var PROFILING_ROOT = { time: 0, children: {}, calls: 0 };
+var PROFILING_NODE;
+
+function startProfiling() {
+  PROFILING_NODE = PROFILING_ROOT;
+  PROFILING = 1;
+}
+
+function stopProfiling() {
+  PROFILING = 0;
+  assert(PROFILING_NODE === PROFILING_ROOT, 'Must have popped all the profiling call stack');
+}
+
+function printProfiling() {
+  function dumpData(name_, node, indent) {
+    print(indent + ('________' + node.time).substr(-8) + ': ' + name_ + ' (' + node.calls + ')');
+    var children = [];
+    for (var child in node.children) {
+      children.push(node.children[child]);
+      children[children.length-1].name_ = child;
+    }
+    children.sort(function(x, y) { return y.time - x.time });
+    children.forEach(function(child) { dumpData(child.name_, child, indent + '  ') });
+  }
+  dumpData('root', PROFILING_ROOT, ' ');
+}
+#endif
+
 //========================================
 // Runtime essentials
 //========================================

src/settings.js

@@ -114,6 +114,8 @@ AUTO_OPTIMIZE = 0; // When run with the CHECK_* options, will not fail on errors
                    // checking enabled and which do not, that is, this is a way to automate the
                    // generation of line data for CORRECT_*_LINES options
 
+PROFILE = 0; // Enables runtime profiling. See test_profiling for a usage example.
+
 EXPORTED_FUNCTIONS = ['_main']; // Functions that are explicitly exported, so they are guaranteed to
                                 // be accessible outside of the generated code.
 

tests/runner.py

@@ -180,7 +180,7 @@ class RunnerCore(unittest.TestCase):
   def do_emscripten(self, filename, output_processor=None, append_ext=True, extra_args=[]):
     # Run Emscripten
     exported_settings = {}
-    for setting in ['QUANTUM_SIZE', 'RELOOP', 'OPTIMIZE', 'ASSERTIONS', 'USE_TYPED_ARRAYS', 'SAFE_HEAP', 'CHECK_OVERFLOWS', 'CORRECT_OVERFLOWS', 'CORRECT_SIGNS', 'CHECK_SIGNS', 'CORRECT_OVERFLOWS_LINES', 'CORRECT_SIGNS_LINES', 'CORRECT_ROUNDINGS', 'CORRECT_ROUNDINGS_LINES', 'INVOKE_RUN', 'SAFE_HEAP_LINES', 'INIT_STACK', 'AUTO_OPTIMIZE', 'EXPORTED_FUNCTIONS', 'EXPORTED_GLOBALS', 'BUILD_AS_SHARED_LIB', 'INCLUDE_FULL_LIBRARY', 'RUNTIME_TYPE_INFO', 'DISABLE_EXCEPTIONS', 'FAST_MEMORY', 'EXCEPTION_DEBUG']:
+    for setting in ['QUANTUM_SIZE', 'RELOOP', 'OPTIMIZE', 'ASSERTIONS', 'USE_TYPED_ARRAYS', 'SAFE_HEAP', 'CHECK_OVERFLOWS', 'CORRECT_OVERFLOWS', 'CORRECT_SIGNS', 'CHECK_SIGNS', 'CORRECT_OVERFLOWS_LINES', 'CORRECT_SIGNS_LINES', 'CORRECT_ROUNDINGS', 'CORRECT_ROUNDINGS_LINES', 'INVOKE_RUN', 'SAFE_HEAP_LINES', 'INIT_STACK', 'AUTO_OPTIMIZE', 'EXPORTED_FUNCTIONS', 'EXPORTED_GLOBALS', 'BUILD_AS_SHARED_LIB', 'INCLUDE_FULL_LIBRARY', 'RUNTIME_TYPE_INFO', 'DISABLE_EXCEPTIONS', 'FAST_MEMORY', 'EXCEPTION_DEBUG', 'PROFILE']:
       try:
         value = eval(setting)
         exported_settings[setting] = value
@@ -3486,6 +3486,56 @@ if 'benchmark' not in str(sys.argv):
       # Using build_ll_hook forces a recompile, which leads to DFE being done even without opts
       self.do_test(src, '*hello slim world*', build_ll_hook=hook)
 
+    def test_profiling(self):
+      global PROFILE; PROFILE = 1
+      global INVOKE_RUN; INVOKE_RUN = 0
+
+      src = '''
+          #include <stdio.h>
+
+          int inner1(int x) {
+            for (int i = 0; i < 20; i++)
+              x += x/3;
+            return x;
+          }
+          int inner2(int x) {
+            for (int i = 0; i < 10; i++)
+              x -= x/4;
+            return x;
+          }
+          int inner3(int x) {
+            for (int i = 0; i < 5; i++)
+              x += x/2;
+            x = inner1(x) - inner2(x);
+            for (int i = 0; i < 5; i++)
+              x -= x/2;
+            return x;
+          }
+
+          int main()
+          {
+            int total = 0;
+            for (int i = 0; i < 5000; i++)
+              total += inner1(i) - 4*inner3(i);
+            printf("*%d*\\n", total);
+            return 0;
+          }
+        '''
+
+      def post(filename):
+        src = open(filename, 'a')
+        src.write('''
+          startProfiling();
+          run();
+          stopProfiling();
+          printProfiling();
+          print('*ok*');
+        ''')
+        src.close()
+
+      # Using build_ll_hook forces a recompile, which leads to DFE being done even without opts
+      self.do_test(src, ': __Z6inner1i (5000)\n*ok*', post_build=post)
+
     ### Integration tests
 
     def test_scriptaclass(self):
@@ -4091,7 +4141,7 @@ Child2:9
     exec('''
 class %s(T):
   def setUp(self):
-    global COMPILER, QUANTUM_SIZE, RELOOP, OPTIMIZE, ASSERTIONS, USE_TYPED_ARRAYS, LLVM_OPTS, SAFE_HEAP, CHECK_OVERFLOWS, CORRECT_OVERFLOWS, CORRECT_OVERFLOWS_LINES, CORRECT_SIGNS, CORRECT_SIGNS_LINES, CHECK_SIGNS, COMPILER_TEST_OPTS, CORRECT_ROUNDINGS, CORRECT_ROUNDINGS_LINES, INVOKE_RUN, SAFE_HEAP_LINES, INIT_STACK, AUTO_OPTIMIZE, RUNTIME_TYPE_INFO, DISABLE_EXCEPTIONS
+    global COMPILER, QUANTUM_SIZE, RELOOP, OPTIMIZE, ASSERTIONS, USE_TYPED_ARRAYS, LLVM_OPTS, SAFE_HEAP, CHECK_OVERFLOWS, CORRECT_OVERFLOWS, CORRECT_OVERFLOWS_LINES, CORRECT_SIGNS, CORRECT_SIGNS_LINES, CHECK_SIGNS, COMPILER_TEST_OPTS, CORRECT_ROUNDINGS, CORRECT_ROUNDINGS_LINES, INVOKE_RUN, SAFE_HEAP_LINES, INIT_STACK, AUTO_OPTIMIZE, RUNTIME_TYPE_INFO, DISABLE_EXCEPTIONS, PROFILE
 
     COMPILER = '%s'
     llvm_opts = %d
@@ -4115,6 +4165,7 @@ class %s(T):
     INIT_STACK = 0
     RUNTIME_TYPE_INFO = 0
     DISABLE_EXCEPTIONS = 0
+    PROFILE = 0
     if LLVM_OPTS:
       self.pick_llvm_opts(3, True)
     COMPILER_TEST_OPTS = ['-g']