perf(lbug): add PROF_LBUG_LOAD persistence-path timing breakdown (#2203 U1)

loadGraphToLbug is un-timed today; the analyze 'emit' number is the
scope-resolution emit bucket, not the CSV->COPY persistence path. Add a
zero-cost-when-off per-stage breakdown (csv-emit/copy-nodes/rel-split/
copy-rels/fallback/total + node/rel counts) gated by PROF_LBUG_LOAD=1,
mirroring the PROF_SCOPE_RESOLUTION pattern. Document the flag in README.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

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 <kb>`.                                       | 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 <seconds>` × 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 <bytes>`. `-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.                                                         |

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<string>(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 };
 };
 

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)');
+  });
+});