Skip to content

Commit 0084777

Browse files
elbrunoelbruno
authored
Add detailed runtime logging across long pipeline stages (#12)
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> # Conflicts: # src/Graphify.Cli/PipelineRunner.cs # src/Graphify/Pipeline/WatchMode.cs
1 parent b657253 commit 0084777

2 files changed

Lines changed: 89 additions & 11 deletions

File tree

‎src/Graphify.Cli/PipelineRunner.cs‎

Lines changed: 41 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;
@@ -33,12 +34,15 @@ public PipelineRunner(TextWriter output, bool verbose = false, IChatClient? chat
3334
{
3435
try
3536
{
37+
var pipelineStopwatch = Stopwatch.StartNew();
3638
await WriteLineAsync("graphify-dotnet: Transform codebases into knowledge graphs");
3739
await WriteLineAsync(new string('─', 60));
40+
await WriteLineAsync($"Started at: {DateTimeOffset.Now:HH:mm:ss}");
3841
await WriteLineAsync();
3942

4043
// Stage 1: Detect files
4144
await WriteLineAsync("[1/6] Detecting files...");
45+
var detectStopwatch = Stopwatch.StartNew();
4246
var fileDetector = new FileDetector();
4347
var detectorOptions = new FileDetectorOptions(
4448
RootPath: inputPath,
@@ -48,6 +52,7 @@ public PipelineRunner(TextWriter output, bool verbose = false, IChatClient? chat
4852

4953
var detectedFiles = await fileDetector.ExecuteAsync(detectorOptions, cancellationToken);
5054
await WriteLineAsync($" Found {detectedFiles.Count} files to process");
55+
await WriteLineAsync($" Detection completed in {FormatElapsed(detectStopwatch.Elapsed)}");
5156
if (_verbose)
5257
{
5358
foreach (var file in detectedFiles.Take(5))
@@ -68,6 +73,7 @@ public PipelineRunner(TextWriter output, bool verbose = false, IChatClient? chat
6873
int processed = 0;
6974
int skipped = 0;
7075
int completed = 0;
76+
var extractionStopwatch = Stopwatch.StartNew();
7177
var verboseWarnings = new ConcurrentQueue<string>();
7278
var extractionProgressStep = Math.Max(1, detectedFiles.Count / 10);
7379

@@ -124,19 +130,22 @@ await Parallel.ForEachAsync(
124130
var totalNodes = extractionResults.Sum(r => r.Nodes.Count);
125131
var totalEdges = extractionResults.Sum(r => r.Edges.Count);
126132
await WriteLineAsync($" Extracted {totalNodes} nodes, {totalEdges} edges");
133+
await WriteLineAsync($" Extraction completed in {FormatElapsed(extractionStopwatch.Elapsed)}");
127134
await WriteLineAsync();
128135

129136
// Stage 2b: AI-enhanced semantic extraction (if provider configured)
130137
if (_chatClient != null)
131138
{
132139
await WriteLineAsync("[2b/6] Running AI-enhanced semantic extraction...");
140+
var semanticStopwatch = Stopwatch.StartNew();
133141
var semanticExtractor = new SemanticExtractor(_chatClient);
134142
int semanticProcessed = 0;
135143
int semanticCompleted = 0;
136144
var semanticProgressStep = Math.Max(1, detectedFiles.Count / 10);
137145

138-
foreach (var file in detectedFiles)
146+
for (var index = 0; index < detectedFiles.Count; index++)
139147
{
148+
var file = detectedFiles[index];
140149
cancellationToken.ThrowIfCancellationRequested();
141150
try
142151
{
@@ -164,6 +173,7 @@ await Parallel.ForEachAsync(
164173
totalNodes = extractionResults.Sum(r => r.Nodes.Count);
165174
totalEdges = extractionResults.Sum(r => r.Edges.Count);
166175
await WriteLineAsync($" Total: {totalNodes} nodes, {totalEdges} edges (AST + AI)");
176+
await WriteLineAsync($" Semantic extraction completed in {FormatElapsed(semanticStopwatch.Elapsed)}");
167177
await WriteLineAsync();
168178
}
169179
else
@@ -175,6 +185,7 @@ await Parallel.ForEachAsync(
175185

176186
// Stage 3: Build graph
177187
await WriteLineAsync("[3/6] Building knowledge graph...");
188+
var graphBuildStopwatch = Stopwatch.StartNew();
178189
var graphBuilder = new GraphBuilder(new GraphBuilderOptions
179190
{
180191
CreateFileNodes = true,
@@ -183,10 +194,12 @@ await Parallel.ForEachAsync(
183194
});
184195
var graph = await graphBuilder.ExecuteAsync(extractionResults, cancellationToken);
185196
await WriteLineAsync($" Graph: {graph.NodeCount} nodes, {graph.EdgeCount} edges");
197+
await WriteLineAsync($" Graph build completed in {FormatElapsed(graphBuildStopwatch.Elapsed)}");
186198
await WriteLineAsync();
187199

188200
// Stage 4: Detect communities (clustering)
189201
await WriteLineAsync("[4/6] Detecting communities...");
202+
var clusterStopwatch = Stopwatch.StartNew();
190203
var clusterEngine = new ClusterEngine(new ClusterOptions
191204
{
192205
MaxIterations = 100,
@@ -201,10 +214,12 @@ await Parallel.ForEachAsync(
201214
.Distinct()
202215
.Count();
203216
await WriteLineAsync($" Found {communityCount} communities");
217+
await WriteLineAsync($" Clustering completed in {FormatElapsed(clusterStopwatch.Elapsed)}");
204218
await WriteLineAsync();
205219

206220
// Stage 5: Analyze graph
207221
await WriteLineAsync("[5/6] Analyzing graph structure...");
222+
var analysisStopwatch = Stopwatch.StartNew();
208223
var analyzer = new Analyzer(new AnalyzerOptions
209224
{
210225
TopGodNodesCount = 10,
@@ -215,6 +230,7 @@ await Parallel.ForEachAsync(
215230
await WriteLineAsync($" God nodes: {analysis.GodNodes.Count}");
216231
await WriteLineAsync($" Surprising connections: {analysis.SurprisingConnections.Count}");
217232
await WriteLineAsync($" Suggested questions: {analysis.SuggestedQuestions.Count}");
233+
await WriteLineAsync($" Analysis completed in {FormatElapsed(analysisStopwatch.Elapsed)}");
218234
await WriteLineAsync();
219235

220236
// Prepare community labels and cohesion scores for report and exports
@@ -223,6 +239,7 @@ await Parallel.ForEachAsync(
223239

224240
// Stage 6: Export
225241
await WriteLineAsync("[6/6] Exporting results...");
242+
var exportStopwatch = Stopwatch.StartNew();
226243

227244
// Validate output directory to prevent path traversal
228245
var validator = new Graphify.Security.InputValidator();
@@ -238,6 +255,7 @@ await Parallel.ForEachAsync(
238255
{
239256
try
240257
{
258+
var formatStopwatch = Stopwatch.StartNew();
241259
var normalizedFormat = format.ToLowerInvariant();
242260

243261
switch (normalizedFormat)
@@ -246,49 +264,49 @@ await Parallel.ForEachAsync(
246264
var jsonExporter = new JsonExporter();
247265
var jsonPath = Path.Combine(outputDir, "graph.json");
248266
await jsonExporter.ExportAsync(graph, jsonPath, cancellationToken);
249-
await WriteLineAsync($" Exported JSON: {jsonPath}");
267+
await WriteLineAsync($" Exported JSON: {jsonPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
250268
break;
251269

252270
case "html":
253271
var htmlExporter = new HtmlExporter();
254272
var htmlPath = Path.Combine(outputDir, "graph.html");
255273
await htmlExporter.ExportAsync(graph, htmlPath, communityLabels, cancellationToken);
256-
await WriteLineAsync($" Exported HTML: {htmlPath}");
274+
await WriteLineAsync($" Exported HTML: {htmlPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
257275
break;
258276

259277
case "svg":
260278
var svgExporter = new SvgExporter();
261279
var svgPath = Path.Combine(outputDir, "graph.svg");
262280
await svgExporter.ExportAsync(graph, svgPath, cancellationToken);
263-
await WriteLineAsync($" Exported SVG: {svgPath}");
281+
await WriteLineAsync($" Exported SVG: {svgPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
264282
break;
265283

266284
case "neo4j":
267285
var neo4jExporter = new Neo4jExporter();
268286
var cypherPath = Path.Combine(outputDir, "graph.cypher");
269287
await neo4jExporter.ExportAsync(graph, cypherPath, cancellationToken);
270-
await WriteLineAsync($" Exported Neo4j Cypher: {cypherPath}");
288+
await WriteLineAsync($" Exported Neo4j Cypher: {cypherPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
271289
break;
272290

273291
case "ladybug":
274292
var ladybugExporter = new LadybugExporter();
275293
var ladybugPath = Path.Combine(outputDir, "graph.ladybug.cypher");
276294
await ladybugExporter.ExportAsync(graph, ladybugPath, cancellationToken);
277-
await WriteLineAsync($" Exported Ladybug Cypher: {ladybugPath}");
295+
await WriteLineAsync($" Exported Ladybug Cypher: {ladybugPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
278296
break;
279297

280298
case "obsidian":
281299
var obsidianExporter = new ObsidianExporter();
282300
var obsidianPath = Path.Combine(outputDir, "obsidian");
283301
await obsidianExporter.ExportAsync(graph, obsidianPath, cancellationToken);
284-
await WriteLineAsync($" Exported Obsidian vault: {obsidianPath}/");
302+
await WriteLineAsync($" Exported Obsidian vault: {obsidianPath}/{FormatWithElapsed(formatStopwatch.Elapsed)}");
285303
break;
286304

287305
case "wiki":
288306
var wikiExporter = new WikiExporter();
289307
var wikiPath = Path.Combine(outputDir, "wiki");
290308
await wikiExporter.ExportAsync(graph, wikiPath, cancellationToken);
291-
await WriteLineAsync($" Exported Wiki: {wikiPath}/");
309+
await WriteLineAsync($" Exported Wiki: {wikiPath}/{FormatWithElapsed(formatStopwatch.Elapsed)}");
292310
break;
293311

294312
case "report":
@@ -297,7 +315,7 @@ await Parallel.ForEachAsync(
297315
var reportMarkdown = reportGenerator.Generate(graph, analysis, communityLabels, cohesionScores, projectName);
298316
var reportPath = Path.Combine(outputDir, "GRAPH_REPORT.md");
299317
await File.WriteAllTextAsync(reportPath, reportMarkdown, cancellationToken);
300-
await WriteLineAsync($" Exported Report: {reportPath}");
318+
await WriteLineAsync($" Exported Report: {reportPath}{FormatWithElapsed(formatStopwatch.Elapsed)}");
301319
break;
302320

303321
default:
@@ -310,9 +328,11 @@ await Parallel.ForEachAsync(
310328
await WriteLineAsync($" Error exporting {format}: {ex.Message}");
311329
}
312330
}
331+
await WriteLineAsync($" Export stage completed in {FormatElapsed(exportStopwatch.Elapsed)}");
313332

314333
await WriteLineAsync();
315334
await WriteLineAsync("✓ Pipeline completed successfully");
335+
await WriteLineAsync($"Total runtime: {FormatElapsed(pipelineStopwatch.Elapsed)}");
316336
await WriteLineAsync();
317337

318338
// Print summary
@@ -371,6 +391,18 @@ private static bool ShouldReportProgress(int completed, int total, int step)
371391
return completed == total || completed % step == 0;
372392
}
373393

394+
private static string FormatElapsed(TimeSpan elapsed)
395+
{
396+
return elapsed.TotalSeconds >= 1
397+
? $"{elapsed.TotalSeconds:F2}s"
398+
: $"{elapsed.TotalMilliseconds:F0}ms";
399+
}
400+
401+
private string FormatWithElapsed(TimeSpan elapsed)
402+
{
403+
return _verbose ? $" ({FormatElapsed(elapsed)})" : string.Empty;
404+
}
405+
374406
private static Dictionary<int, string> BuildCommunityLabels(KnowledgeGraph graph)
375407
{
376408
var result = new Dictionary<int, string>();

‎src/Graphify/Pipeline/WatchMode.cs‎

Lines changed: 48 additions & 2 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);
@@ -190,14 +202,19 @@ private async Task ProcessChangesAsync(
190202
var newResults = new List<ExtractionResult>();
191203
var progressStep = Math.Max(1, filesToProcess.Count / 10);
192204
var completed = 0;
205+
var extractStopwatch = Stopwatch.StartNew();
206+
var extracted = 0;
193207
foreach (var file in filesToProcess)
194208
{
195209
ct.ThrowIfCancellationRequested();
196210
try
197211
{
198212
var result = await extractor.ExecuteAsync(file, ct);
199213
if (result.Nodes.Count > 0 || result.Edges.Count > 0)
214+
{
200215
newResults.Add(result);
216+
extracted++;
217+
}
201218
}
202219
catch (Exception ex)
203220
{
@@ -206,9 +223,10 @@ private async Task ProcessChangesAsync(
206223
}
207224

208225
completed++;
209-
if (completed == filesToProcess.Count || completed % progressStep == 0)
226+
if (ShouldReportProgress(completed, filesToProcess.Count, progressStep))
210227
{
211-
await _output.WriteLineAsync($" Progress: {completed}/{filesToProcess.Count} changed files analyzed");
228+
await _output.WriteLineAsync(
229+
$" Progress: {completed}/{filesToProcess.Count} changed files analyzed ({extracted} produced output, {FormatElapsed(extractStopwatch.Elapsed)})");
212230
}
213231
}
214232

@@ -226,10 +244,16 @@ private async Task ProcessChangesAsync(
226244
MergeStrategy = MergeStrategy.MostRecent
227245
});
228246

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

232255
// Re-cluster
256+
var clusterStopwatch = Stopwatch.StartNew();
233257
var clusterEngine = new ClusterEngine(new ClusterOptions
234258
{
235259
MaxIterations = 100,
@@ -238,8 +262,13 @@ private async Task ProcessChangesAsync(
238262
MaxCommunityFraction = 0.2
239263
});
240264
_currentGraph = await clusterEngine.ExecuteAsync(_currentGraph, ct);
265+
if (_verbose)
266+
{
267+
await _output.WriteLineAsync($" Re-clustering completed in {FormatElapsed(clusterStopwatch.Elapsed)}");
268+
}
241269

242270
// Re-export
271+
var exportStopwatch = Stopwatch.StartNew();
243272
Directory.CreateDirectory(outputDir);
244273
foreach (var format in formats)
245274
{
@@ -254,9 +283,14 @@ private async Task ProcessChangesAsync(
254283
break;
255284
}
256285
}
286+
if (_verbose)
287+
{
288+
await _output.WriteLineAsync($" Export completed in {FormatElapsed(exportStopwatch.Elapsed)}");
289+
}
257290

258291
await _output.WriteLineAsync($" Re-processed {newResults.Count} file(s) → {_currentGraph.NodeCount} nodes, {_currentGraph.EdgeCount} edges");
259292
await _output.WriteLineAsync($" Exported to {outputDir}");
293+
await _output.WriteLineAsync($" Incremental update total time: {FormatElapsed(updateStopwatch.Elapsed)}");
260294
await _output.WriteLineAsync();
261295
}
262296
catch (OperationCanceledException)
@@ -281,4 +315,16 @@ public void Dispose()
281315
_watcher.Dispose();
282316
_processLock.Dispose();
283317
}
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+
}
325+
326+
private static bool ShouldReportProgress(int completed, int total, int step)
327+
{
328+
return completed == total || completed % step == 0;
329+
}
284330
}

0 commit comments

Comments
 (0)