Skip to content

Commit b78cff1

Browse files
Add --debug-stats mode for runtime performance analysis (#632)
Introduces a --debug-stats CLI flag that prints counters and timing to stderr after evaluation: lazy creation counts, function/builtin call counts, comprehension iterations, unique import counts (with cache hit tracking), per-phase timing (parse, eval, materialize), and JVM heap usage. Counters use stable snake_case labels for machine parsing. The DebugStats class is threaded through Interpreter -> Evaluator with null-check guards so there is zero overhead when the flag is not set. Parse counting/timing is handled by CountingParseCache wrapping the existing ParseCache.
1 parent 07b84c0 commit b78cff1

9 files changed

Lines changed: 264 additions & 29 deletions

File tree

CLAUDE.md

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,20 @@ Uses [Mill](https://mill-build.org/) 1.1.2. Cross-built for Scala 3.3.7, 2.13.18
2323

2424
The assembly JAR is at `out/sjsonnet/jvm/3.3.7/assembly.dest/out.jar`. Run it with `java -Xss100m -jar out.jar`.
2525

26+
## Formatting
27+
28+
Scala sources are formatted with [scalafmt](https://scalameta.org/scalafmt/) (config in `.scalafmt.conf`). The `SjsonnetCrossModule` and `bench` modules mix in `ScalafmtModule`.
29+
30+
```bash
31+
# Format all sources
32+
./mill __.reformat
33+
34+
# Check formatting without changing files
35+
./mill __.checkFormat
36+
```
37+
38+
CI checks formatting on PRs, so run `reformat` before committing.
39+
2640
## Test Structure
2741

2842
- **Framework**: uTest
@@ -57,6 +71,16 @@ Every bug fix should include a regression test:
5771
- Error tests (filename starts with `error.`): expected stderr including stack traces.
5872
3. Run `./mill 'sjsonnet.jvm[3.3.7]'.test` to verify.
5973

74+
## Debug Stats
75+
76+
The `--debug-stats` flag prints runtime counters and timing to stderr after evaluation:
77+
78+
```bash
79+
sjsonnet --debug-stats myfile.jsonnet
80+
```
81+
82+
Output includes thunk creation counts, function/builtin call counts, comprehension iterations, import/parse counts, and phase timing (eval, materialize). Counters are formatted with stable labels for machine parsing. The `DebugStats` class (`sjsonnet/src/sjsonnet/DebugStats.scala`) is wired through `Interpreter` -> `Evaluator`, with parse counting handled by `CountingParseCache`.
83+
6084
## Benchmarks
6185

6286
JMH benchmarks live in `bench/`. Benchmark suites in `bench/resources/`: `bug_suite/`, `cpp_suite/`, `go_suite/`, `sjsonnet_suite/`.

build.mill

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -298,6 +298,8 @@ object sjsonnet extends VersionFileModule {
298298
"src-jvm-native"
299299
)
300300
def sources = Task.Sources(sourceDirs.map(d => this.moduleDir / d)*)
301+
def forkArgs =
302+
Seq("-Xss" + stackSize, "--enable-native-access=ALL-UNNAMED")
301303

302304
def mvnDeps = super.mvnDeps() ++ Seq(
303305
mvn"org.tukaani:xz::1.11",

sjsonnet/src-jvm-native/sjsonnet/Config.scala

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -156,6 +156,11 @@ final case class Config(
156156
"Re-enable pre-0.5.5 broken assertion logic. See https://github.com/databricks/sjsonnet/issues/526."
157157
)
158158
brokenAssertionLogic: Flag = Flag(),
159+
@arg(
160+
name = "debug-stats",
161+
doc = "Print runtime statistics (thunks, calls, imports, timing) to stderr after evaluation"
162+
)
163+
debugStats: Flag = Flag(),
159164
@arg(
160165
doc = "The jsonnet file you wish to evaluate",
161166
positional = true

sjsonnet/src-jvm-native/sjsonnet/SjsonnetMainBase.scala

Lines changed: 13 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -125,6 +125,8 @@ object SjsonnetMainBase {
125125
| JSONNET_PATH=d:c:a:b sjsonnet
126126
| sjsonnet -J b -J a -J c -J d""".stripMargin
127127

128+
var statsToReport: DebugStats = null
129+
128130
val result = for {
129131
config <- parser
130132
.constructEither(
@@ -142,6 +144,9 @@ object SjsonnetMainBase {
142144
else Right(())
143145
}
144146
file <- Right(config.file)
147+
debugStats =
148+
if (config.debugStats.value) { val s = new DebugStats; statsToReport = s; s }
149+
else null
145150
outputStr <- mainConfigured(
146151
file,
147152
config,
@@ -162,14 +167,17 @@ object SjsonnetMainBase {
162167
)
163168
},
164169
warn,
165-
std
170+
std,
171+
debugStats = debugStats
166172
)
167173
res <- {
168174
if (hasWarnings && config.fatalWarnings.value) Left("")
169175
else Right(outputStr)
170176
}
171177
} yield (config, res)
172178

179+
if (statsToReport != null) stderr.print(statsToReport.format())
180+
173181
result match {
174182
case Left(err) =>
175183
if (err.nonEmpty) stderr.println(err)
@@ -308,7 +316,8 @@ object SjsonnetMainBase {
308316
importer: Importer,
309317
warnLogger: Evaluator.Logger,
310318
std: Val.Obj,
311-
evaluatorOverride: Option[Evaluator] = None): Either[String, String] = {
319+
evaluatorOverride: Option[Evaluator] = None,
320+
debugStats: DebugStats = null): Either[String, String] = {
312321

313322
val (jsonnetCode, path) =
314323
if (config.exec.value) (file, wd / Util.wrapInLessThanGreaterThan("exec"))
@@ -348,7 +357,8 @@ object SjsonnetMainBase {
348357
storePos = (position: Position) => if (config.yamlDebug.value) currentPos = position else (),
349358
logger = warnLogger,
350359
std = std,
351-
variableResolver = _ => None
360+
variableResolver = _ => None,
361+
debugStats = debugStats
352362
) {
353363
override def createEvaluator(
354364
resolver: CachedResolver,
Lines changed: 104 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,104 @@
1+
package sjsonnet
2+
3+
/**
4+
* Mutable counters and timing data for `--debug-stats` mode. A single instance is created when the
5+
* flag is set and threaded through the Interpreter, Evaluator, and ParseCache so that each
6+
* subsystem can increment its own counters.
7+
*
8+
* All fields are plain `var`s — evaluation is single-threaded, so no synchronisation is needed.
9+
*/
10+
final class DebugStats {
11+
12+
// -- Lazy --
13+
var lazyCreated: Long = 0
14+
15+
// -- Calls --
16+
var functionCalls: Long = 0
17+
var builtinCalls: Long = 0
18+
19+
// -- Comprehensions --
20+
var arrayCompIterations: Long = 0
21+
var objectCompIterations: Long = 0
22+
23+
// -- Parse / import --
24+
var filesParsed: Long = 0
25+
var importCalls: Long = 0
26+
var importCacheHits: Long = 0
27+
28+
// -- Timing (nanoseconds) --
29+
var parseTimeNs: Long = 0
30+
var evalTimeNs: Long = 0
31+
var materializeTimeNs: Long = 0
32+
33+
def totalTimeNs: Long = evalTimeNs + materializeTimeNs
34+
35+
def format(): String = {
36+
val sb = new StringBuilder
37+
sb.append("=== sjsonnet debug stats ===\n")
38+
39+
sb.append(formatLine("lazy_created", lazyCreated))
40+
sb.append(formatLine("function_calls", functionCalls))
41+
sb.append(formatLine("builtin_calls", builtinCalls))
42+
sb.append(formatLine("array_comp_iterations", arrayCompIterations))
43+
sb.append(formatLine("object_comp_iterations", objectCompIterations))
44+
sb.append(formatLine("files_parsed", filesParsed))
45+
sb.append(formatLine("import_calls", importCalls))
46+
sb.append(formatLine("import_cache_hits", importCacheHits))
47+
sb.append(formatTimeLine("parse_time", parseTimeNs))
48+
sb.append(formatTimeLine("eval_time", evalTimeNs))
49+
sb.append(formatTimeLine("materialize_time", materializeTimeNs))
50+
sb.append(formatTimeLine("total_time", totalTimeNs))
51+
52+
val rt = Runtime.getRuntime
53+
val usedBytes = rt.totalMemory() - rt.freeMemory()
54+
val maxBytes = rt.maxMemory()
55+
sb.append(formatBytesLine("heap_used", usedBytes))
56+
sb.append(formatBytesLine("heap_max", maxBytes))
57+
58+
sb.toString
59+
}
60+
61+
private def formatLine(label: String, value: Long): String =
62+
f"$label%-25s $value%d%n"
63+
64+
private def formatTimeLine(label: String, ns: Long): String =
65+
f"$label%-25s ${formatNs(ns)}%s%n"
66+
67+
private def formatBytesLine(label: String, bytes: Long): String =
68+
f"$label%-25s ${formatBytes(bytes)}%s%n"
69+
70+
private def formatNs(ns: Long): String = {
71+
if (ns < 1000L) s"${ns}ns"
72+
else if (ns < 1000000L) f"${ns / 1000.0}%.1fμs"
73+
else if (ns < 1000000000L) f"${ns / 1000000.0}%.1fms"
74+
else f"${ns / 1000000000.0}%.3fs"
75+
}
76+
77+
private def formatBytes(bytes: Long): String = {
78+
if (bytes < 1024L) s"${bytes}B"
79+
else if (bytes < 1024L * 1024) f"${bytes / 1024.0}%.1fKB"
80+
else if (bytes < 1024L * 1024 * 1024) f"${bytes / (1024.0 * 1024)}%.1fMB"
81+
else f"${bytes / (1024.0 * 1024 * 1024)}%.2fGB"
82+
}
83+
}
84+
85+
/**
86+
* A [[ParseCache]] wrapper that counts and times actual parse invocations (cache misses). The
87+
* `defaultValue` thunk in [[ParseCache.getOrElseUpdate]] is only evaluated on a cache miss, so we
88+
* increment [[DebugStats.filesParsed]] and accumulate [[DebugStats.parseTimeNs]] inside that thunk.
89+
*/
90+
final class CountingParseCache(delegate: ParseCache, stats: DebugStats) extends ParseCache {
91+
override def getOrElseUpdate(
92+
key: (Path, String),
93+
defaultValue: => Either[Error, (Expr, FileScope)]): Either[Error, (Expr, FileScope)] = {
94+
delegate.getOrElseUpdate(
95+
key, {
96+
stats.filesParsed += 1
97+
val t0 = System.nanoTime()
98+
val result = defaultValue
99+
stats.parseTimeNs += System.nanoTime() - t0
100+
result
101+
}
102+
)
103+
}
104+
}

0 commit comments

Comments
 (0)