diff --git a/.changeset/core-plugin-startup-duration-name.md b/.changeset/core-plugin-startup-duration-name.md new file mode 100644 index 0000000000..417dbe0651 --- /dev/null +++ b/.changeset/core-plugin-startup-duration-name.md @@ -0,0 +1,19 @@ +--- +"@objectstack/core": minor +--- + +Plugin startup elapsed time is now reported as `duration` — the name the spec contract for the same result already declares. `startTime`, which never held a start time, is deprecated and still populated. + +`PluginStartupResult.startTime` (`packages/core/src/plugin-loader.ts`) has always been assigned `Date.now() - startTime`, an elapsed duration, on both the success and the failure path. The name therefore asserts the opposite of the value: a reader who correctly takes `startTime` for an instant and writes `Date.now() - result.startTime` gets an age near the epoch rather than a wait. That is the one failure mode a unit convention cannot rescue — an ambiguous name makes someone stop and check, this one lets them proceed confidently wrong. + +This is not a naming preference but a divergence between what is declared and what is enforced. `packages/spec/src/kernel/startup-orchestrator.zod.ts` declares `duration: z.number().min(0)` — "Time taken to start the plugin in milliseconds" — for the same measure on the same result, the outcome of starting one plugin. The contract surface was already correct and `packages/core` had drifted away from it. The right spelling is also twelve lines above the defect in the same file: `PluginLoadResult.loadTime` carries the identical `Date.now() - startTime` computation under a name that does not lie. + +Three sites move, and every one of them is additive — nothing is removed, so no consumer has to change anything on this release: + +- `PluginStartupResult` gains `duration?: number`. `startTime?: number` stays, still carrying the same value, marked `@deprecated` with a doc comment that states plainly it is elapsed milliseconds and not an instant. +- `ObjectKernel.getPluginStartupDurations()` is added; `getPluginMetrics()` becomes a `@deprecated` delegating alias returning the same map. +- The private `pluginStartTimes` map is renamed `pluginStartupDurations` (private; no reader outside `kernel.ts` in this repo or in the pinned `objectui` sibling). + +Migration, where you want it: read `result.duration` where you read `result.startTime`, and `kernel.getPluginStartupDurations()` where you called `kernel.getPluginMetrics()`. The values are identical, so the change can be made at leisure; both old spellings keep working until they are removed. + +ADR-0087 disposition: no migration-ledger entry, and none is required. Nothing is retired by this release — the old member and the old method both remain, populated and callable, which is ADR-0087's L1 outcome (the old shape keeps loading while the fleet moves) rather than a retirement. There is also nothing for `objectstack migrate meta` to rewrite: `packages/core/src/plugin-loader.ts#PluginStartupResult` is a runtime TypeScript interface with no Zod schema, no `packages/spec` declaration and no stored representation — the `PluginStartupResult` in `packages/spec/src/kernel/startup-orchestrator.zod.ts` is a separate, differently-shaped declaration that this change does not touch. When the deprecated spellings are removed, that removal is the change that carries the ledger disposition. diff --git a/packages/core/ADVANCED_FEATURES.md b/packages/core/ADVANCED_FEATURES.md index a949cfb106..54bfc036c2 100644 --- a/packages/core/ADVANCED_FEATURES.md +++ b/packages/core/ADVANCED_FEATURES.md @@ -223,14 +223,15 @@ for (const [pluginName, health] of allHealth) { ### 7. Performance Metrics -Track plugin startup times: +Track plugin startup durations -- the map values are elapsed milliseconds, +not start instants: ```typescript await kernel.bootstrap(); -const metrics = kernel.getPluginMetrics(); -for (const [pluginName, startTime] of metrics) { - console.log(`${pluginName}: ${startTime}ms`); +const durations = kernel.getPluginStartupDurations(); +for (const [pluginName, duration] of durations) { + console.log(`${pluginName}: ${duration}ms`); } // plugin-1: 150ms // plugin-2: 320ms @@ -327,7 +328,8 @@ Both kernels adhere to the same `Plugin` interface, but `ObjectKernel` supports - `async shutdown(): Promise` - `async checkPluginHealth(pluginName: string): Promise` - `async checkAllPluginsHealth(): Promise>` -- `getPluginMetrics(): Map` +- `getPluginStartupDurations(): Map` +- `getPluginMetrics(): Map` *(deprecated alias of the above)* - `async getServiceAsync(name: string, scopeId?: string): Promise` - `onShutdown(handler: () => Promise): void` - `getState(): string` diff --git a/packages/core/examples/kernel-features-example.ts b/packages/core/examples/kernel-features-example.ts index a6466bf58d..f0da416669 100644 --- a/packages/core/examples/kernel-features-example.ts +++ b/packages/core/examples/kernel-features-example.ts @@ -232,11 +232,11 @@ async function main() { console.log('\n✅ Kernel started successfully!\n'); - // Show plugin metrics - console.log('📊 Plugin Startup Metrics:'); - const metrics = kernel.getPluginMetrics(); - for (const [name, time] of metrics) { - console.log(` ${name}: ${time}ms`); + // Show plugin startup durations (elapsed ms, not start instants) + console.log('📊 Plugin Startup Durations:'); + const durations = kernel.getPluginStartupDurations(); + for (const [name, duration] of durations) { + console.log(` ${name}: ${duration}ms`); } console.log(''); diff --git a/packages/core/src/kernel.test.ts b/packages/core/src/kernel.test.ts index 2d5e38f477..67f98858a0 100644 --- a/packages/core/src/kernel.test.ts +++ b/packages/core/src/kernel.test.ts @@ -1,6 +1,7 @@ import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; import { ObjectKernel } from './kernel'; import { ServiceLifecycle, PluginMetadata } from './plugin-loader'; +import type { PluginStartupResult } from './plugin-loader'; import type { Plugin, PluginContext } from './types'; import { recordGuards, stillPinningTheLoop } from '@objectstack/refd-timer-testkit'; @@ -582,6 +583,77 @@ describe('ObjectKernel', () => { await kernel.shutdown(); }); + + // These two pin the MEANING of the number, not merely that one is + // present. The result member carrying it was spelled `startTime` while + // holding `Date.now() - start`, so a reader who correctly took it for an + // instant and wrote `Date.now() - result.startTime` got an age near the + // epoch. `toBeGreaterThan(0)` cannot tell the two readings apart -- an + // epoch-millisecond instant passes it too. A ceiling can: any instant + // today is ~1.7e12, orders of magnitude above any plugin's start(). + const INSTANT_FLOOR_MS = 1_000_000_000; // ~11.5 days as a duration; well below any real epoch-ms instant + + it('getPluginStartupDurations reports elapsed durations, not start instants', async () => { + const plugin: Plugin = { + name: 'timed-plugin', + version: '1.0.0', + init: async () => {}, + start: async () => { + await new Promise(resolve => setTimeout(resolve, 20)); + }, + }; + + await kernel.use(plugin); + await kernel.bootstrap(); + + const durations = kernel.getPluginStartupDurations(); + const value = durations.get('timed-plugin'); + + expect(value).toBeGreaterThan(0); + expect(value).toBeLessThan(INSTANT_FLOOR_MS); + // The deprecated alias is the same map, so it must agree. + expect(kernel.getPluginMetrics().get('timed-plugin')).toBe(value); + + await kernel.shutdown(); + }); + + it('PluginStartupResult.duration is an elapsed duration on both the success and the failure path', async () => { + const callStart = (meta: PluginMetadata): Promise => + (kernel as unknown as { + startPluginWithTimeout(p: PluginMetadata): Promise; + }).startPluginWithTimeout(meta); + + const okMeta: PluginMetadata = { + name: 'ok-plugin', + version: '1.0.0', + init: async () => {}, + start: async () => { + await new Promise(resolve => setTimeout(resolve, 20)); + }, + }; + const ok = await callStart(okMeta); + + expect(ok.success).toBe(true); + expect(ok.duration).toBeGreaterThan(0); + expect(ok.duration).toBeLessThan(INSTANT_FLOOR_MS); + // The deprecated alias carries the same elapsed value, not an instant. + expect(ok.startTime).toBe(ok.duration); + + const failingMeta: PluginMetadata = { + name: 'failing-plugin', + version: '1.0.0', + init: async () => {}, + start: async () => { + throw new Error('boom'); + }, + }; + const failed = await callStart(failingMeta); + + expect(failed.success).toBe(false); + expect(failed.duration).toBeGreaterThanOrEqual(0); + expect(failed.duration).toBeLessThan(INSTANT_FLOOR_MS); + expect(failed.startTime).toBe(failed.duration); + }); }); describe('Graceful Shutdown', () => { diff --git a/packages/core/src/kernel.ts b/packages/core/src/kernel.ts index 81a869b5f1..7285dfcb54 100644 --- a/packages/core/src/kernel.ts +++ b/packages/core/src/kernel.ts @@ -66,7 +66,12 @@ export class ObjectKernel { private pluginLoader: PluginLoader; private config: ObjectKernelConfig; private startedPlugins: Set = new Set(); - private pluginStartTimes: Map = new Map(); + /** + * Plugin name -> elapsed milliseconds that plugin's `start()` took. These + * are DURATIONS, never start instants; the old spelling `pluginStartTimes` + * said the opposite of what it held. + */ + private pluginStartupDurations: Map = new Map(); private shutdownHandlers: Array<() => Promise> = []; /** * Name of the plugin whose init() is currently executing (Phase 1 is @@ -533,11 +538,24 @@ export class ObjectKernel { return results; } + /** + * Per-plugin startup durations: plugin name -> elapsed milliseconds that + * plugin's `start()` took. Not start instants -- see + * {@link PluginStartupResult.duration}. + */ + getPluginStartupDurations(): Map { + return new Map(this.pluginStartupDurations); + } + /** * Get plugin startup metrics + * + * @deprecated Renamed to {@link ObjectKernel.getPluginStartupDurations}, + * which states what the values are. Retained as a delegating alias so + * nothing has to change on this release; slated for removal. */ getPluginMetrics(): Map { - return new Map(this.pluginStartTimes); + return this.getPluginStartupDurations(); } /** @@ -684,13 +702,16 @@ export class ObjectKernel { const duration = Date.now() - startTime; this.startedPlugins.add(plugin.name); - this.pluginStartTimes.set(plugin.name, duration); + this.pluginStartupDurations.set(plugin.name, duration); this.logger.debug(`Plugin started: ${plugin.name} (${duration}ms)`); return { success: true, pluginName: plugin.name, + duration, + // Deprecated alias carrying the same elapsed value; see + // PluginStartupResult.startTime. startTime: duration, }; } catch (error) { @@ -701,6 +722,9 @@ export class ObjectKernel { success: false, pluginName: plugin.name, error: error as Error, + duration, + // Deprecated alias carrying the same elapsed value; see + // PluginStartupResult.startTime. startTime: duration, timedOut: isTimeout, }; diff --git a/packages/core/src/plugin-loader.ts b/packages/core/src/plugin-loader.ts index 24c3c31c51..13c93e4fca 100644 --- a/packages/core/src/plugin-loader.ts +++ b/packages/core/src/plugin-loader.ts @@ -91,6 +91,26 @@ export interface PluginLoadResult { export interface PluginStartupResult { success: boolean; pluginName: string; + /** + * Elapsed milliseconds the plugin's `start()` took. + * + * Named for the member `packages/spec` already declares for the same + * measure -- `PluginStartupResultSchema.duration` in + * `packages/spec/src/kernel/startup-orchestrator.zod.ts` ("Time taken to + * start the plugin in milliseconds") -- and matching `PluginLoadResult.loadTime` + * above: the same `Date.now() - startTime` computation under a name that + * does not lie. + */ + duration?: number; + /** + * The same elapsed milliseconds as {@link PluginStartupResult.duration}. + * + * @deprecated Misnamed: this has never held an instant, so a reader who + * correctly takes `startTime` for one and writes `Date.now() - result.startTime` + * gets an age near the epoch instead of a wait. Read `duration` instead. + * Still populated so nothing has to change on this release (ADR-0087 L1 -- + * the old shape keeps working while the fleet moves); slated for removal. + */ startTime?: number; error?: Error; timedOut?: boolean;