From 0a5ca6b0fa1d2b45163139f97a3c77e9aa5ca8ca Mon Sep 17 00:00:00 2001
From: Brian Gough <bjg@network-theory.co.uk>
Date: Mon, 9 May 2016 16:00:24 +0100
Subject: [PATCH] add timing information from /usr/bin/time

---
 app/coffee/CompileManager.coffee | 10 ++++++----
 app/coffee/LatexRunner.coffee    |  8 ++++++--
 2 files changed, 12 insertions(+), 6 deletions(-)

diff --git a/app/coffee/CompileManager.coffee b/app/coffee/CompileManager.coffee
index ca84303..5c70c07 100644
--- a/app/coffee/CompileManager.coffee
+++ b/app/coffee/CompileManager.coffee
@@ -43,17 +43,19 @@ module.exports = CompileManager =
 					compiler:  request.compiler
 					timeout:   request.timeout
 					image:     request.imageName
-				}, (error, output, stats) ->
+				}, (error, output, stats, timings) ->
 					return callback(error) if error?
 					Metrics.inc("compiles-succeeded")
 					for metric_key, metric_value of stats or {}
 						Metrics.count(metric_key, metric_value)
+					for metric_key, metric_value of timings or {}
+						Metrics.timing(metric_key, metric_value)
 					loadavg = os.loadavg?()
 					Metrics.gauge("load-avg", loadavg[0]) if loadavg?
 					ts = timer.done()
-					logger.log {project_id: request.project_id, time_taken: ts, stats:stats, loadavg:loadavg}, "done compile"
-					if stats?["latex-runs"] > 0
-						Metrics.timing("run-compile-per-pass", ts / stats["latex-runs"])
+					logger.log {project_id: request.project_id, time_taken: ts, stats:stats, timings:timings, loadavg:loadavg}, "done compile"
+					if stats?["latex-runs"] > 0 and timings?["cpu-time"] > 0
+						Metrics.timing("run-compile-per-pass", timings["cpu-time"] / stats["latex-runs"])
 
 					OutputFileFinder.findOutputFiles request.resources, compileDir, (error, outputFiles) ->
 						return callback(error) if error?
diff --git a/app/coffee/LatexRunner.coffee b/app/coffee/LatexRunner.coffee
index 4280d95..e5861a5 100644
--- a/app/coffee/LatexRunner.coffee
+++ b/app/coffee/LatexRunner.coffee
@@ -41,9 +41,13 @@ module.exports = LatexRunner =
 			stats["latex-runs-with-errors"] = if failed then runs else 0
 			stats["latex-runs-#{runs}"] = 1
 			stats["latex-runs-with-errors-#{runs}"] = if failed then 1 else 0
-			callback error, output, stats
+			# timing information from /usr/bin/time
+			timings = {}
+			timings["cpu-percent"] = output?.stderr?.match(/Percent of CPU this job got: (\d+)/m)?[1] or 0
+			timings["cpu-time"] = output?.stderr?.match(/User time.*: (\d+.\d+)/m)?[1] or 0
+			callback error, output, stats, timings
 
-	_latexmkBaseCommand: ["latexmk", "-cd", "-f", "-jobname=output", "-auxdir=$COMPILE_DIR", "-outdir=$COMPILE_DIR"]
+	_latexmkBaseCommand: ["/usr/bin/time", "-v", "latexmk", "-cd", "-f", "-jobname=output", "-auxdir=$COMPILE_DIR", "-outdir=$COMPILE_DIR"]
 
 	_pdflatexCommand: (mainFile) ->
 		LatexRunner._latexmkBaseCommand.concat [