Reply
Thread Tools Display Modes
Unread 07-05-05, 06:07 PM   #1
Littlejohn
A Warpwood Thunder Caller
AddOn Author - Click to view addons
Join Date: Jun 2005
Posts: 90
TraceEvent - Dynamic Lua code profiling

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

TraceEvent collects function call counts, calls/second, peak calls/second and average per-call memory usage of Lua global functions. The previous release was designed to trace all OnEvent functions, but v1.2 allows you to specify functions by name or pattern.
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/
Littlejohn is offline   Reply With Quote
Unread 07-05-05, 06:28 PM   #2
Cairenn
Credendo Vides
 
Cairenn's Avatar
Premium Member
WoWInterface Admin
Join Date: Mar 2004
Posts: 6,931
Gave you a bit of free publicity, LJ.
Cairenn is online now   Reply With Quote
Unread 07-05-05, 08:34 PM   #3
Kaelten
Jack's raging bile duct
 
Kaelten's Avatar
Featured
Join Date: May 2005
Posts: 774
hey littlejohn all my mods use a OO aproach to coding does this support them at all?
__________________
WowAce.com & CurseForge.com Adminstrator
Developer of Ace3, OneBag3, and many other addons and libraries
Project lead and Mac developer for the Curse Client

Anyone that needs what they want
And doesn't want what they need
I want nothing to do with
Kaelten is offline   Reply With Quote
Unread 07-05-05, 10:01 PM   #4
Gello
A Scalebane Royal Guard
AddOn Author - Click to view addons
Join Date: Jan 2005
Posts: 444
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?
Gello is offline   Reply With Quote
Unread 07-06-05, 09:46 AM   #5
Littlejohn
A Warpwood Thunder Caller
AddOn Author - Click to view addons
Join Date: Jun 2005
Posts: 90
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.
Littlejohn is offline   Reply With Quote
Unread 07-06-05, 11:33 AM   #6
Gello
A Scalebane Royal Guard
AddOn Author - Click to view addons
Join Date: Jan 2005
Posts: 444
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?
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.
Gello is offline   Reply With Quote
Unread 07-06-05, 11:53 AM   #7
Kaelten
Jack's raging bile duct
 
Kaelten's Avatar
Featured
Join Date: May 2005
Posts: 774
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.
__________________
WowAce.com & CurseForge.com Adminstrator
Developer of Ace3, OneBag3, and many other addons and libraries
Project lead and Mac developer for the Curse Client

Anyone that needs what they want
And doesn't want what they need
I want nothing to do with
Kaelten is offline   Reply With Quote
Unread 07-06-05, 12:01 PM   #8
Littlejohn
A Warpwood Thunder Caller
AddOn Author - Click to view addons
Join Date: Jun 2005
Posts: 90
Originally Posted by Gello
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.
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.

I'll have to rethink my liberal use of table.sort. It's super fast but the memory use is huge.
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.
Littlejohn is offline   Reply With Quote
Unread 07-06-05, 12:04 PM   #9
Kaelten
Jack's raging bile duct
 
Kaelten's Avatar
Featured
Join Date: May 2005
Posts: 774
how do I turn on mem display?
__________________
WowAce.com & CurseForge.com Adminstrator
Developer of Ace3, OneBag3, and many other addons and libraries
Project lead and Mac developer for the Curse Client

Anyone that needs what they want
And doesn't want what they need
I want nothing to do with
Kaelten is offline   Reply With Quote
Unread 07-06-05, 12:08 PM   #10
Littlejohn
A Warpwood Thunder Caller
AddOn Author - Click to view addons
Join Date: Jun 2005
Posts: 90
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!
Littlejohn is offline   Reply With Quote
Unread 07-06-05, 12:34 PM   #11
Kaelten
Jack's raging bile duct
 
Kaelten's Avatar
Featured
Join Date: May 2005
Posts: 774
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.
__________________
WowAce.com & CurseForge.com Adminstrator
Developer of Ace3, OneBag3, and many other addons and libraries
Project lead and Mac developer for the Curse Client

Anyone that needs what they want
And doesn't want what they need
I want nothing to do with

