TraceEvent - Dynamic Lua code profiling
 

I've finished up the next version of my Lua code profiler:

This mod is really useful for anybody tracking down performance problems with an add-on or trying to understand how an add-on works.

TraceEvent can can also help you find stuff buried in Blizzard's interface customization kit. Trace "^%a+_" and then watch the functions as you do stuff. For example, if you want to customize mail: reset the trace stats, open a mailbox, then sort the trace stats. The top functions listed will be related to mail. (Sometimes you have to stop tracing some "noisy" code like ActionButtons in order to find the good stuff.)

WoW Interface download http://www.wowinterface.com/download...php?s=&id=4053

Main web page http://www.vulpes.com/TraceEvent/

Gave you a bit of free publicity, LJ.

hey littlejohn all my mods use a OO aproach to coding does this support them at all?

That's really slick. I like it a lot.

For suggestions, do you think it's possible to profile how much memory an addon is taking up? Or the amount of garbage it creates?

I just uploaded v1.3 that can trace OO code.

Kaelten: That may have been the most polite feature request in history... :) I used your KC_EnhancedTrades to test. (That's a cool mod by the way. I'll have to study how you hook into the existing frames.) Do you know that TSF_Update uses 150-200 KB of memory each call? I don't think I've got a bug, but I've never seen a function use that much memory before. (_getShowState or _getCreationData might be the real culprits though -- they weigh in at 16 KB and 13 KB respectively.)

One thing that's a bit nasty with my code is how OO method names are displayed -- there's a good chance the name will be truncated. Give it a try and let me know if you have any ideas. The pattern I used to trace your code was "KC_EnhancedTradesClass:".

Gello: My code reports memory usage per function call so you can trace memory usage on a mod and then sort the display to see any hot spots. (Hold shift when pressing Sort to sort by memory usage.)

Would it be useful to assume that all functions with a common prefix are part of the same mod and then total up memory usage for all those functions?

I'm not sure how to figure global variable usage though. I'm only catching increases in memory usage, not the total level. If a mod sucks up 10 MB at startup, my code completely misses that.

That'd be extremely useful. Even for mods that don't use a standard "ModName_" prefix, being able to collapse sections of the mods (almost all use Something_Something) would be useful.

It's a shame GetTime() only goes to three decimal places. Would rule to see how much processing time each mod was taking up too.

Even with no change it's very nice :) If a bit frightening lol. I'll have to rethink my liberal use of table.sort. It's super fast but the memory use is huge.

ya I know that TSF_Update is a nasty memory hog. Thats one of the reasons that I wanted your mod to work with mine so bad! hehe that way I Can actually trace and and mesure which method of doing things is actually better.

Thanks alot for this mod man, it might just make alot of pains in my life easier.

I've got a plan to call a traced function multiple times. It might break things (just like tracing memory can break things) so you'll have to turn it on and off. The memory accuracy would be much, much better though, and it allows collecting accurate per-function cpu times.

Are you sure about table.sort? When I trace my own TraceEvent_SortStats it shows only a few bytes of memory per call. (BTW, the Mem column is in bytes, not KB.) I think table.sort sorts the array in place. (Running a test in lua.exe...) Yep. table.sort uses practically no memory at all.

how do I turn on mem display?

Press the shift key when you hit "Add" or "Reset" to enable memory collection on everything. Press the shift key when you hit "Sort" to sort by memory usage.

Press the shift key and left-click on an individual function to enable memory collection on just that function. (This is kind of annoying -- if you forget to hold shift you'll stop the trace on the function.)

I think the next version is going to have a check box next to each function to turn this on and off. Scrolled check boxes, whee!

ok.... here is a feature request list, hehe don't hate me.


1) it would be nice if the window had maybe one or two more rows, or maybe allow us to cofig the rows.

2) a global track memory usage toggle would be good too.

3) being able to have a seperate window with information about groups of function that would logically make up an addon.

4) being able to toggle memory tracking for an "addon" with a single click

5)you said it keeps track of cps over a 3 second window, if there is could be an option to change this it would be nice.

6)I noticed that I had to add OO by KC_EnhancedTradesClass: could it be possible to only add it by the instance? what if I had KC_EnhancedTrades and KC_EnhancedTradesAdv both based off the same class(bad example I know) and I wanted to track them seprately?

7) go buy yerself a beer or your spirit of choice for doing what looks like will be such a useful mod for developers.

btw: it seems if you shift-click reset it will turn mem tracking on.

