From e293d86c148a93b039ef3a084d84e3a9a0983229 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 25 Mar 2020 12:15:16 +0000 Subject: [PATCH 01/10] add metric for project history queue --- .../app/coffee/ProjectHistoryRedisManager.coffee | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/services/document-updater/app/coffee/ProjectHistoryRedisManager.coffee b/services/document-updater/app/coffee/ProjectHistoryRedisManager.coffee index 1cc80ea722..5763aa7ed3 100644 --- a/services/document-updater/app/coffee/ProjectHistoryRedisManager.coffee +++ b/services/document-updater/app/coffee/ProjectHistoryRedisManager.coffee @@ -2,9 +2,13 @@ Settings = require('settings-sharelatex') projectHistoryKeys = Settings.redis?.project_history?.key_schema rclient = require("redis-sharelatex").createClient(Settings.redis.documentupdater) logger = require('logger-sharelatex') +metrics = require('./Metrics') module.exports = ProjectHistoryRedisManager = queueOps: (project_id, ops..., callback = (error, projectUpdateCount) ->) -> + # Record metric for ops pushed onto queue + for op in ops + metrics.summary "redis.projectHistoryOps", op.length, {status: "push"} multi = rclient.multi() # Push the ops onto the project history queue multi.rpush projectHistoryKeys.projectHistoryOps({project_id}), ops... From 891fcc696bcef5d5606dd4086d041eb55c3ccff0 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 25 Mar 2020 12:15:35 +0000 Subject: [PATCH 02/10] add metric for pending updates queue --- .../document-updater/app/coffee/RealTimeRedisManager.coffee | 3 +++ 1 file changed, 3 insertions(+) diff --git a/services/document-updater/app/coffee/RealTimeRedisManager.coffee b/services/document-updater/app/coffee/RealTimeRedisManager.coffee index d04f2304d3..6fd48033da 100644 --- a/services/document-updater/app/coffee/RealTimeRedisManager.coffee +++ b/services/document-updater/app/coffee/RealTimeRedisManager.coffee @@ -5,6 +5,7 @@ Keys = Settings.redis.documentupdater.key_schema logger = require('logger-sharelatex') os = require "os" crypto = require "crypto" +metrics = require('./Metrics') HOST = os.hostname() RND = crypto.randomBytes(4).toString('hex') # generate a random key for this process @@ -27,6 +28,8 @@ module.exports = RealTimeRedisManager = catch e return callback e updates.push update + # record metric for updates removed from queue + metrics.summary "redis.pendingUpdates", jsonUpdate.length, {status: "pop"} callback error, updates getUpdatesLength: (doc_id, callback)-> From 1a0550364dc0fa88dd5d18004632926da14cd66f Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 25 Mar 2020 13:39:37 +0000 Subject: [PATCH 03/10] add metric for getdoc bytes --- services/document-updater/app/coffee/RedisManager.coffee | 1 + 1 file changed, 1 insertion(+) diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index ca4151d299..6b4dc20257 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -41,6 +41,7 @@ module.exports = RedisManager = logger.error {err: error, doc_id: doc_id, docLines: docLines}, error.message return callback(error) docHash = RedisManager._computeHash(docLines) + metrics.summary "redis.setDoc", docLines.length, {status: "set"} logger.log {project_id, doc_id, version, docHash, pathname, projectHistoryId}, "putting doc in redis" RedisManager._serializeRanges ranges, (error, ranges) -> if error? From fcb72b9bf7a6a0974c7f971c9ba2864f75b287a3 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 25 Mar 2020 14:27:04 +0000 Subject: [PATCH 04/10] update tests --- services/document-updater/package-lock.json | 12 ++++++------ services/document-updater/package.json | 2 +- .../ProjectHistoryRedisManagerTests.coffee | 1 + .../RealTimeRedisManagerTests.coffee | 15 ++++++++------- .../coffee/RedisManager/RedisManagerTests.coffee | 1 + 5 files changed, 17 insertions(+), 14 deletions(-) diff --git a/services/document-updater/package-lock.json b/services/document-updater/package-lock.json index 852c1670c1..83448c1c77 100644 --- a/services/document-updater/package-lock.json +++ b/services/document-updater/package-lock.json @@ -853,9 +853,9 @@ } }, "acorn": { - "version": "6.4.0", - "resolved": "https://registry.npmjs.org/acorn/-/acorn-6.4.0.tgz", - "integrity": "sha512-gac8OEcQ2Li1dxIEWGZzsp2BitJxwkwcOm0zHAJLcPJaVvm58FRnk6RkuLRpU1EujipU2ZFODv2P9DLMfnV8mw==" + "version": "6.4.1", + "resolved": "https://registry.npmjs.org/acorn/-/acorn-6.4.1.tgz", + "integrity": "sha512-ZVA9k326Nwrj3Cj9jlh3wGFutC2ZornPNARZwsNYqQYgN0EsV2d53w5RN/co65Ohn4sUAUtb1rSUAOD6XN9idA==" }, "agent-base": { "version": "6.0.0", @@ -2183,9 +2183,9 @@ "integrity": "sha512-2403MfnVypWSNIEpmQ26/ObZ5kSUx37E8NHRvriw0+I8Sne7k0HGuLGCk0OrCqURh4UIygD0cSsYq+Ll+kzNqA==" }, "metrics-sharelatex": { - "version": "2.5.1", - "resolved": "https://registry.npmjs.org/metrics-sharelatex/-/metrics-sharelatex-2.5.1.tgz", - "integrity": "sha512-C2gmkl/tUnq3IlSX/x3dixGhdvfD6H9FR9mBf9lnkeyy2arafxhCU6u+1IQj6byjBM7vGpYHyjwWnmoi3Vb+ZQ==", + "version": "2.6.2", + "resolved": "https://registry.npmjs.org/metrics-sharelatex/-/metrics-sharelatex-2.6.2.tgz", + "integrity": "sha512-bOLfkSCexiPgB96hdXhoOWyvvrwscgjeZPEqdcJ7BTGxY59anzvymNf5hTGJ1RtS4sblDKxITw3L5a+gYKhRYQ==", "requires": { "@google-cloud/debug-agent": "^3.0.0", "@google-cloud/profiler": "^0.2.3", diff --git a/services/document-updater/package.json b/services/document-updater/package.json index e01ebbbb8d..72bb0cd868 100644 --- a/services/document-updater/package.json +++ b/services/document-updater/package.json @@ -26,7 +26,7 @@ "express": "3.11.0", "lodash": "^4.17.13", "logger-sharelatex": "^1.7.0", - "metrics-sharelatex": "^2.5.1", + "metrics-sharelatex": "^2.6.2", "mongojs": "^2.6.0", "redis-sharelatex": "^1.0.11", "request": "^2.47.0", diff --git a/services/document-updater/test/unit/coffee/ProjectHistoryRedisManager/ProjectHistoryRedisManagerTests.coffee b/services/document-updater/test/unit/coffee/ProjectHistoryRedisManager/ProjectHistoryRedisManagerTests.coffee index a93545b250..9810b77d5f 100644 --- a/services/document-updater/test/unit/coffee/ProjectHistoryRedisManager/ProjectHistoryRedisManagerTests.coffee +++ b/services/document-updater/test/unit/coffee/ProjectHistoryRedisManager/ProjectHistoryRedisManagerTests.coffee @@ -26,6 +26,7 @@ describe "ProjectHistoryRedisManager", -> createClient: () => @rclient "logger-sharelatex": log:-> + "./Metrics": @metrics = { summary: sinon.stub()} globals: JSON: @JSON = JSON diff --git a/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee b/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee index 1d97779bfa..13e532736e 100644 --- a/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee +++ b/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee @@ -11,7 +11,7 @@ describe "RealTimeRedisManager", -> auth: () -> exec: sinon.stub() @rclient.multi = () => @rclient - @pubsubClient = + @pubsubClient = publish: sinon.stub() @RealTimeRedisManager = SandboxedModule.require modulePath, requires: "redis-sharelatex": createClient: (config) => if (config.name is 'pubsub') then @pubsubClient else @rclient @@ -25,11 +25,12 @@ describe "RealTimeRedisManager", -> "logger-sharelatex": { log: () -> } "crypto": @crypto = { randomBytes: sinon.stub().withArgs(4).returns(Buffer.from([0x1, 0x2, 0x3, 0x4])) } "os": @os = {hostname: sinon.stub().returns("somehost")} + "./Metrics": @metrics = { summary: sinon.stub()} @doc_id = "doc-id-123" @project_id = "project-id-123" @callback = sinon.stub() - + describe "getPendingUpdatesForDoc", -> beforeEach -> @rclient.lrange = sinon.stub() @@ -44,7 +45,7 @@ describe "RealTimeRedisManager", -> @jsonUpdates = @updates.map (update) -> JSON.stringify update @rclient.exec = sinon.stub().callsArgWith(0, null, [@jsonUpdates]) @RealTimeRedisManager.getPendingUpdatesForDoc @doc_id, @callback - + it "should get the pending updates", -> @rclient.lrange .calledWith("PendingUpdates:#{@doc_id}", 0, 7) @@ -75,10 +76,10 @@ describe "RealTimeRedisManager", -> beforeEach -> @rclient.llen = sinon.stub().yields(null, @length = 3) @RealTimeRedisManager.getUpdatesLength @doc_id, @callback - + it "should look up the length", -> @rclient.llen.calledWith("PendingUpdates:#{@doc_id}").should.equal true - + it "should return the length", -> @callback.calledWith(null, @length).should.equal true @@ -86,6 +87,6 @@ describe "RealTimeRedisManager", -> beforeEach -> @message_id = "doc:somehost:01020304-0" @RealTimeRedisManager.sendData({op: "thisop"}) - + it "should send the op with a message id", -> - @pubsubClient.publish.calledWith("applied-ops", JSON.stringify({op:"thisop",_id:@message_id})).should.equal true \ No newline at end of file + @pubsubClient.publish.calledWith("applied-ops", JSON.stringify({op:"thisop",_id:@message_id})).should.equal true diff --git a/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee b/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee index b666163762..2ac8ac9c16 100644 --- a/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee +++ b/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee @@ -48,6 +48,7 @@ describe "RedisManager", -> createClient: () => @rclient "./Metrics": @metrics = inc: sinon.stub() + summary: sinon.stub() Timer: class Timer constructor: () -> this.start = new Date() From 17c2add0cf55648aae24dd85643ef8c97eb44be2 Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Mon, 30 Mar 2020 11:31:43 +0200 Subject: [PATCH 05/10] [misc] track redis pub/sub payload sizes on publish --- .../app/coffee/RealTimeRedisManager.coffee | 8 ++++++-- .../RealTimeRedisManager/RealTimeRedisManagerTests.coffee | 3 +++ 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/services/document-updater/app/coffee/RealTimeRedisManager.coffee b/services/document-updater/app/coffee/RealTimeRedisManager.coffee index 6fd48033da..775132f1b6 100644 --- a/services/document-updater/app/coffee/RealTimeRedisManager.coffee +++ b/services/document-updater/app/coffee/RealTimeRedisManager.coffee @@ -39,9 +39,13 @@ module.exports = RealTimeRedisManager = # create a unique message id using a counter message_id = "doc:#{HOST}:#{RND}-#{COUNT++}" data?._id = message_id + + blob = JSON.stringify(data) + metrics.summary "redis.publish.applied-ops", blob.length + # publish on separate channels for individual projects and docs when # configured (needs realtime to be configured for this too). if Settings.publishOnIndividualChannels - pubsubClient.publish "applied-ops:#{data.doc_id}", JSON.stringify(data) + pubsubClient.publish "applied-ops:#{data.doc_id}", blob else - pubsubClient.publish "applied-ops", JSON.stringify(data) + pubsubClient.publish "applied-ops", blob diff --git a/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee b/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee index 13e532736e..429a03b971 100644 --- a/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee +++ b/services/document-updater/test/unit/coffee/RealTimeRedisManager/RealTimeRedisManagerTests.coffee @@ -90,3 +90,6 @@ describe "RealTimeRedisManager", -> it "should send the op with a message id", -> @pubsubClient.publish.calledWith("applied-ops", JSON.stringify({op:"thisop",_id:@message_id})).should.equal true + + it "should track the payload size", -> + @metrics.summary.calledWith("redis.publish.applied-ops", JSON.stringify({op:"thisop",_id:@message_id}).length).should.equal true From 00b11bda96c6c1d2d4ec49e68741f5ed038d5913 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 1 Apr 2020 14:50:55 +0100 Subject: [PATCH 06/10] use separate loop for pendingUpdates metric --- .../document-updater/app/coffee/RealTimeRedisManager.coffee | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/services/document-updater/app/coffee/RealTimeRedisManager.coffee b/services/document-updater/app/coffee/RealTimeRedisManager.coffee index 6fd48033da..1bfa509078 100644 --- a/services/document-updater/app/coffee/RealTimeRedisManager.coffee +++ b/services/document-updater/app/coffee/RealTimeRedisManager.coffee @@ -21,6 +21,9 @@ module.exports = RealTimeRedisManager = multi.exec (error, replys) -> return callback(error) if error? jsonUpdates = replys[0] + for jsonUpdate in jsonUpdates + # record metric for each update removed from queue + metrics.summary "redis.pendingUpdates", jsonUpdate.length, {status: "pop"} updates = [] for jsonUpdate in jsonUpdates try @@ -28,8 +31,6 @@ module.exports = RealTimeRedisManager = catch e return callback e updates.push update - # record metric for updates removed from queue - metrics.summary "redis.pendingUpdates", jsonUpdate.length, {status: "pop"} callback error, updates getUpdatesLength: (doc_id, callback)-> From 3a8c362fbaa9f2e875db6322006767a61d39b5e9 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 1 Apr 2020 15:59:25 +0100 Subject: [PATCH 07/10] add doclines set/del metric --- services/document-updater/app/coffee/RedisManager.coffee | 8 ++++++-- .../unit/coffee/RedisManager/RedisManagerTests.coffee | 6 ++++++ 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index 6b4dc20257..d784be8495 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -41,7 +41,7 @@ module.exports = RedisManager = logger.error {err: error, doc_id: doc_id, docLines: docLines}, error.message return callback(error) docHash = RedisManager._computeHash(docLines) - metrics.summary "redis.setDoc", docLines.length, {status: "set"} + metrics.summary "redis.docLines", docLines.length, {status: "set"} logger.log {project_id, doc_id, version, docHash, pathname, projectHistoryId}, "putting doc in redis" RedisManager._serializeRanges ranges, (error, ranges) -> if error? @@ -74,6 +74,7 @@ module.exports = RedisManager = _callback() multi = rclient.multi() + multi.strlen keys.docLines(doc_id:doc_id) multi.del keys.docLines(doc_id:doc_id) multi.del keys.projectKey(doc_id:doc_id) multi.del keys.docVersion(doc_id:doc_id) @@ -85,8 +86,11 @@ module.exports = RedisManager = multi.del keys.unflushedTime(doc_id:doc_id) multi.del keys.lastUpdatedAt(doc_id: doc_id) multi.del keys.lastUpdatedBy(doc_id: doc_id) - multi.exec (error) -> + multi.exec (error, response) -> return callback(error) if error? + length = response?[0] + if length > 0 + metrics.summary "redis.docLines", length, {status: "del"} multi = rclient.multi() multi.srem keys.docsInProject(project_id:project_id), doc_id multi.del keys.projectState(project_id:project_id) diff --git a/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee b/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee index 2ac8ac9c16..254de8d0a7 100644 --- a/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee +++ b/services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee @@ -671,11 +671,17 @@ describe "RedisManager", -> describe "removeDocFromMemory", -> beforeEach (done) -> + @multi.strlen = sinon.stub() @multi.del = sinon.stub() @multi.srem = sinon.stub() @multi.exec.yields() @RedisManager.removeDocFromMemory @project_id, @doc_id, done + it "should check the length of the current doclines", -> + @multi.strlen + .calledWith("doclines:#{@doc_id}") + .should.equal true + it "should delete the lines", -> @multi.del .calledWith("doclines:#{@doc_id}") From 2b72ec49a10e4d599858da32122cc0817f1bebac Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 2 Apr 2020 11:33:52 +0100 Subject: [PATCH 08/10] add comments for redis metrics --- services/document-updater/app/coffee/RedisManager.coffee | 2 ++ 1 file changed, 2 insertions(+) diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index d784be8495..fa2e312f33 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -41,6 +41,7 @@ module.exports = RedisManager = logger.error {err: error, doc_id: doc_id, docLines: docLines}, error.message return callback(error) docHash = RedisManager._computeHash(docLines) + # record bytes sent to redis metrics.summary "redis.docLines", docLines.length, {status: "set"} logger.log {project_id, doc_id, version, docHash, pathname, projectHistoryId}, "putting doc in redis" RedisManager._serializeRanges ranges, (error, ranges) -> @@ -90,6 +91,7 @@ module.exports = RedisManager = return callback(error) if error? length = response?[0] if length > 0 + # record bytes freed in redis metrics.summary "redis.docLines", length, {status: "del"} multi = rclient.multi() multi.srem keys.docsInProject(project_id:project_id), doc_id From beb3691795e3f7432620d4a1114a8392b0cfe94f Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 2 Apr 2020 11:34:19 +0100 Subject: [PATCH 09/10] add metrics for redis get/update --- services/document-updater/app/coffee/RedisManager.coffee | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index fa2e312f33..f212cfbadc 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -132,6 +132,9 @@ module.exports = RedisManager = if timeSpan > MAX_REDIS_REQUEST_LENGTH error = new Error("redis getDoc exceeded timeout") return callback(error) + # record bytes loaded from redis + if docLines? + metrics.summary "redis.docLines", docLines.length, {status: "get"} # check sha1 hash value if present if docLines? and storedHash? computedHash = RedisManager._computeHash(docLines) @@ -247,7 +250,8 @@ module.exports = RedisManager = opVersions = appliedOps.map (op) -> op?.v logger.log doc_id: doc_id, version: newVersion, hash: newHash, op_versions: opVersions, "updating doc in redis" - + # record bytes sent to redis in update + metrics.summary "redis.docLines", newDocLines.length, {status: "update"} RedisManager._serializeRanges ranges, (error, ranges) -> if error? logger.error {err: error, doc_id}, error.message From c095feaa06a6ac9b89114f96279063549e172e6d Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Mon, 6 Apr 2020 10:43:53 +0100 Subject: [PATCH 10/10] upgrade logger-sharelatex --- services/document-updater/package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/document-updater/package.json b/services/document-updater/package.json index 72bb0cd868..0fb47d191f 100644 --- a/services/document-updater/package.json +++ b/services/document-updater/package.json @@ -25,7 +25,7 @@ "coffee-script": "~1.7.0", "express": "3.11.0", "lodash": "^4.17.13", - "logger-sharelatex": "^1.7.0", + "logger-sharelatex": "^1.9.1", "metrics-sharelatex": "^2.6.2", "mongojs": "^2.6.0", "redis-sharelatex": "^1.0.11",