From 868eec978434bc7f58f17b970e572716d7d6231a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Iv=C3=A1n=20Cea=20Fontenla?= Date: Wed, 31 Jul 2024 20:04:52 +0200 Subject: [PATCH] Simplify stats logging and increased metrics precision --- server/index.ts | 2 +- server/logger.ts | 375 -------------------------- server/logic/logic.ts | 29 +- server/logic/room-controller.base.ts | 14 +- server/server.ts | 2 +- server/utils/logger.base.ts | 47 ++++ server/utils/logger.console.ts | 32 +++ server/utils/logger.elastic-search.ts | 250 +++++++++++++++++ server/utils/logger.ts | 32 +++ server/utils/stopwatch.ts | 18 ++ 10 files changed, 399 insertions(+), 402 deletions(-) delete mode 100644 server/logger.ts create mode 100644 server/utils/logger.base.ts create mode 100644 server/utils/logger.console.ts create mode 100644 server/utils/logger.elastic-search.ts create mode 100644 server/utils/logger.ts create mode 100644 server/utils/stopwatch.ts diff --git a/server/index.ts b/server/index.ts index 397ad31..4804e96 100644 --- a/server/index.ts +++ b/server/index.ts @@ -1,8 +1,8 @@ import { clampMagnitude } from "../common/vector"; import { env } from "./env"; -import { getLogger, initializeLogger } from "./logger"; import { disconnectPlayer, joinPlayer } from "./logic/logic"; import { server } from "./server"; +import { getLogger, initializeLogger } from "./utils/logger"; import { getPlayer, getRoom } from "./world"; async function startServer() { diff --git a/server/logger.ts b/server/logger.ts deleted file mode 100644 index e765a75..0000000 --- a/server/logger.ts +++ /dev/null @@ -1,375 +0,0 @@ -/* eslint-disable no-console */ -import { Client as ESClient } from "@elastic/elasticsearch"; -import { - MappingProperty, - PropertyName, -} from "@elastic/elasticsearch/lib/api/types"; -import os from "os"; -import { env } from "./env"; - -const LOGGER_MODULE = "server"; - -type Logger = { - info(message: string): void; - warn(message: string): void; - error(message: string): void; - /** - * Measures a span of time, and logs it when it ends. - */ - measureSpan(name: string, elapsedTime?: number): SpanMetrics; - /** - * Accumulates metrics, and flushes them as metrics: Average, max, min, count... - * - * The returned object should be reused. - */ - stats(name: string, entriesPerFlush: number): StatsMetrics; -}; - -type SpanMetrics = { - name: string; - end: () => void; -}; - -type StatsMetrics = { - name: string; - add(value: number): void; -}; - -type InternalLogger = Logger & { - destroy(): void; -}; - -let logger: InternalLogger = makeConsoleLogger(); - -export function getLogger(): Logger { - return logger; -} - -export async function initializeLogger() { - logger.destroy(); - - let newLogger: InternalLogger | undefined; - - if ( - env.ELASTIC_CLOUD_ID && - env.ELASTIC_API_KEY && - env.ELASTIC_INDEX_NAMESPACE - ) { - console.log("Using ElasticSearch logger"); - newLogger = await makeElasticSearchLogger( - env.ELASTIC_CLOUD_ID, - env.ELASTIC_API_KEY, - env.ELASTIC_INDEX_NAMESPACE, - ); - } - - logger = makeConsoleLogger(newLogger); -} - -function makeConsoleLogger(otherLogger?: InternalLogger): InternalLogger { - return { - info(message: string) { - console.log(message); - otherLogger?.info(message); - }, - warn(message: string) { - console.warn(message); - otherLogger?.warn(message); - }, - error(message: string) { - console.error(message); - otherLogger?.error(message); - }, - destroy() { - otherLogger?.destroy(); - }, - measureSpan(name: string, elapsedTime?: number) { - return ( - otherLogger?.measureSpan(name, elapsedTime) ?? { - name, - end() { - // No-op for console logger - }, - } - ); - }, - stats(name: string, entriesPerFlush: number) { - return ( - otherLogger?.stats(name, entriesPerFlush) ?? { - name, - add() { - // No-op for console logger - }, - } - ); - }, - }; -} - -async function makeElasticSearchLogger( - cloudId: string, - apiKey: string, - indexNamespace: string, -): Promise { - const client = new ESClient({ - cloud: { - id: cloudId, - }, - auth: { - apiKey, - }, - }); - const hostname = os.hostname(); - const logsIndex = `${indexNamespace}_logs`; - const spansIndex = `${indexNamespace}_spans`; - const statsIndex = `${indexNamespace}_stats`; - const bufferLimit = 1000; - - const logsBuffer: Record[] = []; - const spansBuffer: Record[] = []; - const statsBuffer: Record[] = []; - - await initializeElasticSearch(client, logsIndex, spansIndex, statsIndex); - - function flush(index: string, buffer: Record[]) { - if (buffer.length === 0) { - return; - } - - client - .bulk({ - operations: buffer.flatMap((log) => [ - { index: { _index: index } }, - log, - ]), - }) - .catch((error: unknown) => { - console.error( - `Error sending logs to ElasticSearch index ${index}`, - error, - ); - }); - - buffer.length = 0; - } - - function flushLogs() { - flush(logsIndex, logsBuffer); - } - - function flushSpans() { - // Spans add too many records. Ignoring them for now - // flush(spansIndex, spansBuffer); - } - - function flushStats() { - flush(statsIndex, statsBuffer); - } - - function addLog(level: "info" | "warn" | "error", message: string) { - logsBuffer.push({ - hostname, - module: LOGGER_MODULE, - timestamp: Date.now(), - level, - message, - }); - - if (logsBuffer.length >= bufferLimit) { - flushLogs(); - } - } - - function addSpan(name: string, startTime: number, endTime: number) { - spansBuffer.push({ - hostname, - module: LOGGER_MODULE, - timestamp: Date.now(), - name, - startTime, - endTime, - elapsedTimeMillis: endTime - startTime, - }); - - if (spansBuffer.length >= bufferLimit) { - flushSpans(); - } - } - - function addStats( - name: string, - avg: number, - max: number, - min: number, - count: number, - ) { - statsBuffer.push({ - hostname, - module: LOGGER_MODULE, - timestamp: Date.now(), - name, - avg, - max, - min, - count, - }); - - if (statsBuffer.length >= bufferLimit) { - flushStats(); - } - } - - const interval = setInterval(() => { - flushLogs(); - flushSpans(); - flushStats(); - }, 5000); - - return { - info(message: string) { - addLog("info", message); - }, - warn(message: string) { - addLog("warn", message); - }, - error(message: string) { - addLog("error", message); - }, - destroy() { - flushLogs(); - flushSpans(); - flushStats(); - clearInterval(interval); - }, - measureSpan(name: string, elapsedTime?: number) { - const currentTime = Date.now(); - - if (elapsedTime) { - addSpan(name, currentTime - elapsedTime, currentTime); - - return { - name, - end() {}, - }; - } - - let closed = false; - - return { - name, - end() { - if (closed) { - throw new Error("Span already closed"); - } - closed = true; - addSpan(name, currentTime, Date.now()); - }, - }; - }, - stats(name: string, entriesPerFlush: number) { - const metrics: number[] = []; - return { - name, - add(value: number) { - metrics.push(value); - - if (metrics.length >= entriesPerFlush) { - const sum = metrics.reduce((a, b) => a + b, 0); - const max = Math.max(...metrics); - const min = Math.min(...metrics); - addStats(name, sum / metrics.length, max, min, metrics.length); - metrics.length = 0; - } - }, - }; - }, - }; -} - -async function initializeElasticSearch( - client: ESClient, - logsIndex: string, - spansIndex: string, - statsIndex: string, -) { - const commonProperties = { - hostname: { - type: "keyword", - }, - module: { - type: "keyword", - }, - timestamp: { - type: "date", - }, - } as const; - - await createOrUpdateIndex(client, logsIndex, { - ...commonProperties, - level: { - type: "keyword", - }, - message: { - type: "text", - }, - }); - - await createOrUpdateIndex(client, spansIndex, { - ...commonProperties, - name: { - type: "keyword", - }, - startTime: { - type: "date", - }, - endTime: { - type: "date", - }, - elapsedTimeMillis: { - type: "long", - }, - }); - - await createOrUpdateIndex(client, statsIndex, { - ...commonProperties, - name: { - type: "keyword", - }, - avg: { - type: "double", - }, - max: { - type: "double", - }, - min: { - type: "double", - }, - count: { - type: "integer", - }, - }); -} - -async function createOrUpdateIndex( - client: ESClient, - index: string, - properties: Record, -) { - if (await client.indices.exists({ index: index })) { - console.log(`Updating mappings for ElasticSearch "${index}" index`); - await client.indices.putMapping({ - index, - properties, - }); - } else { - console.log(`Creating ElasticSearch "${index}" index`); - await client.indices.create({ - index, - body: { - mappings: { - properties, - }, - }, - }); - } -} diff --git a/server/logic/logic.ts b/server/logic/logic.ts index 967dfcd..b271b4b 100644 --- a/server/logic/logic.ts +++ b/server/logic/logic.ts @@ -1,8 +1,9 @@ import { assert } from "../../common/errors"; import { Player } from "../../common/types/player"; import { Room } from "../../common/types/room"; -import { getLogger } from "../logger"; import { Socket } from "../server"; +import { getLogger } from "../utils/logger"; +import { StopWatch } from "../utils/stopwatch"; import { getRoom, world } from "../world"; import { RoomController } from "./room-controller.base"; import { BotsRoom } from "./room-controller.bots"; @@ -76,30 +77,22 @@ function createRoom(roomWithBots: boolean): Room { world.rooms[room.id] = room; roomControllers[room.id] = controller; - let lastUpdateTime = Date.now() / 1000; - const roomMillisecondsBetweenIntervalsStats = getLogger().stats( - "room milliseconds between intervals", - 500, - ); - const roomUpdateMillisecondsDelayStats = getLogger().stats( - "room update milliseconds delay", - 500, - ); + const elapsedTimeStopWatch = new StopWatch(); const intervalId = setInterval(() => { if (!world.rooms[room.id]) { clearInterval(intervalId); } else { - const now = Date.now(); - const newUpdateTime = now / 1000; - const elapsedTime = newUpdateTime - lastUpdateTime; - - roomMillisecondsBetweenIntervalsStats.add(elapsedTime * 1000); + const roomUpdateStopWatch = new StopWatch(); + const elapsedTime = elapsedTimeStopWatch.next(); - controller.updateRoom(elapsedTime); + controller.updateRoom(elapsedTime / 1000); - roomUpdateMillisecondsDelayStats.add(Date.now() - now); - lastUpdateTime = newUpdateTime; + getLogger().stats("room milliseconds between intervals", elapsedTime); + getLogger().stats( + "room update milliseconds delay", + roomUpdateStopWatch.next(), + ); } }, 15); diff --git a/server/logic/room-controller.base.ts b/server/logic/room-controller.base.ts index 3a54318..ab5d910 100644 --- a/server/logic/room-controller.base.ts +++ b/server/logic/room-controller.base.ts @@ -5,8 +5,8 @@ import { makePlayer, Player } from "../../common/types/player"; import { Room } from "../../common/types/room"; import { makeFlailWeapon } from "../../common/types/weapon"; import { divide } from "../../common/vector"; -import { getLogger } from "../logger"; import { server, Socket } from "../server"; +import { getLogger } from "../utils/logger"; import { getRoom, playersById, socketsById, world } from "../world"; import { updateBots } from "./logic.ai"; @@ -68,13 +68,13 @@ export class BaseRoomController implements RoomController { updateRoom(elapsedTime: number) { const damages: Damage[] = []; - const updateBotsSpan = getLogger().measureSpan("updateBots"); - updateBots(this.room); - updateBotsSpan.end(); + getLogger().statsFunction("updateBots", () => { + updateBots(this.room); + }); - const applyPhysicsSpan = getLogger().measureSpan("applyPhysics"); - applyPhysics(this.room, elapsedTime, (damage) => damages.push(damage)); - applyPhysicsSpan.end(); + getLogger().statsFunction("applyPhysics", () => { + applyPhysics(this.room, elapsedTime, (damage) => damages.push(damage)); + }); const deadPlayerIds = new Set(); diff --git a/server/server.ts b/server/server.ts index 4b28272..738514d 100644 --- a/server/server.ts +++ b/server/server.ts @@ -15,7 +15,7 @@ import { } from "../common/types/socket-io"; import { joinUrl } from "../common/urls"; import { env } from "./env"; -import { getLogger } from "./logger"; +import { getLogger } from "./utils/logger"; export type SocketData = never; diff --git a/server/utils/logger.base.ts b/server/utils/logger.base.ts new file mode 100644 index 0000000..c935f13 --- /dev/null +++ b/server/utils/logger.base.ts @@ -0,0 +1,47 @@ +import { StopWatch } from "./stopwatch"; + +export const LOGGER_MODULE = "server"; + +export type Logger = { + info(message: string): void; + warn(message: string): void; + error(message: string): void; + /** + * Accumulates metrics, and flushes them as metrics: Average, max, min, count... + * + * It accumulates metrics with the same name, and flushes them automatically. + */ + stats(name: string, value: number): void; + /** + * Same as `stats`, but it measures the time it takes to execute the callback. + */ + statsFunction(name: string, callback: () => T): T; +}; + +export type StatsMetrics = { + name: string; + add(value: number): void; +}; + +export type InternalLogger = Logger & { + destroy(): void; +}; + +export abstract class BaseLogger implements Logger { + abstract info(message: string): void; + + abstract warn(message: string): void; + + abstract error(message: string): void; + + abstract stats(name: string, value: number): void; + + abstract destroy(): void; + + statsFunction(name: string, callback: () => T): T { + const stopWatch = new StopWatch(); + const result = callback(); + this.stats(name, stopWatch.next()); + return result; + } +} diff --git a/server/utils/logger.console.ts b/server/utils/logger.console.ts new file mode 100644 index 0000000..8ba3e68 --- /dev/null +++ b/server/utils/logger.console.ts @@ -0,0 +1,32 @@ +/* eslint-disable no-console */ + +import { BaseLogger, InternalLogger } from "./logger.base"; + +export class ConsoleLogger extends BaseLogger { + constructor(private otherLogger?: InternalLogger) { + super(); + } + + info(message: string) { + console.log(message); + this.otherLogger?.info(message); + } + + warn(message: string) { + console.warn(message); + this.otherLogger?.warn(message); + } + + error(message: string) { + console.error(message); + this.otherLogger?.error(message); + } + + stats(name: string, value: number) { + this.otherLogger?.stats(name, value); + } + + destroy() { + this.otherLogger?.destroy(); + } +} diff --git a/server/utils/logger.elastic-search.ts b/server/utils/logger.elastic-search.ts new file mode 100644 index 0000000..fae13ec --- /dev/null +++ b/server/utils/logger.elastic-search.ts @@ -0,0 +1,250 @@ +/* eslint-disable no-console */ +import { Client as ESClient } from "@elastic/elasticsearch"; +import { + MappingProperty, + PropertyName, +} from "@elastic/elasticsearch/lib/api/types"; +import os from "os"; +import { BaseLogger, InternalLogger, LOGGER_MODULE } from "./logger.base"; + +export class ElasticSearchLogger extends BaseLogger { + readonly bufferLimit = 1000; + readonly hostname: string; + + readonly logsBuffer: Record[] = []; + readonly statsBuffer: Record[] = []; + + autoStatsBuffer: Record = {}; + + readonly interval: NodeJS.Timeout; + + constructor( + private client: ESClient, + private logsIndex: string, + private statsIndex: string, + ) { + super(); + + this.hostname = os.hostname(); + + this.interval = setInterval(() => { + this.flushLogs(); + this.flushAutoStats(); + this.flushStats(); + }, 5000); + } + + static async create( + cloudId: string, + apiKey: string, + indexNamespace: string, + ): Promise { + const client = new ESClient({ + cloud: { + id: cloudId, + }, + auth: { + apiKey, + }, + }); + const logsIndex = `${indexNamespace}_logs`; + const statsIndex = `${indexNamespace}_stats`; + + await initializeElasticSearch(client, logsIndex, statsIndex); + + return new ElasticSearchLogger(client, logsIndex, statsIndex); + } + + info(message: string) { + this.addLog("info", message); + } + + warn(message: string) { + this.addLog("warn", message); + } + + error(message: string) { + this.addLog("error", message); + } + + stats(name: string, value: number) { + const existingAutoStats = this.autoStatsBuffer[name]; + + if (!existingAutoStats) { + this.autoStatsBuffer[name] = [value]; + return; + } + + existingAutoStats.push(value); + + if (existingAutoStats.length >= 500) { + const stats = statsFrom(existingAutoStats); + this.addStats(name, stats.avg, stats.max, stats.min, stats.count); + delete this.autoStatsBuffer[name]; + } + } + + destroy() { + this.flushLogs(); + this.flushStats(); + clearInterval(this.interval); + } + + private flush(index: string, buffer: Record[]) { + if (buffer.length === 0) { + return; + } + + this.client + .bulk({ + operations: buffer.flatMap((log) => [ + { index: { _index: index } }, + log, + ]), + }) + .catch((error: unknown) => { + console.error( + `Error sending logs to ElasticSearch index ${index}`, + error, + ); + }); + + buffer.length = 0; + } + + private flushLogs() { + this.flush(this.logsIndex, this.logsBuffer); + } + + private flushAutoStats() { + for (const [name, values] of Object.entries(this.autoStatsBuffer)) { + if (values.length > 0) { + const stats = statsFrom(values); + this.addStats(name, stats.avg, stats.max, stats.min, stats.count); + } + } + + this.autoStatsBuffer = {}; + } + + private flushStats() { + this.flush(this.statsIndex, this.statsBuffer); + } + + private addLog(level: "info" | "warn" | "error", message: string) { + this.logsBuffer.push({ + hostname: this.hostname, + module: LOGGER_MODULE, + timestamp: Date.now(), + level, + message, + }); + + if (this.logsBuffer.length >= this.bufferLimit) { + this.flushLogs(); + } + } + + private addStats( + name: string, + avg: number, + max: number, + min: number, + count: number, + ) { + this.statsBuffer.push({ + hostname: this.hostname, + module: LOGGER_MODULE, + timestamp: Date.now(), + name, + avg, + max, + min, + count, + }); + + if (this.statsBuffer.length >= this.bufferLimit) { + this.flushStats(); + } + } +} + +function statsFrom(values: number[]) { + const sum = values.reduce((a, b) => a + b, 0); + const max = Math.max(...values); + const min = Math.min(...values); + const avg = sum / values.length; + + return { avg, max, min, count: values.length }; +} + +async function initializeElasticSearch( + client: ESClient, + logsIndex: string, + statsIndex: string, +) { + const commonProperties = { + hostname: { + type: "keyword", + }, + module: { + type: "keyword", + }, + timestamp: { + type: "date", + }, + } as const; + + await createOrUpdateIndex(client, logsIndex, { + ...commonProperties, + level: { + type: "keyword", + }, + message: { + type: "text", + }, + }); + + await createOrUpdateIndex(client, statsIndex, { + ...commonProperties, + name: { + type: "keyword", + }, + avg: { + type: "double", + }, + max: { + type: "double", + }, + min: { + type: "double", + }, + count: { + type: "integer", + }, + }); +} + +async function createOrUpdateIndex( + client: ESClient, + index: string, + properties: Record, +) { + if (await client.indices.exists({ index: index })) { + console.log(`Updating mappings for ElasticSearch "${index}" index`); + await client.indices.putMapping({ + index, + properties, + }); + } else { + console.log(`Creating ElasticSearch "${index}" index`); + await client.indices.create({ + index, + body: { + mappings: { + properties, + }, + }, + }); + } +} diff --git a/server/utils/logger.ts b/server/utils/logger.ts new file mode 100644 index 0000000..ae4308a --- /dev/null +++ b/server/utils/logger.ts @@ -0,0 +1,32 @@ +/* eslint-disable no-console */ +import { env } from "../env"; +import { InternalLogger, Logger } from "./logger.base"; +import { ConsoleLogger } from "./logger.console"; +import { ElasticSearchLogger } from "./logger.elastic-search"; + +let logger: InternalLogger = new ConsoleLogger(); + +export function getLogger(): Logger { + return logger; +} + +export async function initializeLogger() { + logger.destroy(); + + let newLogger: InternalLogger | undefined; + + if ( + env.ELASTIC_CLOUD_ID && + env.ELASTIC_API_KEY && + env.ELASTIC_INDEX_NAMESPACE + ) { + console.log("Using ElasticSearch logger"); + newLogger = await ElasticSearchLogger.create( + env.ELASTIC_CLOUD_ID, + env.ELASTIC_API_KEY, + env.ELASTIC_INDEX_NAMESPACE, + ); + } + + logger = new ConsoleLogger(newLogger); +} diff --git a/server/utils/stopwatch.ts b/server/utils/stopwatch.ts new file mode 100644 index 0000000..fc089da --- /dev/null +++ b/server/utils/stopwatch.ts @@ -0,0 +1,18 @@ +export class StopWatch { + lastHrTime: bigint; + + constructor() { + this.lastHrTime = process.hrtime.bigint(); + } + + /** + * Returns the time elapsed since initialization or the last call to `next`. + * In milliseconds. + */ + next() { + const endHrTime = process.hrtime.bigint(); + const elapsedMillis = Number(endHrTime - this.lastHrTime) / 1_000_000; + this.lastHrTime = endHrTime; + return elapsedMillis; + } +}