Why would he want a bear? Or a ghost?

Oh whew hehe looks like what I was seeing was the impact of the examining.

When tracking "Recap_.+". A function named Recap_SortList includes just a table.sort, a post-sort insertion sort (for the life of me I can't get this secondary sort working inside the table.sort but that's another story) and a redo of gauges. The latter two looked fine (just a couple hundred bytes per call) but the Recap_SortList was generating ~250-300 kilobytes per call. (and the gcinfo() seemed to agree with the memory being eaten)

But...just tracking "Recap_SortList" tracked with ~250 combatants, ~500 bytes per call of Recap_SortList. And the memory used from gcinfo() is back to barely noticable.

I'm going to have endless fun with this.

:P I'm still waking up give me a break! hehe.

Yeah. Right. That's gonna happen ... :rolleyes:

*Stops derailing the thread and buggers off out of the way again*

I'd love to know how to do this. The scrolled area is really a static group of XML frames. Any idea how to create them without hardcoding the XML? (I suppose I could create 20 or so and then just hide the ones you don't want. Ick.)

Yep, yep, yep and yep. Gello wanted (3) and (4) too. I'll have to think some more about reporting big-picture system performance.

I'm pretty new at Lua and especially OO in Lua. My code treats objects as just another table to find functions in -- if you don't give it a specific table, then it uses the global table. (All variables in Lua are just entries in a table.) Can you explain what you want a bit more?

What I can do is catch the difference between a class table and an object instance table. If you give it an object table, TraceEvent could put a condition on the trace function that checks if the function is being called with the object you're interested in. If you give it a class table, TraceEvent will work the way it does now. Hmm. I think I made a mistake in the syntax. I should use "." for class tables and ":" for object tables. That's consistent with Lua call syntax -- you could trace "KC_EnhancedTradesClass." or "KC_EnhancedTrades:"

Does that make any sense?

Thanks! Sadly I'm putting shingles on the house today... The cold frosty bear will just have to wait a while. :)

hehe, as far as the scrol being adjustable, it would just have to be 20 of them in there and then hide the uneeded ones


no way to make em dynamicaly sadly.

would it also be possible to trace how long a function takes on average to run?

The trouble is that even a slow function runs faster than the resolution of WoW's timer. It's like measuring your pulse with a sun dial.

One possible solution I'm working on is to run a function 1000 times, measure that, and then divide the time by 1000. Surprisingly this will probably work for all OnEvent and OnUpdate handlers. Other functions maybe not. YMMV. Batteries not included.

what is the resolution of the GetTime() function

I throught I read somewhere that it was milisecond accurate

Yep, it does seem to report increments of 1 millisecond. (If you run GetTime() in a loop just printing it to chat, the values are precisely increments of 1 millisecond.) I'm not sure the time is accurate to the millisecond though -- are all milliseconds created equal? :)

The other problem is that a lot of functions run much quicker than a millisecond. Lua is running about 1,000+ OnEvent/OnUpdate functions per second. That probably fans out to 5,000+ functions per second.

I'll show timing data in v1.4 though. You've helped me convince myself that it's not that big of a problem. I should just try simple timing and see what happens. ;)

A very nice AddOn
 

I have just noticed this AddOn thanks to the publicity it received on the official forums. Good job, Iriel :-) It does look very nice and very useful. However, I would like to make a couple of small comments:

1) In make_hook, you create a function that has ellipsis (...) as argument, so that it can receive multiple arguments. You then use unpack(arg) to pass these onto the hooked function. While this is very nice style-wise, the use of the ellipsis itself generates garbage, and therefore might bias your statistics. Consider replacing it with something like say 20 static arguments, such as: "return function(a1, a2, a3, a4, etc.)", and then pass a1, a2 etc. to the hooked function. It will look ugly but eliminates garbage generation.

2) You are using the Class:Method syntax to enter functions to watch that are elements of a table. I suggest (and hope) that you use the Class.Method syntax instead. Although the choice is arbitrary from the entry point of view, it ties in better with the Lua concepts of elements of a table (Also see point 3). I know that usually the way to call most methods of XML objects is via the Class:Method syntax (e.g. GameTooltip:Show()), but in Lua, the colon is really nothing special, it's just a shorthand for Class.Method(Class, ...). In otherwords, "GameTooltip:Show() = GameTooltip.Show(GameTooltip)". Also, if you are trying to hook a function, you would specify GameTooltip.Show as the function to hook and not GameTooltip:Show.

