Callbacks perf (#14915)

Co-Authored-By: Diego Sampaio <chinello@gmail.com>
Co-Authored-By: Tasso Evangelista <tasso.evangelista@rocket.chat>

app/2fa/server/loginHandler.js

@@ -36,4 +36,4 @@ callbacks.add('onValidateLogin', (login) => {
 			throw new Meteor.Error('totp-invalid', 'TOTP Invalid');
 		}
 	}
-});
+}, callbacks.priority.MEDIUM, '2fa');

app/callbacks/lib/callbacks.js

@@ -2,6 +2,12 @@ import { Meteor } from 'meteor/meteor';
 import { Random } from 'meteor/random';
 import _ from 'underscore';
 
+let timed = false;
+
+if (Meteor.isClient) {
+	const { getConfig } = require('../../ui-utils/client/config');
+	timed = [getConfig('debug'), getConfig('timed-callbacks')].includes('true');
+}
 /*
 * Callback hooks provide an easy way to add extra steps to common operations.
 * @namespace RocketChat.callbacks
@@ -9,15 +15,48 @@ import _ from 'underscore';
 
 export const callbacks = {};
 
-if (Meteor.isServer) {
-	callbacks.showTime = true;
-	callbacks.showTotalTime = true;
-} else {
-	callbacks.showTime = false;
-	callbacks.showTotalTime = false;
-}
+const wrapCallback = (callback) => (...args) => {
+	const time = Date.now();
+	const result = callback(...args);
+	const currentTime = Date.now() - time;
+	let stack = callback.stack
+		&& typeof callback.stack.split === 'function'
+		&& callback.stack.split('\n');
+	stack = stack && stack[2] && (stack[2].match(/\(.+\)/) || [])[0];
+	console.log(String(currentTime), callback.hook, callback.id, stack);
+	return result;
+};
+
+const wrapRun = (hook, fn) => (...args) => {
+	const time = Date.now();
+	const ret = fn(...args);
+	const totalTime = Date.now() - time;
+	console.log(`${ hook }:`, totalTime);
+	return ret;
+};
+
+const handleResult = (fn) => (result, constant) => {
+	const callbackResult = callbacks.runItem({ hook: fn.hook, callback: fn, result, constant });
+	return typeof callbackResult === 'undefined' ? result : callbackResult;
+};
 
 
+const identity = (e) => e;
+const pipe = (f, g) => (e, ...constants) => g(f(e, ...constants), ...constants);
+const createCallback = (hook, callbacks) => callbacks.map(handleResult).reduce(pipe, identity);
+
+const createCallbackTimed = (hook, callbacks) =>
+	wrapRun(hook,
+		callbacks
+			.map(wrapCallback)
+			.map(handleResult)
+			.reduce(pipe, identity)
+	);
+
+const create = (hook, cbs) =>
+	(timed ? createCallbackTimed(hook, cbs) : createCallback(hook, cbs));
+const combinedCallbacks = new Map();
+this.combinedCallbacks = combinedCallbacks;
 /*
 * Callback priorities
 */
@@ -36,26 +75,24 @@ const getHooks = (hookName) => callbacks[hookName] || [];
 * @param {Function} callback - The callback function
 */
 
