Profiling

Profiling your own code

MilliSecs counts whole milliseconds, which is fine for a game that runs at 60 frames per second (one frame is 16.7 ms) and not good enough for anything faster. This page shows what to use instead, how to time the parts of a program, and how to read what the runtime reports.

Why MilliSecs is not enough

MilliSecs() returns an Int that goes up by one every millisecond, and every call returns the whole number, rounded down. A frame that takes 2 ms (500 frames per second) is therefore measured as 1, 2 or 3 ms depending on where in the millisecond the frame started, and one that takes 0.5 ms is measured as 0 or 1. Two things follow:

• A single frame time taken from two MilliSecs() calls is off by up to 1 ms. At 500 frames per second that is up to 50% of the frame. Adding up many of these frame times (for a score, an average or a maximum) keeps the rounding noise instead of cancelling it, and the number changes from run to run even when the program did exactly the same.
• A frame time of 0 makes a division by it useless, and a program that computes 1000 / (now - last) for its frames per second shows jumps between 333, 500 and 1000 instead of a steady value.

Measuring a long stretch with two calls (the start and the end of a run of 3000 frames) is still accurate to 1 ms in total. What breaks is everything that looks at one frame at a time.

On top of that, MilliSecs() wraps around after about 24.8 days, so only the difference between two calls means something. It counts on the same clock as Microseconds() (not following the system time), only in whole milliseconds and from the start of the system.

What to use instead

Need	Use
Time of one frame, time of a loaded file, any duration in a program that has to run the same everywhere	Microseconds
How long the parts of a frame take, with a report	ProfileBegin and ProfileEnd with ProfileValue
How long the runtime spends in UpdateWorld, RenderWorld, Flip, waiting for the GPU, ...	--profile, ProfileFPS and ProfileValue
Which frames stutter	ProfileSlow
Which functions of the program take the time (Windows)	ProfileSample

Microseconds

Microseconds() works in every program, needs no option, and returns a UInt64. Keep the result in a variable declared with :UInt64 and subtract before converting, so that nothing is lost:

start:UInt64 = Microseconds()
Delay 20
elapsed:UInt64 = Microseconds() - start
Print "took " + (Float(elapsed) / 1000.0) + " ms"

• A variable without a type is an Int and keeps only 32 bits, and a Float rounds. Float(Microseconds() - start) is fine, because the difference is small.
• Microseconds() counts from the start of the program and does not follow the system time, so setting the clock while the program runs does not disturb a measurement.
• The value has microsecond digits, but how finely the clock of the system ticks depends on the system, so do not expect the last digits to mean anything. Time many frames, or many repeats of the work, instead of trusting one tiny difference.

ProfileBegin and ProfileEnd

ProfileBegin "name" and ProfileEnd "name" time a part of the program, and the runtime adds the result to its own list of timers. They only do something in a program that was compiled with --profile (or -d); in any other program they are empty calls, so they can stay in the source of a release.

Graphics 64, 64, 0, 2
For i = 1 To 10
	ProfileBegin "ai"
	Delay 2 ; the part that is measured
	ProfileEnd "ai"
	Cls
	Flip
	Print "ai took " + ProfileValue("ai") + " ms"
Next

How it behaves:

• A key is a name of your own, in any case ("AI" and "ai" are the same), up to 63 characters. There are at most 64 keys, and a key can not be the name of one of the runtime's items (see ProfileItemName). A key that does not fit is ignored.
• The numbers are per frame. A frame is the time from one Flip to the next. Everything a key collects between two Flips is added up, so a part that runs 200 times in a frame (one call per entity, for example) gives the sum of all 200. At the Flip the sum is stored and starts again at 0.
• Read the numbers after the Flip. ProfileValue gives the frame that ended with the last Flip, in milliseconds as a Float. Before the first full frame, and for a key that does not exist, it returns 0. ProfileFlipCount changes with every Flip, so a program can see that there are new numbers.
• Different keys can be nested. A key is its own timer, and keys do not know about each other, so an outer part includes the time of the parts inside it. The runtime does not subtract anything: if "frame logic" contains "ai" and "physics", then "frame logic" is at least as large as the two together.
• The same key can not be nested in itself. ProfileBegin "ai" while "ai" is already running starts the timer again and forgets the first start, and the first ProfileEnd ends it. A function that calls itself can not be timed with one key on every level; time the outermost call instead.
• ProfileEnd without ProfileBegin does nothing, and so does a second ProfileEnd for the same start.
• The time is wall time (a clock that does not depend on the system time, like Microseconds), so a part that waits, for example in Delay, shows that waiting.
• Cost. A pair of calls reads the clock twice and searches the list of keys. That is cheap next to a frame, but do not put them around a single addition in a loop that runs a million times; time the loop.
• The timers can be stopped with ProfileEnable 0, for example while the program loads, and started again with 1.

