Auctioneer's usage of debugprofilestart/debugprofilestop
  • So, this started as an issue between my addon (TradeSkillMaster) and Carbonite, but is potentially an issue wherever more than one addon is using these two functions. I know Auctioneer uses debugprofilestart/stop quite a bit in its code. As I'm sure anybody who has worked on this section of code would know, these two functions can be unreliable. What I'm proposing is a library which will make them much more reliable for all addons, even those which don't use the library. This library would only require addons which previously relied on time differences from debugprofilestop() to use debugprofileget() instead, but would preserve the original usage of debugprofilestart/debugprofilestop. Here's what it looks like currently:

    local _debugprofilestart = debugprofilestart
    local _debugprofilestop = debugprofilestop

    local lastStartTime = 0

    function debugprofilestop()
    return _debugprofilestop() - lastStartTime

    function debugprofilestart()
    lastStartTime = _debugprofilestop()

    function debugprofileget()
    return _debugprofilestop()

    As you can see, there's really not much to it. However, it prevents resetting of the timer, by never calling the original debugprofilestart() function. debugprofilestop() will function exactly the same as it does currently, with the same potential issues resulting from others calling debugprofilestart() and resetting the timer. However, debugprofileget() has been added which will give a much more accurate time that is unaffected by other addons calling debugprofilestart().

    This can still fail if somebody is using a non-hooked version of the functions, and doesn't call the hooked functions, but I believe this could be detected very easily, and a bit more code could greatly reduce the risk of this causing issues. Also, I'm not sure if any addons actually do this or not, and hopefully this code will load early enough anyways.

    I'm around in IRC if you'd like to discuss this further. Hopefully my explanation here makes sense. ;)
  • I think this is a good idea, though there are two interesting things that can be done on top.

    Firstly I think the functions should take a single parameter. If the parameter is not supplied you just fall back to the original behavior. But if the parameter is supplied, you can keep track of the timers independently. This ensures that one addon's call to debugprofilestart() cannot interefere with another's timing. I think a unique ID in the form of a string parameter would be fine here.

    Secondly, I think you could improve the behavior by detecting who called the functions (in the case of not passing a parameter). However, this could be more work than it's worth.

    I do think that this is a useful tool, and could be turned into a library. If so, you should name it starting with an !, which on many (albeit not all) systems will guarantee that it gets loaded before someone even has a chance of picking up a local reference to the original debugprofilestop() function.
  • I had thought of adding a single parameter as you described (and even thought of doing this automatically via debugstack(1, 1, 0) instead of a parameter), but this would require addons to call debugprofilestart() in order to start their timer. I'm not sure about other addons, but I know Auctioneer (and I'm currently making TSM do this too) just use time differences in debugprofilestop(), rather than using debugprofilestart(). I'm not sure if changing to using debugprofilestart() would be worth it over just using debugprofileget() (function name up for discussion).

    Another idea is that an OnUpdate script could provide some rough sanity checking to detect if the internal timer (within the actually implementation) got reset, and provide some correction.

  • If you could do a grep through your addons and list the ones which use debugprofilestop(), I think compiling a list (at least among common addons) would be helpful. I don't use very many addons, but here's the ones I'm aware of:

    LibDogTag (many addons)
  • From all Auctioneer libraries and modules:

    Auctioneer/Auc-Advanced/CoreScan.lua:916: -- coroutine speed limiter using debugprofilestop
    Auctioneer/Auc-Advanced/CoreScan.lua:919: local debugprofilestop = debugprofilestop
    Auctioneer/Auc-Advanced/CoreScan.lua:921: -- backup timer, in case debugprofilestop fails - can occur under (currently unknown) circumstances - only used in the merge and cleanup loops {ADV-637}
    Auctioneer/Auc-Advanced/CoreScan.lua:973: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:977: if debugprofilestop() > nextPause then
    Auctioneer/Auc-Advanced/CoreScan.lua:980: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1076: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1078: if debugprofilestop() > nextPause then
    Auctioneer/Auc-Advanced/CoreScan.lua:1081: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1171: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1174: if debugprofilestop() > nextPause or time() > lastTime then
    Auctioneer/Auc-Advanced/CoreScan.lua:1177: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1232: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1235: if debugprofilestop() > nextPause or time() > lastTime then
    Auctioneer/Auc-Advanced/CoreScan.lua:1238: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1973: -- coroutine speed limiter using debugprofilestop
    Auctioneer/Auc-Advanced/CoreScan.lua:1976: local debugprofilestop = debugprofilestop
    Auctioneer/Auc-Advanced/CoreScan.lua:1977: local nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:1998: if debugprofilestop() > nextPause or time() > lastTime then
    Auctioneer/Auc-Advanced/CoreScan.lua:2004: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:2046: -- must use GetTime to time this pause, as debugprofilestop is unsafe across yields
    Auctioneer/Auc-Advanced/CoreScan.lua:2054: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:2058: if debugprofilestop() > nextPause or time() > lastTime then
    Auctioneer/Auc-Advanced/CoreScan.lua:2062: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:2131: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Advanced/CoreScan.lua:2134: if debugprofilestop() > nextPause then
    Auctioneer/Auc-Advanced/CoreScan.lua:2138: nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2081: --[[ processing timer using debugprofilestop:
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2082: we do not call debugprofilestart, instead we check the difference between two calls to debugprofilestop
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2083: this should make it safer if another process actually wants to use debugprofilestart/stop for profiling
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2085: we must not attempt to time across a yield using this method, as during that yield another AddOn could call debugprofilestart
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2089: local GetTime, debugprofilestop, time = GetTime, debugprofilestop, time
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2090: local nextPause = debugprofilestop() + processingTime
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2099: if debugprofilestop() > nextPause or time() > lastTime then
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2102: local b=debugprofilestop()
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2105: local e=debugprofilestop()
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2106: -- we use debugprofilestop to calculate time taken by repaint (in ms; divide this by 1000 to convert for use by GetTime)
    Auctioneer/Auc-Util-SearchUI/SearchMain.lua:2112: nextPause = debugprofilestop() + processingTime
  • (Note that we do not call debugprofilestart(), and in fact try to avoid issues associated with other addons calling it.)
  • Sorry that wasn't clear. What I meant was grep through all the addons you personally are using, in an attempt to find others that use these functions.

    I've done basic testing on it, and haven't encountered any bugs. I have it loaded with my addon which now uses debugprofilestop() only (does not use any of the library APIs yet), and haven't seen any issues with its function either.

    Of course, let me know if you have any comments / questions / concerns / etc. I'm also happy to add people to the project, but want to keep the library very basic so don't see much future work going into it.
  • From my AddOn list, add:

  • I found two addons:
    GHI (GryphonHeart Items)
    Grail (questing addon)

    \GHI\ActionExecutors\GHI_ScriptEnv.lua (2 hits)
    Line 305: debugprofilestop = debugprofilestop,
    Line 305: debugprofilestop = debugprofilestop,
    \Grail\Grail.lua (1 hits)
    Line 3065: if self.debug then print("Done creating indexed quest list with elapsed milliseconds: "..debugprofilestop()) end

    As well as above mentioned overachiever and tmw of course.
  • At this point it's really a matter of any addons that use debugprofilestart().
  • Sorry, however, both of the above ones I posted also use that.

    \GHI\ActionExecutors\GHI_ScriptEnv.lua (2 hits)
    Line 304: debugprofilestart = debugprofilestart,
    Line 304: debugprofilestart = debugprofilestart,
    \Grail\Grail.lua (1 hits)
    Line 2942: if self.debug then debugprofilestart() end

    These two are the only ones I could find that use it out of all addons that I use, Auctioneer and tellmewhen\dogtag have hits, but they're in comments.
  • I found the following that use debugprofilestop:
    Auctioneer (of course)
    LibDogTag-3.0 (IceHud, Pitbull4)

    None of them call debugprofilestart.

    One thing though, any replacements for the original debugprofile functions need to be as simple and fast as possible, just in case someone wants to actually use them for profiling.
  • brykrys,

    I made a few minor optimizations to my local copy which reduced the overhead slightly and then did some profiling. Here's my test code and results:

    function ATTest()
    local start = debugprofilestop()
    for i=1, 10000000 do end
    print("loop", debugprofilestop()-start)
    start = debugprofilestop()
    for i=1, 10000000 do
    print("overriden", debugprofilestop()-start)
    start = debugprofilestop()
    for i=1, 10000000 do
    print("raw", debugprofilestop()-start)

    loop: 39
    overriden 3617
    raw 554

    So, the overhead is 0.3 microseconds. I highly doubt anybody would be calling debugprofilestop() enough times to notice this additional overhead.
Start a New Discussion

Howdy, Stranger!

It looks like you're new here. If you want to get involved, click one of these buttons!

In this Discussion

norganna's addons network · tf2 warehouse · scrap warehouse · auctioneer addon · gatherer addon · addon forums · rdrct