-callbacks.add = function(hook, callback, priority, id = Random.id()) {
-	if (!_.isNumber(priority)) {
-		priority = callbacks.priority.MEDIUM;
+callbacks.add = function(
+	hook,
+	callback,
+	priority = callbacks.priority.MEDIUM,
+	id = Random.id()
+) {
+	callbacks[hook] = getHooks(hook);
+	if (callbacks[hook].find((cb) => cb.id === id)) {
+		return;
 	}
+	callback.hook = hook;
 	callback.priority = priority;
 	callback.id = id;
-	callbacks[hook] = getHooks(hook);
-
-	if (callbacks.showTime === true) {
-		const err = new Error();
-		callback.stack = err.stack;
-	}
+	callback.stack = new Error().stack;
 
-	if (callbacks[hook].find((cb) => cb.id === callback.id)) {
-		return;
-	}
 	callbacks[hook].push(callback);
-	callbacks[hook] = _.sortBy(callbacks[hook], function(callback) {
-		return callback.priority || callbacks.priority.MEDIUM;
-	});
+	callbacks[hook] = _.sortBy(callbacks[hook], (callback) => callback.priority || callbacks.priority.MEDIUM);
+	combinedCallbacks.set(hook, create(hook, callbacks[hook]));
 };
 
 
@@ -67,11 +104,10 @@ callbacks.add = function(hook, callback, priority, id = Random.id()) {
 
 callbacks.remove = function(hook, id) {
 	callbacks[hook] = getHooks(hook).filter((callback) => callback.id !== id);
+	combinedCallbacks.set(hook, create(hook, callbacks[hook]));
 };
 
-callbacks.runItem = function({ callback, result, constant /* , hook */ }) {
-	return callback(result, constant);
-};
+callbacks.runItem = ({ callback, result, constant /* , hook */ }) => callback(result, constant);
 
 /*
 * Successively run all of a hook's callbacks on an item
@@ -82,38 +118,18 @@ callbacks.runItem = function({ callback, result, constant /* , hook */ }) {
 */
 
 callbacks.run = function(hook, item, constant) {
-	const callbackItems = callbacks[hook];
-	if (!callbackItems || !callbackItems.length) {
+	const runner = combinedCallbacks.get(hook);
+	if (!runner) {
 		return item;
 	}
 
-	let totalTime = 0;
-	const result = callbackItems.reduce(function(result, callback) {
-		const time = callbacks.showTime === true || callbacks.showTotalTime === true ? Date.now() : 0;
-
-		const callbackResult = callbacks.runItem({ hook, callback, result, constant, time });
-
-		if (callbacks.showTime === true || callbacks.showTotalTime === true) {
-			const currentTime = Date.now() - time;
-			totalTime += currentTime;
-			if (callbacks.showTime === true) {
-				if (!Meteor.isServer) {
-					let stack = callback.stack && typeof callback.stack.split === 'function' && callback.stack.split('\n');
-					stack = stack && stack[2] && (stack[2].match(/\(.+\)/) || [])[0];
-					console.log(String(currentTime), hook, callback.id, stack);
-				}
-			}
-		}
-		return typeof callbackResult === 'undefined' ? result : callbackResult;
-	}, item);
-
-	if (callbacks.showTotalTime === true) {
-		if (!Meteor.isServer) {
-			console.log(`${ hook }:`, totalTime);
-		}
-	}
+	return runner(item, constant);
 
-	return result;
+	// return callbackItems.reduce(function(result, callback) {
+	// 	const callbackResult = callbacks.runItem({ hook, callback, result, constant });
+
+	// 	return typeof callbackResult === 'undefined' ? result : callbackResult;
+	// }, item);
 };
 
 
@@ -124,12 +140,10 @@ callbacks.run = function(hook, item, constant) {
 * @param {Object} [constant] - An optional constant that will be passed along to each callback
 */
 
-callbacks.runAsync = function(hook, item, constant) {
+callbacks.runAsync = Meteor.isServer ? function(hook, item, constant) {
 	const callbackItems = callbacks[hook];
-	if (Meteor.isServer && callbackItems && callbackItems.length) {
-		Meteor.defer(function() {
-			callbackItems.forEach((callback) => callback(item, constant));
-		});
+	if (callbackItems && callbackItems.length) {
+		callbackItems.forEach((callback) => Meteor.defer(function() { callback(item, constant); }));
 	}
 	return item;
-};
+} : () => { throw new Error('callbacks.runAsync on client server not allowed'); };

app/discussion/server/hooks/joinDiscussionOnMessage.js

@@ -19,4 +19,4 @@ callbacks.add('beforeSaveMessage', (message, room) => {
 	Meteor.runAsUser(message.u._id, () => Meteor.call('joinRoom', room._id));
 
 	return message;
-});
+}, callbacks.priority.MEDIUM, 'joinDiscussionOnMessage');

app/dolphin/lib/common.js

@@ -57,7 +57,7 @@ if (Meteor.isServer) {
 		ServiceConfiguration.configurations.upsert({ service: 'dolphin' }, { $set: data });
 	}
 
-	callbacks.add('beforeCreateUser', DolphinOnCreateUser, callbacks.priority.HIGH);
+	callbacks.add('beforeCreateUser', DolphinOnCreateUser, callbacks.priority.HIGH, 'dolphin');
 } else {
 	Meteor.startup(() =>
 		Tracker.autorun(function() {

app/e2e/server/index.js

@@ -12,4 +12,4 @@ import './methods/requestSubscriptionKeys';
 
 callbacks.add('afterJoinRoom', (user, room) => {
 	Notifications.notifyRoom('e2e.keyRequest', room._id, room.e2eKeyId);
-});
+}, callbacks.priority.MEDIUM, 'e2e');

app/emoji-emojione/server/callbacks.js

@@ -4,5 +4,5 @@ import emojione from 'emojione';
 import { callbacks } from '../../callbacks';
 
 Meteor.startup(function() {
-	callbacks.add('beforeSendMessageNotifications', (message) => emojione.shortnameToUnicode(message));
+	callbacks.add('beforeSendMessageNotifications', (message) => emojione.shortnameToUnicode(message), callbacks.priority.MEDIUM, 'emojione-shortnameToUnicode');
 });

app/google-vision/server/googlevision.js

@@ -35,7 +35,7 @@ class GoogleVision {
 				callbacks.remove('beforeSaveMessage', 'googlevision-blockunsafe');
 			}
 		});
-		callbacks.add('afterFileUpload', this.annotate.bind(this));
+		callbacks.add('afterFileUpload', this.annotate.bind(this), callbacks.priority.MEDIUM, 'GoogleVision');
 	}
 
 	incCallCount(count) {

app/graphql/server/resolvers/messages/chatMessageAdded.js

@@ -44,7 +44,7 @@ const resolver = {
 
 callbacks.add('afterSaveMessage', (message) => {
 	publishMessage(message);
-}, null, 'chatMessageAddedSubscription');
+}, callbacks.priority.MEDIUM, 'chatMessageAddedSubscription');
 
 export {
 	schema,

app/integrations/server/triggers.js

@@ -7,11 +7,11 @@ const callbackHandler = function _callbackHandler(eventType) {
 	};
 };
 
-callbacks.add('afterSaveMessage', callbackHandler('sendMessage'), callbacks.priority.LOW);
-callbacks.add('afterCreateChannel', callbackHandler('roomCreated'), callbacks.priority.LOW);
-callbacks.add('afterCreatePrivateGroup', callbackHandler('roomCreated'), callbacks.priority.LOW);
-callbacks.add('afterCreateUser', callbackHandler('userCreated'), callbacks.priority.LOW);
-callbacks.add('afterJoinRoom', callbackHandler('roomJoined'), callbacks.priority.LOW);
-callbacks.add('afterLeaveRoom', callbackHandler('roomLeft'), callbacks.priority.LOW);
-callbacks.add('afterRoomArchived', callbackHandler('roomArchived'), callbacks.priority.LOW);
-callbacks.add('afterFileUpload', callbackHandler('fileUploaded'), callbacks.priority.LOW);
+callbacks.add('afterSaveMessage', callbackHandler('sendMessage'), callbacks.priority.LOW, 'integrations-sendMessage');
+callbacks.add('afterCreateChannel', callbackHandler('roomCreated'), callbacks.priority.LOW, 'integrations-roomCreated');
+callbacks.add('afterCreatePrivateGroup', callbackHandler('roomCreated'), callbacks.priority.LOW, 'integrations-roomCreated');
+callbacks.add('afterCreateUser', callbackHandler('userCreated'), callbacks.priority.LOW, 'integrations-userCreated');
+callbacks.add('afterJoinRoom', callbackHandler('roomJoined'), callbacks.priority.LOW, 'integrations-roomJoined');
+callbacks.add('afterLeaveRoom', callbackHandler('roomLeft'), callbacks.priority.LOW, 'integrations-roomLeft');
+callbacks.add('afterRoomArchived', callbackHandler('roomArchived'), callbacks.priority.LOW, 'integrations-roomArchived');
+callbacks.add('afterFileUpload', callbackHandler('fileUploaded'), callbacks.priority.LOW, 'integrations-fileUploaded');

app/livechat/server/hooks/externalMessage.js

@@ -1,4 +1,3 @@
-import { Meteor } from 'meteor/meteor';
 import { HTTP } from 'meteor/http';
 import _ from 'underscore';
 
@@ -39,32 +38,30 @@ callbacks.add('afterSaveMessage', function(message, room) {
 		return message;
 	}
 
-	Meteor.defer(() => {
-		try {
-			const response = HTTP.post('https://api.api.ai/api/query?v=20150910', {
-				data: {
-					query: message.msg,
-					lang: apiaiLanguage,
-					sessionId: room._id,
-				},
-				headers: {
-					'Content-Type': 'application/json; charset=utf-8',
-					Authorization: `Bearer ${ apiaiKey }`,
-				},
-			});
+	try {
+		const response = HTTP.post('https://api.api.ai/api/query?v=20150910', {
+			data: {
+				query: message.msg,
+				lang: apiaiLanguage,
+				sessionId: room._id,
+			},
+			headers: {
+				'Content-Type': 'application/json; charset=utf-8',
+				Authorization: `Bearer ${ apiaiKey }`,
+			},
+		});
 
-			if (response.data && response.data.status.code === 200 && !_.isEmpty(response.data.result.fulfillment.speech)) {
-				LivechatExternalMessage.insert({
-					rid: message.rid,
-					msg: response.data.result.fulfillment.speech,
-					orig: message._id,
-					ts: new Date(),
-				});
-			}
-		} catch (e) {
-			SystemLogger.error('Error using Api.ai ->', e);
+		if (response.data && response.data.status.code === 200 && !_.isEmpty(response.data.result.fulfillment.speech)) {
+			LivechatExternalMessage.insert({
+				rid: message.rid,
+				msg: response.data.result.fulfillment.speech,
+				orig: message._id,
+				ts: new Date(),
+			});
 		}
-	});
+	} catch (e) {
+		SystemLogger.error('Error using Api.ai ->', e);
+	}
 
 	return message;
 }, callbacks.priority.LOW, 'externalWebHook');

app/livechat/server/hooks/markRoomResponded.js

@@ -1,4 +1,3 @@
-import { Meteor } from 'meteor/meteor';
 
 import { callbacks } from '../../../callbacks';
 import { Rooms } from '../../../models';
@@ -19,13 +18,11 @@ callbacks.add('afterSaveMessage', function(message, room) {
 		return message;
 	}
 
-	Meteor.defer(() => {
-		Rooms.setResponseByRoomId(room._id, {
-			user: {
-				_id: message.u._id,
-				username: message.u.username,
-			},
-		});
+	Rooms.setResponseByRoomId(room._id, {
+		user: {
+			_id: message.u._id,
+			username: message.u.username,
+		},
 	});
 
 	return message;

app/livechat/server/hooks/saveAnalyticsData.js

@@ -1,5 +1,3 @@
-import { Meteor } from 'meteor/meteor';
-
 import { callbacks } from '../../../callbacks';
 import { Rooms } from '../../../models';
 
@@ -14,54 +12,54 @@ callbacks.add('afterSaveMessage', function(message, room) {
 		return message;
 	}
 
-	Meteor.defer(() => {
-		const now = new Date();
-		let analyticsData;
 
-		// if the message has a token, it was sent by the visitor
-		if (!message.token) {
-			const visitorLastQuery = room.metrics && room.metrics.v ? room.metrics.v.lq : room.ts;
-			const agentLastReply = room.metrics && room.metrics.servedBy ? room.metrics.servedBy.lr : room.ts;
-			const agentJoinTime = room.servedBy && room.servedBy.ts ? room.servedBy.ts : room.ts;
+	const now = new Date();
+	let analyticsData;
+
+	// if the message has a token, it was sent by the visitor
+	if (!message.token) {
+		const visitorLastQuery = room.metrics && room.metrics.v ? room.metrics.v.lq : room.ts;
+		const agentLastReply = room.metrics && room.metrics.servedBy ? room.metrics.servedBy.lr : room.ts;
+		const agentJoinTime = room.servedBy && room.servedBy.ts ? room.servedBy.ts : room.ts;
 
-			const isResponseTt = room.metrics && room.metrics.response && room.metrics.response.tt;
-			const isResponseTotal = room.metrics && room.metrics.response && room.metrics.response.total;
+		const isResponseTt = room.metrics && room.metrics.response && room.metrics.response.tt;
+		const isResponseTotal = room.metrics && room.metrics.response && room.metrics.response.total;
 
-			if (agentLastReply === room.ts) {		// first response
-				const firstResponseDate = now;
-				const firstResponseTime = (now.getTime() - visitorLastQuery) / 1000;
-				const responseTime = (now.getTime() - visitorLastQuery) / 1000;
-				const avgResponseTime = ((isResponseTt ? room.metrics.response.tt : 0) + responseTime) / ((isResponseTotal ? room.metrics.response.total : 0) + 1);
+		if (agentLastReply === room.ts) {		// first response
+			const firstResponseDate = now;
+			const firstResponseTime = (now.getTime() - visitorLastQuery) / 1000;
+			const responseTime = (now.getTime() - visitorLastQuery) / 1000;
+			const avgResponseTime = ((isResponseTt ? room.metrics.response.tt : 0) + responseTime) / ((isResponseTotal ? room.metrics.response.total : 0) + 1);
 
-				const firstReactionDate = now;
-				const firstReactionTime = (now.getTime() - agentJoinTime) / 1000;
-				const reactionTime = (now.getTime() - agentJoinTime) / 1000;
+			const firstReactionDate = now;
+			const firstReactionTime = (now.getTime() - agentJoinTime) / 1000;
+			const reactionTime = (now.getTime() - agentJoinTime) / 1000;
 
-				analyticsData = {
-					firstResponseDate,
-					firstResponseTime,
-					responseTime,
-					avgResponseTime,
-					firstReactionDate,
-					firstReactionTime,
-					reactionTime,
-				};
-			} else if (visitorLastQuery > agentLastReply) {		// response, not first
-				const responseTime = (now.getTime() - visitorLastQuery) / 1000;
-				const avgResponseTime = ((isResponseTt ? room.metrics.response.tt : 0) + responseTime) / ((isResponseTotal ? room.metrics.response.total : 0) + 1);
+			analyticsData = {
+				firstResponseDate,
+				firstResponseTime,
+				responseTime,
+				avgResponseTime,
+				firstReactionDate,
+				firstReactionTime,
+				reactionTime,
+			};
+		} else if (visitorLastQuery > agentLastReply) {		// response, not first
+			const responseTime = (now.getTime() - visitorLastQuery) / 1000;
+			const avgResponseTime = ((isResponseTt ? room.metrics.response.tt : 0) + responseTime) / ((isResponseTotal ? room.metrics.response.total : 0) + 1);
 
-				const reactionTime = (now.getTime() - visitorLastQuery) / 1000;
+			const reactionTime = (now.getTime() - visitorLastQuery) / 1000;
+
+			analyticsData = {
+				responseTime,
+				avgResponseTime,
+				reactionTime,
+			};
+		}	// ignore, its continuing response
+	}
 
-				analyticsData = {
-					responseTime,
-					avgResponseTime,
-					reactionTime,
-				};
-			}	// ignore, its continuing response
-		}
+	Rooms.saveAnalyticsDataByRoomId(room, message, analyticsData);
 
-		Rooms.saveAnalyticsDataByRoomId(room, message, analyticsData);
-	});
 
 	return message;
 }, callbacks.priority.LOW, 'saveAnalyticsData');

app/metrics/server/callbacksMetrics.js

@@ -18,12 +18,15 @@ callbacks.run = function(hook, item, constant) {
 	return result;
 };
 
-callbacks.runItem = function({ callback, result, constant, hook, time }) {
+callbacks.runItem = function({ callback, result, constant, hook, time = Date.now() }) {
 	const rocketchatCallbacksEnd = metrics.rocketchatCallbacks.startTimer({ hook, callback: callback.id });
 
 	const newResult = originalRunItem({ callback, result, constant });
 
-	StatsTracker.timing('callbacks.time', Date.now() - time, [`hook:${ hook }`, `callback:${ callback.id }`]);
+	StatsTracker.timing('callbacks.time', Date.now() - time, [
+		`hook:${ hook }`,
+		`callback:${ callback.id }`,
+	]);
 
 	rocketchatCallbacksEnd();
 

app/search/server/events/events.js

@@ -24,11 +24,11 @@ const eventService = new EventService();
  */
 callbacks.add('afterSaveMessage', function(m) {
 	eventService.promoteEvent('message.save', m._id, m);
-});
+}, callbacks.priority.MEDIUM, 'search-events');
 
 callbacks.add('afterDeleteMessage', function(m) {
 	eventService.promoteEvent('message.delete', m._id);
-});
+}, callbacks.priority.MEDIUM, 'search-events-delete');
 
 /**
  * Listen to user and room changes via cursor

imports/message-read-receipt/server/hooks.js

@@ -15,8 +15,8 @@ callbacks.add('afterSaveMessage', (message, room) => {
 
 	// mark message as read as well
 	ReadReceipt.markMessageAsReadBySender(message, room._id, message.u._id);
-});
+}, callbacks.priority.MEDIUM, 'message-read-receipt-afterSaveMessage');
 
 callbacks.add('afterReadMessages', (rid, { userId, lastSeen }) => {
 	ReadReceipt.markMessagesAsRead(rid, userId, lastSeen);
-});
+}, callbacks.priority.MEDIUM, 'message-read-receipt-afterReadMessages');