Profiling JavaScript applications with Venkman
Published by Jon November 11th, 2006 in Design, Technology, Web, JavaScript, OptimizationVery large JavaScript applications like Thinkature are not yet very common (or at least not as common as their smaller AJAX cousins). As a result, the body of literature on designing, debugging, and optimizing those applications is small, although it is growing.
As we got ready to launch Thinkature, we noticed that loading complicated workspaces (like the tutorial workspace we give to every new user) was a very time-consuming and processor-intensive task. On my 1.6GHz laptop, the tutorial workspaces could take as long as four minutes of full processor usage to load under Internet Explorer. We knew that it really shouldn’t be that hard to put a few rectangles on the page.
The most sensible way to solve the problem, I figured, was to grab a script profiler1, find the problem function or functions in our code, and optimize or re-engineer them. To my chagrin, information on profiling JavaScript applications is sparse at best.
There are lots of great articles about things like optimizing page load time, but not so much about where-are-all-my-processing-cycles-going optimization. I was very excited to find an article from Brad Neuberg entitled “ Tutorial: How to Profile and Optimize Ajax Applications.” To my chagrin, Mr. Neuberg is much more interested in profiling page load time and overall execution time (which is fine for most purposes — I don’t mean to disparage at all) than in finding bottlenecks in long-running code. Few others seem to be talking about profiling JavaScript.
The problem is further complicated by the fact that decent profilers are hard to come by. The otherwise excellent Firebug doesn’t come with a profiler, nor does the somewhat-less-excellent Microsoft Script Debugger. There seem to be a handful of commercial offerings, but I had a very hard time determining if they’d actually do what I wanted.
After searching for a while, I remembered an old friend named Venkman. Venkman was The Really Cool Script Debugger before Firebug came around, and has received little attention since. It does, however, come with a JavaScript profiler. Win!
A caveat - Venkman is finicky. It only runs in Mozilla/Firefox, and often requires a browser restart to work correctly. It also has a tendency to start watching scripts that you may not want it to be paying attention to (such as scripts that are actually part of browser extensions or part of the browser itself). With that said, it does its job and will profile scripts in a way that makes me very happy.
With Venkman installed, I set to work profiling. I started the profiler, ran the problem scripts, and dumped the data to a file. I loaded the report and found… lots of unusable data.
Venkman did, indeed, profile the script correctly and produce a detailed report of exactly how much time was spent in each function, including a range of execution times for each function, the number of times each function was called, and so on. The problem was that all of the functions were anonymous.
The Venkman FAQ explains that simply assigning a function to a named variable (e.g. MyObject.prototype.setConditionOne = function(ship) { ... }) does not assign a name to the function. To actually assign a name to the function, you must define it differently. A named function takes a form similar to: MyObject.prototype.setConditionOne = function setConditionOne(ship) { ... }. A warning: Safari will report that as a syntax error, although other browsers won’t. I’ll try to find a workaround soon.
Venkman will report which files anonymous functions live in. Since only a few files contained high-execution-time functions, I went through those files and manually named all of the functions. I recommend using a regular expression search/replace to do so, but that’s a little bit outside of the scope of what I’m trying to get at here.
With the functions named, I re-ran the profiling drill and found the problem function. The script spent about three quarters of its time in one function that was called literally thousands of times upon load. I couldn’t imagine why. The function itself ran quickly; it was just the repetition that slowed things down.
Using Firebug, I added a console.trace() line to the start of the problem function to figure out what was calling it so often. I’ll spare you the gory details, but it ultimately came down to me accidentally constructing a zillion YUI tooltips, each of which made several calls to YAHOO.util.CustomEvent.fire().
I fixed the bug, re-ran the code, and was disappointed when the page loaded instantly. “Great,” I thought, “now it’s doing something stupid with the cache.” I emptied the cache, closed the browser, re-opened the browser, re-loaded the page, and got the same result. Then it hit me. Everything was just really, really fast. That one bug was slowing things down by at least an order of magnitude.
So the moral of the story is this: if you have a large, complex application that’s performing poorly because of something that you know is happening at runtime, use Venkman to profile your code. Here are step-by-step instructions:
- Get Venkman from http://www.mozilla.org/projects/venkman/.
- Create a branch of your code that has non-anonymous functions.
- Restart your browser.
- Navigate to the de-anonymized version of the page that’s giving you trouble.
- Start Venkman (”JavaScript debugger” from the Tools menu).
- From the “Profile” menu in Venkman, select “Collect Profile Data” (or click on the “Profile” button in the toolbar).
- If you’re trying to profile script startup, reload the problem page in your browser. Otherwise, just start using the page.
- When you’re done, go back to Venkman and turn off profiling (either from the “Profile” menu or the “Profile” button in the toolbar)
- Save the profiling report by choosing “Save Profile Data As…” from the “Profile” menu.
- Read the report, find functions that have long total execution times, and focus your attention accordingly.
There’s no magic bullet for fixing performance problems, but profiling will tell you where the worst of them spring up. Good hunting to you!
- For those of you unfamiliar with them — and I don’t blame you — profilers are programs that latch on to other running programs and monitor which functions are being called and how long each one takes to execute. They then generate a report of how much time was spent in each function. They’re used commonly in traditional application development, so I was surprised to see so little written about them for Javascript applications. ↩2
- Props to John Gruber at Daring Fireball for his very excellent footnote design.↩
thanks !
great article.
You might want to check out Dtrace with javascript. Granted it Solaris only but it should do what you need.
http://blogs.sun.com/brendan/entry/dtrace_meets_javascript
You should check out JavaScript Performance Validator by Software Verification Limited.
http://www.softwareverify.com
Proper profiler - no JavaScript wrappers. All timing handled by C code. Runtime
callstack display, tabular statistics, relations view, call tree, call graph, analysis feature,
HTML/XML export etc, etc. Uses the same profiling APIs that Venkman uses.
Works with Firefox 1.0, 1.5, 2.0 and Flock 0.7
Disclaimer - I was involved in the design of JSPV (Object Media consult for Software Verification).
Stephen
Jon,
Can you elaborate a bit on the problem you found with YUI’s CustomEvent? I, too, am finding extraneous calls being made to CustomEvent, although we’re not using Tooltip.
I’d appreciate any insight you can offer, as I’m sure we’re suffering a similar issue.
Thanks.
Hi, Frank!
The problem, as I remember it, stemmed from anything based on the YUI Container collection. It’s not a bug or a problem in its own right, but when you create a zillion of them, the construction overhead really adds up.
Since I wrote this article, Firebug 1.0 betas have become available and they have [very nice] profiling support, too. To tackle this problem, I’d recommend using Firebug’s stack trace functionality. Modify the YAHOO code to include a call to
console.trace()in whichever function is giving you grief, then run your application normally. Check the Firebug console and you’ll have a ton of debug output. It will take some work, but you can pore over that to figure out what’s making all those zillions of calls.Hope that helps!