Martin Helmut Fieber

Debugging and profiling Lua

Introduction

After having set up Lua, modules with LuaRocks covered, and a solid understanding of testing Lua code, it is time to confront failure — errors, to be precise. And how to fix them.

First and foremost, it is important to understand the anatomy of a Lua error messages, how to define custom errors, work with them, and look at what Lua brings out of the box to handle and incorporate error handling, from protected calls to asserts.

A great strength of Lua is its flexibility, and that goes for errors too. Nevertheless, this also means a flexible approach to debugging. Looking at this article in different ways, from manual to IDE-based debugging with various editors as an example.

To round it all off: ways to profile a Lua application, including a simple tracer that can produce flame graphs, digging even so deeper into solid Lua applications.

All the code shown in this article is also available in the companion repository on GitHub, branch part-4.

About versions

The latest Lua version as of writing is 5.5 (released December 2025), though almost everything in this article series will work with Lua 5.1 (released February 2006) and up. If this deviates, a callout like the following will signal the required version.

An overview of all versions and their main features can be found on the official Lua version history page.

Errors

Any unexpected behaviour in Lua will raise an error. To actually solve problems, errors need to be understood. Besides reading them, it is equally important to understand how to construct them, where they originate from, handle them, and, in general, the flexible and dynamic nature of errors in Lua.

Anatomy of a Lua error

Looking at an error, raised by indexing a non-table value; even though improbable, it gives a good look at a short error message to deconstruct.

-- src/errors/built-in.lua
local non_table = 1
print(non_table[1])

Running this Lua code through a terminal will result in the following error message:

lua: src/errors/built-in.lua:2: attempt to index a number value (local 'non_table')
stack traceback:
  src/errors/built-in.lua:2: in main chunk
  [C]: in ?

The Lua error consists of two sections: the first is the error location, e.g., a file name with a line number, as well as the actual error message; the second section is a stack trace.

The error location can be a file name with a line number, but it can also be the standard input when Lua was run directly through the REPL, or something completely else when a user defined error was raised that is not a string.

After the location information comes the actual error message or description.

The second section of the error message is a stack trace, starting as an indented text block after the line stack traceback:. Line by line, it gives information about the origin of an error, followed through by the function call stack.

In this error example, the first stack trace line gives the executed file with line number src/errors/built-in.lua:2. The code was run in main chunk. Every piece of Lua code is a "chunk", where the "main chunk" is the entry point of a Lua program.

The second line does the same, giving the location as "in a C function" [C], run in ?. The whole line [C]: in ? tells a function was run as a C function, therefore the unknown name in ?, as it is common to see a mix of Lua and C functions executed, especially as part of the Lua standard library.

Running another example, this time with a deeper stack trace.

-- src/errors/built-in-nested.lua
local function will_error()
  local non_table = 1
  return non_table[1]
end

local function parent_function()
  will_error()
end

parent_function()

This will result in the following error message:

lua: src/errors/built-in-nested.lua:3: attempt to index a number value (local 'non_table')
stack traceback:
  src/errors/built-in-nested.lua:3: in upvalue 'will_error'
  src/errors/built-in-nested.lua:7: in local 'parent_function'
  src/errors/built-in-nested.lua:10: in main chunk
  [C]: in ?

User defined errors

-- src/errors/user-defined.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.")
  end
  return "Hello, " .. str
end

print(greet(1))

This will result in the already-seen error message structure, showing where the error happened, including the call stack, but with a user-defined error message.

lua: src/errors/user-defined.lua:3: Function 'greet' expects a string as argument.
stack traceback:
  [C]: in function 'error'
  src/errors/user-defined.lua:3: in local 'greet'
  src/errors/user-defined.lua:8: in main chunk
  [C]: in ?

Defining the error origin

Looking at the previous user-defined error message, even though it is already handy, from a user perspective, the reason for the error is that the function greet was called wrong. The error message though points to the call of error inside the greet function — line three of the file via src/errors/user-defined.lua:3.

