diff --git a/server/index.ts b/server/index.ts index 4804e96..a96e4f2 100644 --- a/server/index.ts +++ b/server/index.ts @@ -24,6 +24,11 @@ async function startServer() { }); socket.on("requestJoin", async (event, callback) => { + getLogger().stats({ + name: "user join request", + unit: "count", + value: 1, + }); const { room, player } = await joinPlayer( socket, event.username, @@ -40,6 +45,11 @@ async function startServer() { }); socket.on("updateAcceleration", (event) => { + getLogger().stats({ + name: "user acceleration update", + unit: "count", + value: 1, + }); const player = getPlayer(socket); if (!player) { diff --git a/server/logic/logic.ts b/server/logic/logic.ts index b271b4b..6aab011 100644 --- a/server/logic/logic.ts +++ b/server/logic/logic.ts @@ -88,11 +88,18 @@ function createRoom(roomWithBots: boolean): Room { controller.updateRoom(elapsedTime / 1000); - getLogger().stats("room milliseconds between intervals", elapsedTime); - getLogger().stats( - "room update milliseconds delay", - roomUpdateStopWatch.next(), - ); + getLogger().stats({ + name: "room interval delay", + unit: "milliseconds", + extra: `room:${room.id}`, + value: elapsedTime, + }); + getLogger().stats({ + name: "room update delay", + unit: "milliseconds", + extra: `room:${room.id}`, + value: roomUpdateStopWatch.next(), + }); } }, 15); diff --git a/server/logic/room-controller.base.ts b/server/logic/room-controller.base.ts index ab5d910..41dfe47 100644 --- a/server/logic/room-controller.base.ts +++ b/server/logic/room-controller.base.ts @@ -68,13 +68,27 @@ export class BaseRoomController implements RoomController { updateRoom(elapsedTime: number) { const damages: Damage[] = []; - getLogger().statsFunction("updateBots", () => { - updateBots(this.room); - }); + getLogger().statsFunction( + { + name: "update bots", + unit: "milliseconds", + extra: `room:${this.room.id}`, + }, + () => { + updateBots(this.room); + }, + ); - getLogger().statsFunction("applyPhysics", () => { - applyPhysics(this.room, elapsedTime, (damage) => damages.push(damage)); - }); + getLogger().statsFunction( + { + name: "apply physics", + unit: "milliseconds", + extra: `room:${this.room.id}`, + }, + () => { + applyPhysics(this.room, elapsedTime, (damage) => damages.push(damage)); + }, + ); const deadPlayerIds = new Set(); diff --git a/server/utils/logger.base.ts b/server/utils/logger.base.ts index c935f13..b5929e2 100644 --- a/server/utils/logger.base.ts +++ b/server/utils/logger.base.ts @@ -2,6 +2,15 @@ import { StopWatch } from "./stopwatch"; export const LOGGER_MODULE = "server"; +export type StatsUnit = "milliseconds" | "count"; + +export type StatsRequest = { + name: string; + unit: StatsUnit; + extra?: string; + value: number; +}; + export type Logger = { info(message: string): void; warn(message: string): void; @@ -11,16 +20,14 @@ export type Logger = { * * It accumulates metrics with the same name, and flushes them automatically. */ - stats(name: string, value: number): void; + stats(statsRequest: StatsRequest): 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; + statsFunction( + statsRequest: Omit, + callback: () => T, + ): T; }; export type InternalLogger = Logger & { @@ -34,14 +41,17 @@ export abstract class BaseLogger implements Logger { abstract error(message: string): void; - abstract stats(name: string, value: number): void; + abstract stats(statsRequest: StatsRequest): void; abstract destroy(): void; - statsFunction(name: string, callback: () => T): T { + statsFunction( + statsRequest: Omit, + callback: () => T, + ): T { const stopWatch = new StopWatch(); const result = callback(); - this.stats(name, stopWatch.next()); + this.stats({ ...statsRequest, value: stopWatch.next() }); return result; } } diff --git a/server/utils/logger.console.ts b/server/utils/logger.console.ts index 8ba3e68..a3c21d4 100644 --- a/server/utils/logger.console.ts +++ b/server/utils/logger.console.ts @@ -1,6 +1,6 @@ /* eslint-disable no-console */ -import { BaseLogger, InternalLogger } from "./logger.base"; +import { BaseLogger, InternalLogger, StatsRequest } from "./logger.base"; export class ConsoleLogger extends BaseLogger { constructor(private otherLogger?: InternalLogger) { @@ -22,8 +22,8 @@ export class ConsoleLogger extends BaseLogger { this.otherLogger?.error(message); } - stats(name: string, value: number) { - this.otherLogger?.stats(name, value); + stats(statsRequest: StatsRequest) { + this.otherLogger?.stats(statsRequest); } destroy() { diff --git a/server/utils/logger.elastic-search.ts b/server/utils/logger.elastic-search.ts index fae13ec..9a42b8e 100644 --- a/server/utils/logger.elastic-search.ts +++ b/server/utils/logger.elastic-search.ts @@ -5,7 +5,12 @@ import { PropertyName, } from "@elastic/elasticsearch/lib/api/types"; import os from "os"; -import { BaseLogger, InternalLogger, LOGGER_MODULE } from "./logger.base"; +import { + BaseLogger, + InternalLogger, + LOGGER_MODULE, + StatsRequest, +} from "./logger.base"; export class ElasticSearchLogger extends BaseLogger { readonly bufferLimit = 1000; @@ -14,7 +19,7 @@ export class ElasticSearchLogger extends BaseLogger { readonly logsBuffer: Record[] = []; readonly statsBuffer: Record[] = []; - autoStatsBuffer: Record = {}; + autoStatsBuffer: Record = {}; readonly interval: NodeJS.Timeout; @@ -29,9 +34,8 @@ export class ElasticSearchLogger extends BaseLogger { this.interval = setInterval(() => { this.flushLogs(); - this.flushAutoStats(); this.flushStats(); - }, 5000); + }, 10_000); } static async create( @@ -67,20 +71,21 @@ export class ElasticSearchLogger extends BaseLogger { this.addLog("error", message); } - stats(name: string, value: number) { - const existingAutoStats = this.autoStatsBuffer[name]; + stats(statsRequest: StatsRequest) { + const key = `${statsRequest.name}__${statsRequest.extra ?? ""}--${statsRequest.unit}`; + const existingAutoStats = this.autoStatsBuffer[key]; if (!existingAutoStats) { - this.autoStatsBuffer[name] = [value]; + this.autoStatsBuffer[key] = [statsRequest]; return; } - existingAutoStats.push(value); + existingAutoStats.push(statsRequest); if (existingAutoStats.length >= 500) { const stats = statsFrom(existingAutoStats); - this.addStats(name, stats.avg, stats.max, stats.min, stats.count); - delete this.autoStatsBuffer[name]; + this.addStats(statsRequest, stats); + delete this.autoStatsBuffer[key]; } } @@ -116,18 +121,17 @@ export class ElasticSearchLogger extends BaseLogger { 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); + private flushStats() { + for (const requests of Object.values(this.autoStatsBuffer)) { + const firstRequest = requests[0]; + if (firstRequest) { + const stats = statsFrom(requests); + this.addStats(firstRequest, stats); } } this.autoStatsBuffer = {}; - } - private flushStats() { this.flush(this.statsIndex, this.statsBuffer); } @@ -145,22 +149,19 @@ export class ElasticSearchLogger extends BaseLogger { } } - private addStats( - name: string, - avg: number, - max: number, - min: number, - count: number, - ) { + private addStats(statsRequest: StatsRequest, stats: Stats) { this.statsBuffer.push({ hostname: this.hostname, module: LOGGER_MODULE, timestamp: Date.now(), - name, - avg, - max, - min, - count, + name: statsRequest.name, + unit: statsRequest.unit, + extra: statsRequest.extra, + sum: stats.sum, + avg: stats.avg, + max: stats.max, + min: stats.min, + count: stats.count, }); if (this.statsBuffer.length >= this.bufferLimit) { @@ -169,13 +170,22 @@ export class ElasticSearchLogger extends BaseLogger { } } -function statsFrom(values: number[]) { +type Stats = { + sum: number; + avg: number; + max: number; + min: number; + count: number; +}; + +function statsFrom(requests: StatsRequest[]): Stats { + const values = requests.map((r) => r.value); 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 }; + return { sum, avg, max, min, count: values.length }; } async function initializeElasticSearch( @@ -210,6 +220,15 @@ async function initializeElasticSearch( name: { type: "keyword", }, + unit: { + type: "keyword", + }, + extra: { + type: "keyword", + }, + sum: { + type: "double", + }, avg: { type: "double", },