Server: Print a heartbeat message to log once per minute

packages/server/package.json

@@ -44,6 +44,7 @@
     "markdown-it": "13.0.2",
     "mustache": "4.2.0",
     "node-cron": "3.0.3",
+    "node-os-utils": "1.3.7",
     "nodemailer": "6.9.8",
     "nodemon": "3.0.3",
     "pg": "8.11.3",
@@ -71,6 +72,7 @@
     "@types/koa": "2.13.12",
     "@types/markdown-it": "13.0.7",
     "@types/mustache": "4.2.5",
+    "@types/node-os-utils": "1.3.4",
     "@types/nodemailer": "6.4.14",
     "@types/yargs": "17.0.32",
     "@types/zxcvbn": "4.4.4",

packages/server/src/env.ts

@@ -23,6 +23,7 @@ const defaultEnvValues: EnvVariables = {
 	COOKIES_SECURE: false,
 	RUNNING_IN_DOCKER: false,
 	USERS_WITH_REPLICATION: '', // Temporary
+	HEARTBEAT_MESSAGE_SCHEDULE: '* * * * *',
 
 	// The admin panel is accessible only if this is an admin instance.
 	// Additionally, processing services (those defined in setupTaskService.ts)
@@ -152,6 +153,7 @@ export interface EnvVariables {
 	COOKIES_SECURE: boolean;
 	RUNNING_IN_DOCKER: boolean;
 	USERS_WITH_REPLICATION: string;
+	HEARTBEAT_MESSAGE_SCHEDULE: string;
 
 	MAX_TIME_DRIFT: number;
 	NTP_SERVER: string;

packages/server/src/middleware/routeHandler.ts

@@ -5,9 +5,14 @@ import config from '../config';
 import { userIp } from '../utils/requestUtils';
 import { createCsrfTag } from '../utils/csrf';
 import { getImpersonatorAdminSessionId } from '../routes/admin/utils/users/impersonate';
+import { onRequestComplete, onRequestStart } from '../utils/metrics';
+import { uuidgen } from '@joplin/lib/uuid';
 
 export default async function(ctx: AppContext) {
 	const requestStartTime = Date.now();
+	const requestId = uuidgen();
+
+	onRequestStart(requestId);
 
 	try {
 		const { response: responseObject, path } = await execRequest(ctx.joplin.routes, ctx);
@@ -88,4 +93,6 @@ export default async function(ctx: AppContext) {
 		const requestDuration = Date.now() - requestStartTime;
 		ctx.joplin.appLogger().info(`${ctx.request.method} ${ctx.path} (${ctx.response.status}) (${requestDuration}ms)`);
 	}
+
+	onRequestComplete(requestId);
 }

packages/server/src/services/TaskService.ts

@@ -31,6 +31,7 @@ export const taskIdToLabel = (taskId: TaskId): string => {
 		[TaskId.ProcessOrphanedItems]: 'Process orphaned items',
 		[TaskId.ProcessShares]: 'Process shared items',
 		[TaskId.ProcessEmails]: 'Process emails',
+		[TaskId.LogHeartbeatMessage]: 'Log heartbeat message',
 	};
 
 	const s = strings[taskId];

packages/server/src/services/database/types.ts

@@ -135,6 +135,7 @@ export enum TaskId {
 	ProcessOrphanedItems,
 	ProcessShares,
 	ProcessEmails,
+	LogHeartbeatMessage,
 }
 
 // AUTO-GENERATED-TYPES

packages/server/src/utils/metrics.test.ts

@@ -0,0 +1,28 @@
+import { clearMetrics, heartbeatMessage, onRequestComplete, onRequestStart } from './metrics';
+
+describe('metrics', () => {
+
+	it('should generate a heartbeat message', async () => {
+		clearMetrics();
+
+		const requestId1 = Math.random().toString();
+		const requestId2 = Math.random().toString();
+		const requestId3 = Math.random().toString();
+
+		onRequestStart(requestId1);
+		onRequestStart(requestId2);
+		onRequestStart(requestId3);
+		onRequestComplete(requestId2);
+
+		const regex = /Cpu: (.*?)%; Mem: (.*?) \/ (.*?) MB \((.*?)%\); Req: 3 \/ min; Active req: 2/;
+
+		const message = await heartbeatMessage();
+
+		const match = message.match(regex);
+		expect(match.length).toBe(5);
+		expect(Number(match[1])).toBeGreaterThan(0);
+		expect(Number(match[2])).toBeLessThan(Number(match[3]));
+		expect(Number(match[3])).toBeGreaterThan(0);
+	});
+
+});

packages/server/src/utils/metrics.ts

@@ -0,0 +1,94 @@
+/* eslint-disable import/prefer-default-export */
+
+// Provides metrics about the operating system and server application, and format them in a message
+// that can be printed to log.
+
+import { MemUsedInfo, cpu, mem } from 'node-os-utils';
+import { Minute } from './time';
+import Logger from '@joplin/utils/Logger';
+
+const logger = Logger.create('metrics');
+
+let requestsPerSecond_: Record<number, number> = {};
+let activeRequests_: Record<string, boolean> = {};
+
+const requestsPerMinute = () => {
+	const nowSeconds = Math.floor(Date.now() / 1000);
+	const startSeconds = nowSeconds - 60;
+
+	let total = 0;
+	for (let i = startSeconds; i < nowSeconds; i++) {
+		if (!(i in requestsPerSecond_)) continue;
+		total += requestsPerSecond_[i];
+	}
+
+	return total;
+};
+
+const deleteRequestInfoOlderThan = (ttl: number) => {
+	const cutOffTime = Math.round((Date.now() - ttl) / 1000);
+	for (const key of (Object.keys(requestsPerSecond_))) {
+		if (Number(key) < cutOffTime) delete requestsPerSecond_[Number(key)];
+	}
+};
+
+const countRequest = () => {
+	const t = Math.floor(Date.now() / 1000);
+	if (!requestsPerSecond_[t]) requestsPerSecond_[t] = 0;
+	requestsPerSecond_[t]++;
+
+	deleteRequestInfoOlderThan(10 * Minute);
+};
+
+export const clearMetrics = () => {
+	requestsPerSecond_ = {};
+	activeRequests_ = {};
+};
+
+export const heartbeatMessage = async () => {
+	const interval = 1000;
+
+	const promises: Promise<void>[] = [];
+
+	interface Info {
+		cpu?: number;
+		memory?: MemUsedInfo;
+	}
+
+	const info: Info = {};
+
+	const getCpu = async () => {
+		info.cpu = await cpu.usage(interval);
+	};
+
+	const getMemory = async () => {
+		info.memory = await mem.used();
+	};
+
+	promises.push(getCpu());
+	promises.push(getMemory());
+
+	await Promise.all(promises);
+
+	const line: string[] = [];
+
+	line.push(`Cpu: ${info.cpu}%`);
+	line.push(`Mem: ${info.memory.usedMemMb} / ${info.memory.totalMemMb} MB (${Math.round((info.memory.usedMemMb / info.memory.totalMemMb) * 100)}%)`);
+	line.push(`Req: ${requestsPerMinute()} / min`);
+	line.push(`Active req: ${Object.keys(activeRequests_).length}`);
+
+	return line.join('; ');
+};
+
+export const logHeartbeat = async () => {
+	logger.info(await heartbeatMessage());
+};
+
+export const onRequestStart = (requestId: string) => {
+	countRequest();
+	activeRequests_[requestId] = true;
+};
+
+export const onRequestComplete = (requestId: string) => {
+	delete activeRequests_[requestId];
+};

packages/server/src/utils/setupTaskService.ts

@@ -2,6 +2,7 @@ import { Models } from '../models/factory';
 import { TaskId } from '../services/database/types';
 import TaskService, { Task, taskIdToLabel } from '../services/TaskService';
 import { Services } from '../services/types';
+import { logHeartbeat as logHeartbeatMessage } from './metrics';
 import { Config, Env } from './types';
 
 export default async function(env: Env, models: Models, config: Config, services: Services): Promise<TaskService> {
@@ -74,6 +75,13 @@ export default async function(env: Env, models: Models, config: Config, services
 			schedule: '* * * * *',
 			run: (_models: Models, services: Services) => services.email.runMaintenance(),
 		},
+
+		{
+			id: TaskId.LogHeartbeatMessage,
+			description: taskIdToLabel(TaskId.LogHeartbeatMessage),
+			schedule: config.HEARTBEAT_MESSAGE_SCHEDULE,
+			run: (_models: Models, _services: Services) => logHeartbeatMessage(),
+		},
 	];
 
 	if (config.USER_DATA_AUTO_DELETE_ENABLED) {

yarn.lock

@@ -7093,6 +7093,7 @@ __metadata:
     "@types/koa": 2.13.12
     "@types/markdown-it": 13.0.7
     "@types/mustache": 4.2.5
+    "@types/node-os-utils": 1.3.4
     "@types/nodemailer": 6.4.14
     "@types/uuid": 9.0.7
     "@types/yargs": 17.0.32
@@ -7117,6 +7118,7 @@ __metadata:
     mustache: 4.2.0
     node-cron: 3.0.3
     node-mocks-http: 1.14.1
+    node-os-utils: 1.3.7
     nodemailer: 6.9.8
     nodemon: 3.0.3
     pg: 8.11.3
@@ -11192,6 +11194,13 @@ __metadata:
   languageName: node
   linkType: hard
 
+"@types/node-os-utils@npm:1.3.4":
+  version: 1.3.4
+  resolution: "@types/node-os-utils@npm:1.3.4"
+  checksum: e0adbb62b9503b86a16c5a09058104ec81975ad58c6c28594986de0602378f4c87d0b46d1f5445a778607e42df1b318cdea91e2ac54994572904490dc1a086af
+  languageName: node
+  linkType: hard
+
 "@types/node-rsa@npm:1.1.4":
   version: 1.1.4
   resolution: "@types/node-rsa@npm:1.1.4"
@@ -31614,6 +31623,13 @@ __metadata:
   languageName: node
   linkType: hard
 
+"node-os-utils@npm:1.3.7":
+  version: 1.3.7
+  resolution: "node-os-utils@npm:1.3.7"
+  checksum: 4059d74def168e2ffcd28e879731fd68f6e9b1e623804224e34bf0ca3c8968070e9e2cbc0cb57d80dd05d27552495a65c865b93ae5f54e61389e5af0b92ee818
+  languageName: node
+  linkType: hard
+
 "node-persist@npm:3.1.3":
   version: 3.1.3
   resolution: "node-persist@npm:3.1.3"