Keyboard shortcuts

Press or to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

Profiler (cmd/jennifer/profile.go, internal/profile)

jennifer profile <prog.j> runs the program with the evaluator instrumented and attributes work back to Jennifer source positions (file:line:col) - the gap go tool pprof leaves, since it profiles the interpreter binary, not the .j program inside it. The program’s own output is redirected to stderr so the profile owns stdout cleanly, even in the binary form:

jennifer profile prog.j                       # table to stdout, program output to stderr
jennifer profile --allocs prog.j              # value-semantics (copy) profile
jennifer profile --format=pprof p.j > p.pb.gz # gzipped protobuf for go tool pprof / speedscope

Statement profile

The default profile records, per source position, how many times a statement ran and how long it took - self (this statement alone) versus cumulative (this statement plus everything it called), highest self-time first:

$ jennifer profile examples/profile.j
Jennifer statement profile (wall-clock, self = excluding nested statements)

  HITS        SELF          CUM  POSITION
     1  2.208054ms  16.438373ms  examples/profile.j:76:1
     1   321.116µs  10.776339ms  examples/profile.j:36:5
   200  5.292611ms   5.553693ms  examples/profile.j:38:9
   200  4.755398ms   4.755398ms  examples/profile.j:37:9
     8  1.438971ms   1.438971ms  examples/profile.j:51:30
     ...
ColumnMeaning
HITSHow many times the statement at this position executed.
SELFWall-clock spent in this statement, excluding nested statements it called.
CUMCumulative wall-clock: this statement plus everything it called.
POSITIONThe file:line:col of the statement. Rows are sorted by SELF descending.

A high SELF is a hot line; a high CUM with low SELF is a line that mostly waits on the work it dispatches.

Modes and formats

FlagEffect
(default)Statement profile: hit counts + self / cumulative time per position.
--allocsValue-semantics profile instead: where compound values are copied (see below).
--format=tableHuman-readable text (default).
--format=pprofGzipped protobuf, hand-encoded to keep the zero-dependency stance; go tool pprof and speedscope.app read it.
--format=traceChrome-trace JSON of the method-call timeline (open in chrome://tracing / Perfetto).

Unknown --format and the unsupported --allocs --format=trace combination (allocation events have no timeline) are rejected at argument parse, not deferred to output.

Allocation profile (--allocs)

Because Jennifer is value-semantic, copies are where hidden cost hides. --allocs reports two copy paths per source position:

$ jennifer profile --allocs examples/profile.j
Jennifer allocation profile (value-semantics copies)

Eager copies - a def / assignment / parameter binding that deep-copied a compound value:
  COUNT  POSITION
    200  examples/profile.j:38:28
    200  examples/profile.j:37:9
     50  examples/profile.j:69:9
     ...
  453 copies across 6 sites

Spawn-frame deep copies - a scope snapshot captured at spawn launch:
  (none)
Copy pathWhat it is
Eager copiesA def / assignment / parameter binding that deep-copies a compound value (Value.Copy()). Where the real allocation cost lives. A fresh list / map / struct literal RHS is already private, so binding it is not counted (no redundant copy).
Spawn-frame copiesThe scope snapshot taken when a spawn launches (snapshotForSpawn).

examples/profile.j exercises both - read it to see where value semantics turn a store into real allocation.

Reading a parallel profile

spawn bodies are profiled too (each on its own goroutine, onto the shared, mutex-guarded collector with a per-goroutine self/cumulative accumulator). Two things to keep in mind:

  • Self time aggregates across goroutines, so total self time can exceed wall-clock elapsed. Four workers each spending 5s at one position report ~20s of self time there though only ~5s of wall-clock passed - time-at-position summed over all goroutines, like pprof’s CPU time exceeding wall time.
  • Blocking counts as self time. A statement that waits (task.wait / task.waitAll on in-flight workers, or time.sleep) attributes that wall-clock wait to itself, so a waitAll line can show large self time with a hit count of one. It is real elapsed time the statement occupied, not computation.

Instrumentation (implementation)

The interpreter carries an optional Profiler interface (internal/interpreter/profiling.go) and three gate flags; nil means no profiling, the only hot-path cost being a nil check. The concrete collector lives in internal/profile and is injected only by this subcommand, so no profiling machinery compiles into either binary’s run path. Hook points:

  • execStmt wraps execStmtRaw, timing each statement. A profChild accumulator splits self from cumulative time (the standard nested-timing subtraction). It lives on each goroutine’s root Environment (env.root.profChild), not the shared Interpreter, so parallel spawn bodies each accumulate into their own snapshot root instead of racing one field; the collector’s maps are mutex-guarded for the same reason.
  • evalCall times each method-call body for the trace timeline.
  • eagerCopy records an eager deep copy at each value-storage site (def / assignment / parameter binding) when the value is a compound.
  • evalSpawn times the snapshotForSpawn deep copy.

evalExpr is deliberately not timed: a time.Now() around every literal read would swamp the profile with its own overhead.

TinyGo. Build-tag split like the linter: profile.go (!tinygo) is the only importer of internal/profile; devtools_tinygo.go stubs the subcommand in the run-only jennifer-tiny binary.

Part of the CLI reference.