diff --git a/README.md b/README.md index ab01db810..55e5a03a7 100644 --- a/README.md +++ b/README.md @@ -324,6 +324,7 @@ Most `analyze` knobs are also CLI flags (`--workers`, `--worker-timeout`, `--max | `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. | +| `PROF_LBUG_LOAD` | unset | When `1`, emits one `[lbug-load prof]` summary line per `loadGraphToLbug` call breaking the graph-DB persistence wall into stages (`csv-emit` / `copy-nodes` / `copy-rels` / `fallback` / `total`) plus node & edge counts. Zero-cost when unset. | Attributing large-repo analyze wall time across CSV generation vs. LadybugDB `COPY` (issue #2203) — the analyze "emit" timing is the scope-resolution bucket, not this DB-write path. | | `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_WAL_CHECKPOINT_THRESHOLD` | `67108864` (64 MiB) | LadybugDB WAL auto-checkpoint threshold in bytes. Equivalent to `--wal-checkpoint-threshold `. `-1` keeps LadybugDB's stock threshold (~16 MiB). Larger thresholds reduce checkpoint frequency but increase the WAL size at rotation time — choose a smaller value on disk-constrained environments. | You need a larger or smaller WAL auto-checkpoint threshold for your analyze workload. | diff --git a/gitnexus/src/core/lbug/lbug-adapter.ts b/gitnexus/src/core/lbug/lbug-adapter.ts index 158d324e8..bc7dc1109 100644 --- a/gitnexus/src/core/lbug/lbug-adapter.ts +++ b/gitnexus/src/core/lbug/lbug-adapter.ts @@ -878,6 +878,17 @@ export const loadGraphToLbug = async ( const log = onProgress || (() => {}); + // ── #2203 persistence-path profiling ────────────────────────────────── + // Mirrors the PROF_SCOPE_RESOLUTION pattern (scope-resolution/pipeline/ + // run.ts): zero-cost when off — process.hrtime.bigint() is only read under + // PROF_LBUG_LOAD=1, and the summary is logged behind the same gate. Fills + // the gap that the DB-persistence path is un-timed today (the analyze + // "emit" number is the scope-resolution emit bucket, not this COPY path). + const PROF = process.env.PROF_LBUG_LOAD === '1'; + const mark = (): bigint => (PROF ? process.hrtime.bigint() : 0n); + const span = (a: bigint, b: bigint): string => (Number(b - a) / 1e6).toFixed(1); + const tStart = mark(); + let csvDir: string; if (process.platform === 'win32' && /[^\x00-\x7F]/.test(storagePath)) { const hash = crypto.createHash('sha256').update(storagePath).digest('hex').slice(0, 16); @@ -888,6 +899,7 @@ export const loadGraphToLbug = async ( log('Streaming CSVs to disk...'); const csvResult = await streamAllCSVsToDisk(graph, repoPath, csvDir); + const tCsv = mark(); const validTables = new Set(NODE_TABLES as readonly string[]); const getNodeLabel = (nodeId: string): string => { @@ -924,6 +936,8 @@ export const loadGraphToLbug = async ( } } + const tCopyNodes = mark(); + // Bulk COPY relationships — split by FROM→TO label pair (LadybugDB requires it) const { relHeader, relsByPairMeta, pairWriteStreams, skippedRels, totalValidRels } = await splitRelCsvByLabelPair(csvResult.relCsvPath, csvDir, validTables, getNodeLabel); @@ -937,6 +951,9 @@ export const loadGraphToLbug = async ( await finished(ws); }), ); + const tSplit = mark(); + let tCopyRels = tSplit; + let tFallback = tSplit; const insertedRels = totalValidRels; const warnings: string[] = []; @@ -980,6 +997,7 @@ export const loadGraphToLbug = async ( } catch {} } } + tCopyRels = mark(); if (failedPairCsvPaths.size > 0) { log(`Inserting ${failedPairEdges} edges individually (missing schema pairs)`); @@ -1002,6 +1020,7 @@ export const loadGraphToLbug = async ( await fallbackRelationshipInserts(allLines, validTables, getNodeLabel); } } + tFallback = mark(); } // Cleanup all CSVs @@ -1025,6 +1044,18 @@ export const loadGraphToLbug = async ( await fs.rmdir(csvDir); } catch {} + if (PROF) { + const tEnd = mark(); + let totalNodeRows = 0; + for (const [, { rows }] of csvResult.nodeFiles) totalNodeRows += rows; + logger.warn( + `[lbug-load prof] csv-emit=${span(tStart, tCsv)}ms ` + + `copy-nodes=${span(tCsv, tCopyNodes)}ms rel-split=${span(tCopyNodes, tSplit)}ms ` + + `copy-rels=${span(tSplit, tCopyRels)}ms fallback=${span(tCopyRels, tFallback)}ms ` + + `total=${span(tStart, tEnd)}ms (${totalNodeRows} nodes, ${insertedRels} rels)`, + ); + } + return { success: true, insertedRels, skippedRels, warnings }; }; diff --git a/gitnexus/test/integration/lbug-load-prof.test.ts b/gitnexus/test/integration/lbug-load-prof.test.ts new file mode 100644 index 000000000..8484e0e2c --- /dev/null +++ b/gitnexus/test/integration/lbug-load-prof.test.ts @@ -0,0 +1,146 @@ +/** + * Integration test: PROF_LBUG_LOAD persistence-path profiling (#2203 U1). + * + * loadGraphToLbug is un-timed in production today; the analyze "emit" number + * is the scope-resolution emit bucket, not this CSV→COPY persistence path. + * U1 adds a zero-cost-when-off per-stage breakdown gated by PROF_LBUG_LOAD=1, + * mirroring the PROF_SCOPE_RESOLUTION pattern. These tests assert the gate: + * - flag off → no `[lbug-load prof]` line is logged, behaviour unchanged + * - flag on → exactly one summary line with every stage key + node/rel counts + * + * Needs a real LadybugDB connection (initLbug), so it lives under integration. + * Logger assertions use `_captureLogger()` — the exported `logger` is a Proxy + * over a lazily-built pino instance and is not directly spy-able. + */ +import { describe, it, expect, beforeAll, beforeEach, afterAll, afterEach } from 'vitest'; +import fs from 'fs/promises'; +import path from 'path'; +import os from 'os'; +import { buildTestGraph } from '../helpers/test-graph.js'; +import { _captureLogger, type LoggerCapture } from '../../src/core/logger.js'; + +let tmpBase: string; +let storagePath: string; +let dbPath: string; +let cap: LoggerCapture; + +const PROF_LINE = '[lbug-load prof]'; + +const profLines = (): string[] => + cap + .records() + .map((r) => (typeof r.msg === 'string' ? r.msg : '')) + .filter((msg) => msg.includes(PROF_LINE)); + +beforeAll(async () => { + tmpBase = path.join(os.tmpdir(), `gitnexus-lbug-prof-${Date.now()}-${process.pid}`); + storagePath = path.join(tmpBase, '.gitnexus'); + dbPath = path.join(storagePath, 'lbug'); + await fs.mkdir(dbPath, { recursive: true }); + + const adapter = await import('../../src/core/lbug/lbug-adapter.js'); + await adapter.initLbug(dbPath); +}); + +beforeEach(() => { + cap = _captureLogger(); +}); + +afterEach(() => { + cap.restore(); + delete process.env.PROF_LBUG_LOAD; +}); + +afterAll(async () => { + try { + const adapter = await import('../../src/core/lbug/lbug-adapter.js'); + await adapter.closeLbug(); + } catch { + /* may not have opened */ + } + try { + await fs.rm(tmpBase, { recursive: true, force: true }); + } catch { + /* best-effort */ + } +}); + +describe('PROF_LBUG_LOAD persistence-path profiling (#2203 U1)', () => { + it('does NOT log a prof summary when the flag is unset', async () => { + delete process.env.PROF_LBUG_LOAD; + const adapter = await import('../../src/core/lbug/lbug-adapter.js'); + + const graph = buildTestGraph( + [ + { id: 'File:src/off.ts', label: 'File', name: 'off.ts', filePath: 'src/off.ts' }, + { + id: 'Function:src/off.ts:offFn:1', + label: 'Function', + name: 'offFn', + filePath: 'src/off.ts', + startLine: 1, + endLine: 2, + }, + ], + [{ sourceId: 'File:src/off.ts', targetId: 'Function:src/off.ts:offFn:1', type: 'DEFINES' }], + ); + + const result = await adapter.loadGraphToLbug(graph, tmpBase, storagePath); + + expect(result.success).toBe(true); + expect(profLines()).toHaveLength(0); + }); + + it('logs exactly one summary line with all stage keys + counts when the flag is set', async () => { + process.env.PROF_LBUG_LOAD = '1'; + const adapter = await import('../../src/core/lbug/lbug-adapter.js'); + + // Distinct ids from the flag-off graph so the COPY does not hit a + // PK-dup IGNORE_ERRORS retry on the shared singleton connection. + const graph = buildTestGraph( + [ + { id: 'File:src/on.ts', label: 'File', name: 'on.ts', filePath: 'src/on.ts' }, + { + id: 'Function:src/on.ts:onFn:1', + label: 'Function', + name: 'onFn', + filePath: 'src/on.ts', + startLine: 1, + endLine: 2, + }, + { + id: 'Class:src/on.ts:OnClass:5', + label: 'Class', + name: 'OnClass', + filePath: 'src/on.ts', + startLine: 5, + endLine: 8, + }, + ], + [ + { sourceId: 'File:src/on.ts', targetId: 'Function:src/on.ts:onFn:1', type: 'DEFINES' }, + { sourceId: 'File:src/on.ts', targetId: 'Class:src/on.ts:OnClass:5', type: 'DEFINES' }, + ], + ); + + const result = await adapter.loadGraphToLbug(graph, tmpBase, storagePath); + expect(result.success).toBe(true); + + const lines = profLines(); + expect(lines).toHaveLength(1); + + const line = lines[0]; + for (const key of [ + 'csv-emit=', + 'copy-nodes=', + 'rel-split=', + 'copy-rels=', + 'fallback=', + 'total=', + ]) { + expect(line).toContain(key); + } + // 3 node rows (File, Function, Class), 2 valid rels emitted. + expect(line).toContain('(3 nodes, 2 rels)'); + }); +});