Reading what the runtime measures

Compile with --profile (or -d, which turns it on as well):

blitzcc --profile -o game.exe game.bb

With --profile the runtime times UpdateWorld, the animation, RenderWorld (and its parts), EntityInView, CopyRect, Flip, Delay, the time the program waits for the GPU, and the passes the GPU runs. The program is a little slower for it (one clock read per call of those commands), which is why it is not on by default. Turn the report on with the environment variable BLITZLLVM_PROFILE_FPS=1 (older name: BLITZ_FPS=1) or with ProfileFPS 1, and it prints once a second on the standard error output, or into the file of ProfileOutput:

cpu: x86_64 v3: sse3 ssse3 ...
fps: 497, submits: 497, waiting: 12.4 ms
  gpu thread: vkQueueSubmit 20.1 ms, vkQueuePresentKHR 3.2 ms, frames that had to be waited for 0
  gpu passes: scene 610.2 ms, 2d 32.5 ms, copy 10.1 ms, present 4.0 ms, frame 702.7 ms
  UpdateWorld: 41.0 ms
  animation: 6.2 ms
  RenderWorld: 480.3 ms
  ...
  Flip: 120.8 ms
  ai: 83.4 ms

(The numbers are made up to show the layout.) How to read it:

• fps is the number of Flips in the last second. Every other number in a report is the total for that second in milliseconds, not per frame: divide by fps for an average per frame. RenderWorld: 480.3 ms at 497 fps is about 0.97 ms per frame.
• The lines that start with two spaces and belong to RenderWorld (lights+cameras, collect, draws, sort+group, record commands) are parts of it. clusters for GPU culling is part of draws. Do not add them to RenderWorld.
• waiting is the time the program waited for the GPU, and frames that had to be waited for counts frames where the GPU was still working on a frame when the program needed its slot. A program with a large waiting is limited by the GPU, not by its own code.
• The GPU passes come back a frame or two late, and are the time the GPU spent, which runs next to the CPU. They do not add up with the CPU timers.
• Your own keys from ProfileBegin are at the end of the list, with the total of the second like the others.
• If the program is vsynced (Flip 1), Flip will contain the wait for the display, and fps will be the refresh rate. Use Flip 2 or Flip 0 to measure how fast the program can go. See Presentation sync.

A frame that takes much longer than the others disappears in these totals. ProfileSlow milliseconds (or BLITZLLVM_PROFILE_SLOW) lists such frames one by one, with the frame number and where their time went:

slow frame 1432: 24.1 ms: UpdateWorld 0.8, RenderWorld 2.1, Flip 20.3, waiting for the GPU 19.7, ai 0.9
  gpu finished since the Flip before: scene 0.4 ms, 2d 0.0 ms, copy 0.0 ms, present 0.0 ms, frame 0.5 ms, vkQueueSubmit 0.1 ms

Only timers of at least 0.5 ms are listed.

To use the numbers inside the program, and not read text, use ProfileValue with the names from ProfileItemName, for example ProfileValue("RenderWorld: draws") or ProfileValue("frame").

The timers measure where the time goes, not how fast the program is. For the speed use the frame rate or the time of a fixed amount of work, and take the number of frames into account (see below).

Updating a program that uses MilliSecs

Before

A frame counter with MilliSecs for the frame time and the score of a benchmark. At 500 frames per second each dt is 1, 2 or 3 (or 0):

Graphics 64, 64, 0, 2
last = MilliSecs()
total = 0
frames = 0
worst = 0
While frames < 3000
	; ... the work of the frame ...
	Cls
	Flip 2

	now = MilliSecs()
	dt = now - last
	last = now
	total = total + dt   ; adds up the rounding
	If dt > worst Then worst = dt
	frames = frames + 1