To solve this and give the user a better message to quickly find the actual problem origin, the error function takes a second argument, the calling hierarchy level, telling "how many levels up did this happen".

Level 1 is the current function, level 2 the parent, and so on. Therefore, changing the greet function to point to its parent when called will give a much better error origin.

-- src/errors/user-defined-origin.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.",
      2) -- One up
  end
  return "Hello, " .. str
end

print(greet(1))

With this change, the line number of the error origin is now the caller function at line eight.

lua: src/errors/user-defined-origin.lua:8: Function 'greet' expects a string as argument.
stack traceback:
  [C]: in function 'error'
  src/errors/user-defined-origin.lua:3: in local 'greet'
  src/errors/user-defined-origin.lua:8: in main chunk
  [C]: in ?

Try..catch, protected call? pcall!

Alright, now how to "catch" or handle an error when it occurs? With a protected call via the function pcall, it takes a function to be called in protected mode; any further arguments get passed to that function when called.

So instead of calling a function directly, …

some_function("first argument", 2)

… it gets called through pcall.

pcall(some_function, "first argument", 2)

Using the previous example of the greet function, this time wrapped in a pcall.

-- src/errors/pcall.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.")
  end
  return "Hello, " .. str
end

-- Proteted call:
if pcall(greet, 1) then
  print("No errors")
else
  print("Error calling greet!")
end

When run, pcall will return a status and, if an error occurred, the error object or the function result as the second return value. The status is true if there are no errors, false if there are.

-- src/errors/pcall-return.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.",
      2)
  end
  return "Hello, " .. str
end

local status, result = pcall(greet, 1)

if status then
  print(result)
else
  print("Error calling greet:\n", result)
end

Running this will result in the following message:

Error calling greet:
  Function 'greet' expects a string as argument.

Be aware that the error message provided by pcall is missing the error location as well as a stack trace. This is due to pcall unwinding part of the stack that goes from pcall to the error caller.

To retrieve a proper stack trace, the function xpcall needs to be used.

xpcall

The function xpcall works just like pcall, running a function in protected mode to be able to handle any errors. The difference is that xpcall takes an error handler as a second argument.

When an error is raised, the error handler gets called with it. Any operation can then be performed, though to get an error result from the call, a return value needs to be provided.

Looking again at the example function greet:

-- src/errors/xpcall.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.",
      2)
  end
  return "Hello, " .. str
end

A possible error handler could check for a specific error string to transform the error message, add additional information to the error, etc.

local function handle_error(err)
  if err == "<unknown>" then
    return "Unknown error!"
  end
  return err
end

Then xpcall can be called with the function to run in protected mode, the error handler, and any arguments for the function.

local status, result = xpcall(greet, handle_error, 1)

if not status then
  print("Error calling greet:\n", result)
end

A very useful feature of xpcall compared to pcall is the access to a stack trace before it gets unwound. Generally, they work the same: after the call, when the status is retrieved, the stack is unwound and part of the function call stack is lost. But, a full stack trace can be retrieved in xpcall's handler function.

As an example, calling debug.traceback after the xpcall function returned gives the same result as pcall.

-- src/errors/xpcall-with-stacktrace.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.",
      2)
  end
  return "Hello, " .. str
end

local function handle_error()
  -- Do nothing for now
end

if not xpcall(greet, handle_error, 1) then
  print(debug.traceback())
end

Meaning, it will only show part of the stack:

stack traceback:
  src/errors/xpcall-with-stacktrace.lua:13: in main chunk
  [C]: in ?

Though, calling debug.traceback inside the handler gives access to the full stack trace.

-- src/errors/xpcall-with-stacktrace.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.",
      2)
  end
  return "Hello, " .. str
end

local function handle_error(err)
  -- Call inside error handler:
  return err .. "\n" .. debug.traceback()
end

local status, result = xpcall(greet, handle_error, 1)

