From 916fa39012b0437bfaaf3b28096fef56688c8f53 Mon Sep 17 00:00:00 2001 From: Laurent Cozic Date: Sun, 26 May 2024 18:27:41 +0100 Subject: [PATCH] Server: Print a heartbeat message to log once per minute --- packages/server/package.json | 2 + packages/server/src/env.ts | 2 + .../server/src/middleware/routeHandler.ts | 7 ++ packages/server/src/services/TaskService.ts | 1 + .../server/src/services/database/types.ts | 1 + packages/server/src/utils/metrics.test.ts | 28 ++++++ packages/server/src/utils/metrics.ts | 94 +++++++++++++++++++ packages/server/src/utils/setupTaskService.ts | 8 ++ yarn.lock | 16 ++++ 9 files changed, 159 insertions(+) create mode 100644 packages/server/src/utils/metrics.test.ts create mode 100644 packages/server/src/utils/metrics.ts diff --git a/packages/server/package.json b/packages/server/package.json index a5a4c9a28..fefd7bb43 100644 --- a/packages/server/package.json +++ b/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", diff --git a/packages/server/src/env.ts b/packages/server/src/env.ts index e28aae50f..0b1c65395 100644 --- a/packages/server/src/env.ts +++ b/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; diff --git a/packages/server/src/middleware/routeHandler.ts b/packages/server/src/middleware/routeHandler.ts index 146d44bb0..741e8d2ec 100644 --- a/packages/server/src/middleware/routeHandler.ts +++ b/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); } diff --git a/packages/server/src/services/TaskService.ts b/packages/server/src/services/TaskService.ts index 34a9985c6..78a05a8ec 100644 --- a/packages/server/src/services/TaskService.ts +++ b/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]; diff --git a/packages/server/src/services/database/types.ts b/packages/server/src/services/database/types.ts index 01a2b60d7..735cbc065 100644 --- a/packages/server/src/services/database/types.ts +++ b/packages/server/src/services/database/types.ts @@ -135,6 +135,7 @@ export enum TaskId { ProcessOrphanedItems, ProcessShares, ProcessEmails, + LogHeartbeatMessage, } // AUTO-GENERATED-TYPES diff --git a/packages/server/src/utils/metrics.test.ts b/packages/server/src/utils/metrics.test.ts new file mode 100644 index 000000000..846daf6a7 --- /dev/null +++ b/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); + }); + +}); diff --git a/packages/server/src/utils/metrics.ts b/packages/server/src/utils/metrics.ts new file mode 100644 index 000000000..b9928311e --- /dev/null +++ b/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 = {}; +let activeRequests_: Record = {}; + +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[] = []; + + 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]; +}; diff --git a/packages/server/src/utils/setupTaskService.ts b/packages/server/src/utils/setupTaskService.ts index d8864b359..05d8afe8d 100644 --- a/packages/server/src/utils/setupTaskService.ts +++ b/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 { @@ -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) { diff --git a/yarn.lock b/yarn.lock index bf8d51cc3..338b25f91 100644 --- a/yarn.lock +++ b/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"