From b6efb051e145367caab6e10b8282c3e9b16af74d Mon Sep 17 00:00:00 2001
From: Brian Gough <bjg@network-theory.co.uk>
Date: Thu, 18 May 2017 11:00:07 +0100
Subject: [PATCH] add profiling

---
 .../app/coffee/Profiler.coffee                | 28 +++++++++++++++++++
 .../app/coffee/UpdateManager.coffee           | 23 +++++++++++++--
 2 files changed, 48 insertions(+), 3 deletions(-)
 create mode 100644 services/document-updater/app/coffee/Profiler.coffee

diff --git a/services/document-updater/app/coffee/Profiler.coffee b/services/document-updater/app/coffee/Profiler.coffee
new file mode 100644
index 0000000000..8aacf2a0a8
--- /dev/null
+++ b/services/document-updater/app/coffee/Profiler.coffee
@@ -0,0 +1,28 @@
+Settings = require('settings-sharelatex')
+logger = require('logger-sharelatex')
+
+deltaMs = (ta, tb) ->
+	return Math.floor(((ta[0]-tb[0])*1e9 + (ta[1]-tb[1]))*1e-6)
+
+module.exports = class Profiler
+	LOG_CUTOFF_TIME: 100
+
+	constructor: (@name, @args) ->
+		@t0 = @t = process.hrtime()
+		@updateTimes = []
+
+	log: (label) ->
+		t1 = process.hrtime()
+		dtMilliSec = deltaMs(t1, @t)
+		@t = t1
+		@updateTimes.push [label, dtMilliSec] # timings in ms
+		return @ # make it chainable
+
+	end: (message) ->
+		totalTime = deltaMs(@t, @t0)
+		return if totalTime < @LOG_CUTOFF_TIME # skip anything less than cutoff
+		args = {}
+		for k,v of @args
+			args[k] = v
+		args.updateTimes = @updateTimes
+		logger.log args, @name
diff --git a/services/document-updater/app/coffee/UpdateManager.coffee b/services/document-updater/app/coffee/UpdateManager.coffee
index 269b16ee67..70caaf1e03 100644
--- a/services/document-updater/app/coffee/UpdateManager.coffee
+++ b/services/document-updater/app/coffee/UpdateManager.coffee
@@ -10,6 +10,7 @@ Metrics = require "./Metrics"
 Errors = require "./Errors"
 DocumentManager = require "./DocumentManager"
 RangesManager = require "./RangesManager"
+Profiler = require "./Profiler"
 
 module.exports = UpdateManager =
 	processOutstandingUpdates: (project_id, doc_id, callback = (error) ->) ->
@@ -20,13 +21,17 @@ module.exports = UpdateManager =
 			callback()
 
 	processOutstandingUpdatesWithLock: (project_id, doc_id, callback = (error) ->) ->
+		profile = new Profiler("processOutstandingUpdatesWithLock", {project_id, doc_id})
 		LockManager.tryLock doc_id, (error, gotLock, lockValue) =>
 			return callback(error) if error?
 			return callback() if !gotLock
+			profile.log("tryLock")
 			UpdateManager.processOutstandingUpdates project_id, doc_id, (error) ->
 				return UpdateManager._handleErrorInsideLock(doc_id, lockValue, error, callback) if error?
+				profile.log("processOutstandingUpdates")
 				LockManager.releaseLock doc_id, lockValue, (error) =>
 					return callback(error) if error?
+					profile.log("releaseLock").end()
 					UpdateManager.continueProcessingUpdatesWithLock project_id, doc_id, callback
 
 	continueProcessingUpdatesWithLock: (project_id, doc_id, callback = (error) ->) ->
@@ -38,13 +43,20 @@ module.exports = UpdateManager =
 				callback()
 
 	fetchAndApplyUpdates: (project_id, doc_id, callback = (error) ->) ->
+		profile = new Profiler("fetchAndApplyUpdates", {project_id, doc_id})
 		RealTimeRedisManager.getPendingUpdatesForDoc doc_id, (error, updates) =>
 			return callback(error) if error?
 			if updates.length == 0
 				return callback()
-			async.eachSeries updates,
-				(update, cb) -> UpdateManager.applyUpdate project_id, doc_id, update, cb
-				callback
+			profile.log("getPendingUpdatesForDoc")
+			doUpdate = (update, cb)->
+				UpdateManager.applyUpdate project_id, doc_id, update, (err) ->
+					profile.log("applyUpdate")
+					cb(err)
+			finalCallback = (err) ->
+				profile.log("async done").end()
+				callback(err)
+			async.eachSeries updates, doUpdate, finalCallback
 
 	applyUpdate: (project_id, doc_id, update, _callback = (error) ->) ->
 		callback = (error) ->
@@ -66,14 +78,19 @@ module.exports = UpdateManager =
 						HistoryManager.recordAndFlushHistoryOps project_id, doc_id, appliedOps, historyOpsLength, callback
 
 	lockUpdatesAndDo: (method, project_id, doc_id, args..., callback) ->
+		profile = new Profiler("lockUpdatesAndDo", {project_id, doc_id})
 		LockManager.getLock doc_id, (error, lockValue) ->
+			profile.log("getLock")
 			return callback(error) if error?
 			UpdateManager.processOutstandingUpdates project_id, doc_id, (error) ->
 				return UpdateManager._handleErrorInsideLock(doc_id, lockValue, error, callback) if error?
+				profile.log("processOutStandingUpdates")
 				method project_id, doc_id, args..., (error, response_args...) ->
 					return UpdateManager._handleErrorInsideLock(doc_id, lockValue, error, callback) if error?
+					profile.log("method")
 					LockManager.releaseLock doc_id, lockValue, (error) ->
 						return callback(error) if error?
+						profile.log("releaseLock").end()
 						callback null, response_args...
 						# We held the lock for a while so updates might have queued up
 						UpdateManager.continueProcessingUpdatesWithLock project_id, doc_id