diff --git a/services/document-updater/app/js/Profiler.js b/services/document-updater/app/js/Profiler.js index b1d5e586f7..5892721ff5 100644 --- a/services/document-updater/app/js/Profiler.js +++ b/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 } diff --git a/services/document-updater/app/js/UpdateManager.js b/services/document-updater/app/js/UpdateManager.js index 651c62b0eb..71b0b89a20 100644 --- a/services/document-updater/app/js/UpdateManager.js +++ b/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) } diff --git a/services/document-updater/app/js/sharejs/server/model.js b/services/document-updater/app/js/sharejs/server/model.js index f91149f627..6ad3eb25ca 100644 --- a/services/document-updater/app/js/sharejs/server/model.js +++ b/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)