diff --git a/services/clsi/app/js/CompileController.js b/services/clsi/app/js/CompileController.js index 7329c14342..285354ad84 100644 --- a/services/clsi/app/js/CompileController.js +++ b/services/clsi/app/js/CompileController.js @@ -2,7 +2,7 @@ const Path = require('node:path') const RequestParser = require('./RequestParser') const CompileManager = require('./CompileManager') const Settings = require('@overleaf/settings') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const ProjectPersistenceManager = require('./ProjectPersistenceManager') const logger = require('@overleaf/logger') const Errors = require('./Errors') diff --git a/services/clsi/app/js/CompileManager.js b/services/clsi/app/js/CompileManager.js index 962e7e6068..f24cb98fdd 100644 --- a/services/clsi/app/js/CompileManager.js +++ b/services/clsi/app/js/CompileManager.js @@ -6,12 +6,13 @@ const { callbackify } = require('node:util') const Settings = require('@overleaf/settings') const logger = require('@overleaf/logger') const OError = require('@overleaf/o-error') +const Metrics = require('@overleaf/metrics') const ResourceWriter = require('./ResourceWriter') const LatexRunner = require('./LatexRunner') const OutputFileFinder = require('./OutputFileFinder') const OutputCacheManager = require('./OutputCacheManager') -const Metrics = require('./Metrics') +const ClsiMetrics = require('./Metrics') const DraftModeManager = require('./DraftModeManager') const TikzManager = require('./TikzManager') const LockManager = require('./LockManager') @@ -67,12 +68,8 @@ async function doCompile(request, stats, timings) { const { project_id: projectId, user_id: userId } = request const compileDir = getCompileDir(request.project_id, request.user_id) - const timerE2E = new Metrics.Timer( - 'compile-e2e-v2', - 1, - request.metricsOpts, - COMPILE_TIME_BUCKETS - ) + const e2eCompileStart = Date.now() + if (request.isInitialCompile) { stats.isInitialCompile = 1 request.metricsOpts.compile = 'initial' @@ -92,11 +89,8 @@ async function doCompile(request, stats, timings) { } else { request.metricsOpts.compile = 'recompile' } - const writeToDiskTimer = new Metrics.Timer( - 'write-to-disk', - 1, - request.metricsOpts - ) + + const syncStart = Date.now() logger.debug( { projectId: request.project_id, userId: request.user_id }, 'syncing resources to disk' @@ -123,15 +117,16 @@ async function doCompile(request, stats, timings) { } throw error } + + timings.sync = Date.now() - syncStart logger.debug( { projectId: request.project_id, userId: request.user_id, - timeTaken: Date.now() - writeToDiskTimer.start, + timeTaken: timings.sync, }, 'written files to disk' ) - timings.sync = writeToDiskTimer.done() // set up environment variables for chktex const env = { @@ -177,21 +172,20 @@ async function doCompile(request, stats, timings) { ) } - const compileTimer = new Metrics.Timer('run-compile', 1, request.metricsOpts) - // find the image tag to log it as a metric, e.g. 2015.1 (convert . to - for graphite) + const compileStart = Date.now() + + // find the image tag to log it as a metric, e.g. 2015.1 let tag = 'default' if (request.imageName != null) { const match = request.imageName.match(/:(.*)/) if (match != null) { - tag = match[1].replace(/\./g, '-') + tag = match[1] } } // exclude smoke test if (!request.project_id.match(/^[0-9a-f]{24}$/)) { tag = 'other' } - Metrics.inc('compiles', 1, request.metricsOpts) - Metrics.inc(`compiles-with-image.${tag}`, 1, request.metricsOpts) const compileName = getCompileName(request.project_id, request.user_id) // Record latexmk -time stats for a subset of users @@ -241,11 +235,6 @@ async function doCompile(request, stats, timings) { error.validate = 'fail' } - // record timeout errors as a separate counter, success is recorded later - if (error.timedout) { - Metrics.inc('compiles-timeout', 1, request.metricsOpts) - } - const { outputFiles, allEntries, buildId } = await _saveOutputFiles({ request, compileDir, @@ -264,49 +253,59 @@ async function doCompile(request, stats, timings) { ) } + if (!_shouldSkipMetrics(request)) { + const status = error.timedout + ? 'timeout' + : error.terminated + ? 'terminated' + : 'failure' + timings.compile = Date.now() - compileStart + ClsiMetrics.compilesTotal.inc({ + status, + engine: request.compiler, + image: tag, + compile: request.metricsOpts.compile, + group: request.compileGroup, + draft: request.draft ? 'true' : 'false', + stop_on_first_error: request.stopOnFirstError ? 'true' : 'false', + }) + ClsiMetrics.compileDurationSeconds.observe( + { + status, + engine: request.compiler, + compile: request.metricsOpts.compile, + group: request.compileGroup, + }, + timings.compile / 1000 + ) + } throw error } - // compile completed normally - Metrics.inc('compiles-succeeded', 1, request.metricsOpts) - for (const metricKey in stats) { - const metricValue = stats[metricKey] - if (typeof metricValue === 'number') { - Metrics.count(metricKey, metricValue, 1, request.metricsOpts) - } - } - for (const metricKey in timings) { - const metricValue = timings[metricKey] - if (typeof metricValue === 'number') { - Metrics.timing(metricKey, metricValue, 1, request.metricsOpts) - } - } - const loadavg = typeof os.loadavg === 'function' ? os.loadavg() : undefined - if (loadavg != null) { - Metrics.gauge('load-avg', loadavg[0]) - } - const ts = compileTimer.done() + timings.compile = Date.now() - compileStart + const status = stats['latexmk-errors'] ? 'error' : 'success' + logger.debug( { projectId: request.project_id, userId: request.user_id, - timeTaken: ts, + timeTaken: timings.compile, stats, timings, - loadavg, }, 'done compile' ) + if (stats['latex-runs'] > 0) { Metrics.histogram( 'avg-compile-per-pass-v2', - ts / stats['latex-runs'], + timings.compile / stats['latex-runs'], COMPILE_TIME_BUCKETS, request.metricsOpts ) Metrics.timing( 'avg-compile-per-pass-v2', - ts / stats['latex-runs'], + timings.compile / stats['latex-runs'], 1, request.metricsOpts ) @@ -319,8 +318,6 @@ async function doCompile(request, stats, timings) { request.metricsOpts ) } - // Emit compile time. - timings.compile = ts const { outputFiles, buildId } = await _saveOutputFiles({ request, @@ -329,10 +326,37 @@ async function doCompile(request, stats, timings) { stats, timings, }) + timings.compileE2E = Date.now() - e2eCompileStart - // Emit e2e compile time. - timings.compileE2E = timerE2E.done() - Metrics.timing('compile-e2e-v2', timings.compileE2E, 1, request.metricsOpts) + if (!_shouldSkipMetrics(request)) { + ClsiMetrics.compilesTotal.inc({ + status, + engine: request.compiler, + image: tag, + compile: request.metricsOpts.compile, + group: request.compileGroup, + draft: request.draft ? 'true' : 'false', + stop_on_first_error: request.stopOnFirstError ? 'true' : 'false', + }) + ClsiMetrics.compileDurationSeconds.observe( + { + status, + engine: request.compiler, + compile: request.metricsOpts.compile, + group: request.compileGroup, + }, + timings.compile / 1000 + ) + ClsiMetrics.syncResourcesDurationSeconds.observe( + { + type: request.syncType, + compile: request.metricsOpts.compile, + group: request.compileGroup, + }, + timings.sync / 1000 + ) + ClsiMetrics.e2eCompileDurationSeconds.observe(timings.compileE2E / 1000) + } if (stats['pdf-size']) { emitPdfStats(stats, timings, request) @@ -353,11 +377,14 @@ async function doCompile(request, stats, timings) { 'error reading fdb file for performance metrics' ) } + + const loadavg = typeof os.loadavg === 'function' ? os.loadavg() : undefined + logger.info( { userId: request.user_id, projectId: request.project_id, - timeTaken: ts, + timeTaken: timings.compile, clsiRequest: request, stats, timings, @@ -382,11 +409,7 @@ async function _saveOutputFiles({ stats, timings, }) { - const timer = new Metrics.Timer( - 'process-output-files', - 1, - request.metricsOpts - ) + const start = Date.now() const outputDir = getOutputDir(request.project_id, request.user_id) const { outputFiles: rawOutputFiles, allEntries } = @@ -400,7 +423,16 @@ async function _saveOutputFiles({ outputDir ) - timings.output = timer.done() + timings.output = Date.now() - start + if (!_shouldSkipMetrics(request)) { + ClsiMetrics.processOutputFilesDurationSeconds.observe( + { + compile: request.metricsOpts.compile, + group: request.compileGroup, + }, + timings.output / 1000 + ) + } return { outputFiles, allEntries, buildId } } @@ -770,6 +802,10 @@ function _isImageNameAllowed(imageName) { return !ALLOWED_IMAGES || ALLOWED_IMAGES.includes(imageName) } +function _shouldSkipMetrics(request) { + return ['clsi-perf', 'health-check'].includes(request.metricsOpts.path) +} + module.exports = { doCompileWithLock: callbackify(doCompileWithLock), stopCompile: callbackify(stopCompile), diff --git a/services/clsi/app/js/ContentCacheMetrics.js b/services/clsi/app/js/ContentCacheMetrics.js index 1e2b598286..cb617ff856 100644 --- a/services/clsi/app/js/ContentCacheMetrics.js +++ b/services/clsi/app/js/ContentCacheMetrics.js @@ -1,5 +1,5 @@ const logger = require('@overleaf/logger') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const os = require('node:os') let CACHED_LOAD = { diff --git a/services/clsi/app/js/Metrics.js b/services/clsi/app/js/Metrics.js index f0e57794fd..956ddcbe51 100644 --- a/services/clsi/app/js/Metrics.js +++ b/services/clsi/app/js/Metrics.js @@ -1,3 +1,55 @@ -// TODO: This file was created by bulk-decaffeinate. -// Sanity-check the conversion and remove this comment. -module.exports = require('@overleaf/metrics') +const { prom } = require('@overleaf/metrics') + +const COMPILE_TIME_BUCKETS = [ + 0.5, 1, 1.5, 2, 3, 4, 5, 6, 8, 10, 15, 20, 25, 30, 45, 60, 75, 90, 120, 150, + 180, 210, 240, +] + +const compilesTotal = new prom.Counter({ + name: 'clsi_compiles_total', + help: 'Number of compiles', + labelNames: [ + 'status', + 'engine', + 'compile', + 'group', + 'image', + 'draft', + 'stop_on_first_error', + ], +}) + +const compileDurationSeconds = new prom.Histogram({ + name: 'clsi_compile_duration_seconds', + help: 'Duration of the latexmkrc invocation', + buckets: COMPILE_TIME_BUCKETS, + labelNames: ['status', 'engine', 'compile', 'group'], +}) + +const e2eCompileDurationSeconds = new prom.Histogram({ + name: 'clsi_e2e_compile_duration_seconds', + help: 'Duration of the entire compile request in clsi (sync, latexmk, output)', + buckets: COMPILE_TIME_BUCKETS, +}) + +const syncResourcesDurationSeconds = new prom.Histogram({ + name: 'clsi_sync_resources_duration_seconds', + help: 'Time it takes to prepare files for a compile', + buckets: [0.1, 0.25, 0.5, 0.75, 1, 2, 3, 5, 10, 15, 30, 45, 60], + labelNames: ['type', 'compile', 'group'], +}) + +const processOutputFilesDurationSeconds = new prom.Histogram({ + name: 'clsi_process_output_files_duration_seconds', + help: 'Time it takes to process output files of a compile', + buckets: [0.1, 0.25, 0.5, 0.75, 1, 2, 3, 5, 7.5, 10], + labelNames: ['compile', 'group'], +}) + +module.exports = { + compilesTotal, + compileDurationSeconds, + e2eCompileDurationSeconds, + syncResourcesDurationSeconds, + processOutputFilesDurationSeconds, +} diff --git a/services/clsi/app/js/OutputCacheManager.js b/services/clsi/app/js/OutputCacheManager.js index a1a0a89aa7..8336d0075a 100644 --- a/services/clsi/app/js/OutputCacheManager.js +++ b/services/clsi/app/js/OutputCacheManager.js @@ -7,7 +7,7 @@ const logger = require('@overleaf/logger') const _ = require('lodash') const Settings = require('@overleaf/settings') const crypto = require('node:crypto') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const OutputFileOptimiser = require('./OutputFileOptimiser') const ContentCacheManager = require('./ContentCacheManager') diff --git a/services/clsi/app/js/OutputFileOptimiser.js b/services/clsi/app/js/OutputFileOptimiser.js index 09ca98672d..5859c006da 100644 --- a/services/clsi/app/js/OutputFileOptimiser.js +++ b/services/clsi/app/js/OutputFileOptimiser.js @@ -17,7 +17,7 @@ const fs = require('node:fs') const Path = require('node:path') const { spawn } = require('node:child_process') const logger = require('@overleaf/logger') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const _ = require('lodash') module.exports = OutputFileOptimiser = { diff --git a/services/clsi/app/js/ResourceWriter.js b/services/clsi/app/js/ResourceWriter.js index bf88538746..06ad6853a2 100644 --- a/services/clsi/app/js/ResourceWriter.js +++ b/services/clsi/app/js/ResourceWriter.js @@ -20,7 +20,7 @@ const fs = require('node:fs') const async = require('async') const OutputFileFinder = require('./OutputFileFinder') const ResourceStateManager = require('./ResourceStateManager') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const logger = require('@overleaf/logger') const settings = require('@overleaf/settings') diff --git a/services/clsi/app/js/UrlCache.js b/services/clsi/app/js/UrlCache.js index 36703e7091..304474bbed 100644 --- a/services/clsi/app/js/UrlCache.js +++ b/services/clsi/app/js/UrlCache.js @@ -15,7 +15,7 @@ const Settings = require('@overleaf/settings') const fs = require('node:fs') const Path = require('node:path') const { callbackify } = require('node:util') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const PENDING_DOWNLOADS = new Map() diff --git a/services/clsi/app/js/UrlFetcher.js b/services/clsi/app/js/UrlFetcher.js index 2c44f3a6dd..82902b9e57 100644 --- a/services/clsi/app/js/UrlFetcher.js +++ b/services/clsi/app/js/UrlFetcher.js @@ -9,7 +9,7 @@ const { } = require('@overleaf/fetch-utils') const { URL } = require('node:url') const { pipeline } = require('node:stream/promises') -const Metrics = require('./Metrics') +const Metrics = require('@overleaf/metrics') const MAX_CONNECT_TIME = 1000 const httpAgent = new CustomHttpAgent({ connectTimeout: MAX_CONNECT_TIME }) diff --git a/services/clsi/test/acceptance/js/SimpleLatexFileTests.js b/services/clsi/test/acceptance/js/SimpleLatexFileTests.js index 315873b575..92b64d145b 100644 --- a/services/clsi/test/acceptance/js/SimpleLatexFileTests.js +++ b/services/clsi/test/acceptance/js/SimpleLatexFileTests.js @@ -1,97 +1,95 @@ const Client = require('./helpers/Client') -const { fetchString, fetchNothing } = require('@overleaf/fetch-utils') +const { fetchNothing } = require('@overleaf/fetch-utils') const ClsiApp = require('./helpers/ClsiApp') -const Settings = require('@overleaf/settings') describe('Simple LaTeX file', function () { - before(async function () { - this.project_id = Client.randomId() - this.request = { - resources: [ - { - path: 'main.tex', - content: `\ + const content = `\ \\documentclass{article} \\begin{document} Hello world \\end{document}\ -`, - }, - ], - options: { - metricsPath: 'clsi-perf', - metricsMethod: 'priority', +` + const scenarios = [ + { + description: 'simple file', + request: { + resources: [{ path: 'main.tex', content }], }, - } + }, + { + description: 'clsi-perf request', + request: { + resources: [{ path: 'main.tex', content }], + options: { + metricsPath: 'clsi-perf', + metricsMethod: 'priority', + }, + }, + }, + ] - await ClsiApp.ensureRunning() - try { - this.body = await Client.compile(this.project_id, this.request) - } catch (error) { - this.error = error - } - }) + for (const scenario of scenarios) { + describe(scenario.description, function () { + before(async function () { + this.project_id = Client.randomId() + this.request = scenario.request - it('should return the PDF', function () { - const pdf = Client.getOutputFile(this.body, 'pdf') - pdf.type.should.equal('pdf') - }) + await ClsiApp.ensureRunning() + try { + this.body = await Client.compile(this.project_id, this.request) + } catch (error) { + this.error = error + } + }) - it('should return the log', function () { - const log = Client.getOutputFile(this.body, 'log') - log.type.should.equal('log') - }) + it('should return the PDF', function () { + const pdf = Client.getOutputFile(this.body, 'pdf') + pdf.type.should.equal('pdf') + }) - it('should provide the pdf for download', async function () { - const pdf = Client.getOutputFile(this.body, 'pdf') - const response = await fetchNothing(pdf.url) - response.status.should.equal(200) - }) + it('should return the log', function () { + const log = Client.getOutputFile(this.body, 'log') + log.type.should.equal('log') + }) - it('should provide the log for download', async function () { - const log = Client.getOutputFile(this.body, 'pdf') - const response = await fetchNothing(log.url) - response.status.should.equal(200) - }) + it('should provide the pdf for download', async function () { + const pdf = Client.getOutputFile(this.body, 'pdf') + const response = await fetchNothing(pdf.url) + response.status.should.equal(200) + }) - it('should gather personalized metrics', async function () { - const body = await fetchString(`${Settings.apis.clsi.url}/metrics`) - body - .split('\n') - .some(line => { - return ( - line.startsWith('compile') && - line.includes('path="clsi-perf"') && - line.includes('method="priority"') + it('should provide the log for download', async function () { + const log = Client.getOutputFile(this.body, 'pdf') + const response = await fetchNothing(log.url) + response.status.should.equal(200) + }) + + it('should return only the expected keys for stats and timings', function () { + const { stats, timings } = this.body.compile + // Note: chai's all.keys assertion rejects extra keys + stats.should.have.all.keys( + 'isInitialCompile', + 'latexmk-errors', + 'latex-runs', + 'latex-runs-with-errors', + 'latex-runs-2', + 'latex-runs-with-errors-2', + 'pdf-caching-total-ranges-size', + 'pdf-caching-reclaimed-space', + 'pdf-caching-new-ranges-size', + 'pdf-caching-n-ranges', + 'pdf-caching-n-new-ranges', + 'pdf-size' + ) + timings.should.have.all.keys( + 'sync', + 'compile', + 'output', + 'compileE2E', + 'compute-pdf-caching', + 'pdf-caching-overhead-delete-stale-hashes' ) }) - .should.equal(true) - }) - - it('should return only the expected keys for stats and timings', function () { - const { stats, timings } = this.body.compile - // Note: chai's all.keys assertion rejects extra keys - stats.should.have.all.keys( - 'isInitialCompile', - 'latexmk-errors', - 'latex-runs', - 'latex-runs-with-errors', - 'latex-runs-2', - 'latex-runs-with-errors-2', - 'pdf-caching-total-ranges-size', - 'pdf-caching-reclaimed-space', - 'pdf-caching-new-ranges-size', - 'pdf-caching-n-ranges', - 'pdf-caching-n-new-ranges', - 'pdf-size' - ) - timings.should.have.all.keys( - 'sync', - 'compile', - 'output', - 'compileE2E', - 'compute-pdf-caching', - 'pdf-caching-overhead-delete-stale-hashes' - ) - }) + }) + } }) diff --git a/services/clsi/test/unit/js/CompileManagerTests.js b/services/clsi/test/unit/js/CompileManagerTests.js index fb93cbb478..ef1515222a 100644 --- a/services/clsi/test/unit/js/CompileManagerTests.js +++ b/services/clsi/test/unit/js/CompileManagerTests.js @@ -2,6 +2,7 @@ const Path = require('node:path') const SandboxedModule = require('sandboxed-module') const { expect } = require('chai') const sinon = require('sinon') +const Metrics = require('../../../app/js/Metrics') const MODULE_PATH = require('node:path').join( __dirname, @@ -177,6 +178,7 @@ describe('CompileManager', function () { './CLSICacheHandler': this.CLSICacheHandler, './LatexMetrics': this.LatexMetrics, './StatsManager': this.StatsManager, + './Metrics': Metrics, }, }) }) diff --git a/services/clsi/test/unit/js/DockerRunnerTests.js b/services/clsi/test/unit/js/DockerRunnerTests.js index d70aab52c7..b060a5eb63 100644 --- a/services/clsi/test/unit/js/DockerRunnerTests.js +++ b/services/clsi/test/unit/js/DockerRunnerTests.js @@ -51,7 +51,7 @@ describe('DockerRunner', function () { }, }), }), - './Metrics': { + '@overleaf/metrics': { Timer: (Timer = class Timer { done() {} }), diff --git a/services/clsi/test/unit/js/OutputFileOptimiserTests.js b/services/clsi/test/unit/js/OutputFileOptimiserTests.js index 1dd1a751b9..1e67792c92 100644 --- a/services/clsi/test/unit/js/OutputFileOptimiserTests.js +++ b/services/clsi/test/unit/js/OutputFileOptimiserTests.js @@ -27,7 +27,7 @@ describe('OutputFileOptimiser', function () { fs: (this.fs = {}), path: (this.Path = {}), child_process: { spawn: (this.spawn = sinon.stub()) }, - './Metrics': {}, + '@overleaf/metrics': {}, }, globals: { Math }, // used by lodash }) diff --git a/services/clsi/test/unit/js/ResourceWriterTests.js b/services/clsi/test/unit/js/ResourceWriterTests.js index c2e09ce9cf..bdb262b507 100644 --- a/services/clsi/test/unit/js/ResourceWriterTests.js +++ b/services/clsi/test/unit/js/ResourceWriterTests.js @@ -34,7 +34,7 @@ describe('ResourceWriter', function () { createProjectDir: sinon.stub().yields(), }), './OutputFileFinder': (this.OutputFileFinder = {}), - './Metrics': (this.Metrics = { + '@overleaf/metrics': (this.Metrics = { inc: sinon.stub(), Timer: (Timer = (function () { Timer = class Timer {