Well, I have my answer [1]. I first found a smaller request that exhibits the behavior as to not generate half a million lines of output:
Table: Lines of code executed for a small request gopher 2549 gemini 564
Good. Two and a half thousand lines of code is tractable. Now, just to show how easy it is to profile Lua code, here's the code I'm using for my gopher server [2]:
local profile = {}
local function doprofile()
local info = debug.getinfo(2)
local name = info.name or "..."
local file = info.source or "@"
local key = string.format("%s$%s(%d)",file,name,info.currentline)
if not profile[key] then
profile[key] = 1
else
profile[key] = profile[key] + 1
end
end
For each line of code executed, we get the filename, the function name and the line of code that's executing, turn that into a key, and use that to count the number of times that line of code is executed. Easy. And then some code to dump the results:
local function cleanup()
local results = {}
for name,value in pairs(profile) do
results[#results + 1] = { file = name , count = value }
end
table.sort(results,function(a,b)
if a.count > b.count then
return true
elseif a.count < b.count then
return false
else
return a.file < b.file
end
end)
local f = io.open("/tmp/dump.txt","w")
for i = 1 , #results do
f:write(string.format("%6d %s\n",results[i].count,results[i].file))
end
f:close()
end
We sort the results based on line count, then alphabetically by key. And like before:
local function main(iostream) debug.sethook(doprofile,'line') -- The rest of the main code debug.sethook() cleanup() end
I make the request and get some results:
215 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(202)
211 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(203)
211 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(204)
211 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(268)
210 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(282)
210 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(283)
169 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(219)
169 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(224)
169 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(239)
169 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(240)
42 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(205)
42 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(206)
42 @/usr/local/share/lua/5.4/org/conman/string.lua$wrapt(207)
17 @port70.lua$...(272)
17 @port70.lua$...(273)
9 @/usr/local/share/lua/5.4/org/conman/net/ios.lua$write(547)
...
Oh.
Yeah.
That.
Obvious in hindsight.
I completely forgot about that.
Okay. The function in question, wrapt(), wraps text [3] and it's a rather heavy function due to Unicode [4] (and I'm not even following the full specification there). This is the major difference between the gopher and Gemini servers—I don't wrap text for Gemini (the clients handle that). I guess I'll have to drop down to C if I want to speed this up.
Sigh.
[2] https://github.com/spc476/port70