if not status then
  print(result)
end

Running this example will show the full call stack:

Function 'greet' expects a string as argument.
stack traceback:
  src/errors/xpcall-with-stacktrace.lua:10: in function <src/errors/xpcall-with-stacktrace.lua:8>
  [C]: in function 'error'
  src/errors/xpcall-with-stacktrace.lua:3: in function <src/errors/xpcall-with-stacktrace.lua:1>
  [C]: in function 'xpcall'
  src/errors/xpcall-with-stacktrace.lua:13: in main chunk
  [C]: in ?

An error can be anything

So far, all errors in the examples were strings, and this is also the case for all errors raised by built-in functions. Nevertheless, "error message" is not a fully correct name, as "error object" describes better that an error can be any value.

Meaning, besides primitive values, the error function can also take a table as value. A caveat of this is that only strings get the "first line location information" prepended to the error description. It is then up to the implementation to give good information to the user to find where a problem originates.

Given a function work that will raise an error with a custom error table:

-- src/errors/custom-error.lua
local function work(str)
  if type(str) ~= "string" then
    error({
      message = "Function 'work' needs a string.",
      status = 42
    }, 2)
  end
  return "Doing some work: " .. str
end

work(1)

Without any extra care, the error message shown when run the code will miss any content of the error table, besides saying the "error object is a table value".

lua: (error object is a table value)
stack traceback:
  [C]: in function 'error'
  src/errors/custom-error.lua:3: in local 'work'
  src/errors/custom-error.lua:11: in main chunk
  [C]: in ?

One version better is using pcall to handle a function that can raise an error with a custom error table.

-- src/errors/custom-error-pcall.lua
local function work(str)
  if type(str) ~= "string" then
    error({
      message = "Function 'work' needs a string.",
      status = 42
    }, 2)
  end
  return "Doing some work: " .. str
end

local status, err = pcall(work, 1)

if not status then
  print(err.message)
end

This will give the option to actually print a value from the error table, like a message, but due to pcall destroying part of the call stack will miss additional information.

In the example, only printing the error message from the table without any location information:

Function 'work' needs a string.

Those types of errors are not just strings, making it necessary to check every time what kind of error gets returned and handle it appropriately.

This makes xpcall indispensable. Using xpcall, custom error tables can be transformed into strings to be handled in any standard way, while also having access to a full stack trace.

Same example function: work.

-- src/errors/custom-error-xpcall.lua
local function work(str)
  if type(str) ~= "string" then
    error({
      message = "Function 'work' needs a string.",
      status = 42
    }, 2)
  end
  return "Doing some work: " .. str
end

The error handler can transform this error table into an error message. Adding additional location information.

local function handle_error(err)
  if err.status == 42 then
    -- Any special handling
  end
  return err.message .. "\n" .. debug.traceback()
end

Enabling a standard use where the expectation can be that any error message is a string, ready to be presented to the user.

local status, result = xpcall(work, handle_error, 1)

if not status then
  print(result)
end

The error result when running the full example:

Function 'work' needs a string.
stack traceback:
  src/errors/custom-error-xpcall.lua:15: in function <src/errors/custom-error-xpcall.lua:11>
  [C]: in function 'error'
  src/errors/custom-error-xpcall.lua:3: in function <src/errors/custom-error-xpcall.lua:1>
  [C]: in function 'xpcall'
  src/errors/custom-error-xpcall.lua:18: in main chunk
  [C]: in ?

assert

Another built-in error handling facility is the assert function. If a value is false or nil assert will raise an error, where the second argument can be an error message.

-- src/examples/assert-load.lua
local function readConfig(path)
  local config = {}
  assert(
    loadfile(path, "t", config),
    "Config not found!")()
  return config
end

local config = readConfig("src/examples/config.lua")
print(config.speed, config.jumpHeight)

Running this code with the file src/examples/config.lua not existent will raise an error and show the provided error message.

