perf(engine): tick-thread diagnostics, hiscores cache, login takeover throttle

- management port: /tickstats (rolling per-phase cycle timings + per-route web
  request stats), /profile (JSC sampling profiler over the main thread),
  /prometheus computed per request instead of frozen at startup
- web: log requests slower than WEB_SLOW_MS (100) with client ip; per-route
  counters in /tickstats
- hiscores: ranked lists cached 60s (HISCORES_CACHE_MS) instead of materialising
  the whole hiscore/hiscore_large table on the tick thread per request; player
  page ranks come from the cached lists instead of 22 count() scans
- login: refuse session takeovers within LOGIN_TAKEOVER_MIN_MS (10s) of the
  previous one (response 5) - crash-looping clients were doing ~3 takeovers/s
- lite/loadtest.ts: N idle lite sessions for local load testing

Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
max bittkerandClaude committed 2026-08-17 19:44:43 -04:00
1 parent 79587ece10
commit 34641c5cbf
5 files changed
+324 -61

No files matched your search

+57
View File
@@ -175,6 +175,13 @@ class World {
readonly lastCycleStats: Uint16Array = new Uint16Array(12);
readonly cycleStats: Uint16Array = new Uint16Array(12);
// rs-sdk: rolling history of the last TICK_HISTORY cycles (per-phase ms + wall interval
// between cycle starts) so /tickstats on the management port can report load without a restart.
static readonly TICK_HISTORY = 300;
readonly tickHistory: Uint16Array = new Uint16Array(World.TICK_HISTORY * 13); // 12 stats + interval
tickHistoryCount: number = 0;
lastCycleStart: number = 0;
tickRate: number = World.TICKRATE; // speeds up when we're processing server shutdown
currentTick: number = 0; // the current tick of the game world.
nextTick: number = 0; // the next time the game world should tick.
@@ -539,6 +546,14 @@ class World {
this.lastCycleStats[WorldStat.BANDWIDTH_IN] = this.cycleStats[WorldStat.BANDWIDTH_IN];
this.lastCycleStats[WorldStat.BANDWIDTH_OUT] = this.cycleStats[WorldStat.BANDWIDTH_OUT];
{
const row: number = (this.tickHistoryCount % World.TICK_HISTORY) * 13;
this.tickHistory.set(this.cycleStats, row);
this.tickHistory[row + 12] = this.lastCycleStart ? Math.min(65535, start - this.lastCycleStart) : 0;
this.tickHistoryCount++;
this.lastCycleStart = start;
}
// push stats to prometheus
if (Environment.node.production) {
trackPlayerCount.set(this.getTotalPlayers());
@@ -1883,6 +1898,48 @@ class World {
}
// todo: could cache this, or increment/decrement on add/remove
// rs-sdk: summary of the recent tick history for the management /tickstats endpoint
getTickStats(): Record<string, unknown> {
const names = ['cycle', 'world', 'clientIn', 'npc', 'player', 'logout', 'login', 'zone', 'clientOut', 'cleanup', 'bandwidthIn', 'bandwidthOut', 'interval'];
const n: number = Math.min(this.tickHistoryCount, World.TICK_HISTORY);
const sum: number[] = new Array(13).fill(0);
const max: number[] = new Array(13).fill(0);
let overBudget = 0;
for (let i = 0; i < n; i++) {
const row: number = i * 13;
for (let j = 0; j < 13; j++) {
const v: number = this.tickHistory[row + j];
sum[j] += v;
if (v > max[j]) max[j] = v;
}
if (this.tickHistory[row] > this.tickRate) overBudget++;
}
const avg: Record<string, number> = {};
const peak: Record<string, number> = {};
for (let j = 0; j < 13; j++) {
avg[names[j]] = n ? Math.round((sum[j] / n) * 10) / 10 : 0;
peak[names[j]] = max[j];
}
const last: Record<string, number> = {};
for (let j = 0; j < 12; j++) {
last[names[j]] = this.lastCycleStats[j];
}
return {
tick: this.currentTick,
tickRate: this.tickRate,
players: this.getTotalPlayers(),
npcs: this.getTotalNpcs(),
zonesTracking: this.zonesTracking.size,
window: n,
overBudget,
avg,
peak,
last,
heapMB: Math.trunc(process.memoryUsage().heapTotal / 1024 / 1024),
rssMB: Math.trunc(process.memoryUsage().rss / 1024 / 1024)
};
}
getTotalPlayers(): number {
let count = 0;
@@ -242,6 +242,11 @@ export default class LoginServer {
// In-memory tracking of concurrent logins per IP
private ipLoginCount: Map<string, Set<number>> = new Map();
private accountIp: Map<number, string> = new Map();
// rs-sdk: last time a login took over an already-logged-in account. Some scripts crash-loop
// and re-login every ~300ms; every takeover is a full save/reload/kick on the world's tick
// thread, so refuse takeovers that come sooner than TAKEOVER_MIN_MS after the previous one.
private lastTakeover: Map<number, number> = new Map();
private static readonly TAKEOVER_MIN_MS = Number(process.env.LOGIN_TAKEOVER_MIN_MS ?? 10_000);
private trackLogin(ip: string, accountId: number) {
// Remove any existing tracking for this account (handles IP changes, takeovers)
@@ -513,6 +518,19 @@ export default class LoginServer {
// Already logged in elsewhere - new login takes over
// Clear the old session's logged_in state so the new login can proceed
// The old world will handle the orphaned session gracefully on disconnect
const lastTakeover = this.lastTakeover.get(account.id) ?? 0;
if (Date.now() - lastTakeover < LoginServer.TAKEOVER_MIN_MS) {
// took over less than TAKEOVER_MIN_MS ago - refuse as "already logged in"
// and leave the current session alone
s.send(
JSON.stringify({
replyTo,
response: 5
})
);
return;
}
this.lastTakeover.set(account.id, Date.now());
console.log(`[LOGIN] Account ${username} already logged in on world ${account.logged_in}, new login taking over`);
this.untrackLogin(account.id);
await db.updateTable('account_login')
+128 -5
View File
@@ -9,6 +9,7 @@ import { handleScreenshotUpload, handleExportCollisionApi } from './pages/api.js
import { handleBugReport } from './pages/bug-report.js';
import { handleDisclaimerPage, handleMapviewPage, handlePublicFiles } from './pages/static.js';
import { WebSocketData, handleWebSocketUpgrade, handleGatewayEndpointGet, websocketHandlers } from './websocket.js';
import { getIp } from './utils.js';
export type { WebSocketData };
@@ -16,12 +17,67 @@ export type WebSocketRoutes = {
'/': Response
};
// rs-sdk: per-route request accounting so /tickstats (management port) can show what the
// public web server is being asked to do, and slow handlers get logged with the client IP.
// Everything here runs on the tick thread, so a slow HTTP handler is a stalled world.
type RouteStat = { count: number; totalMs: number; maxMs: number };
let webWindowStart = Date.now();
let webWindow: Map<string, RouteStat> = new Map();
let webLastWindow: { start: number; end: number; routes: Record<string, RouteStat> } | null = null;
const WEB_WINDOW_MS = 60_000;
const WEB_SLOW_MS = Number(process.env.WEB_SLOW_MS ?? 100);
function routeKey(url: URL): string {
// collapse ids/usernames so keys stay bounded: keep the first two path segments
const parts = url.pathname.split('/').filter(Boolean);
let key = '/' + parts.slice(0, 2).join('/');
if (parts.length > 2) key += '/*';
if (url.searchParams.size > 0) key += '?' + [...url.searchParams.keys()].slice(0, 3).sort().join('&');
return key;
}
function recordRequest(url: URL, req: Request, ms: number) {
const now = Date.now();
if (now - webWindowStart >= WEB_WINDOW_MS) {
webLastWindow = { start: webWindowStart, end: now, routes: Object.fromEntries(webWindow) };
webWindow = new Map();
webWindowStart = now;
}
const key = routeKey(url);
const stat = webWindow.get(key) ?? { count: 0, totalMs: 0, maxMs: 0 };
stat.count++;
stat.totalMs += ms;
if (ms > stat.maxMs) stat.maxMs = ms;
webWindow.set(key, stat);
if (ms >= WEB_SLOW_MS) {
console.warn(`[web] slow ${req.method} ${url.pathname}${url.search} ${ms}ms ip=${getIp(req) ?? req.headers.get('fly-client-ip') ?? '?'}`);
}
}
export function getWebStats() {
return {
current: { start: webWindowStart, end: Date.now(), routes: Object.fromEntries(webWindow) },
last: webLastWindow
};
}
export async function startWeb() {
Bun.serve<WebSocketData, WebSocketRoutes>({
port: Environment.WEB_PORT,
async fetch(req, server) {
const url = new URL(req.url ?? '', `http://${req.headers.get('host')}`);
const start = Date.now();
try {
return await handleRequest(req, server, url);
} finally {
recordRequest(url, req, Date.now() - start);
}
},
websocket: websocketHandlers
});
}
async function handleRequest(req: Request, server: Bun.Server, url: URL): Promise<Response | undefined> {
// Handle WebSocket upgrades first
const wsResponse = handleWebSocketUpgrade(req, server, url);
if (wsResponse !== undefined) {
@@ -216,20 +272,87 @@ export async function startWeb() {
// 404
return new Response(null, { status: 404 });
},
websocket: websocketHandlers
});
}
// Internal-only diagnostics (management port is not exposed by fly). Reach it with
// `fly proxy 8898:8898` or `fly ssh console -C "bun -e 'fetch(\"http://localhost:8898/tickstats\").then(r=>r.text()).then(console.log)'"`.
let profileRunning = false;
export async function startManagementWeb() {
Bun.serve({
port: Environment.WEB_MANAGEMENT_PORT,
routes: {
'/prometheus': new Response(await register.metrics(), {
// computed per request (a static Response here froze the metrics at startup)
'/prometheus': async () => new Response(await register.metrics(), {
headers: {
'Content-Type': register.contentType
}
})
}),
// rolling per-phase cycle timings over the last ~300 ticks
'/tickstats': () => Response.json({ ...World.getTickStats(), web: getWebStats() }),
// sample the main thread with JSC's sampling profiler for ?ms= (default 3000, max 15000)
// at ?interval= microseconds (default 250). Covers everything on the event loop:
// world cycles, websocket I/O callbacks, timers.
'/profile': async (req: Request) => {
if (profileRunning) {
return new Response('profile already running', { status: 409 });
}
const url = new URL(req.url);
const ms = Math.min(15000, Math.max(100, parseInt(url.searchParams.get('ms') ?? '3000') || 3000));
const interval = Math.min(5000, Math.max(50, parseInt(url.searchParams.get('interval') ?? '250') || 250));
const stacks = Math.max(0, parseInt(url.searchParams.get('stacks') ?? '40') || 40);
profileRunning = true;
try {
const { profile } = await import('bun:jsc');
const before = World.getTickStats();
const result = await profile(() => Bun.sleep(ms), interval);
const after = World.getTickStats();
// stackTraces is really { interval, traces: [{ frames: [{ name, sourceURL?, line, category }] }] };
// fold into inclusive sample counts per frame (each frame counted once per trace) and
// the hottest leaf->caller pairs, which is what actually points at the slow code path.
type Frame = { name: string; sourceURL?: string; line: number; category: string };
const traces: { frames: Frame[] }[] = (result.stackTraces as unknown as { traces?: { frames: Frame[] }[] })?.traces ?? [];
const label = (f: Frame) => `${f.name || '(anon)'} ${f.sourceURL ? f.sourceURL.replace(/^.*\/src\//, 'src/') + ':' + f.line : f.category}`;
const inclusive = new Map<string, number>();
const leafPairs = new Map<string, number>();
for (const t of traces) {
const seen = new Set<string>();
for (const f of t.frames) {
const k = label(f);
if (!seen.has(k)) {
seen.add(k);
inclusive.set(k, (inclusive.get(k) ?? 0) + 1);
}
}
// frames[0] is the leaf; walk up to the first frame with a source file
const leaf = t.frames[0];
const caller = t.frames.find((f, i) => i > 0 && f.sourceURL);
if (leaf) {
const k = `${label(leaf)} <- ${caller ? label(caller) : '?'}`;
leafPairs.set(k, (leafPairs.get(k) ?? 0) + 1);
}
}
const top = (m: Map<string, number>) => [...m.entries()].sort((a, b) => b[1] - a[1]).slice(0, stacks).map(([k, v]) => `${String(v).padStart(6)} ${(100 * v / Math.max(1, traces.length)).toFixed(1).padStart(5)}% ${k}`);
const text = [
`# profile ${ms}ms @ ${interval}us, ${traces.length} samples (~${(traces.length * interval / 1000 / ms * 100).toFixed(0)}% of wall busy in JS), ticks ${before.tick}..${after.tick}, players ${after.players}`,
'',
`# inclusive samples per frame (top ${stacks})`,
...top(inclusive),
'',
`# hottest leaf <- nearest source caller (top ${stacks})`,
...top(leafPairs),
'',
result.functions,
'',
result.bytecodes
].join('\n');
return new Response(text, { headers: { 'Content-Type': 'text/plain' } });
} catch (err) {
return new Response(`profile failed: ${err instanceof Error ? err.stack ?? err.message : String(err)}`, { status: 500 });
} finally {
profileRunning = false;
}
}
},
fetch() {
return new Response(null, { status: 404 });
+77 -56
View File
@@ -63,6 +63,75 @@ function formatPlaytime(ticks: number): string {
return `${minutes}m`;
}
// rs-sdk: ranked lists are served from a short-lived cache. Every hiscores request used to
// materialise the whole hiscore/hiscore_large table (160k+ rows) on the tick thread; a burst
// of page loads was enough to freeze the world for seconds. The list changes on player save
// (autosave is 15 min), so a 60s TTL is invisible to users.
type RankedRow = { username: string; level: number; playtime: number };
const RANKED_TTL_MS = Number(process.env.HISCORES_CACHE_MS ?? 60_000);
const rankedCache = new Map<string, { at: number; rows: RankedRow[]; pending: Promise<RankedRow[]> | null }>();
// category 0 = overall (hiscore_large type 0), otherwise hiscore type = category
async function getRankedList(profile: string, category: number): Promise<RankedRow[]> {
const key = `${profile}:${category}`;
const now = Date.now();
const cached = rankedCache.get(key);
if (cached && now - cached.at < RANKED_TTL_MS) {
return cached.rows;
}
if (cached?.pending) {
return cached.pending;
}
const load = (async () => {
let rows: RankedRow[];
if (category === 0) {
let query = db
.selectFrom('hiscore_large')
.innerJoin('account', 'account.id', 'hiscore_large.account_id')
.select(['account.username', 'hiscore_large.level', 'hiscore_large.playtime'])
.where('hiscore_large.type', '=', 0)
.where('hiscore_large.profile', '=', profile)
.where('account.staffmodlevel', '<=', 1)
.orderBy('hiscore_large.level', 'desc')
.orderBy('hiscore_large.playtime', 'asc');
if (hiddenNames.length > 0) {
query = query.where(eb => eb.not(eb(eb.fn('lower', ['account.username']), 'in', hiddenNames)));
}
rows = await query.execute();
} else {
let query = db
.selectFrom('hiscore')
.innerJoin('account', 'account.id', 'hiscore.account_id')
.select(['account.username', 'hiscore.level', 'hiscore.playtime'])
.where('hiscore.type', '=', category)
.where('hiscore.profile', '=', profile)
.where('account.staffmodlevel', '<=', 1)
.orderBy('hiscore.level', 'desc')
.orderBy('hiscore.playtime', 'asc');
if (hiddenNames.length > 0) {
query = query.where(eb => eb.not(eb(eb.fn('lower', ['account.username']), 'in', hiddenNames)));
}
rows = await query.execute();
}
rankedCache.set(key, { at: Date.now(), rows, pending: null });
return rows;
})();
rankedCache.set(key, { at: cached?.at ?? 0, rows: cached?.rows ?? [], pending: load });
try {
return await load;
} catch (err) {
rankedCache.delete(key);
throw err;
}
}
// rank of a player in a ranked list (1-based), or null when absent
function rankIn(rows: RankedRow[], username: string): number | null {
const lower = username.toLowerCase();
const idx = rows.findIndex(r => r.username.toLowerCase() === lower);
return idx === -1 ? null : idx + 1;
}
// Player profile page handler
export async function handleHiscoresPlayerPage(url: URL): Promise<Response | null> {
const match = url.pathname.match(/^\/hi(?:gh)?scores\/player\/([^/]+)\/?$/);
@@ -87,22 +156,11 @@ export async function handleHiscoresPlayerPage(url: URL): Promise<Response | nul
// Get overall stats
const overallStats = await db.selectFrom('hiscore_large').select(['level', 'value', 'playtime']).where('account_id', '=', account.id).where('profile', '=', profile).where('type', '=', 0).executeTakeFirst();
// Get overall rank (by level DESC, playtime ASC)
// Get overall rank (by level DESC, playtime ASC) from the cached ranked list
let overallRank = '-';
if (overallStats) {
let rankQuery = db
.selectFrom('hiscore_large')
.innerJoin('account', 'account.id', 'hiscore_large.account_id')
.select(db.fn.count('hiscore_large.account_id').as('rank'))
.where('hiscore_large.type', '=', 0)
.where('hiscore_large.profile', '=', profile)
.where('account.staffmodlevel', '<=', 1)
.where(eb => eb.or([eb('hiscore_large.level', '>', overallStats.level), eb.and([eb('hiscore_large.level', '=', overallStats.level), eb('hiscore_large.playtime', '<', overallStats.playtime)])]));
if (hiddenNames.length > 0) {
rankQuery = rankQuery.where(eb => eb.not(eb(eb.fn('lower', ['account.username']), 'in', hiddenNames)));
}
const rankResult = await rankQuery.executeTakeFirst();
overallRank = String((Number(rankResult?.rank) || 0) + 1);
const rank = rankIn(await getRankedList(profile, 0), account.username);
overallRank = rank ? String(rank) : '-';
}
// Get individual skill stats
@@ -127,19 +185,8 @@ export async function handleHiscoresPlayerPage(url: URL): Promise<Response | nul
let rank = '-';
if (stat) {
let skillRankQuery = db
.selectFrom('hiscore')
.innerJoin('account', 'account.id', 'hiscore.account_id')
.select(db.fn.count('hiscore.account_id').as('rank'))
.where('hiscore.type', '=', skill.id + 1)
.where('hiscore.profile', '=', profile)
.where('account.staffmodlevel', '<=', 1)
.where(eb => eb.or([eb('hiscore.level', '>', stat.level), eb.and([eb('hiscore.level', '=', stat.level), eb('hiscore.playtime', '<', stat.playtime)])]));
if (hiddenNames.length > 0) {
skillRankQuery = skillRankQuery.where(eb => eb.not(eb(eb.fn('lower', ['account.username']), 'in', hiddenNames)));
}
const rankResult = await skillRankQuery.executeTakeFirst();
rank = String((Number(rankResult?.rank) || 0) + 1);
const r = rankIn(await getRankedList(profile, skill.id + 1), account.username);
rank = r ? String(r) : '-';
}
const iconFile = skill.name.toLowerCase() + '.png';
@@ -261,21 +308,8 @@ export async function handleHiscoresPage(url: URL): Promise<Response | null> {
let searchedPlayer: { rank: number; username: string; level: number; playtime: number } | null = null;
if (category === -1 || category === 0) {
// Overall - query hiscore_large
let query = db
.selectFrom('hiscore_large')
.innerJoin('account', 'account.id', 'hiscore_large.account_id')
.select(['account.username', 'hiscore_large.level', 'hiscore_large.playtime'])
.where('hiscore_large.type', '=', 0)
.where('hiscore_large.profile', '=', profile)
.where('account.staffmodlevel', '<=', 1)
.orderBy('hiscore_large.level', 'desc')
.orderBy('hiscore_large.playtime', 'asc');
if (hiddenNames.length > 0) {
query = query.where(eb => eb.not(eb(eb.fn('lower', ['account.username']), 'in', hiddenNames)));
}
const allResults = await query.execute();
// Overall - cached ranked list of hiscore_large
const allResults = await getRankedList(profile, 0);
// Handle rank search - show 21 entries starting from that rank
const startRank = rankSearch > 0 ? rankSearch - 1 : 0;
@@ -299,20 +333,7 @@ export async function handleHiscoresPage(url: URL): Promise<Response | null> {
const skillIndex = category - 1;
const skillName = SKILL_NAMES[skillIndex];
if (skillName) {
let query = db
.selectFrom('hiscore')
.innerJoin('account', 'account.id', 'hiscore.account_id')
.select(['account.username', 'hiscore.level', 'hiscore.playtime'])
.where('hiscore.type', '=', category)
.where('hiscore.profile', '=', profile)
.where('account.staffmodlevel', '<=', 1)
.orderBy('hiscore.level', 'desc')
.orderBy('hiscore.playtime', 'asc');
if (hiddenNames.length > 0) {
query = query.where(eb => eb.not(eb(eb.fn('lower', ['account.username']), 'in', hiddenNames)));
}
const allResults = await query.execute();
const allResults = await getRankedList(profile, category);
const startRank = rankSearch > 0 ? rankSearch - 1 : 0;
rows = allResults.slice(startRank, startRank + 21).map((r, i) => ({
+44
View File
@@ -0,0 +1,44 @@
// Local load generator: log N idle lite sessions into a server so the engine can be
// profiled with many players (fresh accounts all spawn on the same tile, which
// reproduces a stacked crowd). Pair with the management endpoints:
// curl localhost:8898/tickstats ; curl 'localhost:8898/profile?ms=3000'
//
// cd server/webclient
// bun src/lite/loadtest.ts --n=300 [--host=localhost:8888] [--prefix=load] [--minutes=10]
import { startSession, type LiteSession } from './session.js';
const args = new Map<string, string>();
for (const a of process.argv.slice(2)) {
const m = a.match(/^--([^=]+)=(.*)$/);
if (m) args.set(m[1], m[2]);
}
const n = Number(args.get('n') ?? 100);
const host = args.get('host') ?? 'localhost:8888';
const prefix = args.get('prefix') ?? 'load';
const minutes = Number(args.get('minutes') ?? 10);
const batch = Number(args.get('batch') ?? 10);
const sessions: LiteSession[] = [];
let failed = 0;
const t0 = Date.now();
for (let i = 0; i < n; i += batch) {
const wave = [];
for (let j = i; j < Math.min(n, i + batch); j++) {
const username = `${prefix}${String(j).padStart(3, '0')}`;
wave.push(
startSession({ host, username, password: 'loadtest', quiet: true, profanityFilter: false })
.then(s => sessions.push(s))
.catch(err => {
failed++;
console.error(`[loadtest] ${username}: ${err instanceof Error ? err.message : err}`);
})
);
}
await Promise.all(wave);
console.log(`[loadtest] ${sessions.length} in game, ${failed} failed (${((Date.now() - t0) / 1000).toFixed(0)}s)`);
}
console.log(`[loadtest] holding ${sessions.length} sessions for ${minutes} min`);
await Bun.sleep(minutes * 60_000);
for (const s of sessions) s.stop();
console.log('[loadtest] done');