3) Do you think you will support functions that are more than one layer deep in a table? For example Class.Subclass.Function? I don't know if you are familiar with the Sea library, but if you need some inspiration on how to do something like this, Sea has two functions Sea.util.getValue and Sea.util.setValue. Those work like getglobal/setglobal, but allow table elements as their arguments too. Their code might be a useful starting point.

4) I don't know if you noticed this, but unfortunately due to the way Blizzard coded things, you can't enumerate the native methods of tables that are representing XML-defined objects. You only have access to methods if you know their name exactly. In other words the following code snippet, only returns those elements of the GameTooltip table that have been added from Lua. So if you are using it to iterate over the methods of GameTooltip, you only see those methods that have been modified from Lua, for example hooked into by some AddOn. This means that regular expressions don't work reliably with methods of XML-defined objects. You can see this for yourself: typing "GameTooltip:.+" into TraceEvent results in very few methods being traced. As far as I know, there is no way at the moment to enumerate the native methods.

Apart from the above comments, let me again say that you have a great AddOn here that I am going to be using from now on!

Thanks! I appreciate the feedback. I haven't read the WoW forums in a week or so, but the last I saw, Iriel was rather luke-warm on profiling. Can you point me to the post you saw?

I've already abandoned style for efficiency to handle return values. I originally used

local r = { info.orig_f(unpack(arg)) }

to pick up a dynamic number of function return values. This severely skewed the GC results though so I used the ugly and semi-unreliable code

local a,b,c,d,e = info.orig_f(unpack(arg))

to reduce garbage generation.

You really think it's a good idea to limit the number of arguments a function takes? I convinced myself that 5 return results is unlikely to break things, but I'm not sure what to use as the upper limit to the number of arguments. You think 20 is ok?

There is another thread http://www.wowinterface.com/forums/s...5&page=2&pp=10
where Kaelten asked for method call tracing on particular instances. After I thought about that, I realized I made the mistake you point out. I've decided to use "class.method" syntax to trace functions in a table (works for class methods and package namespaces) and "object:method" syntax to trace method calls on specific objects.

Honestly I didn't know people used that style. It's no big deal to add arbitrary nesting. I should also change the table search code to allow name patterns for tables. (In v1.3 only method names allow patterns; tables must be named precisely.)

Thanks, I definitely wasn't aware of that.

Are you sure Bliz isn't using Lua metatables? I could automatically search __index if it's a table. If __index is a function or if Bliz is using non-Lua method dispatch then I'm pretty much hosed. I'm past the Lua-newbie phase, but I'm not an expert yet... If you have any advice on OO and/or metatables I'd love to hear it.

One of the things that I've sketched out for v1.4 is a more robust way of entering the functions to trace. People (especially gamers without Lua experience) are making mistakes entering the function name patterns. I'm planning on having a GUI to build the table and function patterns with check boxes to turn them on and off.

