Permalink
Browse files

luatrace is a tool for tracing lua script execution and analysing tim…

…e profiles and coverage
  • Loading branch information...
0 parents commit 18b7eb1325e8ab2bd3296acfcd9b2de6cd8532f7 @geoffleyland committed Mar 31, 2011
Showing with 690 additions and 0 deletions.
  1. +3 −0 .gitignore
  2. +1 −0 AUTHORS
  3. +21 −0 LICENSE
  4. +68 −0 README.md
  5. +75 −0 c/c_hook.c
  6. +209 −0 lua/luatrace.lua
  7. +107 −0 lua/luatrace/profile.lua
  8. +131 −0 lua/luatrace/trace_file.lua
  9. +11 −0 lua/test/cl-test.lua
  10. +13 −0 lua/test/tron-test.lua
  11. +1 −0 lua/uatrace.lua
  12. +49 −0 makefile
  13. +1 −0 sh/luaprofile
@@ -0,0 +1,3 @@
+.DS_Store
+Thumbs.db
+
@@ -0,0 +1 @@
+Leyland, Geoff (Incremental IP Ltd)
21 LICENSE
@@ -0,0 +1,21 @@
+Copyright (c) 2011 Incremental IP Limited
+
+Permission is hereby granted, free of charge, to any person obtaining a copy
+of this software and associated documentation files (the "Software"), to deal
+in the Software without restriction, including without limitation the rights
+to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+copies of the Software, and to permit persons to whom the Software is
+furnished to do so, subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in
+all copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+THE SOFTWARE.
+
+
@@ -0,0 +1,68 @@
+# luatrace - tracing, profiling and coverage for Lua
+
+## 1. What?
+
+luatrace adds a layer on top of Lua's debug hooks to make it easier to collect
+information for profiling and coverage.
+It collects traces of every line executed, and can then analyse those traces to
+provide time profiles and coverage reports (not yet implemented).
+
+To use it run you code with `lua -luatrace <your lua file>` and then analyse it with `luaprofile`
+
+luatrace is brought to you by [Incremental](http://www.incremental.co.nz/) (<info@incremental.co.nz>)
+and is available under the [MIT Licence](http://www.opensource.org/licenses/mit-license.php).
+
+
+## 2. How?
+
+luatrace is separated into to 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 one of three ways:
+
++ Lua - with a debug hook calling `os.clock`
++ LuaJIT - with a debug hook calling `ffi.C.clock` - `os.clock` is not yet implemented as a fast function
++ Lua - if c_hook has been built then that's used instead of the Lua hook.
+ The hook should be able to call `clock` closer to actual code execution, so the traces should be more accurate.
+
+The collector outputs traces by calling a recorder's `record` function.
+This can be called in one of four ways, with up to 3 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
++ `("<", <filename>, <line>)` - return from a function
++ `(<line>, <time in microseconds>)` - this many microseconds were just spent on this line of the current file
+
+At the moment, there's two recorders - `luatrace.trace_file` and `luatrace.profile`.
+
+`trace_file` is the default back-end. 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.
+
+Back ends will improve as I need them or as you patch/fork.
+
+
+## 3. Requirements
+
+Lua or LuaJIT.
+
+
+## 4. Issues
+
++ Times probably aren't accurate because of the time spent getting between user code and the hooks
++ The profile back end seems to get numbers wrong - it told me a blank line took was executed several hundred times and took 0.02 of a second
++ Tail calls and coroutines will cause chaos
++ There aren't many back-ends
+
+
+## 5. Alternatives
+
+See [the Lua Wiki](http://lua-users.org/wiki/ProfilingLuaCode) for a list of profiling alternatives.
+[luacov](http://luacov.luaforge.net/) provides coverage analysis.
+
+
@@ -0,0 +1,75 @@
+#include <time.h>
+#include "lauxlib.h"
+
+/*============================================================================*/
+
+static clock_t time_out, elapsed;
+static int hook_index = -1;
+
+
+void hook(lua_State *L, lua_Debug *ar)
+{
+ clock_t time_in = clock();
+ elapsed += time_in - time_out;
+
+ int event = ar->event;
+ if (event == LUA_HOOKLINE ||
+ event == LUA_HOOKCALL ||
+ event == LUA_HOOKRET)
+ {
+ lua_rawgeti(L, LUA_REGISTRYINDEX, hook_index);
+ if (event == LUA_HOOKLINE) lua_pushstring(L, "line");
+ if (event == LUA_HOOKCALL) lua_pushstring(L, "call");
+ if (event == LUA_HOOKRET) lua_pushstring(L, "return");
+ if (event == LUA_HOOKLINE) lua_pushnumber(L, ar->currentline);
+ else lua_pushnil(L);
+ lua_pushinteger(L, elapsed);
+ lua_call(L, 3, 0);
+
+ elapsed = 0;
+ }
+ time_out = clock();
+}
+
+
+static int set_hook(lua_State *L)
+{
+ if (lua_isnoneornil(L, 1))
+ {
+ if (hook_index >= 0)
+ {
+ luaL_unref(L, LUA_REGISTRYINDEX, hook_index);
+ hook_index = -1;
+ }
+ lua_sethook(L, 0, 0, 0);
+ }
+ else
+ {
+ luaL_checktype(L, 1, LUA_TFUNCTION);
+ hook_index = luaL_ref(L, LUA_REGISTRYINDEX);
+ lua_sethook(L, hook, LUA_MASKCALL | LUA_MASKRET | LUA_MASKLINE, 0);
+ elapsed = 0;
+ time_out = clock();
+ }
+}
+
+/*============================================================================*/
+
+
+static luaL_Reg hook_functions[] =
+{
+ {"set_hook", set_hook},
+ {NULL, NULL}
+};
+
+
+LUALIB_API int luaopen_c_hook(lua_State *L)
+{
+ // Register the module functions
+ luaL_register(L, "c_hook", hook_functions);
+ return 1;
+}
+
+
+/*============================================================================*/
+
@@ -0,0 +1,209 @@
+local DEFAULT_RECORDER = "luatrace.trace_file"
+
+
+-- Check if the ffi is available, and get a handle on the c library's clock.
+-- LuaJIT doesn't compile traces containing os.clock yet.
+local ffi
+if jit and jit.status and jit.status() then
+ local ok
+ ok, ffi = pcall(require, "ffi")
+ if ok then
+ ffi.cdef("unsigned long clock(void);")
+ else
+ ffi = nil
+ end
+end
+
+-- See if the c hook is available
+local c_hook
+do
+ local ok
+ ok, c_hook = pcall(require, "luatrace.c_hook")
+ if not ok then
+ c_hook = nil
+ end
+end
+
+
+-- Trace recording -------------------------------------------------------------
+
+local recorder -- The thing that's recording traces
+local current_line -- The line we currently think is active
+local accumulated_us -- The microseconds we've accumulated for that line
+
+
+-- Emit a trace if the current line has changed
+-- and reset the current line and accumulated time
+local function set_current_line(l)
+ if l ~= current_line then
+ recorder.record(current_line, accumulated_us)
+ accumulated_us = 0
+ end
+ current_line = l
+end
+
+
+-- We only trace Lua functions
+local function should_trace(f)
+ return f and f.source:sub(1,1) == "@"
+end
+
+
+local CALLEE_INDEX, CALLER_INDEX
+
+-- Record an action reported to the hook.
+local function record(action, line, time)
+ accumulated_us = accumulated_us + time
+
+ if action == "line" then
+ set_current_line(line)
+ elseif action == "call" or action == "return" then
+ local callee = debug.getinfo(CALLEE_INDEX, "Sl")
+ local caller = debug.getinfo(CALLER_INDEX, "Sl")
+
+ if action == "call" then
+ if should_trace(caller) then
+ set_current_line(caller.currentline)
+ end
+ if should_trace(callee) then
+ set_current_line(callee.currentline)
+ recorder.record(">", callee.short_src, callee.linedefined)
+ end
+ else
+ if should_trace(callee) then
+ set_current_line(callee.currentline)
+ end
+ if should_trace(caller) then
+ set_current_line(caller.currentline)
+ end
+ if should_trace(callee) then
+ recorder.record("<")
+ end
+ end
+ end
+end
+
+
+-- The hooks -------------------------------------------------------------------
+
+-- The Lua version of the hook uses os.clock
+-- The LuaJIT version of the hook uses ffi.C.clock
+
+local time_out -- Time we last left the hook
+
+-- The hook - note the time and record something
+local function hook_lua(action, line)
+ local time_in = os.clock()
+ record(action, line, (time_in - time_out) * 1000000)
+ time_out = os.clock()
+end
+local function hook_luajit(action, line)
+ local time_in = ffi.C.clock()
+ record(action, line, time_in - time_out)
+ time_out = ffi.C.clock()
+end
+
+
+-- Starting the hook - we go to unnecessary trouble to avoid reporting the
+-- first few lines, which are inside and returning from luatrace.tron
+local start_short_src, start_line
+
+local function init_trace(line)
+ local caller = debug.getinfo(3, "S")
+ recorder.record("S", caller.short_src, caller.linedefined)
+ current_line, accumulated_us = line, 0
+end
+
+local function hook_lua_start(action, line)
+ init_trace(line)
+ CALLEE_INDEX, CALLER_INDEX = 3, 4
+ debug.sethook(hook_lua, "crl")
+ time_out = os.clock()
+end
+local function hook_luajit_start(action, line)
+ init_trace(line)
+ CALLEE_INDEX, CALLER_INDEX = 3 ,4
+ debug.sethook(hook_luajit, "crl")
+ time_out = ffi.C.clock()
+end
+local function hook_c_start(action, line)
+ init_trace(line)
+ CALLEE_INDEX, CALLER_INDEX = 2, 3
+ c_hook.set_hook(record)
+end
+
+
+local function hook_start()
+ local callee = debug.getinfo(2, "Sl")
+ if callee.short_src == start_short_src and callee.linedefined == start_line then
+ if ffi then
+ debug.sethook(hook_luajit_start, "l")
+ elseif c_hook then
+ debug.sethook(hook_c_start, "l")
+ else
+ debug.sethook(hook_lua_start, "l")
+ end
+ end
+end
+
+
+-- Shutting down ---------------------------------------------------------------
+
+local luatrace_exit_trick_file_name = os.tmpname()
+local luatrace_raw_exit = os.exit
+
+
+local function luatrace_on_exit()
+ recorder.close()
+ os.remove(luatrace_exit_trick_file)
+end
+
+
+local function luatrace_exit_trick()
+ luatrace_exit_trick_file = io.open(luatrace_exit_trick_file_name, "w")
+ debug.setmetatable(luatrace_exit_trick_file, { __gc = luatrace_on_exit } )
+ os.exit = function(...)
+ luatrace_on_exit()
+ luatrace_raw_exit(...)
+ end
+end
+
+
+-- API Functions ---------------------------------------------------------------
+
+local luatrace = {}
+
+-- Turn the tracer on
+function luatrace.tron(settings)
+ if settings and settings.recorder then
+ if type(settings.recorder) == "string" then
+ recorder = require(settings.recorder)
+ else
+ recorder = settings.recorder
+ end
+ end
+ if not recorder then recorder = require(DEFAULT_RECORDER) end
+ recorder.open(settings)
+
+ local me = debug.getinfo(1, "Sl")
+ start_short_src, start_line = me.short_src, me.linedefined
+
+ luatrace_exit_trick()
+
+ debug.sethook(hook_start, "r")
+end
+
+
+-- Turn it off and close the recorder
+function luatrace.troff()
+ debug.sethook()
+ recorder.close()
+ os.remove(luatrace_exit_trick_file_name)
+ os.exit = luatrace_raw_exit
+end
+
+
+return luatrace
+
+-- EOF -------------------------------------------------------------------------
+
Oops, something went wrong.

0 comments on commit 18b7eb1

Please sign in to comment.