Skip to content

Commit cd07d82

Browse files
aksOpsclaude
aksOps
and
claude
committed
feat: add real-time progress logging and --verbose flag for diagnosing pipeline issues
Progress logging (default): - Per-batch timing with avg ms/file after each batch completes - Within-batch progress counter every 100 files (142/500 files...) - Slow file warnings at INFO (>500ms) and WARN (>5s) levels - Slow detector warnings at WARN (>2s) - ANTLR parse timing: [SLOW ANTLR] warning when parse exceeds 2s - FileDiscovery promoted to INFO with timing - Enrich phases now report elapsed time per step --verbose / -v flag (IndexCommand + EnrichCommand): - Sets Logback level to DEBUG for io.github.randomcodespace.iq - Enables per-file timing, per-detector timing, full ANTLR trace ASCII-safe CLI output: - Replaced emoji with ASCII symbols throughout CLI commands to fix rendering issues in GitLab CI and non-Unicode terminals Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
1 parent d7a6813 commit cd07d82

11 files changed

Lines changed: 97 additions & 37 deletions

File tree

‎src/main/java/io/github/randomcodespace/iq/analyzer/Analyzer.java‎

Lines changed: 30 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -548,6 +548,7 @@ private AnalysisResult runBatchedWithCache(Path root, Integer parallelism, int b
548548
if (batch.size() >= batchSize || fileIdx == files.size() - 1) {
549549
batchNumber++;
550550
report.accept("Processing batch " + batchNumber + " (" + batch.size() + " files)...");
551+
Instant batchStart = Instant.now();
551552

552553
// Analyze batch in parallel
553554
DetectorResult[] resultSlots = new DetectorResult[batch.size()];
@@ -601,9 +602,17 @@ private AnalysisResult runBatchedWithCache(Path root, Integer parallelism, int b
601602
Thread.currentThread().interrupt();
602603
log.warn("Analysis interrupted for {}", batch.get(i).path());
603604
}
605+
int done = i + 1;
606+
if (done % 100 == 0 || done == futures.size()) {
607+
report.accept(" " + done + "/" + futures.size() + " files...");
608+
}
604609
}
605610
}
606611

612+
long batchMs = Duration.between(batchStart, Instant.now()).toMillis();
613+
long avgMs = batch.isEmpty() ? 0 : batchMs / batch.size();
614+
report.accept(" Batch " + batchNumber + " done: " + batchMs + "ms (" + avgMs + "ms/file avg)");
615+
607616
cacheHits += batchCacheHits.get();
608617

609618
// Collect batch results and flush non-cached to H2
@@ -926,6 +935,7 @@ private int[] processSmartBatch(
926935
int batchNumber, Consumer<String> report) {
927936

928937
report.accept("Processing batch " + batchNumber + " (" + batch.size() + " files)...");
938+
Instant batchStart = Instant.now();
929939

930940
DetectorResult[] slots = new DetectorResult[batch.size()];
931941
var batchCacheHits = new java.util.concurrent.atomic.AtomicInteger(0);
@@ -976,8 +986,16 @@ private int[] processSmartBatch(
976986
Thread.currentThread().interrupt();
977987
log.warn("Analysis interrupted for {}", batch.get(i).path());
978988
}
989+
int done = i + 1;
990+
if (done % 100 == 0 || done == futures.size()) {
991+
report.accept(" " + done + "/" + futures.size() + " files...");
992+
}
979993
}
980994