I could probably solve the "secret" method problem by including a built-in list of method names. (I'd rather follow __index up to the superclass if I can do that reliably though.)

I think 20 arguments should be more than sufficient. I don't know if the ellipsis argument is skewing results or not, if it isn't you could just leave it as it is. I am certain that it's generating garbage though.

If you have been asked already, then there is not much to add. To be honest, I don't see the difference between "object", "table" or "class", since in Lua they are the same thing, they are all just tables. GameTooltip is just as much a Lua-table as say MyAddOnClass.

They do, although not very often. One prime example is the Sea function library which has tables such as Sea.io, Sea.util etc. with functions in each such as Sea.io.print and Sea.util.hook.

As you have guessed, Blizzard uses a natively (read, in C) implemented __index function in a metatable attached to every XML-generated object that's using a non-Lua method to dispatch calls, so you are hosed, in principle. In practice however, complete lists of methods for all known XML-generated object types are available, e.g. at
http://www.wowwiki.com/Widget_API
So as you have suggested (and as Iriel has suggested to me in a thread on the WoW forums), you can build a list of these functions, and match any regexp patterns against such a list. The difficulty unfortunately lies in determining what type of UI object a particular Lua table corresponds to, in other words what set of methods it has. There is no good way that I know of to do this :( For example, given the name SomeRandomFrame, there is no known way to tell that the global Lua table called "SomeRandomFrame" is attached to a UI element of type Frame, Button or something else.

This sounds like a great idea!

Right, the "foo.bar" syntax uses "foo" as the name of a table and "bar" as an entry in the table. That works for tables and classes (since classes are just fancy tables).

The "foo:bar" syntax uses "foo" as the name of an object, then fetches the metatable info to find the object class. The trace function is inserted into the class table, but stats are only collected if the object instance matches "foo" at call time. I'm not sure I'm explaining it well. (And maybe I misinterpreted Kaelten's original request...)

Did you ever try replacing __index? Hooking that would yield all sorts of interesting information about frame methods. I'll poke around a bit in the metatable info and see what I can do.

(BTW, cedar's half up! woot! gonna be nice to trade the hammer for a keyboard and get back to coding... ;)

no littlejohn it sounds like you got me right.

It would be nice if I Could track just x instance of whatever class.

And it is kinda odd that in Lua OO is basically a very nasty table hack. (Scary in fact)

This does allow for some things that other OO languages would just choke on though.

if you did support nesting, watch out for circular references. They probably aren't extremely common but they do happen.

ha ha! It is possible to hook getmetatable(foo)[__index] and trace built-in (and inherited) WoW routines on any frame object.

I tried using a proxy table with __index and __newindex methods that just forward to the original table, but that kept crashing WoW for some reason. Maybe lua doesn't like recursive metatable lookup? Anyways, WoW uses the same metatable (and therefore the same __index) on many (all?) XML frame objects. I hooked __index and collected trace history on DEFAULT_CHAT_FRAME. It's possible to dynamically trace an object -- using __index you can see when a new function is called and then it can be dynamically added to the trace.

This is probably not that useful to mod authors though. The only thing that seems really cool is automatic generation of the frame XML APIs. (Where did the WoW wiki docs come from anyways?)

Legorol: What did you have in mind for this feature? Do you really want to be able to trace, for example, DEFAULT_CHAT_FRAME:* and have all the built-in methods show up?

Kaelten: I was hoping I understood you right. I don't think of OO in Lua as a nasty table hack -- I'd call it an elegant table hack. ;) It's like a Python+Scheme love child. Or an alternate universe version of Perl created by a computer scientist instead of a linguist.

I agree that hooking into the __index function is a good way to see method calls at run time, and can make tracing based on patterns work. I presume what you had in mind is that if the user has specified a regexp, then you don't hook there and then, but if you notice a method call that matches the regexp, then you hook it. That would work and in fact sounds like a good idea for being able to use regexp patterns with XML-generated tables. The particular example I was thinking of is specifying a trace pattern such as GameTooltip%.Set.+ (i mean to indicate that the first '.' is not special but the second one is, i don't know what's the best way for you to handle this).

Unfortunately hooking __index will not help with scanning for the API, because it would require you to actually run WoW and wait for all sorts of method calls to actually happen for you to be able to see that they exist. There are some methods that are in fact never called from any of the default Blizzard UI files, and therefore would be missed, even if you made use of every UI element. One such example is the FontString:SetJustifyV method.

The list on the Wiki is generated by a very crude and simple method: scan WoW.exe for all strings and make a list out if, which forms the list of candidates. Then test each object type and see if it has a method that is named any of those candidates. The key here is that testing for a superset that includes stuff other than valid method names is not a problem as long as your set is guaranteed to include all actual methods.

OO

Supporting OO concepts in TraceEvent is going to be tricky in my opinion. Although there are one or two 'standard' text-book ways of doing OO (classes and instances) in Lua using tables, there are actually a number of possible ways of implementing OO or semi-OO concepts. I have seen different AddOns use very different means to implement OO concepts such as classes and instanciation. Catering for all these scenarios will be difficult, because you won't know in what particular way is an AddOn making use of metatables for example.

This is just my opinion, but I beleive that you should drop the ':' syntax alltogether and not try to cater for OO concepts at all. Instead, make sure you have a firm method of tracing table elements, using the '.' syntax. That should be sufficient for those using OO concepts, because they can either specify the table representing the class, or the table representing an instance if they wish. This is just my personal opinion though.

Hmm... sorry for putting this here, but I simply can't get your TraceEvent thingy to work. It shows up fine and spiffy, I just can not seem to add stuff to trace (input field seems to be disabled - it's not accepting any input anyhow, nor can I use direct calls to TraceEvent_AddTrace to get around it).

I have tried to do TraceEventAddName:SetText("A") and nothing whatsoever happens.

Is there any way I can easily detect if an addon (I run numerous) can interfere with it?

( <honks at Legorol> )

Sarf

I have exactly the same issue as Sarf.
I suspect we are both using Cosmos though have no idea whether that is the issue or not.