A compiler whose claim is speed owes its users a way to see where the time goes. This tutorial walks that road with the instruments the field already trusts — hyperfine, callgrind, gdb, perf — on one ordinary Mica binary, and shows what each of them answers. Every transcript below is a real session, captured against the shipped compiler; nothing was configured to get it. The claim the walk demonstrates is this: a fully optimized Mica binary carries, on request, the standard DWARF v5 line table, procedure entries and inlining records, so a profile attributes to source lines and names an inlined function as its own frame — while the machine code stays the plain release build’s to the byte.
The example is
ProfileWalk,
built to be profiled: three procedures with three different costs on a
fixed-size signal of 1024 float64 values. Fill runs once and is cheap;
Smooth and Energy run every one of 100,000 rounds and are the hot ones;
and Square is a one-line function the optimizer inlines into Energy — the
case that tests whether a profile can still name it.
Setup, step by step
Everything below works in the
tutorial container out of the
box: the image ships valgrind, hyperfine and gdb beside the
compiler. On a machine the devkit
set up, the same tools arrive with the profiling feature, which every
machine profile installs; on your own machine, mica-provision profiling
installs them, or sudo apt-get install valgrind hyperfine gdb does.
The two builds. Profiling needs nothing the optimizer does not already produce, plus the tables that say where the code came from. Those tables are one flag away:
cd examples/ProfileWalk
mica -c -l -o O2 -s ProfileWalk.mica -b build/release # the build you ship and benchmark
make # the same code with its tables: -o O2,profilingO2,profiling keeps the line table, the procedure entries and the inlining
records, and describes no variable — a register-homed value at this tier has no
frame location to promise. What it never does is change the code: the
instructions of the two binaries are identical, only the debug sections
differ. So you measure the plain build and profile the profiling build, and
both speak about the same machine code.
The program itself:
function Square(x : float64) : float64; { inlined into Energy by the optimizer }
begin
Square := x * x;
end;
function Energy() : float64; { one Square per element - the hottest line }
var
i : int64;
total : float64;
begin
total := 0.0;
for i := 0 to Size - 1 do
total := total + Square(samples[i]);
Energy := total;
end;
procedure Smooth(); { a three-point moving average, written back in place }
var
i : int64;
previous, current : float64;
begin
previous := samples[0];
for i := 1 to Size - 2 do
begin
current := samples[i];
samples[i] := (previous + current + samples[i + 1]) / 3.0;
previous := current;
end;
end;The program body calls Fill() once, then Smooth() and Energy() every
round, and prints one checksum.
Session 1: the headline, with hyperfine
The first number anyone asks for is the wall clock, and the first thing to check is that the profiling build did not move it:
$ hyperfine -N --warmup 5 --runs 30 build/release/ProfileWalk ../build/ProfileWalk/ProfileWalk
Benchmark 1: build/release/ProfileWalk
Time (mean ± σ): 101.7 ms ± 1.7 ms [User: 101.4 ms, System: 0.3 ms]
Range (min … max): 99.5 ms … 108.9 ms 30 runs
Benchmark 2: ../build/ProfileWalk/ProfileWalk
Time (mean ± σ): 101.6 ms ± 1.2 ms [User: 101.1 ms, System: 0.4 ms]
Range (min … max): 99.5 ms … 104.2 ms 30 runs
Summary
../build/ProfileWalk/ProfileWalk ran
1.00 ± 0.02 times faster than build/release/ProfileWalkSame code, same time, within the noise. -N skips the shell so the 100 ms
program is not measured together with a shell start-up; --warmup lets the
first runs fill the caches. This is the instrument a published claim is made
from, and it says nothing about where the 101 milliseconds go. For that,
read on.
Session 2: where the instructions go, with callgrind
callgrind runs the program under valgrind’s instruction-level simulator and
counts every instruction executed, deterministically — the same count on every
run, on every machine of the same architecture. Then callgrind_annotate
charges those counts to procedures and, with the line table, to source lines:
$ valgrind --tool=callgrind --callgrind-out-file=cg.out ../build/ProfileWalk/ProfileWalk
==660627== Collected : 2254889120
$ callgrind_annotate cg.out
--------------------------------------------------------------------------------
Ir file:function
--------------------------------------------------------------------------------
1,329,408,198 (58.96%) ProfileWalk.mica:main'2 [../build/ProfileWalk/ProfileWalk]
924,799,990 (41.01%) ProfileWalk.mica:ProfileWalk.Energy'2 [../build/ProfileWalk/ProfileWalk]2.25 billion instructions, and only two procedures carry them — because the
optimizer inlined the other two. Fill and Smooth are gone from the table
as procedures; their instructions are charged to main, where their code now
runs. Square was inlined into Energy the same way. callgrind attributes by
the symbol a piece of code lives in, so this is the honest picture of the
machine code, not of the source. (The '2 is callgrind’s numbering of a
function it believes it entered a second time: the runtime’s process start-up
runs before the program body, and callgrind reads the body as re-entering
main. The costs are unaffected.)
The source view restores the program’s own vocabulary. --auto=yes annotates
every line the line table names, and the hot lines stand out at once:
$ callgrind_annotate --auto=yes cg.out
-- Auto-annotated source: …/examples/ProfileWalk/ProfileWalk.mica
Ir
. function Square(x : float64) : float64;
. begin
102,400,000 ( 4.54%) Square := x * x;
. end;
. function Energy() : float64;
. ...
200,000 ( 0.01%) total := 0.0;
307,400,000 (13.63%) for i := 0 to Size - 1 do
512,000,000 (22.71%) total := total + Square(samples[i]);
100,000 ( 0.00%) Energy := total;
. procedure Smooth();
. ...
300,000 ( 0.01%) previous := samples[0];
306,800,000 (13.61%) for i := 1 to Size - 2 do
. begin
306,600,000 (13.60%) current := samples[i];
613,200,002 (27.19%) samples[i] := (previous + current + samples[i + 1]) / 3.0;
102,200,000 ( 4.53%) previous := current;Read the numbers as machine facts. The multiply inside Square costs exactly
102,400,000 instructions: one instruction per element per round, 1024 × 100,000,
the inlined body reduced to its one fmul. The accumulate line above it costs
five times that — the load, the add, and the address arithmetic the loop pays
per element. Smooth’s store line is the single most expensive line of the
program at 27 %: three loads, two adds, a division, a store. Every line’s
count is reproducible to the instruction, which is what makes callgrind the
instrument for before-and-after comparisons: change one line, run again,
and the difference is the change’s whole effect.
The inlined lines are attributed to their own source lines — line 39 is
Square’s line, not Energy’s — because the line table keeps naming the
callee’s source even after its code was planted inside the caller.
Session 3: the inlined frame, in the debugger
callgrind attributes by symbol. gdb reads the inlining records as well, and
that is the difference between “somewhere in main” and a frame with a name.
Set a breakpoint on Square’s one line — a function that, at this tier, has no
call of its own left — and run:
$ gdb -q ../build/ProfileWalk/ProfileWalk
(gdb) break ProfileWalk.mica:39
Breakpoint 1 at 0x19e8: ProfileWalk.mica:39. (2 locations)
(gdb) run
Breakpoint 1.2, ProfileWalk.Square () at ProfileWalk.mica:39
39 Square := x * x;
(gdb) bt
#0 ProfileWalk.Square () at ProfileWalk.mica:39
#1 ProfileWalk.Energy () at ProfileWalk.mica:50
#2 0x0000aaaaaaaa1898 in main () at ProfileWalk.mica:76
(gdb) info frame
Stack level 0, frame at 0xffffffffc8c0:
pc = 0xaaaaaaaa1a64 in ProfileWalk.Square (ProfileWalk.mica:39); saved pc = 0xaaaaaaaa1898
inlined into frame 1Two locations carry line 39: Square’s own body, which the compiler still
emits, and the copy inlined into Energy — and the program stops in the
second one, in a frame named ProfileWalk.Square, with ProfileWalk.Energy
beneath it at the line of the call (line 50) and main beneath that at its
call (line 76). info frame says what the records say: the frame is inlined
into frame 1. There is no call instruction anywhere in this stack above
main; the debugger reconstructs the two frames from the inlining records
alone.
The same holds for a procedure inlined into the program body:
(gdb) delete
(gdb) break ProfileWalk.mica:65
Breakpoint 2 at 0xaaaaaaaa1838: ProfileWalk.mica:65. (3 locations)
(gdb) continue
Breakpoint 2.2, ProfileWalk.Smooth () at ProfileWalk.mica:65
65 samples[i] := (previous + current + samples[i + 1]) / 3.0;
(gdb) bt
#0 ProfileWalk.Smooth () at ProfileWalk.mica:65
#1 main () at ProfileWalk.mica:75
(gdb) info locals
No locals.Smooth is named, main stands at the call’s line 75 — and info locals
answers No locals., which is the one thing the profiling build does not
carry. At this tier i, previous and current live in registers for as
long as the optimizer decides, and a table that promised a frame slot for them
would lie; the flag promises nothing it cannot keep. For variables, build with
debug, as the debugging tutorial does.
Session 4: sampling with perf
perf samples a running program on the clock and attributes the samples to
code; it costs almost nothing and needs no simulator, so it is the instrument
for a long run or a whole machine. It needs the kernel’s cooperation, which a
container usually does not have, so this session ran on a two-core arm64 cloud
machine created with the devkit (mica-cloud up --profile try --arch arm64),
which installed the tools on its own. The binary was built with --static
and copied over, so it ran without a single install.
Two things about the machine first. The processor’s counters were locked
(kernel.perf_event_paranoid at 4, the distribution’s default), and a virtual
machine of this type has no hardware counters at all — perf stat -e cycles
says so. The clock is enough:
$ sudo sysctl -w kernel.perf_event_paranoid=1
$ perf record -e cpu-clock -F 4000 -g -o perf.data ./ProfileWalk
[ perf record: Captured and wrote 0.106 MB perf.data (1029 samples) ]
$ perf report -i perf.data --stdio --no-children --inline
68.32% ProfileWalk ProfileWalk [.] main
|
--68.03%--Smooth (inlined)
main
__libc_start_call_main
__libc_start_main_impl
_start
31.39% ProfileWalk ProfileWalk [.] ProfileWalk.Energy
|
|--17.69%--Square (inlined)
| Energy (inlined)
| main
| ...
--13.70%--Energy (inlined)
--13.61%--main
...
0.19% ProfileWalk ProfileWalk [.] rt.root_static_linkRead it against callgrind’s table. By symbol, perf agrees: main and
ProfileWalk.Energy, 68 against 31 — the sampled clock, not the instruction
count, so the ratio shifts towards Smooth’s division. The --inline view
then opens the symbols up through the inlining records: 68 % of the program is
Smooth (inlined) inside main; inside Energy, 17.7 % is Square (inlined) and 13.7 % the loop around it. The call chains run down to _start
through the C runtime’s start-up, because every Mica binary carries call-frame
information at every tier and perf unwinds it. The last row is the runtime
itself: rt.root_static_link, a tiny routine procedures call at entry,
at a fifth of a percent.
perf annotate takes the view down to instructions, with the line table
placing them:
$ perf annotate -i perf.data --stdio -s ProfileWalk.Energy
Percent | Source code & Disassembly of ProfileWalk for cpu-clock (323 samples)
0.62 : 400af8: ldur x0, [x29, #-0x8]
0.93 : 400afc: mov x10, #0x2040
9.60 : 400b00: sub x10, x0, x10
32.20 : 400b04: ldr d19, [x10, x19, lsl #3]
56.35 : 400b08: fmul d17, d19, d19
0.00 : 400b0c: fadd d21, d21, d17
0.00 : 400b10: cmp x19, x14
0.00 : 400b14: b.ne 0x400af4 <ProfileWalk.Energy+0x50>Eight instructions per element, and the samples land on the load and the multiply — the two that wait on the data. A sampling profiler charges the instruction after the stall as often as the one that caused it, so read these as a region, not as a verdict on one opcode.
Reading an address
The same records serve the command line. Given any address from a crash, a
sample or a listing, addr2line -i unfolds the inlining:
$ addr2line -i -f -e ../build/ProfileWalk/ProfileWalk 0x1a64
ProfileWalk.Square
ProfileWalk.mica:39
ProfileWalk.Energy
ProfileWalk.mica:50One address, two frames, two lines — the inner function and the place it was inlined.
Why this works
Mica emits standard DWARF v5 and a standard ELF symbol table, so the instruments need nothing of Mica’s:
- Names at every tier. Every procedure keeps its flat name —
ProfileWalk.Energy,Outer.Inner.Take— in the symbol table of a release binary. Only--stripremoves them, for the binary you ship. - Call-frame information at every tier, so perf and a debugger unwind a release binary’s stacks without frame pointers or guesswork.
- The line table, the procedure entries and the inlining records under
profiling, on any optimization tier, in their standard forms: the entries that let callgrind charge lines, gdb name an inlined frame with the caller’s call line beneath it, addr2line unfold an address, and perf open a symbol into its inlined parts. - Unchanged code. The profiling flag adds tables, never instructions. The program you profile is the program you measured.
What this does not do
- No variable values at the optimizing tiers.
info localssaysNo locals.underprofiling, by design; build withdebugto inspect values. - callgrind attributes by symbol. Its procedure table shows an inlined
procedure’s instructions under the caller’s name; its
--auto=yessource view, gdb, perf’s--inlineand addr2line name the inlined procedure. - perf needs the kernel. A container without access to the host’s
performance events cannot sample; a machine of your own or a devkit cloud
machine can, with the counter lock relaxed as shown — or with
cpu-clockwhere the processor’s counters are not exposed.
Try it
cd examples/ProfileWalk
make run # O2,profiling, the build the instruments read
valgrind --tool=callgrind --callgrind-out-file=cg.out ../build/ProfileWalk/ProfileWalk
callgrind_annotate --auto=yes cg.out | less # procedures, then every annotated line
gdb -q ../build/ProfileWalk/ProfileWalk # break ProfileWalk.mica:39, run, bt
hyperfine -N --warmup 5 ../build/ProfileWalk/ProfileWalk # the wall clockChange Smooth’s division into a multiplication by a constant, run callgrind
again, and read the difference on one line — that is the loop this tutorial
exists to start.
Next
- Debugging across the boundary — the
debugbuild, with every variable, across Mica and C frames. - The devkit’s profiling road
and
mica-measure profile KERNEL, which profiles a benchmark kernel beside its C twin under callgrind. - The CLI reference for the
--optimizespellings and--strip.