Skip to content

Commit 3bb103c

Browse files
elbrunoCopilot
elbruno
and
Copilot
committed
Add detailed runtime logging across long pipeline stages
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent 49eb5bd commit 3bb103c

2 files changed

Lines changed: 112 additions & 9 deletions

File tree

‎src/Graphify.Cli/PipelineRunner.cs‎

Lines changed: 63 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
using System.Collections.Concurrent;
2+
using System.Diagnostics;
23
using Graphify.Export;
34
using Graphify.Graph;
45
using Graphify.Models;
@@ -32,12 +33,15 @@ public PipelineRunner(TextWriter output, bool verbose = false, IChatClient? chat
3233
{
3334
try
3435
{
36+
var pipelineStopwatch = Stopwatch.StartNew();
3537
await WriteLineAsync("graphify-dotnet: Transform codebases into knowledge graphs");
3638
await WriteLineAsync(new string('─', 60));
39+
await WriteLineAsync($"Started at: {DateTimeOffset.Now:HH:mm:ss}");
3740
await WriteLineAsync();
3841

3942
// Stage 1: Detect files
4043
await WriteLineAsync("[1/6] Detecting files...");
44+
var detectStopwatch = Stopwatch.StartNew();
4145
var fileDetector = new FileDetector();
4246
var detectorOptions = new FileDetectorOptions(
4347
RootPath: inputPath,
@@ -47,6 +51,7 @@ public PipelineRunner(TextWriter output, bool verbose = false, IChatClient? chat
4751

4852
var detectedFiles = await fileDetector.ExecuteAsync(detectorOptions, cancellationToken);
4953
await WriteLineAsync($" Found {detectedFiles.Count} files to process");
54+
await WriteLineAsync($" Detection completed in {FormatElapsed(detectStopwatch.Elapsed)}");
5055
if (_verbose)
5156
{
5257
foreach (var file in detectedFiles.Take(5))
@@ -66,6 +71,9 @@ public PipelineRunner(TextWriter output, bool verbose = false, IChatClient? chat
6671
var extractionBag = new ConcurrentBag<ExtractionResult>();
6772
int processed = 0;
6873
int skipped = 0;
74+
int inspected = 0;
75+
var extractionStopwatch = Stopwatch.StartNew();
76+
var extractionProgressInterval = Math.Max(10, detectedFiles.Count / 10);
6977
var verboseWarnings = new ConcurrentQueue<string>();
7078

7179
await Parallel.ForEachAsync(
@@ -98,6 +106,17 @@ await Parallel.ForEachAsync(
98106
verboseWarnings.Enqueue($" Warning: Failed to extract {file.RelativePath}: {ex.Message}");
99107
}
100108
}
109+
finally
110+
{
111+
var currentInspected = Interlocked.Increment(ref inspected);
112+
if (_verbose &&
113+
detectedFiles.Count > 0 &&
114+
currentInspected % extractionProgressInterval == 0)
115+
{
116+
verboseWarnings.Enqueue(
117+
$" Progress: {currentInspected}/{detectedFiles.Count} files inspected ({processed} extracted, {skipped} skipped)");
118+
}
119+
}
101120
});
102121

103122
var extractionResults = new List<ExtractionResult>(extractionBag);
@@ -110,17 +129,21 @@ await Parallel.ForEachAsync(
110129
var totalNodes = extractionResults.Sum(r => r.Nodes.Count);
111130
var totalEdges = extractionResults.Sum(r => r.Edges.Count);
112131
await WriteLineAsync($" Extracted {totalNodes} nodes, {totalEdges} edges");
132+
await WriteLineAsync($" Extraction completed in {FormatElapsed(extractionStopwatch.Elapsed)}");
113133
await WriteLineAsync();
114134

115135
// Stage 2b: AI-enhanced semantic extraction (if provider configured)
116136
if (_chatClient != null)
117137
{
118138
await WriteLineAsync("[2b/6] Running AI-enhanced semantic extraction...");
139+
var semanticStopwatch = Stopwatch.StartNew();
119140
var semanticExtractor = new SemanticExtractor(_chatClient);
120141
int semanticProcessed = 0;
142+
var semanticProgressInterval = Math.Max(5, detectedFiles.Count / 10);
121143

122-
foreach (var file in detectedFiles)
144+
for (var index = 0; index < detectedFiles.Count; index++)
123145
{
146+
var file = detectedFiles[index];
124147
cancellationToken.ThrowIfCancellationRequested();
125148
try
126149
{
@@ -136,12 +159,21 @@ await Parallel.ForEachAsync(
136159
if (_verbose)
137160
await WriteLineAsync($" Warning: Semantic extraction failed for {file.RelativePath}: {ex.Message}");
138161
}
162+
163+
if (_verbose &&
164+
detectedFiles.Count > 0 &&
165+
(index + 1) % semanticProgressInterval == 0)
166+
{
167+
await WriteLineAsync(
168+
$" Progress: {index + 1}/{detectedFiles.Count} semantic files analyzed ({semanticProcessed} produced output) in {FormatElapsed(semanticStopwatch.Elapsed)}");
169+
}
139170
}
140171

141172
await WriteLineAsync($" AI extracted from {semanticProcessed} files");
142173
totalNodes = extractionResults.Sum(r => r.Nodes.Count);
143174
totalEdges = extractionResults.Sum(r => r.Edges.Count);
144175
await WriteLineAsync($" Total: {totalNodes} nodes, {totalEdges} edges (AST + AI)");
176+
await WriteLineAsync($" Semantic extraction completed in {FormatElapsed(semanticStopwatch.Elapsed)}");
145177
await WriteLineAsync();
146178
}
147179
else
@@ -153,6 +185,7 @@ await Parallel.ForEachAsync(
153185

154186
// Stage 3: Build graph
155187
await WriteLineAsync("[3/6] Building knowledge graph...");
188+
var graphBuildStopwatch = Stopwatch.StartNew();
156189
var graphBuilder = new GraphBuilder(new GraphBuilderOptions
157190
{
158191
CreateFileNodes = true,
@@ -161,10 +194,12 @@ await Parallel.ForEachAsync(
161194
});
162195
var graph = await graphBuilder.ExecuteAsync(extractionResults, cancellationToken);
163196
await WriteLineAsync($" Graph: {graph.NodeCount} nodes, {graph.EdgeCount} edges");
197+
await WriteLineAsync($" Graph build completed in {FormatElapsed(graphBuildStopwatch.Elapsed)}");
164198
await WriteLineAsync();
165199

166200
// Stage 4: Detect communities (clustering)
167201
await WriteLineAsync("[4/6] Detecting communities...");
202+
var clusterStopwatch = Stopwatch.StartNew();
168203
var clusterEngine = new ClusterEngine(new ClusterOptions
169204
{
170205
MaxIterations = 100,
@@ -179,10 +214,12 @@ await Parallel.ForEachAsync(
179214
.Distinct()
180215
.Count();
181216
await WriteLineAsync($" Found {communityCount} communities");
217+
await WriteLineAsync($" Clustering completed in {FormatElapsed(clusterStopwatch.Elapsed)}");
182218
await WriteLineAsync();
183219

184220
// Stage 5: Analyze graph
185221
await WriteLineAsync("[5/6] Analyzing graph structure...");
222+
var analysisStopwatch = Stopwatch.StartNew();
186223
var analyzer = new Analyzer(new AnalyzerOptions
187224
{
188225
TopGodNodesCount = 10,
@@ -193,6 +230,7 @@ await Parallel.ForEachAsync(
193230
await WriteLineAsync($" God nodes: {analysis.GodNodes.Count}");
194231
await WriteLineAsync($" Surprising connections: {analysis.SurprisingConnections.Count}");
195232
await WriteLineAsync($" Suggested questions: {analysis.SuggestedQuestions.Count}");
233+
await WriteLineAsync($" Analysis completed in {FormatElapsed(analysisStopwatch.Elapsed)}");
196234
await WriteLineAsync();
197235

198236
// Prepare community labels and cohesion scores for report and exports
@@ -201,6 +239,7 @@ await Parallel.ForEachAsync(
201239

202240
// Stage 6: Export
203241
await WriteLineAsync("[6/6] Exporting results...");
242+
var exportStopwatch = Stopwatch.StartNew();
204243

205244
// Validate output directory to prevent path traversal
206245
var validator = new Graphify.Security.InputValidator();
@@ -216,6 +255,7 @@ await Parallel.ForEachAsync(
216255
{
217256
try
218257
{
258+
var formatStopwatch = Stopwatch.StartNew();
219259
var normalizedFormat = format.ToLowerInvariant();
220260

221261
switch (normalizedFormat)
@@ -224,49 +264,49 @@ await Parallel.ForEachAsync(
224264
var jsonExporter = new JsonExporter();
225265
var jsonPath = Path.Combine(outputDir, "graph.json");
226266
await jsonExporter.ExportAsync(graph, jsonPath, cancellationToken);
227-
await WriteLineAsync($" Exported JSON: {jsonPath}");
267+
await WriteLineAsync($" Exported JSON: {jsonPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
228268
break;
229269

230270
case "html":
231271
var htmlExporter = new HtmlExporter();
232272
var htmlPath = Path.Combine(outputDir, "graph.html");
233273
await htmlExporter.ExportAsync(graph, htmlPath, communityLabels, cancellationToken);
234-
await WriteLineAsync($" Exported HTML: {htmlPath}");
274+
await WriteLineAsync($" Exported HTML: {htmlPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
235275
break;
236276

237277
case "svg":
238278
var svgExporter = new SvgExporter();
239279
var svgPath = Path.Combine(outputDir, "graph.svg");
240280
await svgExporter.ExportAsync(graph, svgPath, cancellationToken);
241-
await WriteLineAsync($" Exported SVG: {svgPath}");
281+
await WriteLineAsync($" Exported SVG: {svgPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
242282
break;
243283

244284
case "neo4j":
245285
var neo4jExporter = new Neo4jExporter();
246286
var cypherPath = Path.Combine(outputDir, "graph.cypher");
247287
await neo4jExporter.ExportAsync(graph, cypherPath, cancellationToken);
248-
await WriteLineAsync($" Exported Neo4j Cypher: {cypherPath}");
288+
await WriteLineAsync($" Exported Neo4j Cypher: {cypherPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
249289
break;
250290

251291
case "ladybug":
252292
var ladybugExporter = new LadybugExporter();
253293
var ladybugPath = Path.Combine(outputDir, "graph.ladybug.cypher");
254294
await ladybugExporter.ExportAsync(graph, ladybugPath, cancellationToken);
255-
await WriteLineAsync($" Exported Ladybug Cypher: {ladybugPath}");
295+
await WriteLineAsync($" Exported Ladybug Cypher: {ladybugPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
256296
break;
257297

258298
case "obsidian":
259299
var obsidianExporter = new ObsidianExporter();
260300
var obsidianPath = Path.Combine(outputDir, "obsidian");
261301
await obsidianExporter.ExportAsync(graph, obsidianPath, cancellationToken);
262-
await WriteLineAsync($" Exported Obsidian vault: {obsidianPath}/");
302+
await WriteLineAsync($" Exported Obsidian vault: {obsidianPath}/{FormatWithElapsed(formatStopwatch.Elapsed)}");
263303
break;
264304

265305
case "wiki":
266306
var wikiExporter = new WikiExporter();
267307
var wikiPath = Path.Combine(outputDir, "wiki");
268308
await wikiExporter.ExportAsync(graph, wikiPath, cancellationToken);
269-
await WriteLineAsync($" Exported Wiki: {wikiPath}/");
309+
await WriteLineAsync($" Exported Wiki: {wikiPath}/{FormatWithElapsed(formatStopwatch.Elapsed)}");
270310
break;
271311

272312
case "report":
@@ -275,7 +315,7 @@ await Parallel.ForEachAsync(
275315
var reportMarkdown = reportGenerator.Generate(graph, analysis, communityLabels, cohesionScores, projectName);
276316
var reportPath = Path.Combine(outputDir, "GRAPH_REPORT.md");
277317
await File.WriteAllTextAsync(reportPath, reportMarkdown, cancellationToken);
278-
await WriteLineAsync($" Exported Report: {reportPath}");
318+
await WriteLineAsync($" Exported Report: {reportPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
279319
break;
280320

281321
default:
@@ -288,9 +328,11 @@ await Parallel.ForEachAsync(
288328
await WriteLineAsync($" Error exporting {format}: {ex.Message}");
289329
}
290330
}
331+
await WriteLineAsync($" Export stage completed in {FormatElapsed(exportStopwatch.Elapsed)}");
291332

292333
await WriteLineAsync();
293334
await WriteLineAsync("✓ Pipeline completed successfully");
335+
await WriteLineAsync($"Total runtime: {FormatElapsed(pipelineStopwatch.Elapsed)}");
294336
await WriteLineAsync();
295337

296338
// Print summary
@@ -336,6 +378,18 @@ private async Task WriteLineAsync(string message = "")
336378
await _output.WriteLineAsync(message);
337379
}
338380

381+
private static string FormatElapsed(TimeSpan elapsed)
382+
{
383+
return elapsed.TotalSeconds >= 1
384+
? $"{elapsed.TotalSeconds:F2}s"
385+
: $"{elapsed.TotalMilliseconds:F0}ms";
386+
}
387+
388+
private string FormatWithElapsed(TimeSpan elapsed)
389+
{
390+
return _verbose ? $" ({FormatElapsed(elapsed)})" : string.Empty;
391+
}
392+
339393
private static Dictionary<int, string> BuildCommunityLabels(KnowledgeGraph graph)
340394
{
341395
var result = new Dictionary<int, string>();

‎src/Graphify/Pipeline/WatchMode.cs‎

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
using System.Collections.Concurrent;
2+
using System.Diagnostics;
23
using Graphify.Cache;
34
using Graphify.Export;
45
using Graphify.Graph;
@@ -127,6 +128,7 @@ private async Task ProcessChangesAsync(
127128

128129
try
129130
{
131+
var updateStopwatch = Stopwatch.StartNew();
130132
// Filter to files that actually changed content (via SHA256)
131133
var trulyChanged = new List<string>();
132134
foreach (var filePath in changedPaths)
@@ -148,6 +150,11 @@ private async Task ProcessChangesAsync(
148150
}
149151
}
150152

153+
if (_verbose)
154+
{
155+
await _output.WriteLineAsync($" Scanned {changedPaths.Count} path(s) in {FormatElapsed(updateStopwatch.Elapsed)}");
156+
}
157+
151158
if (trulyChanged.Count == 0)
152159
{
153160
if (_verbose)
@@ -173,7 +180,12 @@ private async Task ProcessChangesAsync(
173180
MaxFileSizeBytes: 1024 * 1024,
174181
RespectGitIgnore: true);
175182

183+
var detectStopwatch = Stopwatch.StartNew();
176184
var allDetected = await fileDetector.ExecuteAsync(options, ct);
185+
if (_verbose)
186+
{
187+
await _output.WriteLineAsync($" Re-detected {allDetected.Count} file(s) in {FormatElapsed(detectStopwatch.Elapsed)}");
188+
}
177189

178190
// Filter to changed files only
179191
var changedSet = new HashSet<string>(trulyChanged, StringComparer.OrdinalIgnoreCase);
@@ -188,20 +200,34 @@ private async Task ProcessChangesAsync(
188200
// Extract
189201
var extractor = new Extractor();
190202
var newResults = new List<ExtractionResult>();
203+
var extractStopwatch = Stopwatch.StartNew();
204+
var inspected = 0;
205+
var extracted = 0;
206+
var extractProgressInterval = Math.Max(5, filesToProcess.Count / 5);
191207
foreach (var file in filesToProcess)
192208
{
209+
inspected++;
193210
ct.ThrowIfCancellationRequested();
194211
try
195212
{
196213
var result = await extractor.ExecuteAsync(file, ct);
197214
if (result.Nodes.Count > 0 || result.Edges.Count > 0)
215+
{
198216
newResults.Add(result);
217+
extracted++;
218+
}
199219
}
200220
catch (Exception ex)
201221
{
202222
if (_verbose)
203223
await _output.WriteLineAsync($" Warning: extraction failed for {file.RelativePath}: {ex.Message}");
204224
}
225+
226+
if (_verbose && inspected % extractProgressInterval == 0)
227+
{
228+
await _output.WriteLineAsync(
229+
$" Extraction progress: {inspected}/{filesToProcess.Count} files ({extracted} produced output, {FormatElapsed(extractStopwatch.Elapsed)})");
230+
}
205231
}
206232

207233
if (newResults.Count == 0)
@@ -218,10 +244,16 @@ private async Task ProcessChangesAsync(
218244
MergeStrategy = MergeStrategy.MostRecent
219245
});
220246

247+
var buildStopwatch = Stopwatch.StartNew();
221248
var incrementalGraph = await graphBuilder.ExecuteAsync(newResults, ct);
222249
_currentGraph!.MergeGraph(incrementalGraph);
250+
if (_verbose)
251+
{
252+
await _output.WriteLineAsync($" Graph merge completed in {FormatElapsed(buildStopwatch.Elapsed)}");
253+
}
223254

224255
// Re-cluster
256+
var clusterStopwatch = Stopwatch.StartNew();
225257
var clusterEngine = new ClusterEngine(new ClusterOptions
226258
{
227259
MaxIterations = 100,
@@ -230,8 +262,13 @@ private async Task ProcessChangesAsync(
230262
MaxCommunityFraction = 0.2
231263
});
232264
_currentGraph = await clusterEngine.ExecuteAsync(_currentGraph, ct);
265+
if (_verbose)
266+
{
267+
await _output.WriteLineAsync($" Re-clustering completed in {FormatElapsed(clusterStopwatch.Elapsed)}");
268+
}
233269

234270
// Re-export
271+
var exportStopwatch = Stopwatch.StartNew();
235272
Directory.CreateDirectory(outputDir);
236273
foreach (var format in formats)
237274
{
@@ -246,9 +283,14 @@ private async Task ProcessChangesAsync(
246283
break;
247284
}
248285
}
286+
if (_verbose)
287+
{
288+
await _output.WriteLineAsync($" Export completed in {FormatElapsed(exportStopwatch.Elapsed)}");
289+
}
249290

250291
await _output.WriteLineAsync($" Re-processed {newResults.Count} file(s) → {_currentGraph.NodeCount} nodes, {_currentGraph.EdgeCount} edges");
251292
await _output.WriteLineAsync($" Exported to {outputDir}");
293+
await _output.WriteLineAsync($" Incremental update total time: {FormatElapsed(updateStopwatch.Elapsed)}");
252294
await _output.WriteLineAsync();
253295
}
254296
catch (OperationCanceledException)
@@ -273,4 +315,11 @@ public void Dispose()
273315
_watcher.Dispose();
274316
_processLock.Dispose();
275317
}
318+
319+
private static string FormatElapsed(TimeSpan elapsed)
320+
{
321+
return elapsed.TotalSeconds >= 1
322+
? $"{elapsed.TotalSeconds:F2}s"
323+
: $"{elapsed.TotalMilliseconds:F0}ms";
324+
}
276325
}

0 commit comments

Comments
 (0)