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 mica-container/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, byte for byte. What differs
besides the debug sections is what describes each build: the symbol table, the
build id, and the manifest that mica --inspect prints, which records
"profiling":true and, because make builds from the example’s
mica.project, "version":"1.0.0"; the read-only data differs only in the one
value that holds the manifest’s length. 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 ± σ): … ms ± … ms [User: … ms, System: … ms]
Range (min … max): … ms … … ms 30 runs
Benchmark 2: ../build/ProfileWalk/ProfileWalk
Time (mean ± σ): … ms ± … ms [User: … ms, System: … ms]
Range (min … max): … ms … … ms 30 runs
Summary
… ran
… ± … times faster than …Same code, same time, within the noise: the two means stay within a
percent or two of each other, and which build the summary names as faster
changes from run to run. -N skips the shell so the
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 time goes. 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 program’s own
procedures and lines count the same on every run and on every machine of the
same architecture, and only the total moves, with the environment the C library
reads as it starts, so a share can differ in its last digit. Then callgrind_annotate
charges those counts to procedures and, with the line table, to source lines.
The counts below are an arm64 machine’s; an x86-64 machine counts its own,
just as exactly:
$ valgrind --tool=callgrind --callgrind-out-file=cg.out ../build/ProfileWalk/ProfileWalk
==…== Collected : …
$ callgrind_annotate cg.out
--------------------------------------------------------------------------------
Ir file:function
--------------------------------------------------------------------------------
1,328,908,199 (58.99%) ProfileWalk.mica:main'2 […/build/ProfileWalk/ProfileWalk]
923,199,995 (40.98%) 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: …ProfileWalk.mica
Ir
. function Square(x : float64) : float64;
. begin
102,400,000 ( 4.55%) Square := x * x;
. end;
400,000 ( 0.02%) function Energy() : float64;
. ...
100,000 ( 0.00%) total := 0.0;
307,300,000 (13.64%) for i := 0 to Size - 1 do
512,000,000 (22.73%) total := total + Square(samples[i]);
100,000 ( 0.00%) Energy := total;
. procedure Smooth();
. ...
100,000 ( 0.00%) previous := samples[0];
306,700,000 (13.61%) for i := 1 to Size - 2 do
. begin
306,600,000 (13.61%) current := samples[i];
613,200,004 (27.22%) samples[i] := (previous + current + samples[i + 1]) / 3.0;
102,200,000 ( 4.54%) 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. Energy’s heading line carries the
procedure’s entry, four instructions a call, because the line table pins a
procedure’s entry to its declaration line. The accumulate line in Energy costs
five times the multiply — 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 %: six instructions an element, the load of the next sample, two
additions, that sample’s index, a division and the 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.
The profiling build carries gdb’s printers for Mica strings, which gdb runs
only from a path you trust; -iex gives that trust as gdb starts, as in the
debugging tutorial, and without it gdb begins with a
warning that it declined them:
gdb -q -iex "add-auto-load-safe-path ../build/ProfileWalk/ProfileWalk" ../build/ProfileWalk/ProfileWalkSet a breakpoint on Square’s one line — a function that, at this tier, has no
call of its own left — and run:
(gdb) break ProfileWalk.mica:39
Breakpoint 1 at 0x2878: file ProfileWalk.mica, line 39.
(gdb) run
Starting program: …/mica-container/examples/build/ProfileWalk/ProfileWalk
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/aarch64-linux-gnu/libthread_db.so.1".
Breakpoint 1, Square () at ProfileWalk.mica:39
39 Square := x * x;
(gdb) bt
#0 Square () at ProfileWalk.mica:39
#1 Energy () at ProfileWalk.mica:50
#2 0x0000aaaaaaaa27c4 in main () at ProfileWalk.mica:76
(gdb) info frame
Stack level 0, frame at 0xffffffffc770:
pc = 0xaaaaaaaa2878 in Square (ProfileWalk.mica:39); saved pc = 0xaaaaaaaa27c4
inlined into frame 1
source language minimal.
Arglist at unknown address.
Locals at unknown address, Previous frame's sp in spOne location carries line 39: the copy inlined into Energy, Square’s
only caller. A function inlined at every call keeps no body of its own, just
as GCC drops a static function it inlined everywhere, so the program stops
there, in a frame named Square, with 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. Above main, only one frame comes from a call instruction:
main calls Energy, and the saved pc is that call’s return address. Square
has no call left; the debugger builds its frame from the inlining records
alone.
The same holds for a procedure inlined into the program body:
(gdb) delete 1
(gdb) break ProfileWalk.mica:65
Breakpoint 2 at 0xaaaaaaaa279c: file ProfileWalk.mica, line 65.
(gdb) continue
Continuing.
Breakpoint 2, Smooth () at ProfileWalk.mica:65
65 samples[i] := (previous + current + samples[i + 1]) / 3.0;
(gdb) bt
#0 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 is not in the tutorial image — the
devkit’s profiling feature installs it, and so does your distribution’s perf
package — and it needs the kernel’s cooperation. This session ran in one of
the tutorial container’s dev
containers, which start with --security-opt seccomp=unconfined: arm64 Linux
on an Apple-silicon Mac, under Docker Desktop’s LinuxKit kernel.
Two things about the machine first. The kernel keeps its events at
kernel.perf_event_paranoid level 2, which lets a user sample the user-space
code of their own programs and nothing more — the :u perf adds to the
events below — and the virtual machine has no hardware counters at all;
perf stat -e cycles says so. The clock is enough:
$ perf stat -e cycles ../build/ProfileWalk/ProfileWalk
Error:
No supported events found.
The cycles:u event is not supported.
$ perf record -e cpu-clock -F 4000 -g -o perf.data ../build/ProfileWalk/ProfileWalk
15718105.697706
[ perf record: Woken up 1 times to write data ]
Failed to open /proc/schedstat
[ perf record: Captured and wrote 0.050 MB perf.data (465 samples) ]
$ perf report -i perf.data --stdio --no-children --inline -q
56.99% ProfileWalk ProfileWalk [.] ProfileWalk.Energy
|
---ProfileWalk.Energy
|
|--29.46%--Energy (inlined)
| main
| __libc_start_call_main
| call_init (inlined)
| __libc_start_main_impl (inlined)
| _start
|
--27.53%--main
__libc_start_call_main
call_init (inlined)
__libc_start_main_impl (inlined)
_start
42.80% ProfileWalk ProfileWalk [.] main
|
|--41.72%--main
| main
| __libc_start_call_main
| call_init (inlined)
| __libc_start_main_impl (inlined)
| _start
|
--1.08%--Smooth (inlined)
main
__libc_start_call_main
call_init (inlined)
__libc_start_main_impl (inlined)
_start
0.22% ProfileWalk ProfileWalk [.] rt.root_static_linkThe /proc/schedstat line is perf noting that this kernel keeps no scheduler
statistics; the samples do not need them.
Read it against callgrind’s table. By symbol, perf finds the same two
procedures, ProfileWalk.Energy and main, but at 57 against 43, where
callgrind counted 41 against 59: the sampled clock, not the instruction count,
and on this processor Energy’s fewer instructions take the longer time. The
--inline view then opens the symbols up through the inlining records, and
perf names each address’s frames as addr2line does in
Reading an address below: the innermost line under the procedure
whose code holds it, each line above under its own procedure’s name, marked
(inlined) where no symbol carries that name. So the 29.5 % that pass through
Energy (inlined) are the samples on Square’s multiply, inlined at
Energy’s call on line 50, and the 27.5 % beside them the loop around it;
inside main, the 41.7 % that pass through a second main are Smooth’s
loop, inlined at the body’s call on line 75, and 1.1 % more carry Smooth’s
own name. The call chains run down to _start through the C library’s start-up,
whose own inlined steps perf names the same way: with -g, perf follows the
frame records the procedures keep on the stack, and the inlining records name
the procedures that have no frame of their own. 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:u (265 samples, percent: local period)
-------------------------------------------------------------------------------------------------------------
:
:
:
: 3 Disassembly of section .text:
:
: 5 0000000000002840 <ProfileWalk.Energy>:
: 6 begin
: 7 Square := x * x;
: 8 end;
:
: 10 { The energy of the signal: one pass over the array, one Square per element - the hottest line of the program. }
: 11 function Energy() : float64;
0.00 : 2840: sub sp, sp, #0x10
0.00 : 2844: str x29, [sp]
0.00 : 2848: str x30, [sp, #8]
0.00 : 284c: mov x29, sp
0.00 : 2850: sub sp, sp, #0x10
0.00 : 2854: bl 28e0 <rt.root_static_link>
: 18 var
: 19 i : int64;
: 20 total : float64;
: 21 begin
: 22 total := 0.0;
0.00 : 2858: fmov d18, xzr
: 24 for i := 0 to Size - 1 do
0.00 : 285c: mov x13, #0x0 // #0
0.00 : 2860: b 2868 <ProfileWalk.Energy+0x28>
6.04 : 2864: add x13, x13, #0x1
: 28 total := total + Square(samples[i]);
0.00 : 2868: ldur x0, [x29, #-8]
22.26 : 286c: mov x10, #0x2030 // #8240
0.00 : 2870: sub x10, x0, x10
3.40 : 2874: ldr d20, [x10, x13, lsl #3]
: 33 Square := x * x;
51.70 : 2878: fmul d17, d20, d20
: 35 total := total + Square(samples[i]);
16.23 : 287c: fadd d18, d18, d17
: 37 for i := 0 to Size - 1 do
0.00 : 2880: cmp x13, #0x3ff
0.00 : 2884: b.ne 2864 <ProfileWalk.Energy+0x24> // b.any
: 40 Energy := total;
0.38 : 2888: fmov d0, d18
: 42 end;
0.00 : 288c: mov sp, x29
0.00 : 2890: ldr x29, [sp]
0.00 : 2894: ldr x30, [sp, #8]
0.00 : 2898: add sp, sp, #0x10
0.00 : 289c: retNine instructions per element, each under the line it came from: the
increment, the comparison and the branch of the for line, the four that
reach samples[i] and the addition of the accumulating line, and Square’s
one multiply — callgrind’s three, five and one. The samples land on the
multiply (52 %), on the mov that starts the array’s address (22 %) and on
the addition (16 %). A sampling profiler charges the instruction after a
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 — here Square’s pc from session 3, less the load base
gdb placed the program at, the multiply perf annotate listed at 2878 —
addr2line -i unfolds the inlining, and --basenames prints each source file
without its folder:
$ addr2line -i -f --basenames -e ../build/ProfileWalk/ProfileWalk 0x2878
ProfileWalk.Energy
ProfileWalk.mica:39
Energy
ProfileWalk.mica:50One address, two frames, two lines: Square’s multiply on line 39, in the
code of ProfileWalk.Energy, and the call on line 50 in Energy where it was
inlined. addr2line names each frame by the procedure whose code holds the
address, so the inlined Square shows as its line, and gdb names it.
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 with code of its own 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. A procedure inlined at every call, asSquareandSmoothare here, keeps no code and so no symbol of its own; underprofilingthe inlining records still name it, andbreak Squarestops in every place it was inlined. - 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 and perf’s--inlinename the inlined procedure, and addr2line its line. - perf needs the kernel. A container without access to the kernel’s
performance events cannot sample. Where the kernel locks them further than
level 2,
sudo sysctl -w kernel.perf_event_paranoid=1relaxes the lock; where the processor’s counters are not exposed,cpu-clocksamples on the clock, as above.
Try it
In the example’s folder, where the setup put you:
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 # procedures, then every annotated line
gdb -q -iex "add-auto-load-safe-path ../build/ProfileWalk/ProfileWalk" ../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.