From cc9f9cce4d361fe470dc719e2615221aac6a46f3 Mon Sep 17 00:00:00 2001 From: Paulo Matias Date: Tue, 6 Aug 2013 11:53:44 -0300 Subject: [PATCH] Added LuaJIT profiling support (lulip), better cmdline option handling. --- frontend/lulip.lua | 190 +++++++++++++++++++++++++++++++++++++++++++++ koreader.sh | 2 +- koreader_kobo.sh | 2 +- reader.lua | 43 ++++++++-- 4 files changed, 228 insertions(+), 9 deletions(-) create mode 100644 frontend/lulip.lua diff --git a/frontend/lulip.lua b/frontend/lulip.lua new file mode 100644 index 000000000..aee1c65a5 --- /dev/null +++ b/frontend/lulip.lua @@ -0,0 +1,190 @@ +-- lulip: LuaJIT line level profiler +-- +-- Copyright (c) 2013 John Graham-Cumming +-- +-- License: http://opensource.org/licenses/MIT + +local io_lines = io.lines +local io_open = io.open +local pairs = pairs +local print = print +local debug = debug +local tonumber = tonumber +local setmetatable = setmetatable +local table_sort = table.sort +local table_insert = table.insert +local string_find = string.find +local string_sub = string.sub +local string_gsub = string.gsub +local string_format = string.format +local ffi = require("ffi") + +ffi.cdef[[ + typedef long time_t; + + typedef struct timeval { + time_t tv_sec; + time_t tv_usec; + } timeval; + + int gettimeofday(struct timeval* t, void* tzp); +]] + +module(...) + +local gettimeofday_struct = ffi.new("timeval") +local function gettimeofday() + ffi.C.gettimeofday(gettimeofday_struct, nil) + return tonumber(gettimeofday_struct.tv_sec) * 1000000 + tonumber(gettimeofday_struct.tv_usec) +end + +local mt = { __index = _M } + +-- new: create new profiler object +function new(self) + return setmetatable({ + + -- Time when start() and stop() were called in microseconds + + start_time = 0, + stop_time = 0, + + -- Per line timing information + + lines = {}, + + -- The current line being processed and when it was startd + + current_line = nil, + current_start = 0, + + -- List of files to ignore. Set patterns using dont() + + ignore = {}, + + -- List of short file names used as a cache + + short = {}, + + -- Maximum number of rows of output data, set using maxrows() + + rows = 20, + }, mt) +end + +-- event: called when a line is executed +function event(self, event, line) + local now = gettimeofday() + + local f = string_sub(debug.getinfo(3).source,2) + for i=1,#self.ignore do + if string_find(f, self.ignore[i], 1, true) then + return + end + end + + local short = self.short[f] + if not short then + local start = string_find(f, "[^/]+$") + self.short[f] = string_sub(f, start) + short = self.short[f] + end + + if self.current_line ~= nil then + self.lines[self.current_line][1] = + self.lines[self.current_line][1] + 1 + self.lines[self.current_line][2] = + self.lines[self.current_line][2] + (now - self.current_start) + end + + self.current_line = short .. ':' .. line + + if self.lines[self.current_line] == nil then + self.lines[self.current_line] = {0, 0.0, f} + end + + self.current_start = gettimeofday() +end + +-- dont: tell the profiler to ignore files that match these patterns +function dont(self, file) + table_insert(self.ignore, file) +end + +-- maxrows: set the maximum number of rows of output +function maxrows(self, max) + self.rows = max +end + +-- start: begin profiling +function start(self) + self:dont('lulip.lua') + self.start_time = gettimeofday() + self.current_line = nil + self.current_start = 0 + debug.sethook(function(e,l) self:event(e, l) end, "l") +end + +-- stop: end profiling +function stop(self) + self.stop_time = gettimeofday() + debug.sethook() +end + +-- readfile: turn a file into an array for line-level access +local function readfile(file) + local lines = {} + local ln = 1 + for line in io_lines(file) do + lines[ln] = string_gsub(line, "^%s*(.-)%s*$", "%1") + ln = ln + 1 + end + return lines +end + +-- dump: dump profile information to the named file +function dump(self, file) + local t = {} + for l,d in pairs(self.lines) do + table_insert(t, {line=l, data=d}) + end + table_sort(t, function(a,b) return a["data"][2] > b["data"][2] end) + + local files = {} + + local f = io_open(file, "w") + if not f then + print("Failed to open output file " .. file) + return + end + f:write([[ + + + + + + + + + + + +]]) + + for j=1,self.rows do + if not t[j] then break end + local l = t[j]["line"] + local d = t[j]["data"] + if not files[d[3]] then + files[d[3]] = readfile(d[3]) + end + local ln = tonumber(string_sub(l, string_find(l, ":", 1, true)+1)) + f:write(string_format([[ + +]], +l, d[1], d[2]/1000, files[d[3]][ln])) + end + f:write('
file:linecountelapsed (ms)line
%s%i%.3f%s
crash.log +./reader.lua "$@" 2> crash.log # clean up forked process in case the reader crashed killall reader.lua diff --git a/koreader_kobo.sh b/koreader_kobo.sh index 16e7b1dfb..31f0aa257 100644 --- a/koreader_kobo.sh +++ b/koreader_kobo.sh @@ -14,7 +14,7 @@ export STARDICT_DATA_DIR="data/dict" killall nickel # finally call reader -./reader.lua "$1" 2> crash.log +./reader.lua "$@" 2> crash.log # continue with nickel diff --git a/reader.lua b/reader.lua index e90860bab..596b3ba02 100755 --- a/reader.lua +++ b/reader.lua @@ -12,6 +12,7 @@ require "settings" require "dbg" require "gettext" +Profiler = nil HomeMenu = InputContainer:new{ item_table = {}, @@ -33,6 +34,11 @@ HomeMenu = InputContainer:new{ } function exitReader() + if Profiler ~= nil then + Profiler:stop() + Profiler:dump("./profile.html") + end + G_reader_settings:close() input.closeAll() @@ -189,6 +195,7 @@ end -- option parsing: longopts = { debug = "d", + profile = "p", help = "h", } @@ -197,6 +204,7 @@ function showusage() print(_("Read all the books on your E-Ink reader")) print("") print(_("-d start in debug mode")) + print(_("-p [rows] enable Lua code profiling")) print(_("-h show this usage help")) print("") print(_("If you give the name of a directory instead of a file path, a file")) @@ -209,16 +217,37 @@ function showusage() return end -if ARGV[1] == "-h" then - return showusage() -end +DEBUG = function() end local argidx = 1 -if ARGV[1] == "-d" then - Dbg:turnOn() +while argidx <= #ARGV do + local arg = ARGV[argidx] argidx = argidx + 1 -else - DEBUG = function() end + if arg == "--" then break end + -- parse longopts + if arg:sub(1,2) == "--" then + local opt = longopts[arg:sub(3)] + if opt ~= nil then arg = "-"..opt end + end + -- code for each option + if arg == "-h" then + return showusage() + elseif arg == "-d" then + Dbg:turnOn() + elseif arg == "-p" then + require "lulip" + Profiler = lulip:new() + pcall(function() + -- set maxrows only if the optional arg is numeric + Profiler:maxrows(ARGV[argidx] + 0) + argidx = argidx + 1 + end) + Profiler:start() + else + -- not a recognized option, should be a filename + argidx = argidx - 1 + break + end end if Device:hasNoKeyboard() then