javascript - Understanding Firebug profiler output

Question

I've been trying to use Firebug's profiler to better understand the source of some JavaScript performance issues we are seeing, but I'm a little confused by the output.

When I profile some code the profiler reports Profile (464.323 ms, 26,412 calls). I suspect that the 464.323 ms is the sum of the execution time for those 26,412 calls.

However, when I drill down into the detailed results I see individual results with an average execution time greater than 464.323 ms, e.g. the result with the highest average time reports the following details:

Calls: **1**
Percent: **0%**
Own Time: **0.006 ms**
Time: **783.506 ms**
Avg: **783.506 ms**
Min: **783.506 ms**
Max: **783.506 ms**

Another result reports:

Calls: **4**
Percent: **0.01%**
Own Time: **0.032 ms**
Time: **785.279 ms**
Avg: **196.32 ms**
Min: **0.012 ms**
Max: **783.741 ms**

Between these two results the sum of the Time results is a lot more than 464.323.

So, what do these various numbers mean? Which ones should I trust?

Answer 1

Each column has a description of what it means if you set your mouse to hover over it in Firebug. I'll assume you can read up on how each column works on your own then. However, you have definitely come across some odd behavior which needs to be explained.

The own time is the amount of time the function spent executing code inside of itself. If the function calls no other functions, then own time should be the same as time. However, if there are nested function calls, then time also counts the time spent executing them. Therefore, time will almost always be larger than own time, and will in most cases add up to more than the total time reported by the profiler.

However, no single function's time should be larger than the total time the profiler logged for JavaScript calls. This problem is definitely a bug, and I can see why you have trouble trusting Firebug when it gives you such a paradoxical output. I believe I've tracked down the reason this bug occurs: AJAX.

It appears that AJAX calls are causing columns that count nested function calls to report incorrect information. They end up counting both the time of JavaScript execution and the request to the server.

You can reproduce this profiler bug by doing the following:

1. Go to any site that uses AJAX. (I used http://juicystudio.com/experiments/ajax/index.php)
2. Enable Console/Script debugging.
3. Turn on the profiler.
4. Make an AJAX call. (Multiple ones may illuminate the issue more.)
5. Stop the profiler, examine the output.

In this example, with regards to time vs. own time, the own time of each function adds up to the profiler's total time but the time column incorporates the amount of time the AJAX call took to talk to the server. This means that the time column is incorrect if you're looking for just the speed of JavaScript execution.

It gets worst: since time, average time, min and max all count nested function calls, they're all incorrect if you're using AJAX. On top of that, any function that eventually uses AJAX (in a nested function call) will also report their time incorrectly. This means that a whole lot of functions may be reporting incorrect information! So don't trust any of those columns for now until Firebug fixes the issue. (It's possible they intended the behavior to be this way, though it is confusing at best to leave it this way.)

If you're not using AJAX, then another issue is at play; let us know if you are or not.