Programming in Lua : 23.3

This first edition was written for Lua 5.0. While still largely relevant for later versions, there are some differences.
The fourth edition targets Lua 5.3 and is available at Amazon and other bookstores.
By buying the book, you also help to support the Lua project.

Programming in Lua

Part III. The Standard Libraries Chapter 23. The Debug Library

23.3 – Profiles

Despite its name, the debug library is useful for tasks other than debugging. A common such task is profiling. For a profile with timing, it is better to use the C interface: The overhead of a Lua call for each hook is too high and usually invalidates any measure. However, for counting profiles, Lua code does a decent job. In this section, we will develop a rudimentary profiler, which lists the number of times that each function in the program is called in a run.

The main data structure of our program is a table that associates functions to their call counters and a table that associates functions to their names. The indices to these tables are the functions themselves.

    local Counters = {}
    local Names = {}

We could retrieve the name data after the profiling, but remember that we get better results if we get the name of a function while it is active, because then Lua can look at the code that is calling the function to find its name.

Now we define the hook function. Its job is to get the function being called and increment the corresponding counter; it also collects the function name:

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

The next step is to run the program with this hook. We will assume that the main chunk of the program is in a file and that the user gives this file name as an argument to the profiler:

    prompt> lua profiler main-prog

With this scheme, we get the file name in arg[1], turn on the hook, and run the file:

    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

The last step is to show the results. The next function produces a name for a function. Because function names in Lua are so uncertain, we add to each function its location, given as a pair file:line. If a function has no name, then we use only its location. If a function is a C function, we use only its name (it has no location).

    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

Finally, we print each function with its counter:

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

If we apply our profiler to the markov example that we developed in Section 10.2, we get a result like this:

    [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

That means that the anonymous function at line 4 (which is the iterator function defined inside allwords) was called 884,723 times, write (io.write) was called 10,000 times, and so on.

There are several improvements that you can make to this profiler, such as to sort the output, to print better function names, and to improve the output format. Nevertheless, this basic profiler is already useful as it is and can be used as a base for more advanced tools.