feat: start collecting engine metrics (#86)

## How does this PR impact the user?

No direct impact.

This will help us debug performance issues :)

## Description

<img width="1424" alt="image"
src="https://github.com/user-attachments/assets/d87c38ae-6e72-434b-9ff5-d0f14d3f19c8">

## Limitations

- we most likely will want to get rid of per-user metric at some point;
but, for now, it's fine 😄

## Checklist

- [x] my PR is focused and contains one wholistic change
- [x] I have added screenshots or screen recordings to show the changes

package.json

@@ -61,6 +61,7 @@
     "isolated-vm": "^4.6.0",
     "lru-cache": "^10.2.0",
     "pixi.js": "^8.3.4",
+    "prom-client": "^15.1.3",
     "zod": "^3.22.4"
   }
 }

server/middleware/auth.ts

@@ -1,8 +1,15 @@
 import prisma from "~/other/db";
 import { SESSION_COOKIE_NAME, SESSION_STORAGE } from "~/other/sessionStorage";
 
+const PUBLIC_PATHS = [
+  "/api/auth/login",
+  "/login",
+
+  "/metrics",
+];
+
 export default defineEventHandler(async (event) => {
-  if (event.path.includes("login")) {
+  if (PUBLIC_PATHS.includes(event.path)) {
     return;
   }
 

server/other/engineMetrics.ts

@@ -0,0 +1,35 @@
+import promClient from "prom-client";
+
+export const gameStepTimeMs = new promClient.Histogram({
+  name: "game_step_time_ms",
+  help: "Time all bots took to make a move and engine took to process them",
+  buckets: [200, 250],
+});
+
+export const botCodeRunTimeMs = new promClient.Histogram({
+  name: "bot_code_run_time_ms",
+  help: "Time a bot took to make a move",
+  buckets: [50, 75],
+  labelNames: ["username"] as const,
+});
+
+export const gameStepCodeRunTimeMs = new promClient.Histogram({
+  name: "game_step_code_run_time_ms",
+  help: "Time all bots took to make a move",
+  buckets: [50, 100, 150],
+});
+
+export const gameStepMoveBotTimeMs = new promClient.Summary({
+  name: "game_step_move_bot_time_ms",
+  help: "Time it took to move all bots",
+});
+
+export const gameStepCollisionCheckTimeMs = new promClient.Summary({
+  name: "game_step_collision_check_time_ms",
+  help: "Time it took to check for collisions",
+});
+
+export const gameStepFoodSpawnTimeMs = new promClient.Summary({
+  name: "game_step_food_spawn_time_ms",
+  help: "Time it took to spawn food",
+});

server/plugins/engine.ts

@@ -1,3 +1,4 @@
+import { gameStepCodeRunTimeMs, botCodeRunTimeMs, gameStepTimeMs, gameStepMoveBotTimeMs, gameStepCollisionCheckTimeMs, gameStepFoodSpawnTimeMs } from "../other/engineMetrics";
 import prepareBotCode from "~/other/prepareBotCode";
 import * as botCodeStore from "~/other/botCodeStore";
 import World, { type WorldState } from "~/other/world";
@@ -36,35 +37,53 @@ async function runBots({ bots, world, prevBotState, botApi }: RunBotArgs) {
     botApi,
   }));
 
+  const stopAllBotCodeRuntimeTimer = gameStepCodeRunTimeMs.startTimer();
   const botActions = await Promise.all(preparedBotCodes.map(async (preparedCode, i) => {
     const codeRunner = codeRunners[i % codeRunners.length];
     if (!codeRunner) {
       throw new Error("unexpected: codeRunner is undefined");
     }
 
+    const bot = botArray[i];
+    if (!bot) {
+      throw new Error("unexpected: bot is undefined");
+    }
+
+    const stopBotCodeRuntimeTimer = botCodeRunTimeMs.startTimer({
+      username: bot.username,
+    });
     try {
       const result = await codeRunner.runCode(preparedCode);
       return JSON.parse(result);
     } catch (err) {
       // TODO(yurij): notify user that their bot crashed
       console.error(err);
       return [];
+    } finally {
+      stopBotCodeRuntimeTimer();
     }
   }));
+  stopAllBotCodeRuntimeTimer();
 
+  const stopMoveBotTimeTimer = gameStepMoveBotTimeMs.startTimer();
   for (const [i, actions] of botActions.entries()) {
     const botId = botArray[i]?.id;
     if (botId && actions?.[0]?.type === "move") {
       world.moveBot(botId, actions[0].x, actions[0].y);
     }
   }
+  stopMoveBotTimeTimer();
 
+  const stopCollisionCheckTimeTimer = gameStepCollisionCheckTimeMs.startTimer();
   let collisionCheckLimit = 5;
   while (world.checkCollisions() && --collisionCheckLimit) {
     continue;
   }
+  stopCollisionCheckTimeTimer();
 
+  const stopSpawnFoodTimeTimer = gameStepFoodSpawnTimeMs.startTimer();
   world.spawnFood();
+  stopSpawnFoodTimeTimer();
 }
 
 type StartEngineArgs = {
@@ -107,8 +126,9 @@ async function startEngine({ botApi }: StartEngineArgs) {
     }
 
     const endTs = Date.now();
-
     const timeSpentMs = endTs - startTs;
+    gameStepTimeMs.observe(timeSpentMs);
+
     if (timeSpentMs < GAME_STEP_INTERVAL_MS) {
       await new Promise(resolve => setTimeout(resolve, GAME_STEP_INTERVAL_MS - timeSpentMs));
     } else {

server/routes/metrics.ts

@@ -0,0 +1,12 @@
+import promClient from "prom-client";
+
+promClient.collectDefaultMetrics();
+
+export default defineEventHandler(async () => {
+  const metrics = await promClient.register.metrics();
+  return new Response(metrics, {
+    headers: {
+      "Content-Type": promClient.register.contentType,
+    },
+  });
+});