Bug 24604 – WebKit profiler reports incorrect total times

• Component: Web Inspector (Deprecated)
• Status: RESOLVED FIXED

[boucher]

See linked screenshot. The reported total time of calls to objj_msgSend is over 3000% of execution time, which doesn't seem to make any logical sense (am I missing something here).

Separately, I believe the actual reported percentage of objj_msgSend in "self" is also incorrect, but I don't have a simple way to verify this, so when I get more information I will update the ticket. Here's a link to the test app I was running, which just runs a profile and prints the total time of execution of a test:

http://cappuccino.org/edgy/TDParseKit/

[Francisco Tolmasky]

Created attachment 29478 [details]
Reduction

I've come up with a very simple reduction: this behavior is caused by any recursive function.

[Francisco Tolmasky]

Created attachment 29707 [details]
Fixes heavy view.

Made it so that most the functions now match the behavior of Shark. Most notably, in the heavy view, child nodes now represent the statistics of the root node, but in the callstack originating at that node. Also added a number of performance improvements, making it so the heavy tree is not calculated until its nodes are revealed. Moved a lot out of C++ and into JS, allowing for more representations and easier manipulations in the future.

[Timothy Hatcher]

Comment on attachment 29707 [details]
Fixes heavy view.

[phone]  Francisco Tolmasky  <set EMAIL_ADDRESS environment variable>

Make sure to include your email address in the ChangeLogs.

+         { "callUID", getCallUID, 0, kJSPropertyAttributeNone },

I think "identifier" or "callIdentifier" would be better names.

+    var profileNodeUIDs = 0,
+        profileNodeGroupIndex = 0,
+        profileNodeGroups = [[], [aProfileNode]],
+        visitedProfileNodesForCallUID = {};

I think this would look better having var on each line and not chained.

