TraceEvent - Dynamic Lua code profiling

[Littlejohn]

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/

[Cairenn]

Gave you a bit of free publicity, LJ.

[Kaelten]

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

[Gello]

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?

[Littlejohn]

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.

[Gello]

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.

[Kaelten]

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.

[Littlejohn]

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.

[Kaelten]

how do I turn on mem display?

[Gello]

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.