lua: src/examples/assert-load.lua:3: Config not found!
stack traceback:
  [C]: in function 'assert'
  src/examples/assert-load.lua:3: in local 'readConfig'
  src/examples/assert-load.lua:7: in main chunk
  [C]: in ?

If a function already returns a value and a potential error message as the second return value, the error message gets substituted as the second argument to the assert call when the first return value is nil.

Taking the previous example, the error message can be removed, as loadfile will return nil as the first, and a string error as the second return value.

-- src/examples/assert-load.lua
local function readConfig(path)
  local config = {}
  assert(loadfile(path, "t", config))()
  return config
end

local config = readConfig("src/examples/config.lua")
print(config.speed, config.jumpHeight)

Running this code will show the error from loadfile.

lua: src/examples/assert-load.lua:3: cannot open src/examples/config.lua: No such file or directory
stack traceback:
  [C]: in function 'assert'
  src/examples/assert-load.lua:3: in local 'readConfig'
  src/examples/assert-load.lua:7: in main chunk
  [C]: in ?

The assert function can and should be used wherever appropriate to help catch issues early and give good feedback to potential users.

Aside from that, assert can also be used to replace a typical error handling patter. The following code with error handling can be rewritten much smaller with assert.

-- An often seen error handling pattern
local value, err = loadfile("some/file.lua", "t")
if not value then
  error(err)
end

As said, assert can substitute a second return value as error message. When there is no error raised, the first return value will be returned by the assert call.

-- A better pattern
local value = assert(loadfile("some/file.lua", "t"))

Debugging Lua

There is no built-in debugger in Lua, but, depending on the environment Lua is run in, different options do exist. One of those options is developing Lua in an editor or IDE that offers debugging capabilities with breakpoints and inspections, using a debugger library, writing own debugger functions with Lua and the provided debug module, or just plain and simple manual debugging via assert and print calls scattered over the code.

Manual debugging

Manual debugging sounds a lot like having a bunch of print calls all over the code, but I would argue that proper error handling in the first place is half the way reducing any debugging effort in the first place.

Too often, a comment like the following can be found in code, even production code.

-- TODO: Handle errors ...

Not only handling errors early, but thinking about good error handling from the start, will reduce a large array of bugs to find. The earlier chapter about errors gives a good first read on what error handling methods exists in Lua.

This part will look at some simple options often frowned upon when it comes to debugging — even though they are used by many daily — adding print calls in the code.

print and debug

Just throwing in print calls is usually not the best way to go, that might be true, but if that is the way things go, Lua offers some tools to make those print calls worth something.

Instead of only printing a value where an issue might be suspected, …

-- src/errors/print-debug.lua
local function caller(fn)
  -- Some code ...
  local value = fn()
  print("Problem:", value)
end

… it can be helpful to add a call stack trace to it via debug.traceback.

-- src/errors/print-debug.lua
local function caller(fn)
  -- Some code ...
  local value = fn()
  print("Problem:", value, debug.traceback())
end

The debug.getinfo function can be used to inspect a function or stack level. It will return a table with data about the given function or stack level. For example, using a combination of the properties source and linedefined on a function to get the file and line number for a function.

-- src/errors/print-debug.lua
local function caller(fn)
  -- Some code ...
  local value = fn()
  print("Problem at:",
    debug.getinfo(fn).source
      .. ":" ..
      debug.getinfo(fn).linedefined)
end

-- Some example function
local function callback()
  return "Great value!"
end

print(caller(callback))

Running this will print the following message to the console:

Problem at: @src/errors/print-debug.lua:11

The external inspect module that can be installed via LuaRocks can help to print all values of a table — very handy when debugging.

local function caller(fn)
  -- Some code ...
  local value = fn()
  print("Why is this wrong:", value,
    inspect(debug.getinfo(fn)))
end

debugger.lua