Wend
Print "average " + (Float(total) / frames) + " ms, worst " + worst + " ms"
Print "fps " + (1000.0 / (Float(total) / frames))

After

The same, with Microseconds. The time is kept as a UInt64 and converted to milliseconds only when it is shown or compared:

Graphics 64, 64, 0, 2
last:UInt64 = Microseconds()
begin:UInt64 = last
frames = 0
worst# = 0.0
While frames < 3000
	; ... the work of the frame ...
	Cls
	Flip 2

	now:UInt64 = Microseconds()
	dt# = Float(now - last) / 1000.0   ; milliseconds, with a fraction
	last = now
	If dt > worst Then worst = dt
	frames = frames + 1
Wend
total# = Float(last - begin) / 1000.0
Print "average " + (total / frames) + " ms, worst " + worst + " ms"
Print "fps " + (1000.0 / (total / frames))

Things to take from this:

• The total is taken from one start and one end (last - begin). It is exact, and it does not depend on how many frames the loop has. Only the per-frame values (dt, worst) come from many small differences.
• The score or the frame rate should come from the total divided by the number of frames, not from the average of the single dt.
• Keep now, last and begin as UInt64. A variable that is not declared with :UInt64 is an Int and loses the upper bits of the value.
• Check that the program does not depend on dt being a whole number. A game that moves by speed * dt with dt in milliseconds as an Int becomes smoother with the fraction, which is usually what you want; if a value was a counter of whole milliseconds on purpose, keep it that way.

Finding out where the frame time goes

Add the parts of the frame as keys, compile with --profile, and read them after the Flip:

Graphics 64, 64, 0, 2
For frame = 1 To 600
	ProfileBegin "ai"
	; ... update all enemies ...
	ProfileEnd "ai"

	ProfileBegin "physics"
	; ... collisions ...
	ProfileEnd "physics"

	ProfileBegin "render"
	Cls
	; ... RenderWorld ...
	ProfileEnd "render"

	Flip 2
	If frame Mod 100 = 0
		Print "frame " + ProfileFlipCount() + ": " + ProfileValue("frame") + " ms (ai " + ProfileValue("ai") + ", physics " + ProfileValue("physics") + ", render " + ProfileValue("render") + ", waiting for the GPU " + ProfileValue("waiting for the GPU") + ")"
	EndIf
Next

Run it with BLITZLLVM_PROFILE_FPS=1 to get the averages per second, and with BLITZLLVM_PROFILE_SLOW=5 (or ProfileSlow 5.0) to see the frames that took more than 5 ms. A single value of ProfileValue is one frame, so it has the usual spread; look at the totals of the report or average several frames before you compare two versions.

Comparing two versions

• Compile both the same way, run them on the same machine, and look at several runs. A real-world program shows a spread between two runs of the same build, and a difference smaller than that spread is noise, not a result.
• Use Flip 2 or Flip 0 so the refresh rate does not cap the frame rate, and a window (not fullscreen) with a fixed size.
• Pick the GPU explicitly on a machine that has more than one, and say which. The timers of a program that was compiled with --profile are not the numbers of a release build; use them to find where the time goes, and a release build with Microseconds() for the final comparison.
• Turn the timers off with ProfileEnable 0 for the part that must not be measured, such as the loading.

Where the time goes inside the program (Windows)

ProfileSample "file" (or BLITZLLVM_PROFILE_SAMPLE=file) samples the program every millisecond and writes where it was. It only works on Windows, in a program compiled with --profile; with -g as well the call stacks are recorded, see Environment variables for the files and their format.

Summary of the commands

Command	What it does
Microseconds	Time in microseconds as a UInt64, in every program.
ProfileBegin, ProfileEnd	Time a part of the program, per frame. Needs --profile.
ProfileValue	The number of an item for the last frame, in milliseconds.
ProfileFlipCount	The number of the last measured frame.
ProfileItemCount, ProfileItemName	List the items that ProfileValue knows.
ProfileEnable	Turn the timers on or off at run time.
ProfileFPS	Print the report once a second.
ProfileSlow	List the frames that take longer than a number of milliseconds.
ProfileOutput	Send the text of the profiling to a file.
ProfileSample	Record where the program spends its time (Windows).