From a5500780711507ebea0d55800c06cb55813ae5ff Mon Sep 17 00:00:00 2001
From: Brian Gough <bjg@network-theory.co.uk>
Date: Thu, 18 May 2017 15:04:12 +0100
Subject: [PATCH] replace verbose logging by slow query log

---
 .../app/coffee/LockManager.coffee               | 17 ++++++++++++-----
 1 file changed, 12 insertions(+), 5 deletions(-)

diff --git a/services/document-updater/app/coffee/LockManager.coffee b/services/document-updater/app/coffee/LockManager.coffee
index 1f710b448d..d918dc4332 100644
--- a/services/document-updater/app/coffee/LockManager.coffee
+++ b/services/document-updater/app/coffee/LockManager.coffee
@@ -7,6 +7,8 @@ logger = require "logger-sharelatex"
 os = require "os"
 crypto = require "crypto"
 
+Profiler = require "./Profiler"
+
 HOST = os.hostname()
 PID = process.pid
 RND = crypto.randomBytes(4).toString('hex')
@@ -30,33 +32,36 @@ module.exports = LockManager =
 	tryLock : (doc_id, callback = (err, isFree)->)->
 		lockValue = LockManager.randomLock()
 		key = keys.blockingKey(doc_id:doc_id)
-		logger.log {doc_id: doc_id, key: key}, "tryLock"
+		profile = new Profiler("tryLock", {doc_id, key, lockValue})
 		rclient.set key, lockValue, "EX", @LOCK_TTL, "NX", (err, gotLock)->
 			return callback(err) if err?
 			if gotLock == "OK"
 				metrics.inc "doc-not-blocking"
-				logger.log {doc_id: doc_id, key: key, lockValue: lockValue}, "got lock"
+				profile.log("got lock").end()
 				callback err, true, lockValue
 			else
 				metrics.inc "doc-blocking"
-				logger.log {doc_id: doc_id, key: key}, "doc is locked"
+				profile.log("doc is locked").end()
 				callback err, false
 
 	getLock: (doc_id, callback = (error, lockValue) ->) ->
 		startTime = Date.now()
 		testInterval = LockManager.LOCK_TEST_INTERVAL
+		profile = new Profiler("getLock", {doc_id})
 		do attempt = () ->
 			if Date.now() - startTime > LockManager.MAX_LOCK_WAIT_TIME
 				e = new Error("Timeout")
 				e.doc_id = doc_id
+				profile.log("timeout").end()
 				return callback(e)
 
 			LockManager.tryLock doc_id, (error, gotLock, lockValue) ->
 				return callback(error) if error?
+				profile.log("tryLock")
 				if gotLock
+					profile.end()
 					callback(null, lockValue)
 				else
-					logger.log {doc_id: doc_id, delay: testInterval}, "will retry lock"
 					setTimeout attempt, testInterval
 					# back off when the lock is taken to avoid overloading
 					testInterval = Math.min(testInterval * 2, LockManager.MAX_TEST_INTERVAL)
@@ -75,12 +80,14 @@ module.exports = LockManager =
 
 	releaseLock: (doc_id, lockValue, callback)->
 		key = keys.blockingKey(doc_id:doc_id)
+		profile = new Profiler("releaseLock", {doc_id, key, lockValue})
 		rclient.eval LockManager.unlockScript, 1, key, lockValue, (err, result) ->
 			if err?
 				return callback(err)
 			else if result? and result isnt 1 # successful unlock should release exactly one key
+				profile.log("unlockScript:expired-lock").end()
 				logger.error {doc_id:doc_id, key:key, lockValue:lockValue, redis_err:err, redis_result:result}, "unlocking error"
 				return callback(new Error("tried to release timed out lock"))
 			else
-				logger.log {doc_id:doc_id, key:key, lockValue:lockValue}, "released lock"
+				profile.log("unlockScript:ok").end()
 				callback(err,result)