feat: add Zenith strategy and move latency tracing
Build and Push Docker Container / build-and-push (push) Successful in 2m18s
Build and Push Docker Container / build-and-push (push) Successful in 2m18s
- Register Zenith 1.1 with balanced duel verdicts and forced-outcome overrides. - Prioritize permanent-trail space in Constrictor and health-aware hazard routes. - Deduct executor queue delays and return fallback directions on move timeouts. - Correlate response headers, replay timings, and sampled structured trace logs. - Move shared metrics publication off the response path without losing local counts. - Allow configurable tournament opponents and add a psql helper recipe. - Preserve empty latency values through compact replay encoding and migration. - Update Arena game links and use default assets for missing customizations. - Cover strategy, HTTP lifecycle, tracing, replay codecs, and dashboard behavior. - Validate with 260 passing Python tests, 4 skips, and 2 passing JavaScript tests.
This commit is contained in:
+1
-1
@@ -132,7 +132,7 @@ class GameBoard:
|
||||
def _get_game_url(self, local_game:bool):
|
||||
if local_game:
|
||||
return None
|
||||
return f"https://play.battlesnake.com/game/{self.id}"
|
||||
return f"https://arena.battlesnake.com/games/{self.id}"
|
||||
|
||||
def _set_winner_snake_name(self, snakes:list[dict]):
|
||||
if self.my_snake["id"] in [ x["id"] for x in snakes]:
|
||||
|
||||
@@ -8,6 +8,8 @@ from quart_common.web.logger import await_log
|
||||
from snakes import DEFAULT_SNAKE_CONFIG
|
||||
from server.GameBoard import GameBoard
|
||||
from server.Files import read_file
|
||||
from server.services.move_safety import fallback_move, run_budgeted_move
|
||||
from server.services.move_trace import MoveTrace
|
||||
|
||||
lazy from server.Server import Server
|
||||
|
||||
@@ -58,36 +60,68 @@ def create_battlesnake_blueprint(server:'Server') -> Blueprint:
|
||||
@blueprint.post('/move')
|
||||
@require_user_agent(("BattlesnakeEngine", "BattlesnakeArena"), abort_code=404)
|
||||
async def on_move():
|
||||
move_started = time.perf_counter()
|
||||
server.metrics_collector.record_http_request('move')
|
||||
game_state = await request.get_json()
|
||||
move_started = time.perf_counter()
|
||||
trace = MoveTrace(game_state['game']['id'], game_state.get('turn'))
|
||||
trace.set(parse_ms=round((time.perf_counter() - move_started) * 1000, 3), timed_out=False)
|
||||
|
||||
game_id = game_state['game']['id']
|
||||
timeout_ms = int(game_state.get('game', {}).get('timeout', 500))
|
||||
budget_sec = max(0.05, (timeout_ms - 50) / 1000.0)
|
||||
|
||||
next_move = None
|
||||
next_move = fallback_move(game_state)
|
||||
game_board = None
|
||||
|
||||
try:
|
||||
async with asyncio.timeout(budget_sec):
|
||||
game_board = cast(GameBoard, await server.game_runtime.get_game_board(game_state))
|
||||
with trace.stage('runtime'):
|
||||
game_board = cast(GameBoard, await server.game_runtime.get_game_board(game_state))
|
||||
loop = asyncio.get_running_loop()
|
||||
next_move = await loop.run_in_executor(None, game_board.snake_neat_make_a_move)
|
||||
submitted = time.perf_counter()
|
||||
next_move = await loop.run_in_executor(
|
||||
None, run_budgeted_move, game_board, move_started + budget_sec, next_move, trace, submitted,
|
||||
)
|
||||
except TimeoutError:
|
||||
await await_log(server.logger.warning(f'MOVE TIMEOUT: turn={game_state.get("turn")}, game={game_id}, returning fallback {next_move!r}'))
|
||||
trace.set(timed_out=True)
|
||||
|
||||
thinking = server.gameplay_tracking._extract_latest_snake_thinking(game_board)
|
||||
server.game_lifecycle.submit(
|
||||
game_id, lambda: server.game_lifecycle.turn(game_state, next_move, thinking),
|
||||
)
|
||||
elapsed_ms = (time.perf_counter() - move_started) * 1000.0
|
||||
await server.metrics_collector.record_move(next_move, elapsed_ms)
|
||||
# Never persist another turn's history when the worker has timed out.
|
||||
thinking = None if trace.snapshot()['timed_out'] else server.gameplay_tracking._extract_latest_snake_thinking(game_board)
|
||||
thinking = dict(thinking or {})
|
||||
trace.set(handler_ms=round((time.perf_counter() - move_started) * 1000, 3),
|
||||
move=next_move, budget_ms=round(budget_sec * 1000, 3))
|
||||
thinking['move_trace'] = trace.snapshot()
|
||||
server.metrics_collector.record_move_local(next_move, trace.snapshot()['handler_ms'])
|
||||
|
||||
bookkeeping_submitted = time.perf_counter()
|
||||
|
||||
async def finish_move():
|
||||
trace.set(bookkeeping_queue_ms=round((time.perf_counter() - bookkeeping_submitted) * 1000, 3))
|
||||
try:
|
||||
try:
|
||||
with trace.stage('metrics_publish'):
|
||||
await server.metrics_collector.publish_move_metrics()
|
||||
except Exception:
|
||||
trace.set(metrics_publish_failed=True)
|
||||
server.app.logger.exception('Move metrics publish failed; trace=%s', trace.id)
|
||||
with trace.stage('persistence'):
|
||||
thinking['move_trace'] = trace.snapshot()
|
||||
await server.gameplay_tracking.record_gameplay_turn_snapshot(game_state, next_move, thinking)
|
||||
with trace.stage('dashboard_publish'):
|
||||
await server.dashboard_query.push_dashboard_game_replay_update(game_id)
|
||||
finally:
|
||||
trace.log(server.app.logger)
|
||||
|
||||
server.game_lifecycle.submit(game_id, finish_move)
|
||||
|
||||
if server.debug:
|
||||
await await_log(server.logger.debug(f'TURN: {game_state['turn']:3}, MOVE: {next_move:5}'))
|
||||
|
||||
return {'move': next_move}
|
||||
with trace.stage('response_encode'):
|
||||
response = jsonify(move=next_move)
|
||||
trace.set(handler_ms=round((time.perf_counter() - move_started) * 1000, 3))
|
||||
response.headers['X-Move-Trace-ID'] = trace.id
|
||||
return response
|
||||
|
||||
@blueprint.post('/end')
|
||||
@require_user_agent(("BattlesnakeEngine", "BattlesnakeArena"), abort_code=404)
|
||||
|
||||
@@ -23,7 +23,7 @@ def create_dashboard_blueprint(server:'Server') -> Blueprint:
|
||||
initial_game_id=initial_game_id,
|
||||
initial_summary=initial_summary,
|
||||
initial_games=initial_games,
|
||||
battlesnake_url=os.getenv('BATTLESNAKE_GAMEBOARD_URL', 'https://play.battlesnake.com/game')
|
||||
battlesnake_url=os.getenv('BATTLESNAKE_GAMEBOARD_URL', 'https://arena.battlesnake.com/games')
|
||||
)
|
||||
|
||||
@blueprint.get('/dashboard/game/<game_id>')
|
||||
|
||||
@@ -27,17 +27,24 @@ def decode_move(code:int|None) -> str|None:
|
||||
return None
|
||||
return MOVES[int(code) - 1]
|
||||
|
||||
# The engine reports latency as a string; "" means no response was measured.
|
||||
_EMPTY_LATENCY = -32768
|
||||
|
||||
def encode_latency(latency:object) -> int|None:
|
||||
if latency is None or latency == "":
|
||||
if latency is None:
|
||||
return None
|
||||
if latency == "":
|
||||
return _EMPTY_LATENCY
|
||||
try:
|
||||
value = int(str(latency))
|
||||
except ValueError:
|
||||
return None
|
||||
return value if -32768 <= value <= 32767 else None
|
||||
return value if _EMPTY_LATENCY < value <= 32767 else None
|
||||
|
||||
def decode_latency(value:int|None) -> str|None:
|
||||
return None if value is None else str(value)
|
||||
if value is None:
|
||||
return None
|
||||
return "" if value == _EMPTY_LATENCY else str(value)
|
||||
|
||||
def _point(point:object) -> tuple[int, int]|None:
|
||||
if not isinstance(point, dict):
|
||||
|
||||
@@ -67,7 +67,8 @@ class MetricsCollector:
|
||||
self._metrics['games_autocreated'] += 1
|
||||
await self._auto_publish()
|
||||
|
||||
async def record_move(self, direction:str, elapsed_ms:float) -> None:
|
||||
def record_move_local(self, direction:str, elapsed_ms:float) -> None:
|
||||
"""Update counters without waiting for a shared metrics backend."""
|
||||
self._metrics['total_moves'] += 1
|
||||
self._metrics['move_response_time_ms_total'] += elapsed_ms
|
||||
self._metrics['move_response_time_ms_max'] = max(
|
||||
@@ -80,6 +81,12 @@ class MetricsCollector:
|
||||
# else:
|
||||
# move_counts['unknown'] += 1
|
||||
# self._metrics['last_move_unix'] = int(time.time())
|
||||
|
||||
async def record_move(self, direction:str, elapsed_ms:float) -> None:
|
||||
self.record_move_local(direction, elapsed_ms)
|
||||
await self._auto_publish()
|
||||
|
||||
async def publish_move_metrics(self) -> None:
|
||||
await self._auto_publish()
|
||||
|
||||
async def record_game_end(self, game_state:dict) -> None:
|
||||
|
||||
@@ -0,0 +1,43 @@
|
||||
"""Fast request-local fallback and queue-aware worker budgeting."""
|
||||
from time import perf_counter
|
||||
|
||||
def fallback_move(state):
|
||||
board = state['board']
|
||||
mine = state['you']
|
||||
head = mine['head']
|
||||
occupied = {(p['x'], p['y']) for s in board['snakes'] for p in s['body']}
|
||||
food = {(p['x'], p['y']) for p in board.get('food', [])}
|
||||
hazards = {(p['x'], p['y']) for p in board.get('hazards', [])}
|
||||
ranked = []
|
||||
for name, (dx, dy) in (('up', (0, 1)), ('down', (0, -1)), ('left', (-1, 0)), ('right', (1, 0))):
|
||||
point = head['x'] + dx, head['y'] + dy
|
||||
if not (0 <= point[0] < board['width'] and 0 <= point[1] < board['height']):
|
||||
continue
|
||||
if point in occupied:
|
||||
continue
|
||||
danger = any(
|
||||
s['id'] != mine['id'] and len(s['body']) >= len(mine['body'])
|
||||
and abs(s['head']['x'] - point[0]) + abs(s['head']['y'] - point[1]) == 1
|
||||
for s in board['snakes']
|
||||
)
|
||||
ranked.append((not danger, point not in hazards or point in food, name))
|
||||
return max(ranked)[-1] if ranked else 'up'
|
||||
|
||||
def run_budgeted_move(board, deadline, fallback, trace=None, submitted=None):
|
||||
"""Deduct executor queue wait before the strategy starts its own clock."""
|
||||
started = perf_counter()
|
||||
if trace is not None:
|
||||
trace.set(executor_queue_ms=round((started - submitted) * 1000, 3), worker_started=True)
|
||||
remaining = int((deadline - started) * 1000)
|
||||
if remaining <= 40:
|
||||
if trace is not None:
|
||||
trace.set(worker_skipped=True)
|
||||
return fallback
|
||||
original_timeout = board.timeout
|
||||
try:
|
||||
board.timeout = min(original_timeout, remaining)
|
||||
return board.snake_neat_make_a_move()
|
||||
finally:
|
||||
board.timeout = original_timeout
|
||||
if trace is not None:
|
||||
trace.set(strategy_ms=round((perf_counter() - started) * 1000, 3), worker_finished=True)
|
||||
@@ -0,0 +1,49 @@
|
||||
"""Small request-local timings; no board payloads or external tracing dependency."""
|
||||
from contextlib import contextmanager
|
||||
import json
|
||||
import os
|
||||
from threading import Lock
|
||||
from time import perf_counter
|
||||
from uuid import uuid4
|
||||
|
||||
class MoveTrace:
|
||||
def __init__(self, game_id, turn):
|
||||
self.id = uuid4().hex
|
||||
self.game_id = game_id
|
||||
self.turn = turn
|
||||
self.started = perf_counter()
|
||||
self._lock = Lock()
|
||||
self._fields = {}
|
||||
|
||||
def set(self, **fields):
|
||||
with self._lock:
|
||||
self._fields.update(fields)
|
||||
|
||||
@contextmanager
|
||||
def stage(self, name):
|
||||
started = perf_counter()
|
||||
try:
|
||||
yield
|
||||
finally:
|
||||
self.set(**{name + '_ms': round((perf_counter() - started) * 1000, 3)})
|
||||
|
||||
def snapshot(self):
|
||||
with self._lock:
|
||||
return {'trace_id': self.id, **self._fields}
|
||||
|
||||
def log(self, logger):
|
||||
fields = self.snapshot()
|
||||
# Every timeout/slow request, plus deterministic sampling of normal moves.
|
||||
try:
|
||||
sample = max(0, int(os.getenv('MOVE_TRACE_SAMPLE_EVERY', '100')))
|
||||
slow_ms = max(0, float(os.getenv('MOVE_TRACE_SLOW_MS', '300')))
|
||||
except ValueError:
|
||||
sample, slow_ms = 100, 300
|
||||
slow_stage = any(value >= slow_ms for key, value in fields.items()
|
||||
if key.endswith('_ms') and isinstance(value, (int, float)))
|
||||
if not (fields.get('timed_out') or fields.get('metrics_publish_failed') or slow_stage
|
||||
or (sample and int(self.id[:8], 16) % sample == 0)):
|
||||
return
|
||||
logger.info('move_trace %s', json.dumps({
|
||||
'game_id': self.game_id, 'turn': self.turn, **fields,
|
||||
}, separators=(',', ':')))
|
||||
Reference in New Issue
Block a user