Changeset 173939 in webkit

Timestamp:

Sep 24, 2014 5:25:31 PM (10 years ago)

Author:

Brian Burg

Message:

Web Inspector: subtract elapsed time while debugger is paused from profile nodes
​https://bugs.webkit.org/show_bug.cgi?id=136796

Reviewed by Timothy Hatcher.

Source/JavaScriptCore:

Rather than accruing no time to any profile node created while the debugger is paused,
we can instead count a node's elapsed time and exclude time elapsed while paused.

Time for a node may elapse in a non-contiguous fashion depending on the interleaving of
didPause, didContinue, willExecute, and didExecute. A node's start time is set to the
start of the last such interval that accrues elapsed time.

• profiler/ProfileGenerator.cpp:

(JSC::ProfileGenerator::ProfileGenerator):
(JSC::ProfileGenerator::beginCallEntry):
(JSC::ProfileGenerator::endCallEntry):
(JSC::ProfileGenerator::didPause): Added.
(JSC::ProfileGenerator::didContinue): Added.

• profiler/ProfileGenerator.h:

(JSC::ProfileGenerator::didPause): Deleted.
(JSC::ProfileGenerator::didContinue): Deleted.

• profiler/ProfileNode.h: Rename totalTime to elapsedTime.

(JSC::ProfileNode::Call::Call):
(JSC::ProfileNode::Call::elapsedTime): Added.
(JSC::ProfileNode::Call::setElapsedTime): Added.
(JSC::CalculateProfileSubtreeDataFunctor::operator()):
(JSC::ProfileNode::Call::totalTime): Deleted.
(JSC::ProfileNode::Call::setTotalTime): Deleted.

Source/WebCore:

• inspector/TimelineRecordFactory.cpp:

(WebCore::buildInspectorObject):

Location:

trunk/Source

Files:

• JavaScriptCore/ChangeLog (modified) (1 diff)
• JavaScriptCore/profiler/ProfileGenerator.cpp (modified) (4 diffs)
• JavaScriptCore/profiler/ProfileGenerator.h (modified) (2 diffs)
• JavaScriptCore/profiler/ProfileNode.h (modified) (3 diffs)
• WebCore/ChangeLog (modified) (1 diff)
• WebCore/inspector/TimelineRecordFactory.cpp (modified) (1 diff)

trunk/Source/JavaScriptCore/ChangeLog

@@ +1 @@
+2014-09-24  Brian J. Burg  <burg@cs.washington.edu>
+
+        Web Inspector: subtract elapsed time while debugger is paused from profile nodes
+        https://bugs.webkit.org/show_bug.cgi?id=136796
+
+        Reviewed by Timothy Hatcher.
+
+        Rather than accruing no time to any profile node created while the debugger is paused,
+        we can instead count a node's elapsed time and exclude time elapsed while paused.
+
+        Time for a node may elapse in a non-contiguous fashion depending on the interleaving of
+        didPause, didContinue, willExecute, and didExecute. A node's start time is set to the
+        start of the last such interval that accrues elapsed time.
+
+        * profiler/ProfileGenerator.cpp:
+        (JSC::ProfileGenerator::ProfileGenerator):
+        (JSC::ProfileGenerator::beginCallEntry):
+        (JSC::ProfileGenerator::endCallEntry):
+        (JSC::ProfileGenerator::didPause): Added.
+        (JSC::ProfileGenerator::didContinue): Added.
+        * profiler/ProfileGenerator.h:
+        (JSC::ProfileGenerator::didPause): Deleted.
+        (JSC::ProfileGenerator::didContinue): Deleted.
+        * profiler/ProfileNode.h: Rename totalTime to elapsedTime.
+        (JSC::ProfileNode::Call::Call):
+        (JSC::ProfileNode::Call::elapsedTime): Added.
+        (JSC::ProfileNode::Call::setElapsedTime): Added.
+        (JSC::CalculateProfileSubtreeDataFunctor::operator()):
+        (JSC::ProfileNode::Call::totalTime): Deleted.
+        (JSC::ProfileNode::Call::setTotalTime): Deleted.
+
 2014-09-24  Commit Queue  <commit-queue@webkit.org>
 

trunk/Source/JavaScriptCore/profiler/ProfileGenerator.cpp

@@ -49 +49 @@
     : m_origin(exec ? exec->lexicalGlobalObject() : nullptr)
     , m_profileGroup(exec ? exec->lexicalGlobalObject()->profileGroup() : 0)
+    , m_debuggerPausedTimestamp(NAN)
     , m_foundConsoleStartParent(false)
-    , m_debuggerPaused(false)
 {
     if (Debugger* debugger = exec->lexicalGlobalObject()->debugger())
-        m_debuggerPaused = debugger->isPaused();
+        m_debuggerPausedTimestamp = debugger->isPaused() ? currentTime() : NAN;
 
     m_profile = Profile::create(title, uid);
@@ -119 +119 @@
     if (isnan(startTime))
         startTime = currentTime();
+
+    // If the debugger is paused when beginning, then don't set the start time. It
+    // will be fixed up when the debugger unpauses or the call entry ends.
+    if (!isnan(m_debuggerPausedTimestamp))
+        startTime = NAN;
+
     node->appendCall(ProfileNode::Call(startTime));
 }
@@ -127 +133 @@
 
     ProfileNode::Call& last = node->lastCall();