+    for (; profileNodeGroupIndex < profileNodeGroups.length; ++profileNodeGroupIndex)
+    {

Our coding style puts the "{" on the same line with the for.

+            if (profileNode.head && profileNode !== profileNode.head)
+            {

Same for if statements.

+                }
+                else {

The "}" should be on the same line as the "else {".

+                    var parentIndex = 0,
+                        parentCount = parentProfileNodes.length;

Same comment about the var from earlier.

+                    for (; parentIndex < parentCount; ++parentIndex)
+                        if (visitedNodes[parentProfileNodes[parentIndex].UID]) {
+                            totalTimeAccountedFor = true;
+                            break;
+                        }

The for loop should have braces since is is multiline, even if it isn't needed.

+            if (children.length)
+            {

Put the "{" on the same line with the if.

+        while (currentNode.parent && (currentNode instanceof WebInspector.ProfileDataGridNode))
+        {

Same.

+            }
+            
+            // If not, add it as a true ancestor.
+            else {

The "else {" should be on the same line as "}" with the command inside the else block.

+                if (ancestor !== focusNode)
+                {                    

Put the "{" on the same line with the if.

+            // only

What does this comment mean?

+            if (parent && parent.parent)
+            {

Same.

+        if (this.children.length <= 0)
+            this.hasChildren = false;

The concept for hasChildren was to allow it to be expandable and empty at the same time. But I'm not sure we ever used that feature in DataGrid, but we do in TreeOutline.

+        if (this._hasChildren)
+        {

Put the "{" on the same line with the if.

+        }
+        else
+        {

Should all be on the same line.

+++ WebCore/inspector/front-end/ProfileDataGridNode.js	(revision 0)

This file is missing the license.

+WebInspector.XProfileDataGridNode = function(aProfileView, aProfileNode, aTree, hasChildren)

XProfileDataGridNode should be named something better.

+    if (aProfileNode)
+    {

Put the "{" on the same line with the if.

+    }
+    else
+    {

Should all be on the same line.

+    appendChild: function(/*ProfileDataGridNode*/ aProfileDataGridNode)
+    findChild: function(/*Node*/ aNode)

We don't use this naming technique for parameters. Just drop the "a".

+WebInspector.ProfileDataGridNode = function(aProfileView, aProfileNode, aTree, hasChildren)

ProfileDataGridNode and XProfileDataGridNode should share code. Why did XProfileDataGridNode get it's own file and ProfileDataGridNode stay with ProfileDataGridTree? They could both live in ProfileDataGridNode.js and share code.

I've given up on the style review at this point. Please correct all the style formatting according to our style guidelines (including separate var statements and no "a" prefix for parameters.)

+//        this.children.forEach(function(node) { node._exclude(excludedCallUID); });

We don't commit commented out code. We also like to avoid forEach, since it is pretty expensive compared to a normal for loop.

You also need to add all the new files to WebKit.qrc and WebCore.vcproj.

[Timothy Hatcher]

I am leaving the bulk of the review for Kevin McCullough.

[Timothy Hatcher]

+    for (; profileNodeGroupIndex < profileNodeGroups.length; ++profileNodeGroupIndex)

Also please move the var statement for profileNodeGroupIndex to the for loop instead of leaving it blank, since you don't use profileNodeGroupIndex outside the loop.

[Kevin McCullough]

Comment on attachment 29707 [details]
Fixes heavy view.

> Index: JavaScriptCore/ChangeLog
> ===================================================================
> --- JavaScriptCore/ChangeLog	(revision 42775)
> +++ JavaScriptCore/ChangeLog	(working copy)
> @@ -1,3 +1,33 @@
> +        Made it so that most the functions now match the behavior of Shark. Most notably, in the heavy view,
> +        child nodes now represent the statistics of the root node, but in the callstack originating at that node.

Missing "of" in the first sentence.  I'm not sure what you mean in the second.


> Index: WebCore/ChangeLog
> ===================================================================
> --- WebCore/ChangeLog	(revision 42775)
> +++ WebCore/ChangeLog	(working copy)
> +        Made it so that most the functions now match the behavior of Shark. Most notably, in the heavy view,
> +        child nodes now represent the statistics of the root node, but in the callstack originating at that node.

Same comment


> Index: WebCore/inspector/front-end/ProfileView.js
> ===================================================================
> --- WebCore/inspector/front-end/ProfileView.js	(revision 42746)
> +++ WebCore/inspector/front-end/ProfileView.js	(working copy)
> @@ -115,28 +163,34 @@ WebInspector.ProfileView.prototype = {
>          var selectedProfileNode = this.dataGrid.selectedNode ? this.dataGrid.selectedNode.profileNode : null;
>  
>          this.dataGrid.removeChildren();
> +        
> +        var children = this.profileDataGridTree.children,
> +            index = 0,
> +            count = children.length;

Our style is to declare each variable with "var" on it's own line.  And this will allow you to declare 'index' in the 'for' statement later.

>  
> -        var children = this.profile.head.children;
> -        var childrenLength = children.length;
> -        for (var i = 0; i < childrenLength; ++i)
> -            if (children[i].visible)
> -                this.dataGrid.appendChild(new WebInspector.ProfileDataGridNode(this, children[i]));
> +        for (; index < count; ++index)
> +            this.dataGrid.appendChild(children[index]);
>  

Here is where you can declare the 'index', since it's not used earlier

> @@ -191,71 +245,90 @@ WebInspector.ProfileView.prototype = {
>          if (!isNaN(queryNumber) && !(greaterThan || lessThan))
>              equalTo = true;
>  
> -        function matchesQuery(profileNode)
> +        function matchesQuery(/*ProfileDataGridNode*/ aProfileDataGridNode)

no need to put 'a' in front of arguments, just name this 'profileDataGridNode'.

> @@ -461,37 +542,21 @@ WebInspector.ProfileView.prototype = {
>          this._sortProfile(this.profile);
>      },
>  
> -    _sortProfile: function(profile)
> +    _sortProfile: function()
>      {
> -        if (!profile)
> -            return;
> -
> -        var sortOrder = this.dataGrid.sortOrder;
> -        var sortColumnIdentifier = this.dataGrid.sortColumnIdentifier;
> -
> -        var sortingFunctionName = "sort";
> -
> -        if (sortColumnIdentifier === "self")
> -            sortingFunctionName += "SelfTime";
> -        else if (sortColumnIdentifier === "total")
> -            sortingFunctionName += "TotalTime";
> -        else if (sortColumnIdentifier === "calls")
> -            sortingFunctionName += "Calls";
> -        else if (sortColumnIdentifier === "function")
> -            sortingFunctionName += "FunctionName";
> -
> -        if (sortOrder === "ascending")
> -            sortingFunctionName += "Ascending";
> -        else
> -            sortingFunctionName += "Descending";
> +        var sortAscending = this.dataGrid.sortOrder === "ascending",
> +            sortColumnIdentifier = this.dataGrid.sortColumnIdentifier,
> +            sortProperty = { 
> +                "average": "averageTime", 
> +                "self": "selfTime", 
> +                "total": "totalTime", 
> +                "calls": "numberOfCalls", 
> +                "function": "functionName"
> +            }[sortColumnIdentifier];
> +        

Same comment here about declaring each variable on its own line.

> Index: WebCore/inspector/front-end/inspector.html
> ===================================================================
> --- WebCore/inspector/front-end/inspector.html	(revision 42746)
> +++ WebCore/inspector/front-end/inspector.html	(working copy)
> @@ -73,6 +73,9 @@ THIS SOFTWARE, EVEN IF ADVISED OF THE PO
>      <script type="text/javascript" src="DatabaseTableView.js"></script>
>      <script type="text/javascript" src="DatabaseQueryView.js"></script>
>      <script type="text/javascript" src="ScriptView.js"></script>
> +    <script type="text/javascript" src="ProfileDataGridTree.js"></script>
> +    <script type="text/javascript" src="BottomUpProfileDataGridTree.js"></script>
> +    <script type="text/javascript" src="TopDownProfileDataGridTree.js"></script>-

I don't think you need the '-' at the end of this line

> Index: LayoutTests/ChangeLog
> ===================================================================
> --- LayoutTests/ChangeLog	(revision 42775)
> +++ LayoutTests/ChangeLog	(working copy)
> @@ -1,3 +1,19 @@
> [phone]  Francisco Tolmasky  <set EMAIL_ADDRESS environment variable>
> +
> +        Reviewed by NOBODY (OOPS!).
> +
> +        BUG 24604: WebKit profiler reports incorrect total times
> +        <https://bugs.webkit.org/show_bug.cgi?id=24604>
> +
> +        Changed profile.treeProfile to just profile, since these aren't generated in C++ anymore.
> +        Removed heavy-view test since heavy-view isn't an actual tree that is generated in C++ land anymore,
> +        but rather just a different display of the normal treeProfile in the JS data grid.
> +
> +        * fast/profiler/heavy-view-expected.txt: Removed.
> +        * fast/profiler/heavy-view.html: Removed.
> +        * fast/profiler/resources/profiler-test-JS-resources.js: profiles[i].treeProfile -> profiles[i].treeProfile
> +        (printProfilesDataWithoutTime):
> +
>  2009-04-23  Brady Eidson  <[e-mail]>

If we are going to take this test out we should find a way to make a test so that we can tell if we regress in the heavy-view.

>  
> Index: WebCore/English.lproj/localizedStrings.js
> ===================================================================
> Cannot display: file marked as a binary type.
> svn:mime-type = application/octet-stream
> 
> //52AGEAcgAgAGwAbwBjAGEAbABpAHoAZQBkAFMAdAByAGkAbgBnAHMAIAA9ACAAbgBlAHcAIABP
> AGIAagBlAGMAdAA7AAoACgBsAG8AYwBhAGwAaQB6AGUAZABTAHQAcgBpAG4AZwBzAFsAIgAgACgA

It looks like this file is marked binary, please make it human readable for review

[Timothy Hatcher]

localizedStrings.js has to be binary since it is UTF-16.

[boucher]

> Our style is to declare each variable with "var" on it's own line.  And this
> will allow you to declare 'index' in the 'for' statement later.

This style is not listed in the coding style guidelines for the project. It should either be listed there, or it should not be considered for patches.

> no need to put 'a' in front of arguments, just name this 'profileDataGridNode'.

Another style guideline not listed anywhere (and which seems overly specific).

[Timothy Hatcher]

Our style guidelines don't really cover JavaScript currently. I plan to fix that at some point.

>> no need to put 'a' in front of arguments, just name this 'profileDataGridNode'.

> Another style guideline not listed anywhere (and which seems overly specific).

I didn't realize this wasn't in the style guidelines. But in general none of the WebKit code base uses "a" or "an" parameter prefixes since they don't add anything. We will update the style guide to include this.

[Francisco Tolmasky]

ProfileDataGridNode.js with the XProfileDataGridNode class accidentally got added to the commit, it was just test code, which is why it doesn't show up in inspector.html, I'll fix up these style issues and remove the file and resubmit.

[Francisco Tolmasky]

Created attachment 29716 [details]
style/comment changes

I believe I covered all the style comments. I also added a lengthier explanation in the ChangeLogs detailing the way Heavy View should work and why it was that we were getting 40,000%, etc. previously. As I mentioned in the earlier comment, I also took out ProfileDataGridNode.js which got committed by accident.

[Timothy Hatcher]

Comment on attachment 29716 [details]
style/comment changes

Still some style issues in a couple of places, but I will fix them before landing.

[Eric Seidel (no email)]

Assigning this to Timothy since he said he would land this.

[Timothy Hatcher]

http://trac.webkit.org/changeset/42808