Merge pull request #5327 from overleaf/bg-extend-docupdater-profiler

[docupdater] record synchronous operations in profiler

GitOrigin-RevId: 994139e7f3fb04645e435273f5143e1fa6091be2

services/document-updater/app/js/Profiler.js

@@ -21,7 +21,8 @@ const deltaMs = function (ta, tb) {
 module.exports = Profiler = (function () {
   Profiler = class Profiler {
     static initClass() {
-      this.prototype.LOG_CUTOFF_TIME = 1000
+      this.prototype.LOG_CUTOFF_TIME = 15 * 1000
+      this.prototype.LOG_SYNC_CUTOFF_TIME = 1000
     }
 
     constructor(name, args) {
@@ -30,20 +31,24 @@ module.exports = Profiler = (function () {
       this.t0 = this.t = process.hrtime()
       this.start = new Date()
       this.updateTimes = []
+      this.totalSyncTime = 0
     }
 
-    log(label) {
+    log(label, options = {}) {
       const t1 = process.hrtime()
       const dtMilliSec = deltaMs(t1, this.t)
       this.t = t1
+      this.totalSyncTime += options.sync ? dtMilliSec : 0
       this.updateTimes.push([label, dtMilliSec]) // timings in ms
       return this // make it chainable
     }
 
     end(message) {
       const totalTime = deltaMs(this.t, this.t0)
-      if (totalTime > this.LOG_CUTOFF_TIME) {
-        // log anything greater than cutoff
+      const exceedsCutoff = totalTime > this.LOG_CUTOFF_TIME
+      const exceedsSyncCutoff = this.totalSyncTime > this.LOG_SYNC_CUTOFF_TIME
+      if (exceedsCutoff || exceedsSyncCutoff) {
+        // log anything greater than cutoffs
         const args = {}
         for (const k in this.args) {
           const v = this.args[k]
@@ -52,7 +57,8 @@ module.exports = Profiler = (function () {
         args.updateTimes = this.updateTimes
         args.start = this.start
         args.end = new Date()
-        logger.debug(args, this.name)
+        args.status = { exceedsCutoff, exceedsSyncCutoff }
+        logger.warn(args, this.name)
       }
       return totalTime
     }

services/document-updater/app/js/UpdateManager.js

@@ -167,7 +167,7 @@ module.exports = UpdateManager = {
 
     var profile = new Profiler('applyUpdate', { project_id, doc_id })
     UpdateManager._sanitizeUpdate(update)
-    profile.log('sanitizeUpdate')
+    profile.log('sanitizeUpdate', { sync: true })
     return DocumentManager.getDoc(
       project_id,
       doc_id,
@@ -182,6 +182,7 @@ module.exports = UpdateManager = {
           )
         }
         const previousVersion = version
+        const incomingUpdateVersion = update.v
         return ShareJsUpdateManager.applyUpdate(
           project_id,
           doc_id,
@@ -189,7 +190,11 @@ module.exports = UpdateManager = {
           lines,
           version,
           function (error, updatedDocLines, version, appliedOps) {
-            profile.log('sharejs.applyUpdate')
+            profile.log('sharejs.applyUpdate', {
+              // only synchronous when the update applies directly to the
+              // doc version, otherwise getPreviousDocOps is called.
+              sync: incomingUpdateVersion === previousVersion,
+            })
             if (error != null) {
               return callback(error)
             }
@@ -206,7 +211,7 @@ module.exports = UpdateManager = {
                   projectHistoryId,
                   lines
                 )
-                profile.log('RangesManager.applyUpdate')
+                profile.log('RangesManager.applyUpdate', { sync: true })
                 if (error != null) {
                   return callback(error)
                 }

services/document-updater/app/js/sharejs/server/model.js

@@ -26,6 +26,8 @@ const { EventEmitter } = require('events')
 const queue = require('./syncqueue')
 const types = require('../types')
 
+const Profiler = require('../../Profiler')
+
 const isArray = o => Object.prototype.toString.call(o) === '[object Array]'
 
 // This constructor creates a new Model object. There will be one model object
@@ -167,6 +169,7 @@ module.exports = Model = function (db, options) {
 
         if (ops.length > 0) {
           try {
+            const profile = new Profiler('model.transform')
             // If there's enough ops, it might be worth spinning this out into a webworker thread.
             for (const oldOp of Array.from(ops)) {
               // Dup detection works by sending the id(s) the op has been submitted with previously.
@@ -183,6 +186,7 @@ module.exports = Model = function (db, options) {
               opData.op = doc.type.transform(opData.op, oldOp.op, 'left')
               opData.v++
             }
+            profile.log('transform', { sync: true }).end()
           } catch (error1) {
             error = error1
             return callback(error.message)
@@ -190,7 +194,9 @@ module.exports = Model = function (db, options) {
         }
 
         try {
+          const profile = new Profiler('model.apply')
           snapshot = doc.type.apply(doc.snapshot, opData.op)
+          profile.log('model.apply', { sync: true }).end()
         } catch (error2) {
           error = error2
           return callback(error.message)