luatrace - tracing, profiling and coverage for Lua
luatrace is a Lua module that collects information about what your code is doing and how long it takes, and can analyse that information to generate profile and coverage reports.
luatrace adds a layer on top of Lua's debug hooks to make it easier to collect information for profiling and coverage analysis. luatrace traces of every line executed, not just calls.
luatrace can trace through coroutine resumes and yields, and through xpcalls, pcalls and errors. On some platforms it uses high resolution timers to collect times of the order of nanoseconds.
To use it, install luatrace with
sudo make install,
run your code with
lua -luatrace <your lua file> and then analyse it
luatrace.profile. The profiler will display a list of the top 20 functions
by time, and write a copy of all the source traced annotated with times for each
Alternatively, you can
local luatrace = require("luatrace") and surround the code
you wish to trace with
If you wish to use the profiler directly rather than on a trace file you can use
lua -luatrace.profile <your lua file> or
local luatrace = require("luatrace.profile").
You can pass settings to
Probably the only interesting one is the name of the file to write the trace to,
for example, you might have Lua code that calls
Later, you can run the profiler on this trace with the command-line
luatrace runs under "plain" Lua and LuaJIT with the -joff option (LuaJIT doesn't call hooks in compiled code, and luatrace loses track of where it's up to)
luatrace is separated into two parts - the trace collector, and the backends that record and process the traces.
The trace collector uses Lua's debug hooks and adds timing information and a little bit of processing to make the traces easier to use.
Timing is provided in one of three ways:
- Lua - with a debug hook calling
- LuaJIT - with a debug hook calling
os.clockis not yet implemented as a fast function
- Lua and LuaJIT - if the c_hook has been built then that's used instead of the Lua or LuaJIT hook. It's always better to use the C hook.
By default the C hook uses the C library's
clock and should call it closer to
actual code execution, so the traces should be more accurate.
On some plaforms the C hook uses a high-resolution timer:
- On mach plaforms (ie OS X), the c_hook uses the
- On Linux, it uses
- On Windows, it uses
However, although the timing might be collected at nanosecond resolution, there are many reasons why profiles are not accurate to within a nanosecond!
The collector outputs traces by calling a recorder's
record function with a
range of arguments:
("S", <filename>, <line>)- the trace has started somewhere in a function defined on line
(">", <filename>, <line>)- there's been a call to a function defined on line
("T", <filename>, <line>)- there's been a tailcall to a function defined on line (LuaJIT only)
("<")- return from a function
("R", <thread_id>)- Resume the thread thread_id
("P")- pcall - the current line is protected for the duration of the following call
("E")- Error - unwind the stack looking for a "P"
(<line>, <time in microseconds>)- this many microseconds were just spent on this line of the current file
At the moment, there's two recorders -
trace_file is the default backend. It just writes the trace out to a file in a simple format,
which it can also read. When it reads a file, it reads it to another recorder
as if the recorder were watching the program execute.
profile provides limited profile information.
Backends will improve as I need them or as you patch/fork.
Lua or LuaJIT.
- It's really slow
- Tracing is overcomplicated and has to check the stack depth too frequently
- Profiling is very complicated when there's a lot on one line (one line functions)
- Times probably aren't accurate because of the time spent getting between user code and the hooks
- There aren't many backends
- More of the hook should be in C
- It would be nice if the recorder was in a separate Lua state and a separate thread
-jannotate - Annotate code with LuaJIT trace information
annotate.lua collects information about the traces LuaJIT is attempting and
summarises that information in a format that doesn't contain as much information
-jdump, but which might be more useful for you.
annotate.lua is installed with luatrace.
To use it,
luajit -jannotate mylua.lua.
When your program exits, it will write a report to stdout detailing how many
traces were attempted, how many were successful and how many were aborted.
For the aborted traces, you'll get summaries of the reasons for the aborts,
and the lines that caused the aborts.
The report then lists bytecode for all the traces next to the source code. This listing is a little problematic, since bytecode order doesn't necessarily match source order, and traces cross function boundaries. The traces are listed in source order as much as practicable to make them easier to read.
If you want to write the report to a separate file, then
You can also use annotate.lua as a module:
local annotate = require("jit.annotate") annotate.on() ... annotate.off() annotate.report(io.open("report.txt", "w"))
LuaJIT (this won't work with plain Lua)
- It'd be nice to incorporate timing information from a profiler
LuaJIT trace API
-jannotate uses some internal LuaJIT APIs.
These are not intended for public use, and are subject to change without notice,
however, here's some of what I've managed to learn.
What follows is a bit rough, inaccurate, and very incomplete.
These functions are used in several of the -j library files.
dump.lua is probably a good place to start if you're looking for more information
You can attach callbacks to a number of compiler events with
jit.attach. The callback can be called:
- when a function has been compiled to bytecode ("bc");
- when trace recording starts or stops ("trace");
- as a trace is being recorded ("record");
- or when a trace exits through a side exit ("texit").
Set a callback with
jit.attach(callback, "event") and clear the same callback with
The arguments passed to the callback depend on the event being reported:
funcis the function that's just been recorded.
callback(what, tr, func, pc, otr, oex)
whatis a description of the trace event: "flush", "start", "stop", "abort". Available for all events.
tris the trace number. Not available for flush.
funcis the function being traced. Available for start and abort.
pcis the program counter - the bytecode number of the function being recorded (if this a Lua function). Available for start and abort.
otrstart: the parent trace number if this is a side trace, abort: abort code (integer)?
oexstart: the exit number for the parent trace, abort: abort reason (string)
callback(tr, func, pc, depth). The first arguments are the same as for trace start.
depthis the depth of the inlining of the current bytecode.
callback(tr, ex, ngpr, nfpr).
tris the trace number as before
exis the exit number
nfprare the number of general-purpose and floating point registers that are active at the exit.
pc from a
jit.util.funcinfo returns a table of information about the function,
The fields of the table are:
linedefined: as for
lastlinedefined: as for
params: the number of parameters the function takes
stackslots: the number of stack slots the function's local variable use
upvalues: the number of upvalues the function uses
bytecodes: the number of bytecodes it the compiled function
currentline: as for
isvararg: if the function is a vararg function`
source: as for
loc: a string describing the source and currentline, like "<source>:<line>"
ffid: the fast function id of the function (if it is one). In this case only
addrbelow are valid
addr: the address of the function (if it is not a Lua function). If it's a C function rather than a fast function, only
upvaluesabove is valid