A great option between "print debugging" and a full-blown IDE usage is debugger.lua by Scott Lembcke. It is a single Lua file (or C header if preferred), ready to be included in a project to get a terminal-based, interactive Lua debugger.

I will not go into detail on the C-header usage, but rather focus on the Lua file version of the debugger.

Installation

From the repository at github.com/slembcke/debugger.lua drop the single debugger.lua file into a project. That's it. Now the module can be required where needed to debug code.

local dbg = require "debugger"

dbg()

Setup

A full usage guide is in the README.md on GitHub, though I will show how I use it 90% of the time — to set breakpoints or start the debugger on an assert.

Setting a breakpoint to start the debugger can be done by calling the debugger function.

-- This is a breakpoint
dbg()

The same function can be used with an argument to assert, as a drop-in replacement for the built-in assert function.

-- assert() replacement
dbg(result ~= true)

Another common case is the usage as error handler, a drop-in replacement for error.

-- Just like error()
dbg.error("Problem!")

All of those will, when triggered, start the interactive debugging session in the terminal.

Another often-used function for me is dbg.pretty, replacing the separate inspect module I mentioned earlier, to print a table in a readable format.

-- Print a human readable table
print(dbg.pretty(debug.getinfo(1)))

This covers my usual usage of debugger.lua. But, this is only part of the integration. Seeing that many of the functions are drop-in-replacements of built-in functions, the debugger can be used to enhance already existing error handling, with little work.

Let's take an earlier example, and see how debugger.lua can be added in development without much work. The original code uses the built-in error and pcall function for some simple error handling.

-- src/errors/pcall.lua
local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.")
  end
  return "Hello, " .. str
end

if pcall(greet, 1) then
  print("No errors")
else
  print("Error calling greet!")
end

Requiring the debugger and locally, overriding the error and pcall functions is all that is needed.

-- src/errors/debugger-in-place.lua
local dbg = require "debugger"
local error = dbg.error
local pcall = dbg.call

local function greet(str)
  if type(str) ~= "string" then
    error(
      "Function 'greet' expects a string as argument.")
  end
  return "Hello, " .. str
end

if pcall(greet, 1) then
  print("No errors")
else
  print("Error calling greet!")
end

Let's see it running in action.

Running the debugger

… is like running any other Lua file. As soon as the debugger gets triggered, the interactive debugging session will start. This will give access to running a set of commands to inspect the code.

Here is a quick overview of the available commands, taken from the debugger.lua README commands section.

To show this in action, here is a demo of running the previous src/errors/debugger-in-place.lua example.

What happens is that running the file that integrated the debugger will cause an error in the function greet. This will start the debugging session. Then the command t is used to print a call stack. Followed by q to end the debugging session.

That's the gist of debugger.lua — integrate it, run the code, and when the debugger gets hit, using the provided commands to find the reason for the problem at hand.

Using an IDE

Another great way to debug Lua code is when an editor or IDE is available that offers debugging capabilities for Lua. There are some options available, a few with built-in Lua debugging support, and others that need plugins.

I by no means can offer an exhaustive list, but I want to try and give two popular options a shot with which I have at least some experience.

Visual Studio Code

VS Code or VSCodium can be used to debug Lua when used with the Lua Debug extension, with the setup described in the first article of the series. It offers everything desired for debugging, from breakpoints, runtime inspections, variable watching, an interactive call stack, and more.

Debugging can be started by opening any file and pressing the "Debug File" button at the top right. On start, execution will stop immediately, even without break points, giving the option to step through the program. When pressing "Continue" from the debug control bar, the next stop will be at a breakpoint, or if none is set, run through the whole program.

The debug controls offer options to (from left to right) move the toolbar; continue to the next breakpoint; to step over, into, and out of the execution scope; restart debugging; and to stop the debugger.

In the sidebar are different tools to inspect the running program. One is to inspect variables in different scopes, seeing their values.

The "Watch" panel offers the ability to watch values and how they change while running the program. To watch a variable, the name needs to be added to the watch list via the "plus" button at the right.

