Merge pull request #28909 from overleaf/em-compile-metrics

Use histograms to track CLSI compile times

GitOrigin-RevId: cf25f1e6d2094186f419acc70748f0c71b6c3240

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')

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,
   })
-
-  // Emit e2e compile time.
-  timings.compileE2E = timerE2E.done()
-  Metrics.timing('compile-e2e-v2', timings.compileE2E, 1, request.metricsOpts)
+  timings.compileE2E = Date.now() - e2eCompileStart
+
+  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),

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 = {

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,
+}

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')

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 = {

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')
 

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()
 

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 })

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}\
-`,
+`
+  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',
         },
-      ],
-      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)
       })
-      .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'
-    )
-  })
+      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'
+        )
+      })
+    })
+  }
 })

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,
       },
     })
   })

services/clsi/test/unit/js/DockerRunnerTests.js

@@ -51,7 +51,7 @@ describe('DockerRunner', function () {
             },
           }),
         }),
-        './Metrics': {
+        '@overleaf/metrics': {
           Timer: (Timer = class Timer {
             done() {}
           }),

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
     })

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 {