995+
long batchMs = Duration.between(batchStart, Instant.now()).toMillis();
996+
long avgMs = batch.isEmpty() ? 0 : batchMs / batch.size();
997+
report.accept(" Batch " + batchNumber + " done: " + batchMs + "ms (" + avgMs + "ms/file avg)");
998+
981999
int nodes = 0, edges = 0, analyzed = 0;
9821000
List<CodeNode> batchNodes = new ArrayList<>();
9831001
List<CodeEdge> batchEdges = new ArrayList<>();
@@ -1149,8 +1167,10 @@ DetectorResult analyzeFileWithRegistry(DiscoveredFile file, Path repoPath,
11491167
AntlrParserFactory.clearCache();
11501168

11511169
long fileMs = Duration.between(fileStart, Instant.now()).toMillis();
1152-
if (fileMs > 500) {
1153-
log.debug("Slow file {} ({}): {}ms", file.path(), file.language(), fileMs);
1170+
if (fileMs > 5000) {
1171+
log.warn("[SLOW] {} took {}ms", file.path(), fileMs);
1172+
} else if (fileMs > 500) {
1173+
log.info("[SLOW] {} took {}ms", file.path(), fileMs);
11541174
}
11551175

11561176
if (moduleName != null) {
@@ -1293,7 +1313,10 @@ DetectorResult analyzeFile(DiscoveredFile file, Path repoPath, DetectorRegistry
12931313
Instant detStart = Instant.now();
12941314
DetectorResult result = detector.detect(ctx);
12951315
long detMs = Duration.between(detStart, Instant.now()).toMillis();
1296-
if (detMs > 100) {
1316+
if (detMs > 2000) {
1317+
log.warn("[SLOW DETECTOR] {} on {}: {}ms",
1318+
detector.getName(), file.path(), detMs);
1319+
} else if (detMs > 100) {
12971320
log.debug("Slow detector {} on {} ({} bytes): {}ms",
12981321
detector.getName(), file.path(), content.length(), detMs);
12991322
}
@@ -1309,8 +1332,10 @@ DetectorResult analyzeFile(DiscoveredFile file, Path repoPath, DetectorRegistry
13091332
AntlrParserFactory.clearCache();
13101333

13111334
long fileMs = Duration.between(fileStart, Instant.now()).toMillis();
1312-
if (fileMs > 500) {
1313-
log.debug("Slow file {} ({}): {}ms", file.path(), file.language(), fileMs);
1335+
if (fileMs > 5000) {
1336+
log.warn("[SLOW] {} took {}ms", file.path(), fileMs);
1337+
} else if (fileMs > 500) {
1338+
log.info("[SLOW] {} took {}ms", file.path(), fileMs);
13141339
}
13151340

13161341
// Set module on all nodes that don't have one yet

‎src/main/java/io/github/randomcodespace/iq/analyzer/FileDiscovery.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,7 @@ public FileDiscovery(CodeIqConfig config) {
7979
*/
8080
public List<DiscoveredFile> discover(Path repoPath) {
8181
Path root = repoPath.toAbsolutePath().normalize();
82+
java.time.Instant discoverStart = java.time.Instant.now();
8283
List<DiscoveredFile> result;
8384

8485
if (isGitRepo(root)) {
@@ -89,7 +90,8 @@ public List<DiscoveredFile> discover(Path repoPath) {
8990

9091
// Sort for deterministic ordering
9192
result.sort(Comparator.comparing(f -> f.path().toString()));
92-
log.debug("Discovered {} files in {}", result.size(), root);
93+
long discoverMs = java.time.Duration.between(discoverStart, java.time.Instant.now()).toMillis();
94+
log.info("Discovered {} files in {} ({}ms)", result.size(), root, discoverMs);
9395
return result;
9496
}
9597

‎src/main/java/io/github/randomcodespace/iq/cli/AnalyzeCommand.java‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -66,28 +66,28 @@ public Integer call() {
6666
// --no-cache overrides --incremental
6767
boolean useIncremental = incremental && !noCache;
6868

69-
CliOutput.step("\uD83D\uDD0D", "Scanning " + root + " ...");
69+
CliOutput.step("[*]", "Scanning " + root + " ...");
7070
if (useIncremental) {
71-
CliOutput.info(" (incremental mode — use --no-cache for full re-analysis)");
71+
CliOutput.info(" (incremental mode -- use --no-cache for full re-analysis)");
7272
}
7373

7474
AnalysisResult result = analyzer.run(root, parallelism, useIncremental, msg -> {
7575
if (msg.startsWith("Discovering")) {
76-
CliOutput.step("\uD83D\uDD0D", msg);
76+
CliOutput.step("[*]", msg);
7777
} else if (msg.startsWith("Found")) {
78-
CliOutput.step("\uD83D\uDCC1", "@|cyan " + msg + "|@");
78+
CliOutput.step("[+]", "@|cyan " + msg + "|@");
7979
} else if (msg.startsWith("Analyzing")) {
80-
CliOutput.step("\u2699\uFE0F", msg.replace("files...", "files using " + cores + " cores..."));
80+
CliOutput.step("[~]", msg.replace("files...", "files using " + cores + " cores..."));
8181
} else if (msg.startsWith("Building")) {
82-
CliOutput.step("\uD83C\uDFD7\uFE0F", msg);
82+
CliOutput.step("[^]", msg);
8383
} else if (msg.startsWith("Linking")) {
84-
CliOutput.step("\uD83D\uDD17", msg);
84+
CliOutput.step("[-]", msg);
8585
} else if (msg.startsWith("Classifying")) {
86-
CliOutput.step("\uD83C\uDFF7\uFE0F", msg);
86+
CliOutput.step("[#]", msg);
8787
} else if (msg.startsWith("Cache hits")) {
88-
CliOutput.step("\u26A1", "@|green " + msg + "|@");
88+
CliOutput.step("[!]", "@|green " + msg + "|@");
8989
} else if (msg.startsWith("Incremental")) {
90-
CliOutput.step("\u26A1", msg);
90+
CliOutput.step("[!]", msg);
9191
} else if (msg.startsWith("Analysis complete")) {
9292
// handled below
9393
} else {

‎src/main/java/io/github/randomcodespace/iq/cli/BundleCommand.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -132,7 +132,7 @@ public Integer call() {
132132
}
133133
}
134134

135-
CliOutput.step("\uD83D\uDCE6", "Creating bundle...");
135+
CliOutput.step("[+]", "Creating bundle...");
136136

137137
try (var zos = new ZipOutputStream(Files.newOutputStream(zipPath))) {
138138

@@ -202,7 +202,7 @@ public Integer call() {
202202
: nf.format(sizeBytes / 1024) + " KB";
203203

204204
System.out.println();
205-
CliOutput.success("\u2705 Bundle created: " + zipPath);
205+
CliOutput.success("[OK] Bundle created: " + zipPath);
206206
CliOutput.info(" Tag: " + bundleTag);
207207
CliOutput.info(" Nodes: " + nf.format(nodeCount));
208208
CliOutput.info(" Edges: " + nf.format(edgeCount));

‎src/main/java/io/github/randomcodespace/iq/cli/CacheCommand.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -120,7 +120,7 @@ public Integer call() {
120120
CliOutput.warn("Could not delete: " + p);
121121
}
122122
});
123-
CliOutput.success("\u2705 Cache cleared: " + cacheDir);
123+
CliOutput.success("[OK] Cache cleared: " + cacheDir);
124124
} catch (IOException e) {
125125
CliOutput.error("Failed to clear cache: " + e.getMessage());
126126
return 1;

‎src/main/java/io/github/randomcodespace/iq/cli/CliOutput.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -107,7 +107,7 @@ static void printResultSummary(AnalysisResult result, NumberFormat nf) {
107107
String timeStr = secs > 0 ? secs + "s" : result.elapsed().toMillis() + "ms";
108108

109109
System.out.println();
110-
success("\u2705 Complete \u2014 "
110+
success("[OK] Complete -- "
111111
+ nf.format(result.nodeCount()) + " nodes, "
112112
+ nf.format(result.edgeCount()) + " edges in " + timeStr);
113113
System.out.println();

‎src/main/java/io/github/randomcodespace/iq/cli/EnrichCommand.java‎

Lines changed: 28 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,9 @@ public class EnrichCommand implements Callable<Integer> {
5858
@picocli.CommandLine.Option(names = {"--graph"}, description = "Path to shared graph directory (for multi-repo)")
5959
private Path graphDir;
6060

61+
@picocli.CommandLine.Option(names = {"--verbose", "-v"}, description = "Enable verbose per-file logging")
62+
private boolean verbose;
63+
6164
private final CodeIqConfig config;
6265
private final LayerClassifier layerClassifier;
6366
private final List<Linker> linkers;
@@ -76,6 +79,11 @@ public EnrichCommand(CodeIqConfig config, LayerClassifier layerClassifier,
7679

7780
@Override
7881
public Integer call() {
82+
if (verbose) {
83+
((ch.qos.logback.classic.Logger) org.slf4j.LoggerFactory.getLogger("io.github.randomcodespace.iq"))
84+
.setLevel(ch.qos.logback.classic.Level.DEBUG);
85+
}
86+
7987
Instant start = Instant.now();
8088
Path root = path.toAbsolutePath().normalize();
8189
NumberFormat nf = NumberFormat.getIntegerInstance(Locale.US);
@@ -94,7 +102,7 @@ public Integer call() {
94102
return 1;
95103
}
96104

97-
CliOutput.step("\uD83D\uDCE6", "Loading index from H2...");
105+
CliOutput.step("[+]", "Loading index from H2...");
98106
AnalysisCache cache;
99107
try {
100108
cache = new AnalysisCache(cachePath);
@@ -124,7 +132,8 @@ private int enrichFromCache(AnalysisCache cache, Path root, NumberFormat nf, Ins
124132
+ nf.format(allEdges.size()) + " edges from H2");
125133

126134
// 2. Run linkers (these work on in-memory node/edge lists)
127-
CliOutput.step("\uD83D\uDD17", "Running cross-file linkers...");
135+
CliOutput.step("[-]", "Running cross-file linkers...");
136+
Instant stepStart = Instant.now();
128137
RepositoryIdentity repoIdentity = RepositoryIdentity.resolve(root);
129138
var builder = new GraphBuilder(repoIdentity, VersionCommand.VERSION);
130139
for (CodeNode node : allNodes) {
@@ -146,21 +155,29 @@ private int enrichFromCache(AnalysisCache cache, Path root, NumberFormat nf, Ins
146155
CliOutput.info(" Linkers added " + nf.format(linkerNodeDelta) + " nodes, "
147156
+ nf.format(linkerEdgeDelta) + " edges");
148157
}
158+
CliOutput.info(" Done in " + Duration.between(stepStart, Instant.now()).toMillis() + "ms");
149159

150160
// 3. Classify layers
151-
CliOutput.step("\uD83C\uDFF7\uFE0F", "Classifying layers...");
161+
CliOutput.step("[#]", "Classifying layers...");
162+
stepStart = Instant.now();
152163
layerClassifier.classify(enrichedNodes);
164+
CliOutput.info(" Done in " + Duration.between(stepStart, Instant.now()).toMillis() + "ms");
153165

154166
// 3b. Enrich lexical metadata (doc comments, config keys) for fulltext search
155-
CliOutput.step("\uD83D\uDD0D", "Enriching lexical metadata...");
167+
CliOutput.step("[*]", "Enriching lexical metadata...");
168+
stepStart = Instant.now();
156169
lexicalEnricher.enrich(enrichedNodes, root);
170+
CliOutput.info(" Done in " + Duration.between(stepStart, Instant.now()).toMillis() + "ms");
157171

158172
// 3b2. Language-specific enrichment (call graph, type hints, import resolution)
159-
CliOutput.step("\uD83D\uDD0D", "Running language-specific enrichment...");
173+
CliOutput.step("[*]", "Running language-specific enrichment...");
174+
stepStart = Instant.now();
160175
languageEnricher.enrich(enrichedNodes, enrichedEdges, root);
176+
CliOutput.info(" Done in " + Duration.between(stepStart, Instant.now()).toMillis() + "ms");
161177

162178
// 3c. Detect services
163-
CliOutput.step("\uD83C\uDFD7\uFE0F", "Detecting service boundaries...");
179+
CliOutput.step("[^]", "Detecting service boundaries...");
180+
stepStart = Instant.now();
164181
var serviceDetector = new io.github.randomcodespace.iq.analyzer.ServiceDetector();
165182
String projectName = root.getFileName().toString();
166183
var serviceResult = serviceDetector.detect(enrichedNodes, enrichedEdges, projectName, root);
@@ -173,13 +190,15 @@ private int enrichFromCache(AnalysisCache cache, Path root, NumberFormat nf, Ins
173190
enrichedEdges = new ArrayList<>(builder.getEdges());
174191
CliOutput.info(" Detected " + serviceResult.serviceNodes().size() + " service(s)");
175192
}
193+
CliOutput.info(" Done in " + Duration.between(stepStart, Instant.now()).toMillis() + "ms");
176194

177195
// 4. Start Neo4j Embedded and bulk-load
178196
Path graphPath = graphDir != null
179197
? graphDir.toAbsolutePath().normalize().resolve("graph.db")
180198
: root.resolve(".osscodeiq/graph.db");
181199

182-
CliOutput.step("\uD83D\uDCBE", "Bulk-loading into Neo4j at " + graphPath + "...");
200+
CliOutput.step("[~]", "Bulk-loading into Neo4j at " + graphPath + "...");
201+
stepStart = Instant.now();
183202

184203
DatabaseManagementService dbms = null;
185204
try {
@@ -343,13 +362,14 @@ private int enrichFromCache(AnalysisCache cache, Path root, NumberFormat nf, Ins
343362
log.debug("Secondary index await returned: {}", e.getMessage());
344363
}
345364
CliOutput.info(" Created Neo4j indexes");
365+
CliOutput.info(" Done in " + Duration.between(stepStart, Instant.now()).toMillis() + "ms");
346366

347367
Duration elapsed = Duration.between(start, Instant.now());
348368
long secs = elapsed.toSeconds();
349369
String timeStr = secs > 0 ? secs + "s" : elapsed.toMillis() + "ms";
350370

351371
System.out.println();
352-
CliOutput.success("\u2705 Enrichment complete -- "
372+
CliOutput.success("[OK] Enrichment complete -- "
353373
+ nf.format(nodesLoaded) + " nodes, "
354374
+ nf.format(edgesLoaded) + " edges in " + timeStr);
355375
System.out.println();

‎src/main/java/io/github/randomcodespace/iq/cli/IndexCommand.java‎

Lines changed: 15 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,9 @@ public class IndexCommand implements Callable<Integer> {
5050
@Option(names = {"--service-name"}, description = "Service name tag for nodes (for multi-repo)")
5151
private String serviceName;
5252

53+
@Option(names = {"--verbose", "-v"}, description = "Enable verbose per-file logging")
54+
private boolean verbose;
55+
5356
private final Analyzer analyzer;
5457
private final CodeIqConfig config;
5558

@@ -60,6 +63,11 @@ public IndexCommand(Analyzer analyzer, CodeIqConfig config) {
6063

6164
@Override
6265
public Integer call() {
66+
if (verbose) {
67+
((ch.qos.logback.classic.Logger) org.slf4j.LoggerFactory.getLogger("io.github.randomcodespace.iq"))
68+
.setLevel(ch.qos.logback.classic.Level.DEBUG);
69+
}
70+
6371
Path root = path.toAbsolutePath().normalize();
6472

6573
CliOutput.configureFromOptions(config, graphDir, serviceName, root);
@@ -73,7 +81,7 @@ public Integer call() {
7381
// --no-cache overrides --incremental
7482
boolean useIncremental = incremental && !noCache;
7583

76-
CliOutput.step("\uD83D\uDD0D", "Indexing " + root + " ...");
84+
CliOutput.step("[*]", "Indexing " + root + " ...");
7785
CliOutput.info(" (batch size: " + effectiveBatchSize + " files, "
7886
+ cores + " cores, H2 store, config-first smart pipeline)");
7987
if (useIncremental) {
@@ -83,17 +91,17 @@ public Integer call() {
8391
AnalysisResult result = analyzer.runSmartIndex(root, parallelism, effectiveBatchSize,
8492
useIncremental, msg -> {
8593
if (msg.startsWith("Phase 1")) {
86-
CliOutput.step("\uD83D\uDD0D", "@|bold " + msg + "|@");
94+
CliOutput.step("[*]", "@|bold " + msg + "|@");
8795
} else if (msg.startsWith("Phase 2")) {
88-
CliOutput.step("\uD83D\uDCC1", "@|bold " + msg + "|@");
96+
CliOutput.step("[+]", "@|bold " + msg + "|@");
8997
} else if (msg.startsWith("Processing module")) {
90-
CliOutput.step("\uD83E\uDDF1", msg);
98+
CliOutput.step("[:]", msg);
9199
} else if (msg.startsWith("Processing batch")) {
92-
CliOutput.step("\u2699\uFE0F", msg);
100+
CliOutput.step("[~]", msg);
93101
} else if (msg.startsWith("Keyword filter")) {
94-
CliOutput.step("\u26A1", "@|green " + msg + "|@");
102+
CliOutput.step("[!]", "@|green " + msg + "|@");
95103
} else if (msg.startsWith("Cache hits")) {
96-
CliOutput.step("\u26A1", "@|green " + msg + "|@");
104+
CliOutput.step("[!]", "@|green " + msg + "|@");
97105
} else if (msg.startsWith("Service:")) {
98106
CliOutput.info(" " + msg);
99107
} else if (msg.startsWith("Smart index complete")) {

‎src/main/java/io/github/randomcodespace/iq/cli/ServeCommand.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,7 @@ public Integer call() {
7575
}
7676
}
7777

78-
CliOutput.step("\uD83D\uDE80", "@|bold,green Server started|@");
78+
CliOutput.step("[OK]", "@|bold,green Server started|@");
7979
System.out.println();
8080
if (noUi) {
8181
CliOutput.info(" Web UI: disabled (API and MCP active at :" + port + ")");

‎src/main/java/io/github/randomcodespace/iq/cli/StatsCommand.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -141,7 +141,7 @@ int outputPretty(Map<String, Object> stats) {
141141
String projectName = path.toAbsolutePath().normalize().getFileName().toString();
142142

143143
out.println();
144-
CliOutput.print(out, "@|bold \uD83D\uDCCA Code IQ Stats \u2014 " + projectName + "|@");
144+
CliOutput.print(out, "@|bold [=] Code IQ Stats -- " + projectName + "|@");
145145
out.println();
146146

147147
// Graph

0 commit comments

Comments
 (0)