diff --git a/services/clsi/app/js/LatexRunner.js b/services/clsi/app/js/LatexRunner.js index f8799d216c..4800021932 100644 --- a/services/clsi/app/js/LatexRunner.js +++ b/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) diff --git a/services/clsi/test/unit/js/LatexRunnerTests.js b/services/clsi/test/unit/js/LatexRunnerTests.js index a9116d0fd7..f763f39cb0 100644 --- a/services/clsi/test/unit/js/LatexRunnerTests.js +++ b/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 () {