diff --git a/services/clsi/app/js/CompileManager.js b/services/clsi/app/js/CompileManager.js index 9ddb5ad4a8..f0fd8514a2 100644 --- a/services/clsi/app/js/CompileManager.js +++ b/services/clsi/app/js/CompileManager.js @@ -766,6 +766,19 @@ function _emitMetrics(request, status, stats, timings) { } } + const imgTimings = stats.latexmk?.['latexmk-img-times'] + if (imgTimings != null) { + for (const timing of imgTimings) { + ClsiMetrics.imageProcessingDurationSeconds.observe( + { + group: request.compileGroup, + type: timing.type, + }, + timing.time_ms / 1000 + ) + } + } + ClsiMetrics.compilesTotal.inc({ status, engine: request.compiler, diff --git a/services/clsi/app/js/LatexMetrics.js b/services/clsi/app/js/LatexMetrics.js index e84d652f88..3aa2a0b3e1 100644 --- a/services/clsi/app/js/LatexMetrics.js +++ b/services/clsi/app/js/LatexMetrics.js @@ -22,7 +22,7 @@ const NOTEWORTHY_DEPENDENCIES_REGEXP = * There are different formats of `latexmk` output depending on the version. * The parsers attempt to handle these variations gracefully. */ -const LATEX_MK_METRICS = [ +const LATEX_MK_METRICS_STDOUT = [ // Extract individual latexmk rule times as an array of objects, each with 'rule' // and 'time_ms' properties [ @@ -100,22 +100,61 @@ const LATEX_MK_METRICS = [ ], ] +const LATEX_MK_METRICS_STDERR = [ + [ + 'latexmk-img-times', + s => { + const pngCopyMatches = s.matchAll(/^PNG copy: (.*)$/gm) + const pngCopyFiles = new Set() + for (const match of pngCopyMatches) { + const filename = match[1] + pngCopyFiles.add(filename) + } + + const timingMatches = s.matchAll( + /^Image written \((PNG|JPG|JBIG2|PDF), (\d+) ms\): (.*)$/gm + ) + const timingsByType = new Map() + for (const match of timingMatches) { + let type = match[1] + const timeMs = parseInt(match[2], 10) + const filename = match[3] + if (type === 'PNG' && pngCopyFiles.has(filename)) { + type = 'PNG-fast-copy' + } + const accumulatedTime = timingsByType.get(type) ?? 0 + timingsByType.set(type, accumulatedTime + timeMs) + } + return Array.from(timingsByType.entries()).map(([type, timeMs]) => ({ + type, + time_ms: timeMs, + })) + }, + ], +] + /** * Parses latexmk stdout for metrics and adds them to the stats object. * It iterates through a predefined list of metric matchers (LATEX_MK_METRICS), * applies them to the stdout, and adds any successful matches to the * `stats.latexmk` object. * - * @param {{stdout?: string}} output - The output from the latexmk process. + * @param {{stdout?: string, stderr?: string}} output - The output from the latexmk process. * @param {{latexmk: object}} stats - The statistics object to update. This object is mutated. */ function addLatexMkMetrics(output, stats) { - for (const [stat, matcher] of LATEX_MK_METRICS) { + for (const [stat, matcher] of LATEX_MK_METRICS_STDOUT) { const match = matcher(output?.stdout || '', stats.latexmk) if (match) { stats.latexmk[stat] = match } } + for (const [stat, matcher] of LATEX_MK_METRICS_STDERR) { + const match = matcher(output?.stderr || '', stats.latexmk) + if (match) { + stats.latexmk[stat] = match + } + } } /** diff --git a/services/clsi/app/js/Metrics.js b/services/clsi/app/js/Metrics.js index d064c43b3e..598da90342 100644 --- a/services/clsi/app/js/Metrics.js +++ b/services/clsi/app/js/Metrics.js @@ -54,6 +54,13 @@ const latexmkRuleDurationSeconds = new prom.Histogram({ labelNames: ['group', 'rule'], }) +const imageProcessingDurationSeconds = new prom.Histogram({ + name: 'clsi_image_processing_duration_seconds', + help: 'Time spent processing images', + buckets: COMPILE_TIME_BUCKETS, + labelNames: ['group', 'type'], +}) + module.exports = { compilesTotal, compileDurationSeconds, @@ -61,4 +68,5 @@ module.exports = { syncResourcesDurationSeconds, processOutputFilesDurationSeconds, latexmkRuleDurationSeconds, + imageProcessingDurationSeconds, } diff --git a/services/clsi/test/unit/js/LatexRunnerTests.js b/services/clsi/test/unit/js/LatexRunnerTests.js index 0314800d85..fca58b63f8 100644 --- a/services/clsi/test/unit/js/LatexRunnerTests.js +++ b/services/clsi/test/unit/js/LatexRunnerTests.js @@ -249,6 +249,7 @@ describe('LatexRunner', function () { 'makeindex,bibtex,latex,makeindex,bibtex,latex,makeindex,bibtex,latex', 'latexmk-rules-run': 9, 'latexmk-time': { total: 2930 }, + 'latexmk-img-times': [], }) }) }) @@ -280,6 +281,7 @@ describe('LatexRunner', function () { }, 'latexmk-clock-time': 4870, 'latexmk-rules-run': 4, + 'latexmk-img-times': [], }) }) })