Another panel offers the ability to look at and inspect the current call stack.

More information about debugging with VSCode can be found in the official Microsoft documentation.

ZeroBrane

ZeroBrane is a free, Lua first, editor supporting all mayor operating systems, coming with all that is needed for debugging, out-of-the-box, with the setup described in the first article of the series. From debugging, breakpoints, variable watching, call stack, and more.

The editor has a set of debugging controls in the middle of the top bar. Besides running the current open file, it can start the debugger, which will stop immediately with options to observe the running program.

Same as with other debugger controls, from left to right, it can run the whole file; continue and stop execution; stop debugging and continue regular execution; break at the next line; step in, over, and out scopes; run to a point set by the cursor; and toggle all breakpoints.

To inspect values while debugging, the variable in question can be hovered, and a tooltip will show the current state. Alternatively, a variable can be watched to view its value over the course of running the debugger.

Right-click a variable and select "Add Watch Expression" from the context menu.

Another feature is a stack window, showing the current execution stack.

There is much, much, more. A lot of more ways to debug Lua can be found in the official ZeroBrane documentation for debugging.

Profiling

Being able to consistently profile an application enables writing fast and efficient code. Thanks to Lua's debug library and specifically the debug.sethook function, a user can implement any debug mechanic themselves.

Function execution count

One of those examples can be found directly on lua.org Programming in Lua section about profiling. The example profiler will count how often each function got called. The whole profiler looks like this:

-- src/tools/profiler-pil.lua
local Counters = {}
local Names = {}

