fix: waited on time should not include wait time

monti-apm · May 4, 2024 · c00de0d · c00de0d
1 parent 0354827
commit c00de0d
Show file tree

Hide file tree

Showing 6 changed files with 85 additions and 8 deletions.
diff --git a/lib/models/methods.js b/lib/models/methods.js
@@ -120,12 +120,12 @@ MethodsModel.prototype.trackMsgSize = function (method, size) {
   methodMetrics.sentMsgSize += size;
 };
 
-MethodsModel.prototype.trackWaitedOn = function (method, messageQueue) {
+MethodsModel.prototype.trackWaitedOn = function (method, messageQueue, started) {
   const timestamp = Ntp._now();
   const dateId = this._getDateId(timestamp);
 
   let methodMetrics = this._getMetrics(dateId, method);
-  methodMetrics.waitedOn += calculateWaitedOnTime(messageQueue);
+  methodMetrics.waitedOn += calculateWaitedOnTime(messageQueue, started);
 };
 
 /*

diff --git a/lib/models/pubsub.js b/lib/models/pubsub.js
@@ -396,12 +396,13 @@ PubsubModel.prototype.trackMsgSize = function (name, type, size) {
   }
 };
 
-PubsubModel.prototype.trackWaitedOn = function (name, messageQueue) {
+PubsubModel.prototype.trackWaitedOn = function (name, messageQueue, started) {
   let timestamp = Ntp._now();
   let publicationName = this._getPublicationName(name);
+
   let metrics = this._getMetrics(timestamp, publicationName);
 
-  metrics.waitedOn += calculateWaitedOnTime(messageQueue);
+  metrics.waitedOn += calculateWaitedOnTime(messageQueue, started);
 };
 PubsubModel.prototype.trackWaitTime = function (msg) {
   let subscriptionState = this.subscriptions[msg.id];

diff --git a/lib/utils.js b/lib/utils.js
@@ -115,7 +115,7 @@ export function pick (obj, keys) {
   }, {});
 }
 
-export function calculateWaitedOnTime (messageQueue) {
+export function calculateWaitedOnTime (messageQueue, startedTime) {
   let waitedOnTime = 0;
 
   const now = Ntp._now();
@@ -124,6 +124,9 @@ export function calculateWaitedOnTime (messageQueue) {
     messageQueue.toArray().forEach(function (msg) {
       if (msg._waitEventId) {
         waitedOnTime += now - msg._waitEventId.at;
+        if(msg._waitEventId.at < startedTime) {
+          waitedOnTime -= startedTime - msg._waitEventId.at
+        }
       }
     });
 

diff --git a/lib/wait_time_builder.js b/lib/wait_time_builder.js
@@ -102,9 +102,9 @@ export class WaitTimeBuilder {
         unblocked = true;
 
         if (msg.msg === 'method') {
-          Kadira.models.methods.trackWaitedOn(msg.method, session.inQueue);
+          Kadira.models.methods.trackWaitedOn(msg.method, session.inQueue, started);
         } else if (msg.msg === 'sub') {
-          Kadira.models.pubsub.trackWaitedOn(msg.name, session.inQueue);
+          Kadira.models.pubsub.trackWaitedOn(msg.name, session.inQueue, started);
         }
 
         unblock();

diff --git a/tests/models/methods.js b/tests/models/methods.js
@@ -1,7 +1,7 @@
 import { EJSON } from 'meteor/ejson';
 import { MethodsModel } from '../../lib/models/methods';
 import { TestData } from '../_helpers/globals';
-import { CleanTestData, GetMeteorClient, RegisterMethod, Wait, WithDocCacheGetSize, findMetricsForMethod } from '../_helpers/helpers';
+import { CleanTestData, CloseClient, GetMeteorClient, RegisterMethod, Wait, WithDocCacheGetSize, findMetricsForMethod, waitForConnection } from '../_helpers/helpers';
 import { Meteor } from 'meteor/meteor';
 
 Tinytest.add(
@@ -211,6 +211,41 @@ Tinytest.addAsync('Models - Method - Waited On - track wait time of queued messa
   done();
 });
 
+
+Tinytest.addAsync('Models - Method - Waited On - track waitedOn without wait time', async (test, done) => {
+  CleanTestData();
+
+  let slowMethod = RegisterMethod(function () {
+    console.log('slow method start');
+    Meteor._sleepForMs(100);
+    console.log('slow method end');
+  });
+  let unblockedMethod = RegisterMethod(function () {
+    this.unblock()
+    Meteor._sleepForMs(100);
+    console.log('slow method end');
+  });
+  let fastMethod = RegisterMethod(function () {
+    console.log('fastMethod');
+  });
+
+
+  let client = GetMeteorClient();
+
+  // subscriptions and method calls made before connected are not run in order
+  waitForConnection(client);
+
+  client.call(slowMethod, () => {});
+  client.call(unblockedMethod, () => {});
+  await new Promise(r => client.call(fastMethod, () => r()));
+
+  const metrics = findMetricsForMethod(unblockedMethod);
+
+  test.isTrue(metrics.waitedOn < 10, `${metrics.waitedOn} should be less than 10`);
+  CloseClient(client);
+
+  done();
+});
 Tinytest.addAsync('Models - Method - Waited On - check unblock time', async (test, done) => {
   let methodId = RegisterMethod( function (id) {
     this.unblock();

diff --git a/tests/models/pubsub.js b/tests/models/pubsub.js
@@ -779,6 +779,44 @@ Tinytest.addAsync('Models - PubSub - Waited On - track wait time of queued messa
   done();
 });
 
+Meteor.publish('tinytest-unblock-fast', function () {
+  console.log('unblock-fast-pub')
+  this.unblock();
+  Meteor._sleepForMs(100);
+  this.ready();
+});
+
+Tinytest.addAsync('Models - PubSub - Waited On - track waitedOn without wait time', async (test, done) => {
+  CleanTestData();
+
+  let slowMethod = RegisterMethod(function () {
+    console.log('slow method start');
+    Meteor._sleepForMs(100);
+    console.log('slow method end');
+  });
+  let fastMethod = RegisterMethod(function () {
+    console.log('fastMethod');
+  });
+
+
+  let client = GetMeteorClient();
+
+  // subscriptions and method calls made before connected are not run in order
+  waitForConnection(client);
+
+  const pubName = 'tinytest-unblock-fast';
+  client.call(slowMethod, () => {});
+  client.subscribe(pubName);
+  await new Promise(r => client.call(fastMethod, () => r()));
+
+  const metrics = FindMetricsForPub(pubName);
+
+  test.isTrue(metrics.waitedOn < 10 && metrics.waitedOn >= 0, `${metrics.waitedOn} should be less than 10`);
+  CloseClient(client);
+
+  done();
+});
+
 Tinytest.addAsync('Models - PubSub - Waited On - track waited on time of next message', async (test, done) => {
   CleanTestData();
   let fastMethod = RegisterMethod(function () {