source: webkit/trunk/JavaScriptCore/profiler/ProfileNode.cpp@ 42808

Last change on this file since 42808 was 42808, checked in by [email protected], 16 years ago

BUG 24604: WebKit profiler reports incorrect total times

JavaScriptCore:

2009-04-23 Francisco Tolmasky <[email protected]>

BUG 24604: WebKit profiler reports incorrect total times
<https://bugs.webkit.org/show_bug.cgi?id=24604>

Reviewed by Timothy Hatcher and Kevin McCullough.

  • JavaScriptCore.exp:
  • JavaScriptCore.xcodeproj/project.pbxproj:
  • profiler/CallIdentifier.h: (JSC::CallIdentifier::Hash::hash): (JSC::CallIdentifier::Hash::equal): (JSC::CallIdentifier::hash): (WTF::):
  • profiler/HeavyProfile.cpp: Removed.
  • profiler/HeavyProfile.h: Removed.
  • profiler/Profile.cpp: No more need for TreeProfile/HeavyProfile (JSC::Profile::create):
  • profiler/Profile.h:
  • profiler/ProfileNode.cpp:
  • profiler/ProfileNode.h:
  • profiler/TreeProfile.cpp: Removed.
  • profiler/TreeProfile.h: Removed.

WebCore:

2009-04-23 Francisco Tolmasky <[email protected]>

BUG 24604: WebKit profiler reports incorrect total times
<https://bugs.webkit.org/show_bug.cgi?id=24604>

Reviewed by Timothy Hatcher and Kevin McCullough.

Made it so that most of the profiler functions now match the behavior of Shark. Most notably, in the
heavy view, child nodes now represent the statistics of the root node. Each root node of heavy view
displays flattened statistics for a particular function that ran during the profile, and each child
of these root nodes represents a callpath that lead to it. Thus, the statistics for each of these child
nodes should show how much of the root nodes values came from it. For example, if you had the following to
stacks take place during the profile:

A ->calls 1 times-> B ->calls 2 times-> C
D ->calls 4 times-> C

The tree for the C root node would look like this:

C -> B -> A

-> D

The number of calls values would look like this:

C (6) -> B (2) -> A(2)

-> D (4)

What this means is that "2 of the total 6 C calls came from B", "2 of the total C calls came from A", and
"4 of the total C calls came from D". Notice that the "A ->calls 2 time->" is completely ignored. This becomes
particularly tricky during recursive calls, because each child note can represent multiple possible paths. This
is the reason that we would get things like 40000% previously with recursion.