Last edited by Kaelten : 07-06-05 at 12:42 PM.
Kaelten is offline   Reply With Quote
Unread 07-06-05, 12:38 PM   #12
Cairenn
Credendo Vides
 
Cairenn's Avatar
Premium Member
WoWInterface Admin
Join Date: Mar 2004
Posts: 6,931
Originally Posted by Kaelten
ok.... here is a feature request list, hehe don't hate me.

7) go buy yerself a bear or your spirit of choice for doing what looks like will be such a useful mod for developers.
Why would he want a bear? Or a ghost?
Cairenn is online now   Reply With Quote
Unread 07-06-05, 12:42 PM   #13
Gello
A Scalebane Royal Guard
AddOn Author - Click to view addons
Join Date: Jan 2005
Posts: 444
Originally Posted by Littlejohn
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.
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.
Gello is offline   Reply With Quote
Unread 07-06-05, 12:42 PM   #14
Kaelten
Jack's raging bile duct
 
Kaelten's Avatar
Featured
Join Date: May 2005
Posts: 774
Originally Posted by Cairenn
Why would he want a bear? Or a ghost?
:P I'm still waking up give me a break! hehe.
__________________
WowAce.com & CurseForge.com Adminstrator
Developer of Ace3, OneBag3, and many other addons and libraries
Project lead and Mac developer for the Curse Client

Anyone that needs what they want
And doesn't want what they need
I want nothing to do with
Kaelten is offline   Reply With Quote
Unread 07-06-05, 12:45 PM   #15
Cairenn
Credendo Vides
 
Cairenn's Avatar
Premium Member
WoWInterface Admin
Join Date: Mar 2004
Posts: 6,931
Originally Posted by Kaelten
:P I'm still waking up give me a break! hehe.
Yeah. Right. That's gonna happen ...

*Stops derailing the thread and buggers off out of the way again*
Cairenn is online now   Reply With Quote
Unread 07-06-05, 02:26 PM   #16
Littlejohn
A Warpwood Thunder Caller
AddOn Author - Click to view addons
Join Date: Jun 2005
Posts: 90
Originally Posted by Kaelten
1) it would be nice if the window had maybe one or two more rows, or maybe allow us to cofig the rows.
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.)

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.
Yep, yep, yep and yep. Gello wanted (3) and (4) too. I'll have to think some more about reporting big-picture system performance.

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?
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?

7) go buy yerself a beer or your spirit of choice for doing what looks like will be such a useful mod for developers.
Thanks! Sadly I'm putting shingles on the house today... The cold frosty bear will just have to wait a while.
Littlejohn is offline   Reply With Quote
Unread 07-06-05, 02:48 PM   #17
Kaelten
Jack's raging bile duct
 
Kaelten's Avatar
Featured
Join Date: May 2005
Posts: 774
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.
__________________
WowAce.com & CurseForge.com Adminstrator
Developer of Ace3, OneBag3, and many other addons and libraries
Project lead and Mac developer for the Curse Client

Anyone that needs what they want
And doesn't want what they need
I want nothing to do with
Kaelten is offline   Reply With Quote
Unread 07-06-05, 02:50 PM   #18
Quu
An Aku'mai Servant
 
Quu's Avatar
AddOn Author - Click to view addons
Join Date: Mar 2005
Posts: 36
would it also be possible to trace how long a function takes on average to run?
Quu is offline   Reply With Quote
Unread 07-06-05, 03:00 PM   #19
Littlejohn
A Warpwood Thunder Caller
AddOn Author - Click to view addons
Join Date: Jun 2005
Posts: 90
Originally Posted by Quu
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.
Littlejohn is offline   Reply With Quote
Unread 07-06-05, 04:17 PM   #20
Quu
An Aku'mai Servant
 
Quu's Avatar
AddOn Author - Click to view addons
Join Date: Mar 2005
Posts: 36
what is the resolution of the GetTime() function

I throught I read somewhere that it was milisecond accurate
Quu is offline   Reply With Quote
Reply

Go BackWoWInterface » Developer Discussions » Dev Tools » TraceEvent - Dynamic Lua code profiling

Thread Tools
Display Modes

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

vB code is On
Smilies are On
[IMG] code is On
HTML code is Off