Profiling

When a game runs slowly, the first question is where the time goes. raylib-miniscript has a built-in profiler that answers it: run your script with --profile, play for a while, and you get a report of which functions and which lines took the time, plus a flame graph you can browse.

Profiling works in the desktop build only.

Making a profile

Run your script with --profile and a name for the results:

build/raylib-miniscript --profile myprofile path/to/game.ms

The script runs as usual, just a little slower (see Accuracy and overhead). Play through the part you want to measure, then close the window, let the script end, or press Ctrl-C. Three files are written:

File	What it is
myprofile.txt	a readable report
myprofile.speedscope.json	the full profile, for the viewer described below or for speedscope.app
myprofile.folded	the same data as plain "folded stacks", for flamegraph.pl and other tools that read that format

The name is a path without an extension, relative to the folder you launched from (even if your script changes its working directory). The folder must already exist; if it doesn't, the profiler says it could not write the files.

When the run ends, the profiler also prints a short summary to the console: the total time recorded, and the top few functions.

Reading the report

myprofile.txt begins with a summary of where the time went:

Time recorded:               0.207 s
  MiniScript code:           0.182 s  ( 87.6%)
  timed raylib calls:        0.000 s  (  0.0%)
  garbage collection:        0.026 s  ( 12.4%)  1 collections, 25.69 ms each
  host, between slices:      0.000 s  (  0.0%)

For a game that draws frames, it also lists the timed raylib calls: those that can take a long time, with their total time, call count, and time per call.

Then come two tables. Functions by self time lists each function with two numbers:

• self time is spent in the function's own code, including any intrinsics it calls.
• total time also includes the MiniScript functions it calls.

A function with high self time is slow itself; a function with low self time but high total time is slow because of what it calls.

   self ms   self%   total ms  total%  function
    167.43   80.8%     167.43   80.8%  churn (line 5)
     25.69   12.4%      25.69   12.4%  (garbage collection)
     14.04    6.8%      14.04    6.8%  fib (line 1)
      0.16    0.1%     207.33  100.0%  @main

Functions are named by the variable they were assigned to and the line where they were defined, plus the file name for functions in imported modules (update (player.ms line 40)). @main is your main program.

Hottest lines lists individual source lines by self time, which usually points straight at the problem:

   self ms   self%  line  in function
    139.64   67.3%  line 8  in churn (line 5)
     27.78   13.4%  line 7  in churn (line 5)
     25.69   12.4%  line 14  in @main  (garbage collection)

Special entries

Some entries aren't MiniScript functions:

• [raylib.EndDrawing] and other bracketed names are raylib calls that can take a long time. The profiler times these exactly and charges them to the line that called them. They are EndDrawing, WaitTime, SwapScreenBuffer, UpdateMusicStream, and the Begin/End mode calls that flush raylib's batch of drawing (texture, 2D, 3D, shader, blend and scissor modes).
• [raylib.EndDrawing] includes the wait for SetTargetFPS, so in a game that keeps up with its frame rate, most of that time is idle. That is good news, not a problem. The other timed calls are mostly raylib sending drawing to the graphics card.
• (garbage collection) is time spent reclaiming memory. MiniScript collects inside yield and wait, so this is charged to the line with the yield. A lot of it means the script is creating a lot of short-lived lists, maps or strings.
• (host, between script slices) is the engine's own work between runs of your script.

Viewing a profile

raylib-miniscript comes with a profile viewer, written in MiniScript:

build/raylib-miniscript tools/profview.ms myprofile.speedscope.json

It shows a flame graph above a table of functions.

In the flame graph, each bar is a function, as wide as its share of the time, with the functions it called stacked beneath it. MiniScript functions are warm colors, timed raylib calls are blue, garbage collection is green, and the host's own work is gray.

To...	Do this
see a bar's file, line and times	hover over it
zoom in on a bar	click it
zoom back out	right-click, Escape or Backspace
zoom all the way out	Home
highlight a function wherever it appears	click its row in the table
sort the table	click the self or total column heading
switch between the By function and By line views	Tab
scroll	the mouse wheel, over either panel

The By function view gives one bar per function. The By line view splits each function into its lines, so you can see which call site each call came through.

Options

These go after the file name:

Option	Effect
--view <n>	start in view n: 0 is By function, 1 is By line
--select <name>	highlight the first function whose name contains name
--zoom <name>	zoom to the heaviest bar whose name contains name
--screenshot <file>	draw one frame, save it as file, and quit
--selftest	check that the profile's totals add up, print a summary, and quit (no window)

For example, to open a profile already zoomed in on a function called update:

build/raylib-miniscript tools/profview.ms myprofile.speedscope.json --zoom update

Other viewers

speedscope.app also reads myprofile.speedscope.json: drag the file onto the page. It runs in your browser, so nothing is uploaded. The menu at the top switches between the By function and By line profiles; the Sandwich view of By line lists the hottest lines. Selecting a frame shows its file and line.

myprofile.folded works with Brendan Gregg's flamegraph.pl and other tools that read folded stacks. Its times are in microseconds.

Accuracy and overhead

The profiler samples: it runs your script a few hundred instructions at a time, and after each batch it records the call stack and how long the batch took. Times are wall-clock times. This has a few consequences:

• Most intrinsics aren't timed individually. Their time is charged to the line where their batch ends, which is the line that called them, or one shortly after it. (The special entries above are the exceptions.)
• A yield always ends a batch, so the yield's line also gets the work done since the previous sample: the last few hundred instructions before it, and any untimed intrinsics among them. If a yield line looks surprisingly expensive, that's probably why.
• Totals are reliable over a run of any length; a single line's numbers are more reliable the more often it ran.

--profile-interval <n> changes the average batch size (the default is 250). Smaller batches charge time to the right line more often, but slow the script down more. On a CPU-bound benchmark, profiling adds about 20% to the run time at 250, 50% at 100, and 90% at 50.

When you run without --profile, the profiler costs nothing measurable.