This is also the way gprof works, and as close as we can get to Shark's behavior (Shark is not instrumented so it
can't know exactly how many calls came from where, etc).

  • English.lproj/localizedStrings.js: Added "Average" for average times in the profile.
  • inspector/JavaScriptProfile.cpp: (WebCore::ProfileClass):
  • inspector/JavaScriptProfileNode.cpp: (WebCore::getParent): (WebCore::getHead): (WebCore::getCallUID): (WebCore::ProfileNodeClass):
  • inspector/front-end/BottomUpProfileDataGridTree.js: Added. (WebInspector.BottomUpProfileDataGridTree): (WebInspector.BottomUpProfileDataGridTree.prototype.focus): (WebInspector.BottomUpProfileDataGridNode): (WebInspector.BottomUpProfileDataGridNode.prototype._takePropertiesFromProfileDataGridNode): (WebInspector.BottomUpProfileDataGridNode.prototype._keepOnlyChild): (WebInspector.BottomUpProfileDataGridNode.prototype._exclude): (WebInspector.BottomUpProfileDataGridNode.prototype._merge): (WebInspector.BottomUpProfileDataGridNode.prototype._populate):
  • inspector/front-end/DataGrid.js: (WebInspector.DataGrid.prototype.insertChild): (WebInspector.DataGrid.prototype.removeChild): (WebInspector.DataGrid.prototype.removeChildren): (WebInspector.DataGridNode.prototype.set hasChildren): (WebInspector.DataGridNode.prototype.get hasChildren):
  • inspector/front-end/ProfileDataGridTree.js: Added. (WebInspector.ProfileDataGridNode): (WebInspector.ProfileDataGridNode.prototype.get data.formatMilliseconds): (WebInspector.ProfileDataGridNode.prototype.get data): (WebInspector.ProfileDataGridNode.prototype.createCell): (WebInspector.ProfileDataGridNode.prototype.select): (WebInspector.ProfileDataGridNode.prototype.deselect): (WebInspector.ProfileDataGridNode.prototype.expand): (WebInspector.ProfileDataGridNode.prototype.insertChild): (WebInspector.ProfileDataGridNode.prototype.removeChild): (WebInspector.ProfileDataGridNode.prototype.removeChildren): (WebInspector.ProfileDataGridNode.prototype.findChild): (WebInspector.ProfileDataGridNode.prototype.get averageTime): (WebInspector.ProfileDataGridNode.prototype.get averagePercent): (WebInspector.ProfileDataGridNode.prototype.get selfPercent): (WebInspector.ProfileDataGridNode.prototype.get totalPercent): (WebInspector.ProfileDataGridNode.prototype._save): (WebInspector.ProfileDataGridNode.prototype._restore): (WebInspector.ProfileDataGridNode.prototype._merge): (WebInspector.ProfileDataGridTree): (WebInspector.ProfileDataGridTree.prototype.get expanded): (WebInspector.ProfileDataGridTree.prototype.appendChild): (WebInspector.ProfileDataGridTree.prototype.insertChild): (WebInspector.ProfileDataGridTree.prototype.removeChildren): (WebInspector.ProfileDataGridTree.prototype.findChild.WebInspector.ProfileDataGridNode.prototype.findChild.sort.WebInspector.ProfileDataGridNode.prototype.sort._save): (WebInspector.ProfileDataGridTree.propertyComparator.comparator): (WebInspector.ProfileDataGridTree.propertyComparator.else.comparator): (WebInspector.ProfileDataGridTree.propertyComparator):
  • inspector/front-end/ProfileView.js: (WebInspector.ProfileView): (WebInspector.ProfileView.prototype.set profile): (WebInspector.ProfileView.prototype.get bottomUpProfileDataGridTree): (WebInspector.ProfileView.prototype.get topDownProfileDataGridTree): (WebInspector.ProfileView.prototype.get currentTree): (WebInspector.ProfileView.prototype.set currentTree): (WebInspector.ProfileView.prototype.get topDownTree): (WebInspector.ProfileView.prototype.get bottomUpTree): (WebInspector.ProfileView.prototype.refresh): (WebInspector.ProfileView.prototype.refreshVisibleData): (WebInspector.ProfileView.prototype.refreshShowAsPercents): (WebInspector.ProfileView.prototype.performSearch.matchesQuery): (WebInspector.ProfileView.prototype.performSearch): (WebInspector.ProfileView.prototype._changeView): (WebInspector.ProfileView.prototype._focusClicked): (WebInspector.ProfileView.prototype._excludeClicked): (WebInspector.ProfileView.prototype._resetClicked): (WebInspector.ProfileView.prototype._sortProfile):
  • inspector/front-end/ProfilesPanel.js: (WebInspector.ProfilesPanel.prototype.showProfile): (WebInspector.ProfilesPanel.prototype.showView): (WebInspector.ProfilesPanel.prototype.searchMatchFound):
  • inspector/front-end/TopDownProfileDataGridTree.js: Added. (WebInspector.TopDownProfileDataGridNode): (WebInspector.TopDownProfileDataGridNode.prototype._populate): (WebInspector.TopDownProfileDataGridNode.prototype._exclude): (WebInspector.TopDownProfileDataGridTree): (WebInspector.TopDownProfileDataGridTree.prototype.focus): (WebInspector.TopDownProfileDataGridTree.prototype.exclude):
  • inspector/front-end/WebKit.qrc:
  • inspector/front-end/inspector.css:
  • inspector/front-end/inspector.html:

LayoutTests:

2009-04-23 Francisco Tolmasky <[email protected]>

