Understanding Firebug profiler output
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?
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:
- Go to any site that uses AJAX. (I used http://juicystudio.com/experiments/ajax/index.php)
- Enable Console/Script debugging.
- Turn on the profiler.
- Make an AJAX call. (Multiple ones may illuminate the issue more.)
- 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.
If I understand things correctly it goes something like this:
On the first line you'll see that the Own time is "only 0.006ms". That means that even though time spent in that function was 783.506ms most of it was spent inside functions called from that function.
When I use Firebug to optimize code I try to reduce the "own time" of functions that are called the most. (obviously checking also for any unnecessary function calls to remove altogether)
From Firebug Tutorial - Logging, Profiling and CommandLine (Part II): (the examples there are good)
Columns and Description of Profiler
Function column : It show the name of each function.
Call column : It shows the count of how many a particular function has been invoked.
Percent column : It shows the time consuming of each function in percentage.
Time column : It shows the duration of execution from start point of a function to the end point of a function.
Avg column : It shows the average execution time of a particular function. If you are calling a function one time only, you won’t see the differences. If you are calling more than one time, you will see the differences.
The formula for that column is
Avg = Own Ttime / Call;
Min column and Max column: It shows the minimum execution time of a particular function.
File column: the file name of file where the function located.
From what I understand this is how it works... total profiler time is the sum of the 'Own Time' column. However, you may notice that some single Time values may be greater than the total profiler time. Those overtimes were spent outside of JavaScript, eg. in a plugin call. If your JS function makes a plugin call for eg., and waits for the plugin function to return to JS, then those waiting times will NOT be reported by the total profiler time, but will be included in the Time column.