local function hook()
  local f = debug.getinfo(2, "f").func
  -- first time `f' is called?
  if Counters[f] == nil then
    Counters[f] = 1
    Names[f] = debug.getinfo(2, "Sn")
  else -- only increment the counter
    Counters[f] = Counters[f] + 1
  end
end

local function getname(func)
  local n = Names[func]
  if n.what == "C" then
    return n.name
  end
  local loc = string.format("[%s]:%s", n.short_src, n.linedefined)
  if n.namewhat ~= "" then
    return string.format("%s (%s)", loc, n.name)
  else
    return string.format("%s", loc)
  end
end

local f = assert(loadfile(arg[1]))
debug.sethook(hook, "c") -- turn on the hook
f()                      -- run the main program
debug.sethook()          -- turn off the hook

for func, count in pairs(Counters) do
  print(getname(func), count)
end

The idea is to run the profiler and give it a Lua file as an argument. The file will be loaded via loadfile. Before running the loaded chunk, the function hook will be set as debug hook via sethook for function execution via the argument "c".

The hook then counts how often a function gets called in the table Counters and saves the name into Names. At the end, all names will be printed via a for loop with the amount of executions.

This is how the count profiler can be run:

$ lua src/tools/profiler-pil.lua some/nice/file.lua

The profiler will produce an output similar to the following one, taken from the example on lua.org.

[markov.lua]:4 884723
write   10000
[markov.lua]:0 (f)     1
read    31103
sub     884722
[markov.lua]:1 (allwords)      1
[markov.lua]:20 (prefix)       894723
find    915824
[markov.lua]:26 (insert)       884723
random  10000
sethook 1
insert  884723

More profiler options can be found at lua-users.org/wiki/ProfilingLuaCode, like the Pepperfish Profiler or the lua-callgrind.lua profiler that will produce "callgrind file-spec" files to be used with KCachegrind.

Memory profile

Even though simplistic, nevertheless effective, the used memory at any point of execution can be measured with collectgarbage("count"). The call returns the total memory in use in kilobytes.

Here is an example of printing the count at the start and end of a test program.

-- src/examples/memory-profile.lua
print("Memory Before:\t",
  collectgarbage("count") .. " kb")

local lu = require "luaunit"
local round = require "examples/round"

local TestRound = {}

function TestRound.test1()
  lu.assertEquals(round(3.44), 3)
end

function TestRound.test2()
  lu.assertEquals(round(3.44, 1), 3.4)
end

print("Memory After:\t",
  collectgarbage("count") .. " kb")

return TestRound

Running this file …

$ lua src/examples/memory-profile.lua

… will show the used memory in kilobytes at the start and end of the file.

Memory Before: 22.9609375 kb
Memory After:  229.1533203125 kb

Simple, but helpful.

Own tracer

I always found flame graphs pretty handy when profiling. May it be in web development through Chromium based browsers, accessing it via chrome://tracing/, Firefox through the Performance tab, or for general application development using a frame profiler like Tracy.

The tracer can be found in the companion repository in the file src/tools/profiler-mhf.lua.

Looking at the parts that make the (less than 200 lines) tracer, the Profile table holds the logic to write the tracing file format. It defines some settings, like the file name the trace gets written to, and sets a new function to create a new profiler.

-- src/tools/profiler-mhf.lua
local Profile = {
  file = "profile.json",
  output = "",
}

function Profile:new(file)
  local obj = {
    file = file or self.file
  }
  self.__index = self
  setmetatable(obj, self)
  return obj
end

The functions write_header and write_footer handle the start and end of the JSON file that will be created, the footer will also create the file itself.

function Profile:write_header()
  self.output = string.format([[{"metadata": {
    "source": "CustomProfiler",
    "startTime": "%s",
    "dataOrigin": "TraceEvents"
  },"traceEvents":[]], os.date("%Y-%m-%dT%X"))
end

function Profile:write_footer()
  local file_handle = io.open(self.file, "w")
  if file_handle then
    file_handle:write(self.output:sub(1, -2) .. "]}")
    self.output = ""
    io.close(file_handle)
  end
end

The function write_item is what creates a new entry for the tracer with the start and end time of an execution scope, as well as a name.

function Profile:write_item(name, start_time, end_time)
  local json = [[
  {
    "args":{},
    "cat": "function",
    "dur": %f,
    "name": "%s",
    "ph": "X",
    "pid": 0,
    "tid": 0,
    "ts": %f
  },]]
  self.output = self.output
    .. string.format(json, end_time, name, start_time)
end

The Instrumentator table is what defines a couple of settings and the function to be set as a debug hook. The settings are a potential custom clock function that returns a time in nanoseconds, as well as some values to hold on execution.

local Instrumentator = {
  -- Clock milliseconds to nanoseconds
  clock = function() return os.clock() * 1000000 end,
  profile = nil,
  tail_calls = 0,
  function_stack = {},
  scope_stack = {},
}

The create_hook function is the meat of the tracer. It creates a hook function to be used with debug.sethook that will listen for all but the line event.

function Instrumentator:create_hook()
  return function(event, _line, info)
    info = info or debug.getinfo(2)
    local func = info.func

    -- Ignore internal or C functions in trace
    if internal_functions[func] or info.what ~= "Lua" then
      return
    end

    local _, stack_depth = debug.traceback():gsub("\n", "\n")
    if info.istailcall == true then
      stack_depth = stack_depth - 1
    end

    if event == "tail call" then
      self.tail_calls = self.tail_calls + 1

      if not self.function_stack[func] then
        self.function_stack[func] = {}
      end

      self.function_stack[func][stack_depth + self.tail_calls] = self.clock()
    end

    if event == "call" then
      if not self.function_stack[func] then
        self.function_stack[func] = {}
      end

      self.function_stack[func][stack_depth] = self.clock()
    end

    if event == "return" then
      if not self.function_stack[func] then
        return
      end

      local function _write(id, depth)
        if self.function_stack[func][depth] == nil then
          return
        end

        local name = info.name
          or string.format("%s(%s:%s)",
            id, info.short_src, info.linedefined)
        local start_time = self.function_stack[func][depth]
        local end_time = self.clock() - start_time

        -- Avoid 0 values for end_time as it can
        -- get interpreted as "forever"
        if end_time < 1 then end_time = 1 end

        self.profile:write_item(name, start_time, end_time)
        self.function_stack[func][depth] = nil
      end

      if info.istailcall == true then
        for i = self.tail_calls, 1, -1 do
          _write("tail_call", stack_depth + i)
        end
        self.tail_calls = 0
      end

      _write("unknown", stack_depth)

      -- Cleanup
      if next(self.function_stack[func]) == nil then
        self.function_stack[func] = nil
      end
    end
  end
end

It will also skip functions that are referenced in the table internal_functions. This table will hold all tracer own functions to not show up in a trace.

The Instrumentator functions begin_session and end_session are to scope on what part of the code the tracer shall run. The begin_session function will create a new Profiler, write the header and set the actual debugging hook.

function Instrumentator:begin_session(file)
  self.profile = Profile:new(file)
  self.profile:write_header()
  debug.sethook(self:create_hook(), "cr")
end

The function end_session will remove the hook and write the footer.

function Instrumentator:end_session()
  debug.sethook()
  self.profile:write_footer()
  self.profile = nil;
end

One last function, scope, is added to give the option to create trace entries for a non-function scope.

function Instrumentator:scope(name)
  self.scope_stack[name] = self.clock()

  local function __close()
    if not self.scope_stack[name] then
      return
    end

    local info = debug.getinfo(2)
    local scope_name = string.format("%s(%s:%s)",
      name, info.short_src, info.linedefined)
    local start_time = self.scope_stack[name]
    local end_time = self.clock() - start_time

    -- Avoid 0 values for end_time as it can
    -- get interpreted as "forever"
    if end_time < 1 then end_time = 1 end

    self.profile:write_item(
      scope_name, start_time, end_time)

    self.scope_stack[name] = nil
  end

  local closable = { close = __close }
  setmetatable(closable, { __close = __close })
  internal_functions[__close] = true

  return closable
end

The meta-method __close that is defined in that function is an optional Lua 5.4 feature to support the local variable attribute "close".

And at last, adding all functions that should not be profiled to the internal_functions table.

local function collect_function(from, into)
  for _, v in pairs(from) do
    if type(v) == "function" then
      into[v] = true
    end
  end
end

internal_functions[collect_function] = true
collect_function(Instrumentator, internal_functions)
collect_function(Profile, internal_functions)

Again, the whole tracer can be found in the companion repository in the file src/tools/profiler-mhf.lua.

How to use the tracer? After requiring the profiler into a file to be profiled, the function begin_session needs to be called to start the profiler.

-- src/examples/profiler-example.lua
local profiler = require "tools/profiler-mhf"

profiler:begin_session()

And, at the end, calling end_session to close the profiler.

profiler:end_session()

That is all that is necessary to profile function calls in the code. After running the code with the profiler, a profile.json will be created. Loading this file, e.g., into Speedscope, will show the flame graph of the executed program.

The scope function now gives another way of defining a scope to profile. It takes a name for the scope and returns a scope-table, with a close function that needs to be called at the end of the scope.

local function test_fn()
  -- Some code ...
  if something then
    local scope = profiler:scope("test scope")
    -- More code ...
    scope:close()
  end
  -- Could be even more code here ...
end

When using Lua 5.4 or later, the <close> attribute can be used to automatically close a scope, removing the need to call close manually.

local function test_fn()
  -- Some code ...
  if something then
    local _ <close> = profiler:scope("test scope")
    -- More code ...
  end
  -- Could be even more code here ...
end

Again, as mentioned initially, this tracer may not be the most efficient. If precision is needed, a nanosecond-resolution profiler like Tracy Profiler should be used.

What comes next

As usual, all the code shown in this article is also available in the companion repository on GitHub, branch part-4.

Up next is extending a C++ application with Lua. Taking a look at the Lua C-API, both-way function calls, user data, custom modules, how setup the application using CMake, and much more.

Until then 👋🏻