Collect timing information for commands running on travis (microsoft#10308)

weswigham · web-flow · commit d2060466590a · 2016-08-12T14:00:50.000-07:00
diff --git a/Jakefile.js b/Jakefile.js
@@ -33,6 +33,28 @@ if (process.env.path !== undefined) {
    process.env.PATH = nodeModulesPathPrefix + process.env.PATH;
 }
 
+function toNs(diff) {
+    return diff[0] * 1e9 + diff[1];
+}
+
+function mark() {
+    if (!fold.isTravis()) return;
+    var stamp = process.hrtime();
+    var id = Math.floor(Math.random() * 0xFFFFFFFF).toString(16);
+    console.log("travis_time:start:" + id + "\r");
+    return {
+        stamp: stamp,
+        id: id
+    };
+}
+
+function measure(marker) {
+    if (!fold.isTravis()) return;
+    var diff = process.hrtime(marker.stamp);
+    var total = [marker.stamp[0] + diff[0], marker.stamp[1] + diff[1]];
+    console.log("travis_time:end:" + marker.id + ":start=" + toNs(marker.stamp) + ",finish=" + toNs(total) + ",duration=" + toNs(diff) + "\r");
+}
+
 var compilerSources = [
     "core.ts",
     "performance.ts",
@@ -286,6 +308,7 @@ var builtLocalCompiler = path.join(builtLocalDirectory, compilerFilename);
     */
 function compileFile(outFile, sources, prereqs, prefixes, useBuiltCompiler, opts, callback) {
     file(outFile, prereqs, function() {
+        var startCompileTime = mark();
         opts = opts || {};
         var compilerPath = useBuiltCompiler ? builtLocalCompiler : LKGCompiler;
         var options = "--noImplicitAny --noImplicitThis --noEmitOnError --types " 
@@ -362,11 +385,13 @@ function compileFile(outFile, sources, prereqs, prefixes, useBuiltCompiler, opts
                 callback();
             }
 
+            measure(startCompileTime);
             complete();
         });
         ex.addListener("error", function() {
             fs.unlinkSync(outFile);
             fail("Compilation of " + outFile + " unsuccessful");
+            measure(startCompileTime);
         });
         ex.run();
     }, {async: true});
@@ -769,6 +794,7 @@ function runConsoleTests(defaultReporter, runInParallel) {
     // timeout normally isn't necessary but Travis-CI has been timing out on compiler baselines occasionally
     // default timeout is 2sec which really should be enough, but maybe we just need a small amount longer
     if(!runInParallel) {
+        var startTime = mark();
         tests = tests ? ' -g "' + tests + '"' : '';
         var cmd = "mocha" + (debug ? " --debug-brk" : "") + " -R " + reporter + tests + colors + bail + ' -t ' + testTimeout + ' ' + run;
         console.log(cmd);
@@ -777,20 +803,23 @@ function runConsoleTests(defaultReporter, runInParallel) {
         process.env.NODE_ENV = "development";
         exec(cmd, function () {
             process.env.NODE_ENV = savedNodeEnv;
+            measure(startTime);
             runLinter();
             finish();
         }, function(e, status) {
             process.env.NODE_ENV = savedNodeEnv;
+            measure(startTime);
             finish(status);
         });
 
     }
     else {
         var savedNodeEnv = process.env.NODE_ENV;
         process.env.NODE_ENV = "development";
+        var startTime = mark();
         runTestsInParallel(taskConfigsFolder, run, { testTimeout: testTimeout, noColors: colors === " --no-colors " }, function (err) {
             process.env.NODE_ENV = savedNodeEnv;
-
+            measure(startTime);
             // last worker clean everything and runs linter in case if there were no errors
             deleteTemporaryProjectOutput();
             jake.rmRf(taskConfigsFolder);
@@ -1069,6 +1098,7 @@ var lintTargets = compilerSources
 desc("Runs tslint on the compiler sources. Optional arguments are: f[iles]=regex");
 task("lint", ["build-rules"], function() {
     if (fold.isTravis()) console.log(fold.start("lint"));
+    var startTime = mark();
     var lintOptions = getLinterOptions();
     var failed = 0;
     var fileMatcher = RegExp(process.env.f || process.env.file || process.env.files || "");
@@ -1084,6 +1114,7 @@ task("lint", ["build-rules"], function() {
             done[target] = true;
         }
     }
+    measure(startTime);
     if (fold.isTravis()) console.log(fold.end("lint"));
     if (failed > 0) {
         fail('Linter errors.', failed);