-    ASSERT(isnan(last.totalTime()));
-
-    last.setTotalTime(m_debuggerPaused ? 0.0 : currentTime() - last.startTime());
+
+    // If the debugger is paused, ignore the interval that ends now.
+    if (!isnan(m_debuggerPausedTimestamp) && !isnan(last.elapsedTime()))
+        return;
+
+    // If paused and no time was accrued then the debugger was never unpaused. The call will
+    // have no time accrued and appear to have started when the debugger was paused.
+    if (!isnan(m_debuggerPausedTimestamp)) {
+        last.setStartTime(m_debuggerPausedTimestamp);
+        last.setElapsedTime(0.0);
+        return;
+    }
+
+    // Otherwise, add the interval ending now to elapsed time.
+    double previousElapsedTime = isnan(last.elapsedTime()) ? 0.0 : last.elapsedTime();
+    double newlyElapsedTime = currentTime() - last.startTime();
+    last.setElapsedTime(previousElapsedTime + newlyElapsedTime);
 }
 
@@ -197 +217 @@
 }
 
+void ProfileGenerator::didPause(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&)
+{
+    ASSERT(isnan(m_debuggerPausedTimestamp));
+
+    m_debuggerPausedTimestamp = currentTime();
+
+    for (ProfileNode* node = m_currentNode.get(); node != m_profile->rootNode(); node = node->parent()) {
+        ProfileNode::Call& last = node->lastCall();
+        ASSERT(!isnan(last.startTime()));
+
+        double previousElapsedTime = isnan(last.elapsedTime()) ? 0.0 : last.elapsedTime();
+        double additionalElapsedTime = m_debuggerPausedTimestamp - last.startTime();
+        last.setStartTime(NAN);
+        last.setElapsedTime(previousElapsedTime + additionalElapsedTime);
+    }
+}
+
+void ProfileGenerator::didContinue(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&)
+{
+    ASSERT(!isnan(m_debuggerPausedTimestamp));
+
+    for (ProfileNode* node = m_currentNode.get(); node != m_profile->rootNode(); node = node->parent())
+        node->lastCall().setStartTime(m_debuggerPausedTimestamp);
+
+    m_debuggerPausedTimestamp = NAN;
+}
+
 void ProfileGenerator::stopProfiling()
 {

trunk/Source/JavaScriptCore/profiler/ProfileGenerator.h

@@ -55 +55 @@
         void exceptionUnwind(ExecState* handlerCallFrame, const CallIdentifier&);
 
-        void didPause(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&) { m_debuggerPaused = true; }
-        void didContinue(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&) { m_debuggerPaused = false; }
+        void didPause(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&);
+        void didContinue(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&);
 
         void stopProfiling();
@@ -75 +75 @@
         JSGlobalObject* m_origin;
         unsigned m_profileGroup;
+        // Timestamp is set to NAN when the debugger is not currently paused.
+        double m_debuggerPausedTimestamp;
         RefPtr<ProfileNode> m_rootNode;
         RefPtr<ProfileNode> m_currentNode;
         bool m_foundConsoleStartParent;
-        bool m_debuggerPaused;
     };
 

trunk/Source/JavaScriptCore/profiler/ProfileNode.h

@@ -57 +57 @@
         struct Call {
         public:
-            Call(double startTime, double totalTime = NAN)
+            Call(double startTime, double elapsedTime = NAN)
                 : m_startTime(startTime)
-                , m_totalTime(totalTime)
+                , m_elapsedTime(elapsedTime)
             {
             }
@@ -66 +66 @@
             void setStartTime(double time)
             {
-                ASSERT_ARG(time, time >= 0.0);
+                ASSERT_ARG(time, time >= 0.0 || isnan(time));
                 m_startTime = time;
             }
 
-            double totalTime() const { return m_totalTime; }
-            void setTotalTime(double time)
+            double elapsedTime() const { return m_elapsedTime; }
+            void setElapsedTime(double time)
             {
-                ASSERT_ARG(time, time >= 0.0);
-                m_totalTime = time;
+                ASSERT_ARG(time, time >= 0.0 || isnan(time));
+                m_elapsedTime = time;
             }
 
         private:
             double m_startTime;
-            double m_totalTime;
+            double m_elapsedTime;
         };
 
@@ -171 +171 @@
             double selfTime = 0.0;
             for (const ProfileNode::Call& call : node->calls())
-                selfTime += call.totalTime();
+                selfTime += call.elapsedTime();
 
             double totalTime = selfTime;

trunk/Source/WebCore/ChangeLog

@@ +1 @@
+2014-09-24  Brian J. Burg  <burg@cs.washington.edu>
+
+        Web Inspector: subtract elapsed time while debugger is paused from profile nodes
+        https://bugs.webkit.org/show_bug.cgi?id=136796
+
+        Reviewed by Timothy Hatcher.
+
+        * inspector/TimelineRecordFactory.cpp:
+        (WebCore::buildInspectorObject):
+
 2014-09-24  Christophe Dumez  <cdumez@apple.com>
 

trunk/Source/WebCore/inspector/TimelineRecordFactory.cpp

@@ -275 +275 @@
     RefPtr<Protocol::Timeline::CPUProfileNodeCall> result = Protocol::Timeline::CPUProfileNodeCall::create()
         .setStartTime(call.startTime())
-        .setTotalTime(call.totalTime());
+        .setTotalTime(call.elapsedTime());
     return result.release();
 }