Posted by
| Nick Gammon
Australia (22,973 posts) bio
Forum Administrator |
Message
| To answer the direct question first, I added profiling by putting the following code at the end of the script part of my mapping plugin:
-- set up profiling
local profile = {}
local myGetInfo = GetInfo -- make local for speed and efficiency
-- stub function to profile an existing function
local function make_profile_func (fname, f)
profile [fname] = { func = f, elapsed = 0, count = 0 }
return function (...)
local start = myGetInfo (232) -- high-precision timer
profile [fname].count = profile [fname].count + 1
local results = { f (...) } -- call original function
-- calculate how long it took
profile [fname].elapsed = profile [fname].elapsed + myGetInfo (232) - start
return unpack (results) -- return results
end -- function
end -- make_profile_func
-- replace world functions by profiling stub function
for k, f in pairs (world) do
if type (f) == "function" then
world [k] = make_profile_func (k, f)
end -- if
end -- for
require "pairsbykeys"
-- show profile, called by alias
function show_profile (name, line, wildcards)
print (string.rep ("-", 20), "Function profile - alpha order", string.rep ("-", 20))
print ""
print (string.format ("%25s %8s %8s", "Function", "Count", "Seconds"))
print ""
for k, v in pairsByKeys (profile) do
if v.count > 0 then
print (string.format ("%25s %8i %8.4f", k, v.count, v.elapsed))
end -- if
end -- for
print ""
local t = {}
for k, v in pairs (profile) do
if v.count > 0 then
table.insert (t, k)
end -- if used
end -- for
table.sort (t, function (a, b) return profile [a].elapsed > profile [b].elapsed end )
print (string.rep ("-", 20), "Function profile - time order", string.rep ("-", 20))
print ""
print (string.format ("%25s %8s %8s", "Function", "Count", "Seconds"))
print ""
for _, k in ipairs (t) do
print (string.format ("%25s %8i %8.4f", k, profile [k].count, profile [k].elapsed))
end -- for
print ""
end -- show_profile
Inside the <aliases> ... </aliases> part I added an alias to call the function that displays the results:
<alias
match="profile"
enabled="y"
sequence="100"
script="show_profile"
>
</alias>
What the code does is replace each world.xxx function in the script space with a "stub" that works out how long that function took to run (using the high-resolution timer) and also how often it is called.
The "profile" alias prints out the current profile information. The results look like this, after walking around a bit:
-------------------- Function profile - alpha order --------------------
Function Count Seconds
CallPlugin 24 0.0076
ColourNameToRGB 11411 0.0842
DoAfter 1 0.0000
DoAfterSpecial 1 0.0000
GetInfo 361 0.0029
GetNoteColourFore 1 0.0000
GetPluginID 1 0.0000
GetPluginInfo 7 0.0000
GetPluginVariable 24 0.0004
GetVariable 5 0.0000
IsConnected 2 0.0000
IsPluginInstalled 1 0.0000
Send 1 0.0011
SetNoteColourFore 2 0.0000
SetStatus 4 0.0004
Trim 1 0.0000
WindowAddHotspot 14147 0.1644
WindowCircleOp 25452 0.3548
WindowCreate 181 0.2555
WindowDragHandler 180 0.0017
WindowFont 2 0.0000
WindowFontInfo 717 0.0243
WindowInfo 181 0.0026
WindowLine 30708 0.4177
WindowPosition 1 0.0000
WindowRectOp 1432 0.0094
WindowShow 180 0.0022
WindowText 721 0.0055
WindowTextWidth 1437 0.0107
WorldAddress 1 0.0000
WorldPort 1 0.0000
-------------------- Function profile - time order --------------------
Function Count Seconds
WindowLine 30708 0.4177
WindowCircleOp 25452 0.3548
WindowCreate 181 0.2555
WindowAddHotspot 14147 0.1644
ColourNameToRGB 11411 0.0842
WindowFontInfo 717 0.0243
WindowTextWidth 1437 0.0107
WindowRectOp 1432 0.0094
CallPlugin 24 0.0076
WindowText 721 0.0055
GetInfo 361 0.0029
WindowInfo 181 0.0026
WindowShow 180 0.0022
WindowDragHandler 180 0.0017
Send 1 0.0011
SetStatus 4 0.0004
GetPluginVariable 24 0.0004
GetVariable 5 0.0000
GetPluginInfo 7 0.0000
WindowPosition 1 0.0000
SetNoteColourFore 2 0.0000
WindowFont 2 0.0000
DoAfter 1 0.0000
IsConnected 2 0.0000
DoAfterSpecial 1 0.0000
Trim 1 0.0000
GetPluginID 1 0.0000
IsPluginInstalled 1 0.0000
WorldAddress 1 0.0000
GetNoteColourFore 1 0.0000
WorldPort 1 0.0000
In this particular case, you can see that WindowLine and WindowCircleOp have the highest execution time (and are also called the most often).
You could use something like this (in each plugin) to see if there is a particular function call that takes longer than you expect. You could adapt these lines:
for k, f in pairs (world) do
if type (f) == "function" then
world [k] = make_profile_func (k, f)
end -- if
end -- for
... to also profile other functions (eg. string functions).
Having presented that (which you could usefully turn into a module if you are going to use it everywhere), I have to say that in testing my various GUI demonstrations I didn't notice any slowdown, even with the mapper, and other windows all being displayed at once.
For example: Playing a MUD game with a MMO-style look to it
and: Playing a MUD game with MUSHclient
Also note that the profiling code I describe above will itself slow the execution of the plugin down, naturally.
Some tips that might help keep things running smoothly:
- Don't use the Repaint function - that makes the client do a lot of work, when Redraw will usually work just as well
- Use Lua variables instead of MUSHclient variables, where possible
- If you are writing to an SQLite database, writing more than once thing at once, put them in a transaction
- Don't unnecessarily create or draw to miniwindows, if you can just re-use an existing one. Once drawn to, the window is just "blitted" to the output window.
- Functions like ColourNameToRGB should not really be called frequently (as I did above) because the colours should be converted from names to numbers once, not every time through an inner loop.
- Be cautious of using a design that tracks the movement of the mouse over every pixel (as others have done) but rather use hotspots as they were intended to be used.
|
- Nick Gammon
www.gammon.com.au, www.mushclient.com | top |
|