BUG 24604: WebKit profiler reports incorrect total times
<https://bugs.webkit.org/show_bug.cgi?id=24604>

Reviewed by Timothy Hatcher and Kevin McCullough.

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):
File size: 10.2 KB
Line 
1/*
2 * Copyright (C) 2008 Apple Inc. All rights reserved.
3 *
4 * Redistribution and use in source and binary forms, with or without
5 * modification, are permitted provided that the following conditions
6 * are met:
7 *
8 * 1. Redistributions of source code must retain the above copyright
9 * notice, this list of conditions and the following disclaimer.
10 * 2. Redistributions in binary form must reproduce the above copyright
11 * notice, this list of conditions and the following disclaimer in the
12 * documentation and/or other materials provided with the distribution.
13 * 3. Neither the name of Apple Computer, Inc. ("Apple") nor the names of
14 * its contributors may be used to endorse or promote products derived
15 * from this software without specific prior written permission.
16 *
17 * THIS SOFTWARE IS PROVIDED BY APPLE AND ITS CONTRIBUTORS "AS IS" AND ANY
18 * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
19 * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
20 * DISCLAIMED. IN NO EVENT SHALL APPLE OR ITS CONTRIBUTORS BE LIABLE FOR ANY
21 * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
22 * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
23 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
24 * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
25 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF
26 * THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27 */
28
29#include "config.h"
30#include "ProfileNode.h"
31
32#include "DateMath.h"
33#include "Profiler.h"
34#include <stdio.h>
35
36#if PLATFORM(WIN_OS)
37#include <windows.h>
38#endif
39
40namespace JSC {
41
42static double getCount()
43{
44#if PLATFORM(WIN_OS)
45 static LARGE_INTEGER frequency = {0};
46 if (!frequency.QuadPart)
47 QueryPerformanceFrequency(&frequency);
48 LARGE_INTEGER counter;
49 QueryPerformanceCounter(&counter);
50 return static_cast<double>(counter.QuadPart) / frequency.QuadPart;
51#else
52 return getCurrentUTCTimeWithMicroseconds();
53#endif
54}
55
56ProfileNode::ProfileNode(const CallIdentifier& callIdentifier, ProfileNode* headNode, ProfileNode* parentNode)
57 : m_callIdentifier(callIdentifier)
58 , m_head(headNode)
59 , m_parent(parentNode)
60 , m_nextSibling(0)
61 , m_startTime(0.0)
62 , m_actualTotalTime(0.0)
63 , m_visibleTotalTime(0.0)
64 , m_actualSelfTime(0.0)
65 , m_visibleSelfTime(0.0)
66 , m_numberOfCalls(0)
67 , m_visible(true)
68{
69 startTimer();
70}
71
72ProfileNode::ProfileNode(ProfileNode* headNode, ProfileNode* nodeToCopy)
73 : m_callIdentifier(nodeToCopy->callIdentifier())
74 , m_head(headNode)
75 , m_parent(nodeToCopy->parent())
76 , m_nextSibling(0)
77 , m_startTime(0.0)
78 , m_actualTotalTime(nodeToCopy->actualTotalTime())
79 , m_visibleTotalTime(nodeToCopy->totalTime())
80 , m_actualSelfTime(nodeToCopy->actualSelfTime())
81 , m_visibleSelfTime(nodeToCopy->selfTime())
82 , m_numberOfCalls(nodeToCopy->numberOfCalls())
83 , m_visible(nodeToCopy->visible())
84{
85}
86
87ProfileNode* ProfileNode::willExecute(const CallIdentifier& callIdentifier)
88{
89 for (StackIterator currentChild = m_children.begin(); currentChild != m_children.end(); ++currentChild) {
90 if ((*currentChild)->callIdentifier() == callIdentifier) {
91 (*currentChild)->startTimer();
92 return (*currentChild).get();
93 }
94 }
95
96 RefPtr<ProfileNode> newChild = ProfileNode::create(callIdentifier, m_head ? m_head : this, this); // If this ProfileNode has no head it is the head.
97 if (m_children.size())
98 m_children.last()->setNextSibling(newChild.get());
99 m_children.append(newChild.release());
100 return m_children.last().get();
101}
102
103ProfileNode* ProfileNode::didExecute()
104{
105 endAndRecordCall();
106 return m_parent;
107}
108
109void ProfileNode::addChild(PassRefPtr<ProfileNode> prpChild)
110{
111 RefPtr<ProfileNode> child = prpChild;
112 child->setParent(this);
113 if (m_children.size())
114 m_children.last()->setNextSibling(child.get());
115 m_children.append(child.release());
116}
117
118ProfileNode* ProfileNode::findChild(ProfileNode* node) const
119{
120 if (!node)
121 return 0;
122
123 for (size_t i = 0; i < m_children.size(); ++i) {
124 if (*node == m_children[i].get())
125 return m_children[i].get();
126 }
127
128 return 0;
129}
130
131void ProfileNode::removeChild(ProfileNode* node)
132{
133 if (!node)
134 return;
135
136 for (size_t i = 0; i < m_children.size(); ++i) {
137 if (*node == m_children[i].get()) {
138 m_children.remove(i);
139 break;
140 }
141 }
142
143 resetChildrensSiblings();
144}
145
146void ProfileNode::insertNode(PassRefPtr<ProfileNode> prpNode)
147{
148 RefPtr<ProfileNode> node = prpNode;
149
150 for (unsigned i = 0; i < m_children.size(); ++i)
151 node->addChild(m_children[i].release());
152
153 m_children.clear();
154 m_children.append(node.release());
155}
156
157void ProfileNode::stopProfiling()
158{
159 if (m_startTime)
160 endAndRecordCall();
161
162 m_visibleTotalTime = m_actualTotalTime;
163
164 ASSERT(m_actualSelfTime == 0.0 && m_startTime == 0.0);
165
166 // Because we iterate in post order all of our children have been stopped before us.
167 for (unsigned i = 0; i < m_children.size(); ++i)
168 m_actualSelfTime += m_children[i]->totalTime();
169
170 ASSERT(m_actualSelfTime <= m_actualTotalTime);
171 m_actualSelfTime = m_actualTotalTime - m_actualSelfTime;
172 m_visibleSelfTime = m_actualSelfTime;
173}
174
175ProfileNode* ProfileNode::traverseNextNodePostOrder() const
176{
177 ProfileNode* next = m_nextSibling;
178 if (!next)
179 return m_parent;
180 while (ProfileNode* firstChild = next->firstChild())
181 next = firstChild;
182 return next;
183}
184
185ProfileNode* ProfileNode::traverseNextNodePreOrder(bool processChildren) const
186{
187 if (processChildren && m_children.size())
188 return m_children[0].get();
189
190 if (m_nextSibling)
191 return m_nextSibling;
192
193 ProfileNode* nextParent = m_parent;
194 if (!nextParent)
195 return 0;
196
197 ProfileNode* next;
198 for (next = m_parent->nextSibling(); !next; next = nextParent->nextSibling()) {
199 nextParent = nextParent->parent();
200 if (!nextParent)
201 return 0;
202 }
203
204 return next;
205}
206
207void ProfileNode::setTreeVisible(ProfileNode* node, bool visible)
208{
209 ProfileNode* nodeParent = node->parent();
210 ProfileNode* nodeSibling = node->nextSibling();
211 node->setParent(0);
212 node->setNextSibling(0);
213
214 for (ProfileNode* currentNode = node; currentNode; currentNode = currentNode->traverseNextNodePreOrder())
215 currentNode->setVisible(visible);
216
217 node->setParent(nodeParent);
218 node->setNextSibling(nodeSibling);
219}
220
221void ProfileNode::calculateVisibleTotalTime()
222{
223 double sumOfVisibleChildrensTime = 0.0;
224
225 for (unsigned i = 0; i < m_children.size(); ++i) {
226 if (m_children[i]->visible())
227 sumOfVisibleChildrensTime += m_children[i]->totalTime();
228 }
229
230 m_visibleTotalTime = m_visibleSelfTime + sumOfVisibleChildrensTime;
231}
232
233bool ProfileNode::focus(const CallIdentifier& callIdentifier)
234{
235 if (!m_visible)
236 return false;
237
238 if (m_callIdentifier != callIdentifier) {
239 m_visible = false;
240 return true;
241 }
242
243 for (ProfileNode* currentParent = m_parent; currentParent; currentParent = currentParent->parent())
244 currentParent->setVisible(true);
245
246 return false;
247}
248
249void ProfileNode::exclude(const CallIdentifier& callIdentifier)
250{
251 if (m_visible && m_callIdentifier == callIdentifier) {
252 setTreeVisible(this, false);
253
254 m_parent->setVisibleSelfTime(m_parent->selfTime() + m_visibleTotalTime);
255 }
256}
257
258void ProfileNode::restore()
259{
260 m_visibleTotalTime = m_actualTotalTime;
261 m_visibleSelfTime = m_actualSelfTime;
262 m_visible = true;
263}
264
265void ProfileNode::endAndRecordCall()
266{
267 m_actualTotalTime += m_startTime ? getCount() - m_startTime : 0.0;
268 m_startTime = 0.0;
269
270 ++m_numberOfCalls;
271}
272
273void ProfileNode::startTimer()
274{
275 if (!m_startTime)
276 m_startTime = getCount();
277}
278
279void ProfileNode::resetChildrensSiblings()
280{
281 unsigned size = m_children.size();
282 for (unsigned i = 0; i < size; ++i)
283 m_children[i]->setNextSibling(i + 1 == size ? 0 : m_children[i + 1].get());
284}
285
286#ifndef NDEBUG
287void ProfileNode::debugPrintData(int indentLevel) const
288{
289 // Print function names
290 for (int i = 0; i < indentLevel; ++i)
291 printf(" ");
292
293 printf("Function Name %s %d SelfTime %.3fms/%.3f%% TotalTime %.3fms/%.3f%% VSelf %.3fms VTotal %.3fms Visible %s Next Sibling %s\n",
294 functionName().UTF8String().c_str(),
295 m_numberOfCalls, m_actualSelfTime, selfPercent(), m_actualTotalTime, totalPercent(),
296 m_visibleSelfTime, m_visibleTotalTime,
297 (m_visible ? "True" : "False"),
298 m_nextSibling ? m_nextSibling->functionName().UTF8String().c_str() : "");
299
300 ++indentLevel;
301
302 // Print children's names and information
303 for (StackIterator currentChild = m_children.begin(); currentChild != m_children.end(); ++currentChild)
304 (*currentChild)->debugPrintData(indentLevel);
305}
306
307// print the profiled data in a format that matches the tool sample's output.
308double ProfileNode::debugPrintDataSampleStyle(int indentLevel, FunctionCallHashCount& countedFunctions) const
309{
310 printf(" ");
311
312 // Print function names
313 const char* name = functionName().UTF8String().c_str();
314 double sampleCount = m_actualTotalTime * 1000;
315 if (indentLevel) {
316 for (int i = 0; i < indentLevel; ++i)
317 printf(" ");
318
319 countedFunctions.add(functionName().rep());
320
321 printf("%.0f %s\n", sampleCount ? sampleCount : 1, name);
322 } else
323 printf("%s\n", name);
324
325 ++indentLevel;
326
327 // Print children's names and information
328 double sumOfChildrensCount = 0.0;
329 for (StackIterator currentChild = m_children.begin(); currentChild != m_children.end(); ++currentChild)
330 sumOfChildrensCount += (*currentChild)->debugPrintDataSampleStyle(indentLevel, countedFunctions);
331
332 sumOfChildrensCount *= 1000; //
333 // Print remainder of samples to match sample's output
334 if (sumOfChildrensCount < sampleCount) {
335 printf(" ");
336 while (indentLevel--)
337 printf(" ");
338
339 printf("%.0f %s\n", sampleCount - sumOfChildrensCount, functionName().UTF8String().c_str());
340 }
341
342 return m_actualTotalTime;
343}
344#endif
345
346} // namespace JSC
Note: See TracBrowser for help on using the repository browser.