diff --git a/README.md b/README.md index 9b14396a81..d55e8ef94b 100644 --- a/README.md +++ b/README.md @@ -237,6 +237,8 @@ Most `analyze` knobs are also CLI flags (`--workers`, `--worker-timeout`, `--max | `GITNEXUS_WORKER_POOL_SIZE` | `cores - 1`, capped at 16 | Parse worker pool size. `0` disables the pool (sequential fallback). Equivalent to `--workers `. | Constrained containers (cgroup CPU limits), CI runners with explicit quotas, or debugging a worker-only crash via `0`. | | `GITNEXUS_PARSE_CHUNK_CONCURRENCY` | `2` | Number of chunks whose file contents may be read into memory in parallel while the pool dispatches the current chunk. Worker dispatch itself stays serial. | Repos large enough to chunk (multi-MB total source) where disk I/O is a measurable fraction of analyze wall-clock. | | `GITNEXUS_VERBOSE` | unset | When `1`, enables verbose ingestion logs (skipped-file warnings, per-chunk throughput, parse-cache stats). Equivalent to `--verbose`. | Debugging an analyze that "completed" but seems to have missed files; tuning `--workers` / chunk concurrency against observable throughput. | +| `GITNEXUS_PROFILE_DEFERRED` | unset | When `1`, emits `[deferred-profile]` timing/progress logs for the post-chunk deferred resolution band (imports → heritage → buildHeritageMap → legacy call resolution). Implied by `GITNEXUS_VERBOSE`. | Diagnosing analyze stalls in "Resolving calls (all chunks)" on large Java/Kotlin repos (issue #1741) without the full verbose ingestion noise. | +| `GITNEXUS_PROFILE_DEFERRED_SLOW_MS` | `3000` (verbose) / `5000` | Per-file threshold in ms above which `processCallsFromExtracted` emits a `slow file …` log line. Parsed via `Number()`: accepts integers (`5000`), scientific notation (`2.5e3`), decimals (`.5`), and hex (`0x10`). Non-finite or non-positive values fall back to the default. | Hunting a few outlier files dominating the deferred call-resolution stage; lower to surface more, raise to focus only on the worst. | | `GITNEXUS_MAX_FILE_SIZE` | `512` (KB) | Walker skip threshold in KB. Hard cap is `32768` (tree-sitter buffer ceiling). Equivalent to `--max-file-size `. | Indexing repos with intentionally-large source files (generated parsers, vendored bundles) that should still be parsed. | | `GITNEXUS_WORKER_SUB_BATCH_TIMEOUT_MS` | `30000` | Worker idle timeout in milliseconds before retry/fallback. Equivalent to `--worker-timeout ` × 1000. | Slow-parsing files (large minified JS, deeply-nested TS types) that legitimately need more than 30s. | | `GITNEXUS_WORKER_SUB_BATCH_MAX_BYTES` | `8388608` (8 MB) | Per-job byte budget the pool will send to a worker in one `postMessage`. | Very large individual files; mostly diagnostic — bumping past 8 MB risks structured-clone memory pressure. | diff --git a/gitnexus/src/cli/analyze.ts b/gitnexus/src/cli/analyze.ts index 29253f969c..55995b76bd 100644 --- a/gitnexus/src/cli/analyze.ts +++ b/gitnexus/src/cli/analyze.ts @@ -473,6 +473,8 @@ async function ensureHeap(): Promise { */ const ANALYZE_CLI_ENV_KEYS = [ 'GITNEXUS_VERBOSE', + 'GITNEXUS_PROFILE_DEFERRED', + 'GITNEXUS_PROFILE_DEFERRED_SLOW_MS', 'GITNEXUS_MAX_FILE_SIZE', 'GITNEXUS_WORKER_SUB_BATCH_TIMEOUT_MS', 'GITNEXUS_EMBEDDING_THREADS', diff --git a/gitnexus/src/core/ingestion/call-processor.ts b/gitnexus/src/core/ingestion/call-processor.ts index 1b5a234b4e..0ab961a7a8 100644 --- a/gitnexus/src/core/ingestion/call-processor.ts +++ b/gitnexus/src/core/ingestion/call-processor.ts @@ -39,6 +39,16 @@ import { generateId } from '../../lib/utils.js'; import { getLanguageFromFilename, SupportedLanguages } from 'gitnexus-shared'; import { isRegistryPrimary } from './registry-primary-flag.js'; import { isVerboseIngestionEnabled } from './utils/verbose.js'; +import { + deferredCallFileSlowMs, + deferredCallLogEveryN, + getDeferredProfileDroppedCount, + isDeferredResolutionProfileEnabled, + logDeferredProfile, + profileElapsedMs, + resetDeferredProfileDroppedCount, + startTimer, +} from './utils/deferred-resolution-profile.js'; import { yieldToEventLoop } from './utils/event-loop.js'; import { parseSourceSafe } from '../tree-sitter/safe-parse.js'; import { @@ -2909,6 +2919,39 @@ export const processCallsFromExtracted = async ( } const totalFiles = byFile.size; let filesProcessed = 0; + // Counts only files that survived the registry-primary skip — what the user + // is actually waiting on. Keyed by this counter, the first per-file progress + // log fires on the first *resolved* file rather than file #1 of byFile, + // which would silently land inside the skip block on mixed Python+JVM repos + // where the skipped language sorts first. + let resolvedFiles = 0; + const profileCalls = isDeferredResolutionProfileEnabled(); + const slowFileMs = profileCalls ? deferredCallFileSlowMs() : 0; + const logEveryN = profileCalls ? deferredCallLogEveryN() : 0; + let skippedRegistryPrimaryFiles = 0; + + // Fresh dropped-log counter per analyze run — the module-private counter + // in deferred-resolution-profile.ts is process-lived, so without a reset + // here it would accumulate across consecutive analyze invocations in the + // same Node process (e.g., the MCP server, eval harness, integration + // tests). + if (profileCalls) resetDeferredProfileDroppedCount(); + + // One-pass pre-count of the eventual non-skipped total so the live progress + // denominator stays stable as the loop iterates. Otherwise `${totalFiles - + // skippedRegistryPrimaryFiles}` drifts upward — files iterated before later + // registry-primary skips have been seen carry an inflated denominator, and + // the ratio only self-corrects after every file has been classified. Pre- + // count runs only on the enabled path so the disabled path stays free of + // the extra Map iteration. Defaults to 0 on the disabled path; the live log + // gate is also disabled there, so the value is never read. + let resolvedTotal = 0; + if (profileCalls) { + for (const filePath of byFile.keys()) { + const lang = getLanguageFromFilename(filePath); + if (!lang || !isRegistryPrimary(lang)) resolvedTotal++; + } + } for (const [filePath, calls] of byFile) { filesProcessed++; @@ -2920,7 +2963,19 @@ export const processCallsFromExtracted = async ( // Registry-primary gate: skip Python (etc.) entirely when the // scope-based phase owns CALLS for this language. const fileLanguage = getLanguageFromFilename(filePath); - if (fileLanguage && isRegistryPrimary(fileLanguage)) continue; + if (fileLanguage && isRegistryPrimary(fileLanguage)) { + skippedRegistryPrimaryFiles++; + continue; + } + + resolvedFiles++; + const tFile = startTimer(profileCalls); + + if (profileCalls && (resolvedFiles === 1 || resolvedFiles % logEveryN === 0)) { + logDeferredProfile( + `calls ${resolvedFiles}/${resolvedTotal} file=${filePath} sites=${calls.length}`, + ); + } ctx.enableCache(filePath); const widenCache: WidenCache = new Map(); @@ -3079,6 +3134,25 @@ export const processCallsFromExtracted = async ( } ctx.clearCache(); + + if (tFile !== null) { + const elapsed = profileElapsedMs(tFile); + if (elapsed >= slowFileMs) { + logDeferredProfile( + `slow file ${elapsed.toFixed(0)}ms path=${filePath} calls=${calls.length} lang=${fileLanguage ?? 'unknown'}`, + ); + } + } + } + + if (profileCalls) { + logDeferredProfile( + `processCallsFromExtracted done: ${totalFiles} files, ${extractedCalls.length} call sites, skipped registry-primary files=${skippedRegistryPrimaryFiles}`, + ); + const droppedCount = getDeferredProfileDroppedCount(); + if (droppedCount > 0) { + logDeferredProfile(`note: ${droppedCount} profile log lines dropped (logger errors)`); + } } onProgress?.(totalFiles, totalFiles); diff --git a/gitnexus/src/core/ingestion/model/heritage-map.ts b/gitnexus/src/core/ingestion/model/heritage-map.ts index ae89022b4d..4cee244e39 100644 --- a/gitnexus/src/core/ingestion/model/heritage-map.ts +++ b/gitnexus/src/core/ingestion/model/heritage-map.ts @@ -15,6 +15,10 @@ import type { ResolutionContext } from './resolution-context.js'; import { getLanguageFromFilename, type SupportedLanguages } from 'gitnexus-shared'; +import { + isDeferredResolutionProfileEnabled, + logDeferredProfile, +} from '../utils/deferred-resolution-profile.js'; // --------------------------------------------------------------------------- // ExtractedHeritage — the shape produced by the parse worker / heritage @@ -176,11 +180,35 @@ export const buildHeritageMap = ( // interfaceName → Set (implementor lookup for interface dispatch) const implementorFiles = new Map>(); + const profileHeritage = isDeferredResolutionProfileEnabled(); + let maxNameCartesian = 0; + let ambiguousHeritageRecords = 0; + let unresolvedChildLookups = 0; + let unresolvedParentLookups = 0; + for (const h of heritage) { // ── Parent lookup (nodeId-based) ──────────────────────────────── const childDefs = ctx.model.types.lookupClassByName(h.className); const parentDefs = ctx.model.types.lookupClassByName(h.parentName); + // Unresolved-side counters live in a separate guard so they observe + // records the ambiguity block below skips. On JVM monorepos the + // pathological fan-out case is precisely "many same-named children + // with an unresolved external supertype" (or the inverse) — both + // sides non-empty is the case `ambiguousHeritageRecords` already + // covers; the unresolved cases were silently dropped from the + // metric before this counter. + if (profileHeritage) { + if (childDefs.length === 0) unresolvedChildLookups++; + if (parentDefs.length === 0) unresolvedParentLookups++; + } + + if (profileHeritage && childDefs.length > 0 && parentDefs.length > 0) { + const product = childDefs.length * parentDefs.length; + if (product > 1) ambiguousHeritageRecords++; + if (product > maxNameCartesian) maxNameCartesian = product; + } + if (childDefs.length > 0 && parentDefs.length > 0) { for (const child of childDefs) { for (const parent of parentDefs) { @@ -368,6 +396,17 @@ export const buildHeritageMap = ( return implementorFiles.get(interfaceName) ?? EMPTY_SET; }; + if (profileHeritage) { + logDeferredProfile( + `buildHeritageMap: ${heritage.length} heritage records, ` + + `${ambiguousHeritageRecords} with child×parent lookup product >1, ` + + `max product ${maxNameCartesian}, ` + + `${unresolvedChildLookups} unresolved child lookups, ` + + `${unresolvedParentLookups} unresolved parent lookups, ` + + `${implementorFiles.size} interface implementor keys`, + ); + } + return { getParents, getAncestors, diff --git a/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts b/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts index 10e4557d24..bf954b5cfb 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts @@ -71,6 +71,12 @@ import { fileURLToPath, pathToFileURL } from 'node:url'; import { isDev } from '../utils/env.js'; import { isVerboseIngestionEnabled } from '../utils/verbose.js'; +import { + endTimer, + isDeferredResolutionProfileEnabled, + logDeferredProfile, + startTimer, +} from '../utils/deferred-resolution-profile.js'; import { synthesizeWildcardImportBindings, needsSynthesis } from './wildcard-synthesis.js'; import { extractORMQueriesInline } from './orm-extraction.js'; @@ -698,7 +704,15 @@ export async function runChunkedParseAndResolve( // heritage: 75 -> 80 (5) // routes: 80 -> 85 (5) // calls: 85 -> 95 (10) + const deferredProfile = isDeferredResolutionProfileEnabled(); + if (deferredProfile) { + logDeferredProfile( + `deferred band start: imports=${deferredWorkerImports.length} heritage=${deferredWorkerHeritage.length} ` + + `calls=${deferredWorkerCalls.length} routes=${allExtractedRoutes.length}`, + ); + } if (deferredWorkerImports.length > 0) { + const tImports = startTimer(deferredProfile); await processImportsFromExtracted( graph, allPathObjects, @@ -721,6 +735,11 @@ export async function runChunkedParseAndResolve( repoPath, importCtx, ); + endTimer( + tImports, + (ms) => + `processImportsFromExtracted: ${ms.toFixed(0)}ms (${deferredWorkerImports.length} import batches before drain)`, + ); // U15 (lightweight M1): processImportsFromExtracted is the sole // consumer of `deferredWorkerImports`. Free the array now so the // GC can reclaim the per-file ExtractedImport records before the @@ -732,8 +751,10 @@ export async function runChunkedParseAndResolve( deferredWorkerImports.length = 0; } if (anyChunkNeedsWildcardSynth) { + const tWildcard = startTimer(deferredProfile); synthesizeWildcardImportBindings(graph, ctx); hasSynthesized = true; + endTimer(tWildcard, (ms) => `synthesizeWildcardImportBindings: ${ms.toFixed(0)}ms`); } // L5 from PR #1693 review: populate `exportedTypeMap` from the in-progress // graph BEFORE `seedCrossFileReceiverTypes` runs. Previously the seeding @@ -754,11 +775,22 @@ export async function runChunkedParseAndResolve( ctx.namedImportMap, exportedTypeMap, ); - if (isDev && enrichedCount > 0) { - logger.info(`🔗 E1: Seeded ${enrichedCount} cross-file receiver types (all chunks)`); + if (enrichedCount > 0) { + // Two independent gates, not else-if: when both isDev AND + // deferredProfile are active, BOTH lines fire — log scrapers keyed + // on the original "🔗 E1" emoji marker keep matching, AND operators + // grepping the [deferred-profile] prefix see no gap between the + // wildcard-synth and heritage timings. + if (isDev) { + logger.info(`🔗 E1: Seeded ${enrichedCount} cross-file receiver types (all chunks)`); + } + if (deferredProfile) { + logDeferredProfile(`E1: seeded ${enrichedCount} cross-file receiver types (all chunks)`); + } } } if (deferredWorkerHeritage.length > 0) { + const tHeritage = startTimer(deferredProfile); await processHeritageFromExtracted(graph, deferredWorkerHeritage, ctx, (current, total) => { const ratio = total > 0 ? current / total : 1; onProgress({ @@ -773,8 +805,14 @@ export async function runChunkedParseAndResolve( }, }); }); + endTimer( + tHeritage, + (ms) => + `processHeritageFromExtracted: ${ms.toFixed(0)}ms (${deferredWorkerHeritage.length} records)`, + ); } if (allExtractedRoutes.length > 0) { + const tRoutes = startTimer(deferredProfile); await processRoutesFromExtracted(graph, allExtractedRoutes, ctx, (current, total) => { const ratio = total > 0 ? current / total : 1; onProgress({ @@ -789,12 +827,25 @@ export async function runChunkedParseAndResolve( }, }); }); + endTimer( + tRoutes, + (ms) => + `processRoutesFromExtracted: ${ms.toFixed(0)}ms (${allExtractedRoutes.length} routes)`, + ); } - const fullWorkerHeritageMap = - deferredWorkerHeritage.length > 0 - ? buildHeritageMap(deferredWorkerHeritage, ctx, getHeritageStrategyForLanguage) - : undefined; + let fullWorkerHeritageMap: ReturnType | undefined; + if (deferredWorkerHeritage.length > 0) { + const tBuildHeritage = startTimer(deferredProfile); + fullWorkerHeritageMap = buildHeritageMap( + deferredWorkerHeritage, + ctx, + getHeritageStrategyForLanguage, + ); + endTimer(tBuildHeritage, (ms) => `buildHeritageMap wall: ${ms.toFixed(0)}ms`); + } else if (deferredProfile) { + logDeferredProfile('buildHeritageMap: skipped (no heritage records)'); + } // U15 (lightweight M1): buildHeritageMap is the LAST consumer of the // raw `deferredWorkerHeritage` records — processCallsFromExtracted // below reads from the derived `fullWorkerHeritageMap` instead. Free @@ -804,6 +855,12 @@ export async function runChunkedParseAndResolve( deferredWorkerHeritage.length = 0; if (deferredWorkerCalls.length > 0) { + if (deferredProfile) { + logDeferredProfile( + `processCallsFromExtracted: starting (${deferredWorkerCalls.length} call sites, heritageMap=${fullWorkerHeritageMap !== undefined})`, + ); + } + const tCalls = startTimer(deferredProfile); await processCallsFromExtracted( graph, deferredWorkerCalls, @@ -829,6 +886,7 @@ export async function runChunkedParseAndResolve( fullWorkerHeritageMap, bindingAccumulator, ); + endTimer(tCalls, (ms) => `processCallsFromExtracted: ${ms.toFixed(0)}ms total`); } if (deferredAssignments.length > 0) { diff --git a/gitnexus/src/core/ingestion/registry-primary-flag.ts b/gitnexus/src/core/ingestion/registry-primary-flag.ts index e050c65534..94fc172dc1 100644 --- a/gitnexus/src/core/ingestion/registry-primary-flag.ts +++ b/gitnexus/src/core/ingestion/registry-primary-flag.ts @@ -37,6 +37,7 @@ */ import { SupportedLanguages } from 'gitnexus-shared'; +import { parseTruthyEnv } from './utils/env.js'; /** * Languages whose RFC #909 Ring 3 scope-resolution migration is complete. @@ -115,10 +116,6 @@ export function primaryLanguages(): ReadonlySet { // ─── Internal ─────────────────────────────────────────────────────────────── -/** Accepted truthy strings (case-insensitive, trimmed). */ -const TRUTHY_VALUES: ReadonlySet = new Set(['true', '1', 'yes']); - function parseFlag(raw: string | undefined): boolean { - if (raw === undefined) return false; - return TRUTHY_VALUES.has(raw.trim().toLowerCase()); + return parseTruthyEnv(raw); } diff --git a/gitnexus/src/core/ingestion/utils/deferred-resolution-profile.ts b/gitnexus/src/core/ingestion/utils/deferred-resolution-profile.ts new file mode 100644 index 0000000000..697ca3bb6f --- /dev/null +++ b/gitnexus/src/core/ingestion/utils/deferred-resolution-profile.ts @@ -0,0 +1,120 @@ +/** + * Wall-clock logging for the post-chunk deferred resolution band + * (imports → heritage → heritage map → legacy call resolution). + * + * Enabled when either: + * - `GITNEXUS_VERBOSE=1` / `gitnexus analyze -v` (primary path for #1741), or + * - `GITNEXUS_PROFILE_DEFERRED=1` (force on without full verbose ingestion noise) + * + * Issue #1741: large Java/Kotlin repos appear stuck at "Resolving calls" + * because the UI progress bar updates every 100 files and intermediate + * stages emit little to the log. + */ + +import { logger } from '../../logger.js'; +import { parseTruthyEnv } from './env.js'; +import { isVerboseIngestionEnabled } from './verbose.js'; + +// Module-private tuning constants for the gates below. Not exported — these +// are internal knobs, not part of the module's API surface. +const LOG_EVERY_N_VERBOSE = 10; +const LOG_EVERY_N_PROFILE = 100; +const DEFAULT_SLOW_MS_VERBOSE = 3_000; +const DEFAULT_SLOW_MS = 5_000; + +/** True when deferred-stage timing / progress logs should emit. */ +export const isDeferredResolutionProfileEnabled = (): boolean => + isVerboseIngestionEnabled() || parseTruthyEnv(process.env.GITNEXUS_PROFILE_DEFERRED); + +/** Log a call-resolution progress line every N files (finer when verbose). */ +export const deferredCallLogEveryN = (): number => + isVerboseIngestionEnabled() ? LOG_EVERY_N_VERBOSE : LOG_EVERY_N_PROFILE; + +/** Per-file call-resolution log threshold (ms). Lower default when verbose. */ +export const deferredCallFileSlowMs = (): number => { + const raw = process.env.GITNEXUS_PROFILE_DEFERRED_SLOW_MS; + if (raw) { + // Use Number() not parseInt: parseInt('1e9', 10) === 1 (prefix-parses, drops the exponent), + // which would turn a user-intended "effectively disabled" threshold into a 1 ms log storm. + const n = Number(raw); + if (Number.isFinite(n) && n > 0) return n; + } + return isVerboseIngestionEnabled() ? DEFAULT_SLOW_MS_VERBOSE : DEFAULT_SLOW_MS; +}; + +export const profileNow = (): bigint => process.hrtime.bigint(); + +export const profileElapsedMs = (start: bigint): number => + Number(process.hrtime.bigint() - start) / 1e6; + +// Module-private counter for `[deferred-profile]` log lines the underlying +// logger refused to accept. Pino's SonicBoom transport is sync:false today, +// so steady-state `logger.info(string)` calls don't throw — but first-use +// construction paths (pino-pretty resolve, level validation) and any future +// transport reconfiguration could. The wrap below catches and counts so a +// failing logger cannot abort the deferred band, and the count surfaces in +// the deferred-band done-summary (see processCallsFromExtracted) so the +// failure is visible rather than silently swallowed (DoD §2.8). +let droppedLogLines = 0; + +/** + * Number of `logDeferredProfile` calls whose underlying `logger.info` threw. + * Surfaced in the deferred-band done-summary when greater than zero. + */ +export const getDeferredProfileDroppedCount = (): number => droppedLogLines; + +/** + * Reset the dropped-line counter. Call from test `afterEach` to keep the + * module-private state from leaking across tests. Also used inside + * `processCallsFromExtracted` at function entry so each analyze run gets + * a fresh count rather than accumulating across the process lifetime. + */ +export const resetDeferredProfileDroppedCount = (): void => { + droppedLogLines = 0; +}; + +export const logDeferredProfile = (message: string): void => { + try { + logger.info(`[deferred-profile] ${message}`); + } catch { + // Do not call the failing logger from the handler — that would risk + // an infinite loop if the failure mode is steady-state. Just count. + droppedLogLines++; + } +}; + +/** + * Capture a monotonic timestamp when profiling is enabled; otherwise return null. + * Pair with `endTimer` so the type system narrows correctly — using `null` instead + * of a `0n` sentinel makes "profiling disabled" structurally distinct from + * "zero elapsed time" and lets TypeScript catch missing guards. + */ +export const startTimer = (enabled: boolean): bigint | null => + enabled ? process.hrtime.bigint() : null; + +/** + * Emit a `[deferred-profile]` log line for a captured timer. No-op when the + * timer is `null` (profiling was disabled at capture time). The formatter + * receives elapsed ms so the call sites stay readable. + * + * The format callback runs inside a try/catch so a throwing formatter + * (custom toString, JSON.stringify on a circular object) cannot abort the + * deferred resolution band — observability code must never escalate to a + * load-bearing failure. On catch we emit a single `formatter error: …` + * line via logDeferredProfile and return; the caller's stage continues + * as if profiling had no-op'd for this timer. DoD §2.8 ("no silent + * catches that swallow diagnostics") is satisfied by surfacing the + * failure message rather than dropping it. + */ +export const endTimer = (start: bigint | null, format: (elapsedMs: number) => string): void => { + if (start === null) return; + const elapsedMs = profileElapsedMs(start); + let message: string; + try { + message = format(elapsedMs); + } catch (err) { + logDeferredProfile(`formatter error: ${err instanceof Error ? err.message : String(err)}`); + return; + } + logDeferredProfile(message); +}; diff --git a/gitnexus/src/core/ingestion/utils/env.ts b/gitnexus/src/core/ingestion/utils/env.ts index 6cb9d549f9..5beeb818fd 100644 --- a/gitnexus/src/core/ingestion/utils/env.ts +++ b/gitnexus/src/core/ingestion/utils/env.ts @@ -10,6 +10,24 @@ /** Whether we're running in development mode (enables verbose console logging). */ export const isDev = process.env.NODE_ENV === 'development'; +/** + * Parse a narrow-form truthy env-var value. Accepts `'1'`, `'true'`, `'yes'` + * (case-insensitive, whitespace-trimmed). Anything else — including + * `undefined`, empty string, `'0'`, `'false'`, `'no'`, or unknown tokens — + * returns `false`. + * + * This is the shared helper for narrow-form truthy parsing across the + * ingestion module. `logger.ts` uses a broader negative-list form + * (`isTruthyEnv`) that intentionally accepts anything except a small set of + * falsy tokens — that lives separately because it follows pino-debug + * conventions and serves a different purpose. + */ +export const parseTruthyEnv = (raw: string | undefined): boolean => { + if (raw === undefined) return false; + const value = raw.trim().toLowerCase(); + return value === '1' || value === 'true' || value === 'yes'; +}; + /** * Whether scope-resolution dev validators (e.g. `validateBindingsImmutability`) * should run AND emit warnings. Off by default in CLI runs to avoid silent diff --git a/gitnexus/src/core/ingestion/utils/verbose.ts b/gitnexus/src/core/ingestion/utils/verbose.ts index 0e616dca9b..c697a5aaa9 100644 --- a/gitnexus/src/core/ingestion/utils/verbose.ts +++ b/gitnexus/src/core/ingestion/utils/verbose.ts @@ -1,6 +1,4 @@ -export const isVerboseIngestionEnabled = (): boolean => { - const raw = process.env.GITNEXUS_VERBOSE; - if (!raw) return false; - const value = raw.toLowerCase(); - return value === '1' || value === 'true' || value === 'yes'; -}; +import { parseTruthyEnv } from './env.js'; + +export const isVerboseIngestionEnabled = (): boolean => + parseTruthyEnv(process.env.GITNEXUS_VERBOSE); diff --git a/gitnexus/test/unit/deferred-resolution-profile-wiring.test.ts b/gitnexus/test/unit/deferred-resolution-profile-wiring.test.ts new file mode 100644 index 0000000000..0fe4ead863 --- /dev/null +++ b/gitnexus/test/unit/deferred-resolution-profile-wiring.test.ts @@ -0,0 +1,230 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { _captureLogger } from '../../src/core/logger.js'; +import { processCallsFromExtracted } from '../../src/core/ingestion/call-processor.js'; +import { buildHeritageMap } from '../../src/core/ingestion/model/heritage-map.js'; +import { createResolutionContext } from '../../src/core/ingestion/model/resolution-context.js'; +import { createKnowledgeGraph } from '../../src/core/graph/graph.js'; +import { + getDeferredProfileDroppedCount, + resetDeferredProfileDroppedCount, +} from '../../src/core/ingestion/utils/deferred-resolution-profile.js'; +import type { ExtractedHeritage } from '../../src/core/ingestion/model/heritage-map.js'; +import type { ExtractedCall } from '../../src/core/ingestion/workers/parse-worker.js'; + +describe('deferred-resolution-profile wiring', () => { + let cap: ReturnType; + let prevProfileDeferred: string | undefined; + let prevVerbose: string | undefined; + let prevRegistryTypeScript: string | undefined; + + beforeEach(() => { + cap = _captureLogger(); + prevProfileDeferred = process.env.GITNEXUS_PROFILE_DEFERRED; + prevVerbose = process.env.GITNEXUS_VERBOSE; + prevRegistryTypeScript = process.env.REGISTRY_PRIMARY_TYPESCRIPT; + process.env.GITNEXUS_PROFILE_DEFERRED = '1'; + delete process.env.GITNEXUS_VERBOSE; + process.env.REGISTRY_PRIMARY_TYPESCRIPT = 'false'; + }); + + afterEach(() => { + cap.restore(); + if (prevProfileDeferred === undefined) delete process.env.GITNEXUS_PROFILE_DEFERRED; + else process.env.GITNEXUS_PROFILE_DEFERRED = prevProfileDeferred; + if (prevVerbose === undefined) delete process.env.GITNEXUS_VERBOSE; + else process.env.GITNEXUS_VERBOSE = prevVerbose; + if (prevRegistryTypeScript === undefined) delete process.env.REGISTRY_PRIMARY_TYPESCRIPT; + else process.env.REGISTRY_PRIMARY_TYPESCRIPT = prevRegistryTypeScript; + resetDeferredProfileDroppedCount(); + vi.restoreAllMocks(); + }); + + const deferredMsgs = (): string[] => + cap + .records() + .map((r) => String(r.msg ?? '')) + .filter((m) => m.includes('[deferred-profile]')); + + it('buildHeritageMap emits profile stats when GITNEXUS_PROFILE_DEFERRED=1', () => { + const ctx = createResolutionContext(); + ctx.model.symbols.add('src/a.java', 'Foo', 'class:a:Foo', 'Class'); + ctx.model.symbols.add('src/b.java', 'Foo', 'class:b:Foo', 'Class'); + ctx.model.symbols.add('src/c.java', 'Bar', 'class:c:Bar', 'Class'); + ctx.model.symbols.add('src/d.java', 'Bar', 'class:d:Bar', 'Class'); + + const heritage: ExtractedHeritage[] = [ + { filePath: 'src/a.java', className: 'Foo', parentName: 'Bar', kind: 'extends' }, + ]; + + buildHeritageMap(heritage, ctx); + + expect( + deferredMsgs().some( + (m) => + m.includes('buildHeritageMap:') && + m.includes('child×parent lookup product >1') && + m.includes('max product') && + m.includes('0 unresolved child lookups') && + m.includes('0 unresolved parent lookups'), + ), + ).toBe(true); + }); + + it('buildHeritageMap counts unresolved parent lookups (U7, JVM pathological case)', () => { + const ctx = createResolutionContext(); + // Many same-named children all resolved. + ctx.model.symbols.add('src/a.java', 'Foo', 'class:a:Foo', 'Class'); + ctx.model.symbols.add('src/b.java', 'Foo', 'class:b:Foo', 'Class'); + // Parent (e.g., external library) is NOT in the symbol index — lookup + // returns []. The legacy counter would silently drop this record from + // the metric. With U7, it shows up as an unresolved-parent lookup. + + const heritage: ExtractedHeritage[] = [ + { filePath: 'src/a.java', className: 'Foo', parentName: 'ExternalBase', kind: 'extends' }, + ]; + + buildHeritageMap(heritage, ctx); + + expect(deferredMsgs().some((m) => m.includes('1 unresolved parent lookups'))).toBe(true); + expect(deferredMsgs().some((m) => m.includes('0 unresolved child lookups'))).toBe(true); + }); + + it('buildHeritageMap counts unresolved child lookups (U7, inverse case)', () => { + const ctx = createResolutionContext(); + // Parent resolved, child name not in symbol index. + ctx.model.symbols.add('src/c.java', 'Bar', 'class:c:Bar', 'Class'); + + const heritage: ExtractedHeritage[] = [ + { filePath: 'src/x.java', className: 'UnknownChild', parentName: 'Bar', kind: 'extends' }, + ]; + + buildHeritageMap(heritage, ctx); + + expect(deferredMsgs().some((m) => m.includes('1 unresolved child lookups'))).toBe(true); + expect(deferredMsgs().some((m) => m.includes('0 unresolved parent lookups'))).toBe(true); + }); + + it('processCallsFromExtracted emits done summary with skipped registry-primary count', async () => { + const graph = createKnowledgeGraph(); + const ctx = createResolutionContext(); + ctx.model.symbols.add('src/index.ts', 'helper', 'Function:src/index.ts:helper', 'Function'); + + const calls: ExtractedCall[] = [ + { + filePath: 'src/index.ts', + calledName: 'helper', + sourceId: 'Function:src/index.ts:main', + }, + { + filePath: 'src/main.py', + calledName: 'run', + sourceId: 'Function:src/main.py:main', + }, + ]; + + await processCallsFromExtracted(graph, calls, ctx); + + expect( + deferredMsgs().some( + (m) => + m.includes('processCallsFromExtracted done:') && + m.includes('skipped registry-primary files=1'), + ), + ).toBe(true); + }); + + it('processCallsFromExtracted logs the first non-skipped file as 1/1 even when a registry-primary file sorts first', async () => { + const graph = createKnowledgeGraph(); + const ctx = createResolutionContext(); + ctx.model.symbols.add('src/index.ts', 'helper', 'Function:src/index.ts:helper', 'Function'); + + // Python sorts before TypeScript in byFile insertion order. Before the + // fix for #4 the first per-file log was keyed on filesProcessed===1, which + // was consumed by the Python skip and never emitted for the TS file. + const calls: ExtractedCall[] = [ + { filePath: 'src/early.py', calledName: 'run', sourceId: 'Function:src/early.py:main' }, + { filePath: 'src/index.ts', calledName: 'helper', sourceId: 'Function:src/index.ts:main' }, + ]; + + await processCallsFromExtracted(graph, calls, ctx); + + expect(deferredMsgs().some((m) => m.includes('calls 1/1 file=src/index.ts'))).toBe(true); + expect(deferredMsgs().some((m) => m.includes('skipped registry-primary files=1'))).toBe(true); + }); + + it('processCallsFromExtracted denominator stays stable across mixed-language interleaving (A1 pre-pass)', async () => { + const graph = createKnowledgeGraph(); + const ctx = createResolutionContext(); + ctx.model.symbols.add('src/a.ts', 'a', 'Function:src/a.ts:a', 'Function'); + ctx.model.symbols.add('src/b.ts', 'b', 'Function:src/b.ts:b', 'Function'); + ctx.model.symbols.add('src/c.ts', 'c', 'Function:src/c.ts:c', 'Function'); + ctx.model.symbols.add('src/d.ts', 'd', 'Function:src/d.ts:d', 'Function'); + + // Alternating TS / PY order: byFile = [ts, py, ts, py, ts, py, ts, py]. + // Before the U1 pre-pass, the first per-file log carried denominator 8 + // (totalFiles - 0 skips) and self-corrected only after every skip was + // observed. With the pre-pass, the denominator is 4 from the first + // emission onward — every entry uses the same resolvedTotal. + const calls: ExtractedCall[] = [ + { filePath: 'src/a.ts', calledName: 'a', sourceId: 'Function:src/a.ts:f' }, + { filePath: 'src/p1.py', calledName: 'a', sourceId: 'Function:src/p1.py:f' }, + { filePath: 'src/b.ts', calledName: 'b', sourceId: 'Function:src/b.ts:f' }, + { filePath: 'src/p2.py', calledName: 'b', sourceId: 'Function:src/p2.py:f' }, + { filePath: 'src/c.ts', calledName: 'c', sourceId: 'Function:src/c.ts:f' }, + { filePath: 'src/p3.py', calledName: 'c', sourceId: 'Function:src/p3.py:f' }, + { filePath: 'src/d.ts', calledName: 'd', sourceId: 'Function:src/d.ts:f' }, + { filePath: 'src/p4.py', calledName: 'd', sourceId: 'Function:src/p4.py:f' }, + ]; + + await processCallsFromExtracted(graph, calls, ctx); + + // Every per-file emission carries `/4` (the eventual resolved-file + // total), not the in-flight `totalFiles - skippedSoFar`. + expect(deferredMsgs().some((m) => m.includes('calls 1/4 file=src/a.ts'))).toBe(true); + expect(deferredMsgs().some((m) => /calls \d+\/[^4]/.test(m))).toBe(false); + expect(deferredMsgs().some((m) => m.includes('skipped registry-primary files=4'))).toBe(true); + }); + + it('processCallsFromExtracted resets the dropped-line counter at entry (U4)', async () => { + // logger is a Proxy that vi.spyOn can't override; we seed the counter by + // directly mutating it via the public reset / observation surface. The + // test then verifies processCallsFromExtracted brings the counter back to + // zero at the start of its run. + resetDeferredProfileDroppedCount(); + // Force-bump the counter by simulating a dropped line: there's no public + // increment, but we can prove the reset happens by setting up a non-zero + // counter state via processCallsFromExtracted's own reset path called + // twice in a row — both invocations should leave the counter at zero. + const graph = createKnowledgeGraph(); + const ctx = createResolutionContext(); + ctx.model.symbols.add('src/index.ts', 'helper', 'Function:src/index.ts:helper', 'Function'); + const calls: ExtractedCall[] = [ + { filePath: 'src/index.ts', calledName: 'helper', sourceId: 'Function:src/index.ts:main' }, + ]; + + await processCallsFromExtracted(graph, calls, ctx); + expect(getDeferredProfileDroppedCount()).toBe(0); + + // Second run: counter is still zero (idempotent reset). + await processCallsFromExtracted(graph, calls, ctx); + expect(getDeferredProfileDroppedCount()).toBe(0); + }); + + it('processCallsFromExtracted does not log per-file progress for registry-primary skips', async () => { + const graph = createKnowledgeGraph(); + const ctx = createResolutionContext(); + + const calls: ExtractedCall[] = [ + { + filePath: 'src/only.py', + calledName: 'run', + sourceId: 'Function:src/only.py:main', + }, + ]; + + await processCallsFromExtracted(graph, calls, ctx); + + expect(deferredMsgs().some((m) => m.includes('calls 1/1 file=src/only.py'))).toBe(false); + expect(deferredMsgs().some((m) => m.includes('skipped registry-primary files=1'))).toBe(true); + }); +}); diff --git a/gitnexus/test/unit/deferred-resolution-profile.test.ts b/gitnexus/test/unit/deferred-resolution-profile.test.ts new file mode 100644 index 0000000000..21f4a85510 --- /dev/null +++ b/gitnexus/test/unit/deferred-resolution-profile.test.ts @@ -0,0 +1,193 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { + deferredCallFileSlowMs, + deferredCallLogEveryN, + endTimer, + getDeferredProfileDroppedCount, + isDeferredResolutionProfileEnabled, + logDeferredProfile, + profileElapsedMs, + profileNow, + resetDeferredProfileDroppedCount, + startTimer, +} from '../../src/core/ingestion/utils/deferred-resolution-profile.js'; +import { _captureLogger } from '../../src/core/logger.js'; + +describe('deferred-resolution-profile', () => { + afterEach(() => { + delete process.env.GITNEXUS_PROFILE_DEFERRED; + delete process.env.GITNEXUS_PROFILE_DEFERRED_SLOW_MS; + delete process.env.GITNEXUS_VERBOSE; + resetDeferredProfileDroppedCount(); + vi.restoreAllMocks(); + }); + + it('is off by default', () => { + expect(isDeferredResolutionProfileEnabled()).toBe(false); + }); + + it('enables on GITNEXUS_VERBOSE=1', () => { + process.env.GITNEXUS_VERBOSE = '1'; + expect(isDeferredResolutionProfileEnabled()).toBe(true); + expect(deferredCallLogEveryN()).toBe(10); + expect(deferredCallFileSlowMs()).toBe(3000); + }); + + it('enables on GITNEXUS_PROFILE_DEFERRED=1', () => { + process.env.GITNEXUS_PROFILE_DEFERRED = '1'; + expect(isDeferredResolutionProfileEnabled()).toBe(true); + expect(deferredCallLogEveryN()).toBe(100); + }); + + it('reads slow-file threshold from env', () => { + process.env.GITNEXUS_PROFILE_DEFERRED_SLOW_MS = '250'; + expect(deferredCallFileSlowMs()).toBe(250); + }); + + describe('logDeferredProfile dropped-line counter (U4)', () => { + // Background: `logger` (gitnexus/src/core/logger.ts) is a Proxy with a lazy + // `get` trap and no `set` trap, so vi.spyOn on `logger.info` fails with + // "property is not defined on the object" — the inner pino method isn't a + // stable own-property to wrap. These tests exercise the helper API and the + // happy path; the catch arm is pinned by source-shape assertions below. + + it('counter is zero at module entry (after reset in afterEach)', () => { + expect(getDeferredProfileDroppedCount()).toBe(0); + }); + + it('does not increment when logger.info succeeds', () => { + const cap = _captureLogger(); + try { + logDeferredProfile('normal message'); + expect(getDeferredProfileDroppedCount()).toBe(0); + } finally { + cap.restore(); + } + }); + + it('multiple successful calls keep the counter at zero', () => { + const cap = _captureLogger(); + try { + logDeferredProfile('m1'); + logDeferredProfile('m2'); + logDeferredProfile('m3'); + expect(getDeferredProfileDroppedCount()).toBe(0); + } finally { + cap.restore(); + } + }); + + it('resetDeferredProfileDroppedCount returns the counter to zero', () => { + // Drive the counter via a stub since we can't spy on the Proxy. + // Mutate the counter through the public API: simulate a dropped line + // by calling logDeferredProfile inside a forced-throw context. + // Without a way to force logger.info to throw, the most we can test + // here is that reset() is idempotent on an already-zero counter and + // that the getter reads what reset wrote. + resetDeferredProfileDroppedCount(); + expect(getDeferredProfileDroppedCount()).toBe(0); + resetDeferredProfileDroppedCount(); + expect(getDeferredProfileDroppedCount()).toBe(0); + }); + + it('source defines a try/catch around the logger.info call', () => { + // Pin the catch arm via source shape — see logger Proxy note above. + const fs = require('node:fs') as typeof import('node:fs'); + const path = require('node:path') as typeof import('node:path'); + const url = require('node:url') as typeof import('node:url'); + const here = path.dirname(url.fileURLToPath(import.meta.url)); + const sourcePath = path.resolve( + here, + '../../src/core/ingestion/utils/deferred-resolution-profile.ts', + ); + const source = fs.readFileSync(sourcePath, 'utf-8'); + + expect( + /export const logDeferredProfile[\s\S]*?try \{\s*logger\.info\(`\[deferred-profile\] \$\{message\}`\);\s*\} catch[\s\S]*?droppedLogLines\+\+/.test( + source, + ), + ).toBe(true); + }); + }); + + describe('endTimer (U3 formatter exception safety)', () => { + it('emits the formatter output via [deferred-profile] when start is non-null', () => { + const cap = _captureLogger(); + try { + const start = startTimer(true); + endTimer(start, (ms) => `stage A: ${ms.toFixed(0)}ms`); + const messages = cap.records().map((r) => String(r.msg ?? '')); + expect(messages.some((m) => /\[deferred-profile\] stage A: \d+ms/.test(m))).toBe(true); + } finally { + cap.restore(); + } + }); + + it('is a no-op when start is null (profiling disabled), even if formatter would throw', () => { + const cap = _captureLogger(); + try { + const formatter = vi.fn(() => { + throw new Error('should never run'); + }); + endTimer(null, formatter); + expect(formatter).not.toHaveBeenCalled(); + expect(cap.records()).toEqual([]); + } finally { + cap.restore(); + } + }); + + it('catches a throwing formatter and emits one formatter-error line', () => { + const cap = _captureLogger(); + try { + const start = startTimer(true); + expect(() => + endTimer(start, () => { + throw new Error('boom'); + }), + ).not.toThrow(); + + const messages = cap.records().map((r) => String(r.msg ?? '')); + const errLines = messages.filter((m) => + m.includes('[deferred-profile] formatter error: boom'), + ); + expect(errLines.length).toBe(1); + } finally { + cap.restore(); + } + }); + + it('coerces non-Error throws (string, plain object) via String() in the error message', () => { + const cap = _captureLogger(); + try { + const start = startTimer(true); + endTimer(start, () => { + throw 'plain string'; + }); + const messages = cap.records().map((r) => String(r.msg ?? '')); + expect( + messages.some((m) => m.includes('[deferred-profile] formatter error: plain string')), + ).toBe(true); + } finally { + cap.restore(); + } + }); + }); + + it('profileElapsedMs converts hrtime deltas to ms with exact arithmetic', () => { + const spy = vi.spyOn(process.hrtime, 'bigint'); + try { + spy.mockReturnValueOnce(1_000_000_000n); + const start = profileNow(); + spy.mockReturnValueOnce(1_002_500_000n); + expect(profileElapsedMs(start)).toBe(2.5); + + spy.mockReturnValueOnce(5_000_000_000n); + const startZero = profileNow(); + spy.mockReturnValueOnce(5_000_000_000n); + expect(profileElapsedMs(startZero)).toBe(0); + } finally { + spy.mockRestore(); + } + }); +}); diff --git a/gitnexus/test/unit/env.test.ts b/gitnexus/test/unit/env.test.ts new file mode 100644 index 0000000000..6b5e767f36 --- /dev/null +++ b/gitnexus/test/unit/env.test.ts @@ -0,0 +1,38 @@ +import { describe, expect, it } from 'vitest'; +import { parseTruthyEnv } from '../../src/core/ingestion/utils/env.js'; + +describe('parseTruthyEnv', () => { + it.each([ + ['1', true], + ['true', true], + ['yes', true], + ['TRUE', true], + ['Yes', true], + ['YES', true], + [' 1 ', true], + [' true ', true], + ['\tyes\n', true], + ])('accepts %j as truthy', (raw, expected) => { + expect(parseTruthyEnv(raw)).toBe(expected); + }); + + it.each([ + ['0', false], + ['false', false], + ['no', false], + ['off', false], + ['', false], + [' ', false], + ['maybe', false], + ['2', false], + ['truthy', false], + ['1.0', false], + ['yes please', false], + ])('rejects %j as falsy', (raw, expected) => { + expect(parseTruthyEnv(raw)).toBe(expected); + }); + + it('returns false for undefined', () => { + expect(parseTruthyEnv(undefined)).toBe(false); + }); +}); diff --git a/gitnexus/test/unit/parse-impl-e1-emission-shape.test.ts b/gitnexus/test/unit/parse-impl-e1-emission-shape.test.ts new file mode 100644 index 0000000000..55b3a19ca8 --- /dev/null +++ b/gitnexus/test/unit/parse-impl-e1-emission-shape.test.ts @@ -0,0 +1,63 @@ +/** + * U2 (A2 from PR #1773 review) — regression guard for the E1 enrichment + * log dual-emission shape. + * + * The E1 line at the top of `runChunkedParseAndResolve`'s post-chunk band + * has two independent emission targets: + * - `logger.info('🔗 E1: Seeded …')` for the `isDev` path (dev-mode log + * scrapers still match the original emoji marker). + * - `logDeferredProfile('E1: seeded …')` for the `GITNEXUS_PROFILE_DEFERRED` + * path (operators grepping the [deferred-profile] prefix see no gap + * between wildcard-synth and heritage timings). + * + * When both flags are set, BOTH lines must fire. The original code used + * `if (isDev) { ... } else if (deferredProfile) { ... }` which is mutually + * exclusive and silently swallowed the [deferred-profile] line on combined- + * flag runs. This pin guards against the regression returning. + * + * Driving the four-case truth table via the real pipeline requires the + * worker path (`deferredWorkerCalls` only populates from chunk-worker + * extraction), which is slow and harness-dependent. A source-shape pin is + * the right test scope for a purely structural change — and is exactly + * how downstream readers grep for the regression anyway. + */ +import { describe, expect, it } from 'vitest'; +import fs from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const __dirname = path.dirname(fileURLToPath(import.meta.url)); +const PARSE_IMPL_PATH = path.resolve( + __dirname, + '../../src/core/ingestion/pipeline-phases/parse-impl.ts', +); + +describe('parse-impl E1 dual-emission shape (U2)', () => { + const source = fs.readFileSync(PARSE_IMPL_PATH, 'utf-8'); + + it('has a standalone `if (isDev)` branch emitting the original emoji line', () => { + expect(/if \(isDev\) \{\s*logger\.info\(`🔗 E1: Seeded \$\{enrichedCount\}/.test(source)).toBe( + true, + ); + }); + + it('has a standalone `if (deferredProfile)` branch emitting the [deferred-profile] line', () => { + expect( + /if \(deferredProfile\) \{\s*logDeferredProfile\(`E1: seeded \$\{enrichedCount\}/.test( + source, + ), + ).toBe(true); + }); + + it('does not chain the E1 branches via `else if`', () => { + // Tight regex anchored to the closing `}` of the isDev branch — confirms + // the very next token is `if` (independent branch) not `else if` (mutually + // exclusive). Unrelated `else if (deferredProfile)` later in the file + // (e.g., the buildHeritageMap-skipped log) is outside this window. + expect( + /if \(isDev\) \{\s*logger\.info\(`🔗 E1: Seeded[^`]+`\);\s*\}\s*if \(deferredProfile\)/.test( + source, + ), + ).toBe(true); + }); +});