diff --git a/server/engine/src/engine/World.ts b/server/engine/src/engine/World.ts index bd54e0873..757fb16b2 100644 --- a/server/engine/src/engine/World.ts +++ b/server/engine/src/engine/World.ts @@ -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 { + 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 = {}; + const peak: Record = {}; + 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 = {}; + 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; diff --git a/server/engine/src/server/login/LoginServer.ts b/server/engine/src/server/login/LoginServer.ts index 5cf33a951..0e07e7bc1 100644 --- a/server/engine/src/server/login/LoginServer.ts +++ b/server/engine/src/server/login/LoginServer.ts @@ -242,6 +242,11 @@ export default class LoginServer { // In-memory tracking of concurrent logins per IP private ipLoginCount: Map> = new Map(); private accountIp: Map = 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 = 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') diff --git a/server/engine/src/web/index.ts b/server/engine/src/web/index.ts index 23a33557e..ec490eec7 100644 --- a/server/engine/src/web/index.ts +++ b/server/engine/src/web/index.ts @@ -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 = new Map(); +let webLastWindow: { start: number; end: number; routes: Record } | 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({ 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 { // 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(); + const leafPairs = new Map(); + for (const t of traces) { + const seen = new Set(); + 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) => [...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 }); diff --git a/server/engine/src/web/pages/hiscores.ts b/server/engine/src/web/pages/hiscores.ts index 645c5b1f0..c6a527c7a 100644 --- a/server/engine/src/web/pages/hiscores.ts +++ b/server/engine/src/web/pages/hiscores.ts @@ -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 | null }>(); + +// category 0 = overall (hiscore_large type 0), otherwise hiscore type = category +async function getRankedList(profile: string, category: number): Promise { + 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 { const match = url.pathname.match(/^\/hi(?:gh)?scores\/player\/([^/]+)\/?$/); @@ -87,22 +156,11 @@ export async function handleHiscoresPlayerPage(url: URL): Promise', 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', 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 { 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 { 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) => ({ diff --git a/server/webclient/src/lite/loadtest.ts b/server/webclient/src/lite/loadtest.ts new file mode 100644 index 000000000..ba8332c94 --- /dev/null +++ b/server/webclient/src/lite/loadtest.ts @@ -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(); +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');