basant307/AI_Governance_Project

1/**2 * @license3 * Copyright 2025 Google LLC4 * SPDX-License-Identifier: Apache-2.05 */6 7/**8 * Lightweight startup performance profiler.9 *10 * Activated by setting QWEN_CODE_PROFILE_STARTUP=1. When enabled, collects11 * high-resolution timestamps at key phases of CLI startup and writes a JSON12 * report to ~/.qwen/startup-perf/ on finalization.13 *14 * Usage (already wired in index.ts / gemini.tsx):15 *   initStartupProfiler()        — call once at process start to record T016 *   profileCheckpoint('name')    — call at each phase boundary (sequential)17 *   recordStartupEvent('name', attrs?) — record a discrete event (multi-fire allowed)18 *   finalizeStartupProfile(id)   — call after last checkpoint to write report19 *20 * By default profiles inside the sandbox child process to avoid duplicate21 * reports. `qwen serve` has no sandbox child, so it is profiled directly.22 * Set QWEN_CODE_PROFILE_STARTUP_OUTER=1 to also profile the outer23 * (pre-sandbox) process for non-serve runs; outer reports are written with an24 * `outer-` filename prefix to keep them separate from sandbox-child reports.25 *26 * Zero overhead when disabled (single env var check).27 */28import * as fs from 'node:fs';29import * as os from 'node:os';30import * as path from 'node:path';31import { performance } from 'node:perf_hooks';32 33import type { StartupEventAttrs } from '@qwen-code/qwen-code-core';34import { isServeFastPathArgv } from '../serve/fast-path-argv.js';35 36interface Checkpoint {37  name: string;38  timestamp: number;39  heapUsedMb?: number;40}41 42export interface StartupPhase {43  name: string;44  startMs: number;45  durationMs: number;46  heapUsedMb?: number;47}48 49export interface StartupEvent {50  name: string;51  tMs: number;52  heapUsedMb?: number;53  attrs?: StartupEventAttrs;54}55 56/**57 * Derived phase summary, keyed by phase name. Values are absolute ms from T0.58 * Mirrors the spirit of Claude Code's PHASE_DEFINITIONS for nightly CI thresholds.59 * Only phases for which the underlying checkpoint/event was recorded appear.60 */61export type DerivedPhases = Partial<{62  /** Time from process start to T0 (covers V8 module-eval). */63  module_load: number;64  /** T0 → after_load_settings. */65  settings_time: number;66  /** after_load_settings → after_load_cli_config. */67  config_time: number;68  /** after_load_cli_config → after_initialize_app. */69  init_time: number;70  /** T0 → before_render. */71  pre_render: number;72  /** T0 → first_paint. */73  to_first_paint: number;74  /** T0 → input_enabled. (Real TTI.) */75  to_input_enabled: number;76  /** Duration of `config.initialize()` (interactive only). */77  config_initialize_dur: number;78  /** T0 → mcp_first_tool_registered. */79  mcp_first_tool: number;80  /** T0 → mcp_all_servers_settled. */81  mcp_all_settled: number;82  /** mcp_first_tool_registered → gemini_tools_updated lag. */83  gemini_tools_lag: number;84}>;85 86export interface StartupReport {87  timestamp: string;88  sessionId: string;89  /** Whether this run was an interactive UI startup. */90  interactiveMode: boolean;91  /** True when the report was produced by the outer (pre-sandbox) process. */92  outerProcess: boolean;93  /** Time from Node.js process start to T0 (initStartupProfiler call), covers module loading. */94  processUptimeAtT0Ms: number;95  totalMs: number;96  phases: StartupPhase[];97  events: StartupEvent[];98  /** True if the events list hit MAX_EVENTS and dropped some entries. */99  eventsTruncated: boolean;100  derivedPhases: DerivedPhases;101  nodeVersion: string;102  platform: string;103  arch: string;104}105 106let enabled = false;107let captureHeap = false;108let outerProcess = false;109let interactiveMode = false;110let t0 = 0;111let processUptimeAtT0Ms = 0;112let checkpoints: Checkpoint[] = [];113let events: StartupEvent[] = [];114let eventsTruncated = false;115let finalized = false;116 117// Defense-in-depth cap on the events list. Under normal flow `finalized`118// stops new events shortly after `input_enabled`. This bound only matters in119// pathological paths where finalize is bypassed (e.g. crash before the mount120// effect runs while MCP still emits server-ready events).121const MAX_EVENTS = 1024;122 123const HEAP_BYTES_TO_MB = 1 / (1024 * 1024);124 125function snapshotHeapMb(): number | undefined {126  if (!captureHeap) return undefined;127  try {128    return (129      Math.round(process.memoryUsage().heapUsed * HEAP_BYTES_TO_MB * 100) / 100130    );131  } catch {132    return undefined;133  }134}135 136export function initStartupProfiler(): void {137  // Reset any prior state so the function is idempotent.138  resetStartupProfiler();139 140  if (process.env['QWEN_CODE_PROFILE_STARTUP'] !== '1') {141    return;142  }143 144  const inSandboxChild = !!process.env['SANDBOX'];145  const outerOptIn = process.env['QWEN_CODE_PROFILE_STARTUP_OUTER'] === '1';146  const serveCommand = isServeFastPathArgv(process.argv.slice(2));147 148  // Non-serve outer (pre-sandbox) collection requires an explicit opt-in to149  // avoid accidentally producing duplicate reports. Serve has no sandbox child,150  // so the primary startup flag should collect in the current process.151  if (!inSandboxChild && !outerOptIn && !serveCommand) {152    return;153  }154 155  enabled = true;156  outerProcess = !inSandboxChild && !serveCommand;157  // Default to capturing heap snapshots at every checkpoint.158  // Disable with QWEN_CODE_PROFILE_STARTUP_NO_HEAP=1 when measuring the159  // Heisenberg overhead of the heap call itself.160  captureHeap = process.env['QWEN_CODE_PROFILE_STARTUP_NO_HEAP'] !== '1';161  finalized = false;162  processUptimeAtT0Ms = Math.round(process.uptime() * 1000 * 100) / 100;163  t0 = performance.now();164  checkpoints = [];165  events = [];166}167 168export function profileCheckpoint(name: string): void {169  if (!enabled || finalized) return;170  checkpoints.push({171    name,172    timestamp: performance.now(),173    heapUsedMb: snapshotHeapMb(),174  });175}176 177/**178 * Records a discrete startup event (allowed to fire multiple times).179 * Distinct from `profileCheckpoint` which is sequential and assumed unique.180 *181 * Once {@link finalizeStartupProfile} runs, further events are dropped to182 * keep memory bounded — long-running interactive sessions still call183 * `setTools()` (which emits `gemini_tools_updated`) for each MCP refresh.184 */185export function recordStartupEvent(186  name: string,187  attrs?: StartupEventAttrs,188): void {189  if (!enabled || finalized) return;190  if (events.length >= MAX_EVENTS) {191    eventsTruncated = true;192    return;193  }194  events.push({195    name,196    tMs: Math.round((performance.now() - t0) * 100) / 100,197    heapUsedMb: snapshotHeapMb(),198    ...(attrs ? { attrs } : {}),199  });200}201 202/**203 * Marks this run as an interactive UI startup. Affects derived phases and204 * is recorded in the report for downstream filtering.205 */206export function setInteractiveMode(value: boolean): void {207  if (!enabled) return;208  interactiveMode = value;209}210 211function findCheckpointMs(name: string): number | undefined {212  for (const cp of checkpoints) {213    if (cp.name === name) {214      return Math.round((cp.timestamp - t0) * 100) / 100;215    }216  }217  return undefined;218}219 220function findEventMs(name: string): number | undefined {221  for (const ev of events) {222    if (ev.name === name) return ev.tMs;223  }224  return undefined;225}226 227function computeDerivedPhases(): DerivedPhases {228  const out: DerivedPhases = {};229  out.module_load = processUptimeAtT0Ms;230 231  const afterSettings = findCheckpointMs('after_load_settings');232  if (afterSettings !== undefined) out.settings_time = afterSettings;233 234  const afterCfg = findCheckpointMs('after_load_cli_config');235  if (afterSettings !== undefined && afterCfg !== undefined) {236    out.config_time = Math.round((afterCfg - afterSettings) * 100) / 100;237  }238 239  const afterInit = findCheckpointMs('after_initialize_app');240  if (afterCfg !== undefined && afterInit !== undefined) {241    out.init_time = Math.round((afterInit - afterCfg) * 100) / 100;242  }243 244  const beforeRender = findCheckpointMs('before_render');245  if (beforeRender !== undefined) out.pre_render = beforeRender;246 247  const firstPaint = findCheckpointMs('first_paint');248  if (firstPaint !== undefined) out.to_first_paint = firstPaint;249 250  const inputEnabled = findCheckpointMs('input_enabled');251  if (inputEnabled !== undefined) out.to_input_enabled = inputEnabled;252 253  const ciStart = findCheckpointMs('config_initialize_start');254  const ciEnd = findCheckpointMs('config_initialize_end');255  if (ciStart !== undefined && ciEnd !== undefined) {256    out.config_initialize_dur = Math.round((ciEnd - ciStart) * 100) / 100;257  }258 259  const mcpFirst = findEventMs('mcp_first_tool_registered');260  if (mcpFirst !== undefined) out.mcp_first_tool = mcpFirst;261 262  const mcpSettled = findEventMs('mcp_all_servers_settled');263  if (mcpSettled !== undefined) out.mcp_all_settled = mcpSettled;264 265  // gemini_tools_lag = how long after the first MCP server finished266  // discover did the model actually receive an updated tool list. We must267  // pick the FIRST `gemini_tools_updated` event whose timestamp is >=268  // `mcp_first_tool_registered`, because earlier `setTools()` calls fire269  // from `GeminiClient.initialize() -> startChat()` (built-in tools only)270  // and from `SkillTool` post-construction refresh — both happen BEFORE271  // MCP discovery starts under PR-A, so naively taking the first272  // `gemini_tools_updated` would give a misleading negative lag.273  if (mcpFirst !== undefined) {274    for (const ev of events) {275      if (ev.name === 'gemini_tools_updated' && ev.tMs >= mcpFirst) {276        out.gemini_tools_lag = Math.round((ev.tMs - mcpFirst) * 100) / 100;277        break;278      }279    }280  }281 282  return out;283}284 285export function getStartupReport(): StartupReport | null {286  if (!enabled || (checkpoints.length === 0 && events.length === 0)) {287    return null;288  }289 290  const phases: StartupPhase[] = [];291  let prev = t0;292 293  // Each phase's durationMs is the delta from the previous checkpoint (or T0294  // for the first one). Checkpoints are assumed to be recorded sequentially.295  for (const cp of checkpoints) {296    phases.push({297      name: cp.name,298      startMs: Math.round((prev - t0) * 100) / 100,299      durationMs: Math.round((cp.timestamp - prev) * 100) / 100,300      ...(cp.heapUsedMb !== undefined ? { heapUsedMb: cp.heapUsedMb } : {}),301    });302    prev = cp.timestamp;303  }304 305  const lastTimestamp =306    checkpoints.length > 0307      ? checkpoints[checkpoints.length - 1]!.timestamp308      : performance.now();309 310  return {311    timestamp: new Date().toISOString(),312    sessionId: 'unknown',313    interactiveMode,314    outerProcess,315    processUptimeAtT0Ms,316    totalMs: Math.round((lastTimestamp - t0) * 100) / 100,317    phases,318    events: [...events],319    eventsTruncated,320    derivedPhases: computeDerivedPhases(),321    nodeVersion: process.version,322    platform: process.platform,323    arch: process.arch,324  };325}326 327export function finalizeStartupProfile(sessionId?: string): void {328  if (!enabled || finalized) return;329  finalized = true;330 331  const report = getStartupReport();332  if (!report) return;333 334  if (sessionId) {335    report.sessionId = sessionId;336  }337 338  try {339    const dir = path.join(os.homedir(), '.qwen', 'startup-perf');340    fs.mkdirSync(dir, { recursive: true });341 342    const prefix = report.outerProcess ? 'outer-' : '';343    const filename = `${prefix}${report.timestamp.replace(/[:.]/g, '-')}-${report.sessionId}.json`;344    const filepath = path.join(dir, filename);345    fs.writeFileSync(filepath, JSON.stringify(report, null, 2), 'utf-8');346    process.stderr.write(`Startup profile written to: ${filepath}\n`);347  } catch {348    process.stderr.write('Warning: Failed to write startup profile report\n');349  }350}351 352export function resetStartupProfiler(): void {353  enabled = false;354  captureHeap = false;355  outerProcess = false;356  interactiveMode = false;357  t0 = 0;358  processUptimeAtT0Ms = 0;359  checkpoints = [];360  events = [];361  eventsTruncated = false;362  finalized = false;363}364 365/**366 * Test-only: returns whether profiling is currently active. Used by the367 * cli to short-circuit the cross-package event sink registration.368 */369export function isStartupProfilerEnabled(): boolean {370  return enabled;371}372