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>
This commit is contained in:
Dorian
2026-03-13 09:35:42 +00:00
co-authored by Claude Opus 4.6
parent dc9884e27e
commit d3bb00c5c8
+13
View File
@@ -397,6 +397,8 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
for (let round = 1; round <= MAX_ROUNDS; round++) { for (let round = 1; round <= MAX_ROUNDS; round++) {
lastRound = round lastRound = round
const roundStart = Date.now()
const challenge = (round === retroRound && !hasHuman) const challenge = (round === retroRound && !hasHuman)
? generateRetroChallenge() ? generateRetroChallenge()
: pickChallenge(usedTypes, arena.modifier, undefined, round, hasHuman) : pickChallenge(usedTypes, arena.modifier, undefined, round, hasHuman)
@@ -408,10 +410,12 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
}) })
// Call both bots simultaneously // Call both bots simultaneously
const webhookStart = Date.now()
const [responseA, responseB] = await Promise.all([ const [responseA, responseB] = await Promise.all([
getBotResponse(botA, challenge, round, fightId, { name: botB.name, wins: botB.wins, losses: botB.losses }, arena), 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), 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 // Track webhook reliability for real bots
await Promise.all([ await Promise.all([
@@ -420,6 +424,7 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
]) ])
// Score the round // Score the round
const scoreStart = Date.now()
const result = scoreRound( const result = scoreRound(
challenge, challenge,
{ id: botA.id, name: botA.name }, { id: botA.id, name: botA.name },
@@ -430,6 +435,7 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
comboA, comboA,
comboB, comboB,
) )
const scoreMs = Date.now() - scoreStart
// Apply damage // Apply damage
hpB = Math.max(KO_THRESHOLD, hpB - result.botADamage) hpB = Math.max(KO_THRESHOLD, hpB - result.botADamage)
@@ -445,6 +451,7 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
} }
// Save round // Save round
const dbStart = Date.now()
await db.insert(schema.rounds).values({ await db.insert(schema.rounds).values({
id: nanoid(12), id: nanoid(12),
fightId, fightId,
@@ -483,6 +490,10 @@ async function executeFightRounds(fightId: string, botA: BotRecord, botB: BotRec
botBHp: hpB, botBHp: hpB,
totalRounds: round, totalRounds: round,
}).where(eq(schema.fights.id, fightId)).run() }).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 // Check for KO
if (hpA <= KO_THRESHOLD || hpB <= KO_THRESHOLD) { 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() finalize()
logger.info('perf', `fight=${fightId} finalize=${Date.now() - finalizeStart}ms rounds=${lastRound}`)
// Track aggregate analytics (no PII) // Track aggregate analytics (no PII)
trackBotActive(botA.id) trackBotActive(botA.id)