wip(perf): backend completed - tests pending

core/components/FxRunner/outputHandler.ts

@@ -102,6 +102,8 @@ export default class OutputHandler {
                     this.#txAdmin.healthMonitor.handleHeartBeat('fd3');
                 } else if (data.payload.type === 'txAdminLogData') {
                     this.#txAdmin.logger.server.write(data.payload.logs, mutex);
+                } else if (data.payload.type === 'txAdminLogNodeHeap') {
+                    this.#txAdmin.performanceCollector.logServerNodeMemory(data.payload);
                 } else if (data.payload.type === 'txAdminResourceEvent') {
                     this.#txAdmin.resourcesManager.handleServerEvents(data.payload, mutex);
                 } else if (data.payload.type === 'txAdminPlayerlistEvent') {

core/components/PerformanceCollector/index.ts

@@ -3,17 +3,41 @@ import fsp from 'node:fs/promises';
 import * as d3array from 'd3-array';
 import consoleFactory from '@extras/console';
 import type TxAdmin from '@core/txAdmin.js';
-import { PERF_DATA_BUCKET_COUNT, PERF_DATA_MIN_TICKS, SSFileSchema, isSSLogDataType } from './perfSchemas';
-import type { SSFileType, SSLogDataType, SSLogType, SSPerfBoundariesType, SSPerfCountsType } from './perfSchemas';
+import { LogNodeHeapEventSchema, SSFileSchema, isSSLogDataType } from './perfSchemas';
+import type { LogNodeHeapEventType, SSFileType, SSLogDataType, SSLogType, SSPerfBoundariesType, SSPerfCountsType } from './perfSchemas';
 import { diffPerfs, fetchFxsMemory, fetchRawPerfData, perfCountsToHist } from './perfUtils';
 import { optimizeStatsLog } from './statsLogOptimizer';
 import { convars } from '@core/globalData';
+import { ValuesType } from 'utility-types';
+import bytes from 'bytes';
 const console = consoleFactory(modulename);
 
 
 //Consts
+const minutesMs = 60 * 1000;
+const hoursMs = 60 * minutesMs;
+const megabyte = 1024 * 1024;
+
+
+/**
+ * Configs
+ */
 const STATS_DATA_FILE_VERSION = 1;
 const STATS_DATA_FILE_NAME = 'statsData.json';
+export const PERF_DATA_BUCKET_COUNT = 15;
+export const PERF_DATA_MIN_TICKS = 2000; //less than that and the data is not reliable
+export const PERF_DATA_INITIAL_RESOLUTION = 5 * minutesMs;
+export const STATS_RESOLUTION_TABLE = [
+    //00~12h =  5min = 12/h = 144 snaps
+    //12~24h = 15min =  4/h =  48 snaps
+    //24~96h = 30min =  2/h = 144 snaps
+    { maxAge: 12 * hoursMs, resolution: PERF_DATA_INITIAL_RESOLUTION },
+    { maxAge: 24 * hoursMs, resolution: 15 * minutesMs },
+    { maxAge: 96 * hoursMs, resolution: 30 * minutesMs },
+];
+export const STATS_LOG_SIZE_LIMIT = 720; //144+48+144 (max data snaps) + 384 (1 reboot every 30 mins)
+export const PERF_DATA_THREAD_NAMES = ['svNetwork', 'svSync', 'svMain'] as const;
+export type PerfDataThreadNamesType = ValuesType<typeof PERF_DATA_THREAD_NAMES>;
 
 
 /**
@@ -24,11 +48,14 @@ export default class PerformanceCollector {
     readonly #txAdmin: TxAdmin;
     private readonly statsDataPath: string;
     private statsLog: SSLogType = [];
+    private lastFxsMemory: number | undefined;
+    private lastNodeMemory: { used: number, total: number } | undefined;
     private lastPerfBoundaries: SSPerfBoundariesType | undefined;
     private lastPerfCounts: SSPerfCountsType | undefined;
-    private lastPerfCountsSaved: SSPerfCountsType | undefined;
-    private lastNodeMemory: { used: number, total: number } | undefined;
-    private lastFxsMemory: number | undefined;
+    private lastPerfSaved: {
+        ts: number,
+        counts: SSPerfCountsType,
+    } | undefined;
 
     constructor(txAdmin: TxAdmin) {
         this.#txAdmin = txAdmin;
@@ -45,30 +72,72 @@ export default class PerformanceCollector {
     }
 
 
+    /**
+     * Reset the last perf data except boundaries
+     */
+    resetPerfState() {
+        this.lastPerfCounts = undefined;
+        this.lastPerfSaved = undefined;
+        this.lastNodeMemory = undefined;
+        this.lastFxsMemory = undefined;
+    }
+
+
     /**
      * Registers that fxserver has BOOTED (healthMonitor is ONLINE)
      */
     logServerBoot(bootTime: number) {
-        //TODO: if last log is a boot, remove it as the server didn't really start if it didn't live enough to have the stats logged
-        //FIXME: do we need any other kind of logic?
+        this.resetPerfState();
+        //If last log is a boot, remove it as the server didn't really start 
+        // otherwise it would have lived long enough to have stats logged
+        if (this.statsLog.length && this.statsLog.at(-1)!.type === 'svBoot') {
+            this.statsLog.pop();
+        }
+        this.statsLog.push({
+            ts: Date.now(),
+            type: 'svBoot',
+            bootTime,
+        });
     }
 
 
     /**
      * Registers that fxserver has CLOSED (fxRunner killing the process)
      */
     logServerClose(reason: string) {
-        //TODO: if last log is not of data type, don't even register it?
-        //FIXME: do we need any other kind of logic?
+        this.resetPerfState();
+        if (this.statsLog.length) {
+            if (this.statsLog.at(-1)!.type === 'svClose') {
+                //If last log is a close, skip saving a new one
+                return;
+            } else if (this.statsLog.at(-1)!.type === 'svBoot') {
+                //If last log is a boot, remove it as the server didn't really start
+                this.statsLog.pop();
+                return;
+            }
+        }
+        this.statsLog.push({
+            ts: Date.now(),
+            type: 'svClose',
+            reason,
+        });
     }
 
 
     /**
      * Stores the last server Node.JS memory usage for later use in the data log 
      */
-    logServerNodeMemory(heapUsedBytes: number, heapTotalBytes: number) {
-        //FIXME: disabled for now
-        //TODO: convert to mb
+    logServerNodeMemory(payload: LogNodeHeapEventType) {
+        const validation = LogNodeHeapEventSchema.safeParse(payload);
+        if (!validation.success) {
+            console.verbose.warn('Invalid LogNodeHeapEvent payload:');
+            console.verbose.dir(validation.error.errors);
+            return;
+        }
+        this.lastNodeMemory = {
+            used: parseFloat((payload.heapUsed / megabyte).toFixed(2)),
+            total: parseFloat((payload.heapTotal / megabyte).toFixed(2)),
+        };
     }
 
 
@@ -123,36 +192,56 @@ export default class PerformanceCollector {
             return;
         }
 
-        //Check if first collection, boundaries changed, or counter (somehow) reset
-        if (!this.lastPerfCounts || !this.lastPerfBoundaries) {
-            console.verbose.log('First perf collection');
+        //Check if first collection, boundaries changed
+        if (!this.lastPerfCounts || !this.lastPerfSaved || !this.lastPerfBoundaries) {
+            console.verbose.debug('First perf collection.');
             this.lastPerfBoundaries = perfBoundaries;
+            this.resetPerfState();
         } else if (JSON.stringify(perfBoundaries) !== JSON.stringify(this.lastPerfBoundaries)) {
             console.warn('Performance boundaries changed. Resetting history.');
             this.statsLog = [];
             this.lastPerfBoundaries = perfBoundaries;
-            this.lastPerfCounts = undefined;
-            this.lastPerfCountsSaved = undefined;
-        } else if (this.lastPerfCounts.svMain.count > perfMetrics.svMain.count) {
-            console.warn('Performance counter reset. Resetting lastPerfCounts.');
-            this.lastPerfCounts = undefined;
-            this.lastPerfCountsSaved = undefined;
+            this.resetPerfState();
+        }
+
+        //Checking if the counter (somehow) reset
+        if (this.lastPerfCounts && this.lastPerfCounts.svMain.count > perfMetrics.svMain.count) {
+            console.warn('Performance counter reset. Resetting lastPerfCounts/lastPerfSaved.');
+            this.resetPerfState();
+        } else if (this.lastPerfSaved && this.lastPerfSaved.counts.svMain.count > perfMetrics.svMain.count) {
+            console.warn('Performance counter reset. Resetting lastPerfSaved.');
+            this.lastPerfSaved = undefined;
         }
 
-        //Calculate the tick/time counts since last epoch
-        const currPerfCountsDiff = diffPerfs(perfMetrics, this.lastPerfCounts);
-        const currPerfHist = perfCountsToHist(currPerfCountsDiff);
+        //Calculate the tick/time counts since last collection (1m ago)
+        const latestPerfHist = perfCountsToHist(diffPerfs(perfMetrics, this.lastPerfCounts));
+        this.lastPerfCounts = perfMetrics;
 
-        //Update cache
+        //Check if enough time passed since last collection
         const now = Date.now();
-        this.lastPerfCounts = perfMetrics;
+        let perfHistToSave;
+        if (!this.lastPerfSaved) {
+            perfHistToSave = latestPerfHist;
+        } else if (now - this.lastPerfSaved.ts >= PERF_DATA_INITIAL_RESOLUTION) {
+            perfHistToSave = perfCountsToHist(diffPerfs(perfMetrics, this.lastPerfSaved.counts));
+        }
+        if (!perfHistToSave) {
+            console.verbose.debug('Not enough time passed since last saved collection. Skipping save.');
+            return;
+        }
+
+        //Update cache
+        this.lastPerfSaved = {
+            ts: now,
+            counts: perfMetrics,
+        };
         const currSnapshot: SSLogDataType = {
             ts: now,
             type: 'data',
             players: this.#txAdmin.playerlistManager.onlineCount,
             fxsMemory: this.lastFxsMemory ?? null,
             nodeMemory: this.lastNodeMemory?.used ?? null,
-            perf: currPerfHist,
+            perf: perfHistToSave,
         };
         this.statsLog.push(currSnapshot);
         await optimizeStatsLog(this.statsLog);
@@ -161,7 +250,6 @@ export default class PerformanceCollector {
         const savePerfData: SSFileType = {
             version: STATS_DATA_FILE_VERSION,
             lastPerfBoundaries: this.lastPerfBoundaries,
-            lastPerfCounts: this.lastPerfCounts,
             log: this.statsLog,
         };
         await fsp.writeFile(this.statsDataPath, JSON.stringify(savePerfData));
@@ -179,9 +267,8 @@ export default class PerformanceCollector {
             if (fileData?.version !== STATS_DATA_FILE_VERSION) throw new Error('invalid version');
             const statsData = await SSFileSchema.parseAsync(fileData);
             this.lastPerfBoundaries = statsData.lastPerfBoundaries;
-            this.lastPerfCounts = statsData.lastPerfCounts;
-            this.lastPerfCountsSaved = statsData.lastPerfCounts;
             this.statsLog = statsData.log;
+            this.resetPerfState();
             console.verbose.debug(`Loaded ${this.statsLog.length} performance snapshots from cache`);
             optimizeStatsLog(this.statsLog);
         } catch (error) {

core/components/PerformanceCollector/perfParser.ts

@@ -1,4 +1,5 @@
-import { PERF_DATA_BUCKET_COUNT, isValidPerfThreadName, type SSPerfBoundariesType, type SSPerfCountsType } from "./perfSchemas";
+import { PERF_DATA_BUCKET_COUNT } from "./index";
+import { isValidPerfThreadName, type SSPerfBoundariesType, type SSPerfCountsType } from "./perfSchemas";
 
 
 //Consts

core/components/PerformanceCollector/perfSchemas.ts

@@ -1,14 +1,6 @@
-import { ValuesType } from 'utility-types';
 import * as z from 'zod';
-
-
-/**
- * Consts
- */
-export const PERF_DATA_BUCKET_COUNT = 15;
-export const PERF_DATA_MIN_TICKS = 2000; //less than that and the data is not reliable
-export const PERF_DATA_THREAD_NAMES = ['svNetwork', 'svSync', 'svMain'] as const;
-export type PerfDataThreadNamesType = ValuesType<typeof PERF_DATA_THREAD_NAMES>;
+import { PERF_DATA_BUCKET_COUNT, PERF_DATA_THREAD_NAMES, PerfDataThreadNamesType } from './index';
+import { ValuesType } from 'utility-types';
 
 
 /**
@@ -83,10 +75,14 @@ export const SSLogSvCloseSchema = z.object({
 export const SSFileSchema = z.object({
     version: z.literal(1),
     lastPerfBoundaries: SSPerfBoundariesSchema,
-    lastPerfCounts: SSPerfCountsSchema,
     log: z.array(z.union([SSLogDataSchema, SSLogSvBootSchema, SSLogSvCloseSchema])),
 });
 
+export const LogNodeHeapEventSchema = z.object({
+    heapUsed: zIntNonNegative,
+    heapTotal: zIntNonNegative,
+});
+
 
 //Exporting types
 export type SSFileType = z.infer<typeof SSFileSchema>;
@@ -97,3 +93,4 @@ export type SSLogType = (SSLogSvCloseType | SSLogSvBootType | SSLogDataType)[];
 export type SSPerfHistType = z.infer<typeof SSPerfHistSchema>;
 export type SSPerfCountsType = z.infer<typeof SSPerfCountsSchema>;
 export type SSPerfBoundariesType = z.infer<typeof SSPerfBoundariesSchema>;
+export type LogNodeHeapEventType = z.infer<typeof LogNodeHeapEventSchema>;

core/components/PerformanceCollector/perfUtils.ts

@@ -1,9 +1,9 @@
 import { cloneDeep } from 'lodash-es';
-import { PERF_DATA_BUCKET_COUNT } from "./perfSchemas";
-import type { SSPerfCountsType, SSPerfHistType, PerfDataThreadNamesType } from "./perfSchemas";
+import type { SSPerfCountsType, SSPerfHistType } from "./perfSchemas";
 import got from '@core/extras/got.js';
 import { parseRawPerf } from './perfParser';
 import { getProcessesData } from '@core/webroutes/diagnostics/diagnosticsFuncs';
+import { PERF_DATA_BUCKET_COUNT, PerfDataThreadNamesType } from './index';
 
 
 //Consts

core/components/PerformanceCollector/statsLogOptimizer.ts

@@ -1,17 +1,7 @@
+import { STATS_LOG_SIZE_LIMIT, STATS_RESOLUTION_TABLE } from "./index";
 import type { SSLogType } from "./perfSchemas";
 
 //Consts
-const minutesMs = 60 * 1000;
-const hoursMs = 60 * minutesMs;
-const STATS_RESOLUTION_TABLE = [
-     //00~12h =  5m = 12/h = 144 snaps
-     //12~24h = 15m =  4/h =  48 snaps
-     //24~96h = 30m =  2/h = 144 snaps
-     { maxAge: 12 * hoursMs, resolution: 5 * minutesMs },
-     { maxAge: 24 * hoursMs, resolution: 15 * minutesMs },
-     { maxAge: 96 * hoursMs, resolution: 30 * minutesMs },
-];
-const STATS_LOG_SIZE_LIMIT = 720; //144+48+144 (max data snaps) + 384 (1 reboot every 30 mins)
 const YIELD_INTERVAL = 100;
 
 

core/extras/testEnv.ts

@@ -49,12 +49,15 @@ vi.stubGlobal('GetResourcePath', (resourceName: string) => {
 vi.stubGlobal('IsDuplicityVersion', () => {
     return true;
 });
-vi.stubGlobal('VerifyPasswordHash', (password: string, hash: string) => {
-    return true;
+vi.stubGlobal('PrintStructuredTrace', (payload: string) => {
+    //noop
 });
 vi.stubGlobal('ScanResourceRoot', (rootPath: string, callback: (data: object) => void) => {
     throw new Error(`not implemented`);
 });
+vi.stubGlobal('VerifyPasswordHash', (password: string, hash: string) => {
+    return true;
+});
 vi.stubGlobal('Intl.getCanonicalLocales', (locales?: string | readonly string[] | undefined) => {
     return Array.isArray(locales) ? locales : [locales];
 });

core/types/global.d.ts

@@ -19,8 +19,9 @@ declare function GetPasswordHash(password: string): string;
 declare function GetResourceMetadata(resourceName: string, metadataKey: string, index: number): string;
 declare function GetResourcePath(resourceName: string): string;
 declare function IsDuplicityVersion(): boolean;
-declare function VerifyPasswordHash(password: string, hash: string): boolean;
+declare function PrintStructuredTrace(payload: string): void;
 declare function ScanResourceRoot(rootPath: string, callback: (data: object) => void): boolean;
+declare function VerifyPasswordHash(password: string, hash: string): boolean;
 
 declare namespace Intl {
     function getCanonicalLocales(locales: string | string[]): string[];

entrypoint.js

@@ -15,7 +15,7 @@ try {
     if (GetConvar('monitorMode', 'false') == 'true') {
         require('./core/index.js');
     } else if (GetConvar('txAdminServerMode', 'false') == 'true') {
-        //Nothing, for now
+        require('./resource/sv_reportHeap.js');
     }
 } catch (error) {
     //Prevent any async console.log messing with the output

resource/sv_reportHeap.js

@@ -0,0 +1,13 @@
+setInterval(() => {
+    try {
+        const { heapUsed, heapTotal } = process.memoryUsage();
+        PrintStructuredTrace(JSON.stringify({
+            type: 'txAdminLogNodeHeap',
+            heapUsed,
+            heapTotal,
+        }));
+    } catch (error) {
+        const msg = `Error reporting heap: ${error.message}`;
+        console.log(`^5[txAdmin]^1${msg}^0`);
+    }
+}, 15_000);