From d3bb00c5c879aa648e9a9eea358bd33be59a7273 Mon Sep 17 00:00:00 2001
From: Dorian <dorian@Dorians-MacBook-Air.local>
Date: Fri, 13 Mar 2026 09:35:42 +0000
Subject: [PATCH] feat: add per-phase timing instrumentation to fight
 orchestration

Log timing for each round phase: webhook calls, scoring, DB operations,
and total round time. Also log finalize transaction time. Uses logger
with 'perf' category for easy filtering.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
---
 server/src/engine/orchestrator.ts | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/server/src/engine/orchestrator.ts b/server/src/engine/orchestrator.ts
index b2d0ad4..379d587 100644
--- a/server/src/engine/orchestrator.ts
+++ b/server/src/engine/orchestrator.ts
@@ -397,6 +397,8 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
 
   for (let round = 1; round <= MAX_ROUNDS; round++) {
     lastRound = round
+    const roundStart = Date.now()
+
     const challenge = (round === retroRound && !hasHuman)
       ? generateRetroChallenge()
       : pickChallenge(usedTypes, arena.modifier, undefined, round, hasHuman)
@@ -408,10 +410,12 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
     })
 
     // Call both bots simultaneously
+    const webhookStart = Date.now()
     const [responseA, responseB] = await Promise.all([
       getBotResponse(botA, challenge, round, fightId, { name: botB.name, wins: botB.wins, losses: botB.losses }, arena),
       getBotResponse(botB, challenge, round, fightId, { name: botA.name, wins: botA.wins, losses: botA.losses }, arena),
     ])
+    const webhookMs = Date.now() - webhookStart
 
     // Track webhook reliability for real bots
     await Promise.all([
@@ -420,6 +424,7 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
     ])
 
     // Score the round
+    const scoreStart = Date.now()
     const result = scoreRound(
       challenge,
       { id: botA.id, name: botA.name },
@@ -430,6 +435,7 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
       comboA,
       comboB,
     )
+    const scoreMs = Date.now() - scoreStart
 
     // Apply damage
     hpB = Math.max(KO_THRESHOLD, hpB - result.botADamage)
@@ -445,6 +451,7 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
     }
 
     // Save round
+    const dbStart = Date.now()
     await db.insert(schema.rounds).values({
       id: nanoid(12),
       fightId,
@@ -483,6 +490,10 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
       botBHp: hpB,
       totalRounds: round,
     }).where(eq(schema.fights.id, fightId)).run()
+    const dbMs = Date.now() - dbStart
+
+    const roundMs = Date.now() - roundStart
+    logger.info('perf', `fight=${fightId} round=${round} total=${roundMs}ms webhook=${webhookMs}ms score=${scoreMs}ms db=${dbMs}ms`)
 
     // Check for KO
     if (hpA <= KO_THRESHOLD || hpB <= KO_THRESHOLD) {
@@ -565,7 +576,9 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
     }
   })
 
+  const finalizeStart = Date.now()
   finalize()
+  logger.info('perf', `fight=${fightId} finalize=${Date.now() - finalizeStart}ms rounds=${lastRound}`)
 
   // Track aggregate analytics (no PII)
   trackBotActive(botA.id)