Merge pull request #238 from overleaf/jpa-drop-broken-timings

[LatexRunner] do not emit empty cpu/sys timings

services/clsi/app/js/LatexRunner.js

@@ -23,6 +23,12 @@ const fs = require('fs')
 
 const ProcessTable = {} // table of currently running jobs (pids or docker container names)
 
+const TIME_V_METRICS = Object.entries({
+  'cpu-percent': /Percent of CPU this job got: (\d+)/m,
+  'cpu-time': /User time.*: (\d+.\d+)/m,
+  'sys-time': /System time.*: (\d+.\d+)/m
+})
+
 module.exports = LatexRunner = {
   runLatex(project_id, options, callback) {
     let command
@@ -116,28 +122,16 @@ module.exports = LatexRunner = {
         stats[`latex-runs-with-errors-${runs}`] = failed ? 1 : 0
         // timing information from /usr/bin/time
         const timings = {}
-        const stderr = output != null ? output.stderr : undefined
-        timings['cpu-percent'] =
-          __guard__(
-            stderr != null
-              ? stderr.match(/Percent of CPU this job got: (\d+)/m)
-              : undefined,
-            (x3) => x3[1]
-          ) || 0
-        timings['cpu-time'] =
-          __guard__(
-            stderr != null
-              ? stderr.match(/User time.*: (\d+.\d+)/m)
-              : undefined,
-            (x4) => x4[1]
-          ) || 0
-        timings['sys-time'] =
-          __guard__(
-            stderr != null
-              ? stderr.match(/System time.*: (\d+.\d+)/m)
-              : undefined,
-            (x5) => x5[1]
-          ) || 0
+        const stderr = (output && output.stderr) || ''
+        if (stderr.includes('Command being timed:')) {
+          // Add metrics for runs with `$ time -v ...`
+          for (const [timing, matcher] of TIME_V_METRICS) {
+            const match = stderr.match(matcher)
+            if (match) {
+              timings[timing] = parseFloat(match[1])
+            }
+          }
+        }
         // record output files
         LatexRunner.writeLogOutput(project_id, directory, output, () => {
           return callback(error, output, stats, timings)

services/clsi/test/unit/js/LatexRunnerTests.js

@@ -11,6 +11,7 @@
  */
 const SandboxedModule = require('sandboxed-module')
 const sinon = require('sinon')
+const { expect } = require('chai')
 const modulePath = require('path').join(
   __dirname,
   '../../../app/js/LatexRunner'
@@ -58,7 +59,7 @@ describe('LatexRunner', function () {
     })
 
     describe('normally', function () {
-      beforeEach(function () {
+      beforeEach(function (done) {
         return this.LatexRunner.runLatex(
           this.project_id,
           {
@@ -70,7 +71,10 @@ describe('LatexRunner', function () {
             environment: this.env,
             compileGroup: this.compileGroup
           },
-          this.callback
+          (error, output, stats, timings) => {
+            this.timings = timings
+            done(error)
+          }
         )
       })
 
@@ -96,6 +100,47 @@ describe('LatexRunner', function () {
           .calledWith(this.directory + '/' + 'output.stderr', 'this is stderr')
           .should.equal(true)
       })
+
+      it('should not record cpu metrics', function () {
+        expect(this.timings['cpu-percent']).to.not.exist
+        expect(this.timings['cpu-time']).to.not.exist
+        expect(this.timings['sys-time']).to.not.exist
+      })
+    })
+
+    describe('with time -v', function () {
+      beforeEach(function (done) {
+        this.CommandRunner.run = sinon.stub().callsArgWith(7, null, {
+          stdout: 'this is stdout',
+          stderr:
+            '\tCommand being timed: "sh -c timeout 1 yes > /dev/null"\n' +
+            '\tUser time (seconds): 0.28\n' +
+            '\tSystem time (seconds): 0.70\n' +
+            '\tPercent of CPU this job got: 98%\n'
+        })
+        this.LatexRunner.runLatex(
+          this.project_id,
+          {
+            directory: this.directory,
+            mainFile: this.mainFile,
+            compiler: this.compiler,
+            timeout: (this.timeout = 42000),
+            image: this.image,
+            environment: this.env,
+            compileGroup: this.compileGroup
+          },
+          (error, output, stats, timings) => {
+            this.timings = timings
+            done(error)
+          }
+        )
+      })
+
+      it('should record cpu metrics', function () {
+        expect(this.timings['cpu-percent']).to.equal(98)
+        expect(this.timings['cpu-time']).to.equal(0.28)
+        expect(this.timings['sys-time']).to.equal(0.7)
+      })
     })
 
     describe('with an .Rtex main file', function () {