Changeset 175203 in webkit for trunk/Source/JavaScriptCore/profiler

Timestamp:

Oct 25, 2014, 3:05:57 PM (11 years ago)

Author:

Brian Burg

Message:

Web Inspector: timelines should not count time elapsed while paused in the debugger
​https://bugs.webkit.org/show_bug.cgi?id=136351

Reviewed by Timothy Hatcher.

Source/JavaScriptCore:

Now that we have a stopwatch to provide pause-aware timing data, we can remove the
profiler's handling of debugger pause/continue callbacks. The debugger agent accounts
for suspended execution by pausing and resuming the stopwatch.

• API/JSProfilerPrivate.cpp:

(JSStartProfiling): Use a fresh stopwatch when profiling from the JSC API.

• inspector/InspectorEnvironment.h:
• inspector/JSGlobalObjectInspectorController.cpp:

(Inspector::JSGlobalObjectInspectorController::JSGlobalObjectInspectorController):
(Inspector::JSGlobalObjectInspectorController::executionStopwatch):

• inspector/JSGlobalObjectInspectorController.h:
• inspector/ScriptDebugServer.cpp:

(Inspector::ScriptDebugServer::handlePause):

• inspector/agents/InspectorDebuggerAgent.cpp:

(Inspector::InspectorDebuggerAgent::didPause):
(Inspector::InspectorDebuggerAgent::breakpointActionProbe):
(Inspector::InspectorDebuggerAgent::didContinue):

• inspector/agents/InspectorDebuggerAgent.h:
• profiler/LegacyProfiler.cpp:

(JSC::LegacyProfiler::profiler): Use nullptr.
(JSC::LegacyProfiler::startProfiling): Hand off a stopwatch to the profile generator.
(JSC::LegacyProfiler::stopProfiling): Use nullptr.
(JSC::LegacyProfiler::didPause): Deleted.
(JSC::LegacyProfiler::didContinue): Deleted.

• profiler/LegacyProfiler.h:
• profiler/Profile.cpp: The root node should always have a start time of 0.0.

(JSC::Profile::Profile):

• profiler/ProfileGenerator.cpp: Remove debugger pause/continue callbacks and the

timestamp member that was used to track time elapsed by the debugger. Just use the
stopwatch's elapsed times to generate start/elapsed times for function calls.

(JSC::ProfileGenerator::create):
(JSC::ProfileGenerator::ProfileGenerator):
(JSC::AddParentForConsoleStartFunctor::operator()): The parent node of |console.profile|
should have a start time of 0.0, since it represents the starting node of profiling.

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

• profiler/ProfileGenerator.h:

Source/WebCore:

To avoid counting time elapsed while the debugger is paused, timeline records should
keep track of time elapsed since the start of timeline capturing, rather than wall clock
timestamps. We can easily compute elapsed time by sharing a Stopwatch instance through the
inspector environment. The stopwatch runs with timelines and is paused with the debugger,
so subsequent time measurements will not include time elapsed while the debugger is paused.

This refactoring is safe because start and end times are only used to graph records; the
timestamp's actual value is irrelevant and is not displayed in the user interface. Date
timestamps are still included with network-related records as part of their header data.

No new tests, because we cannot reliably test timing changes induced by debugger pauses.
It is possible for records to accrue time before the debugger pauses or after it resumes.

• inspector/InspectorCSSAgent.cpp: Remove unnecessary include.
• inspector/InspectorController.cpp:

(WebCore::InspectorController::InspectorController):
(WebCore::InspectorController::executionStopwatch): Add a shared stopwatch.

• inspector/InspectorController.h:
• inspector/InspectorPageAgent.cpp:

(WebCore::InspectorPageAgent::timestamp): Redirect to the shared stopwatch.
(WebCore::InspectorPageAgent::domContentEventFired):
(WebCore::InspectorPageAgent::loadEventFired):

• inspector/InspectorPageAgent.h:
• inspector/InspectorResourceAgent.cpp:

(WebCore::InspectorResourceAgent::timestamp): Redirect to the shared stopwatch.
(WebCore::InspectorResourceAgent::willSendRequest):
(WebCore::InspectorResourceAgent::didReceiveResponse):
(WebCore::InspectorResourceAgent::didReceiveData):
(WebCore::InspectorResourceAgent::didFinishLoading):
(WebCore::InspectorResourceAgent::didFailLoading):
(WebCore::InspectorResourceAgent::didLoadResourceFromMemoryCache):
(WebCore::InspectorResourceAgent::willSendWebSocketHandshakeRequest):
(WebCore::InspectorResourceAgent::didReceiveWebSocketHandshakeResponse):
(WebCore::InspectorResourceAgent::didCloseWebSocket):
(WebCore::InspectorResourceAgent::didReceiveWebSocketFrame):
(WebCore::InspectorResourceAgent::didSendWebSocketFrame):
(WebCore::InspectorResourceAgent::didReceiveWebSocketFrameError):

• inspector/InspectorResourceAgent.h:
• inspector/InspectorTimelineAgent.cpp:

(WebCore::InspectorTimelineAgent::internalStart): Start and stop the stopwatch with timelines.
(WebCore::InspectorTimelineAgent::internalStop):
(WebCore::InspectorTimelineAgent::timestamp): Redirect to the shared stopwatch.
(WebCore::startProfiling):
(WebCore::InspectorTimelineAgent::startFromConsole):
(WebCore::InspectorTimelineAgent::willCallFunction):
(WebCore::InspectorTimelineAgent::willEvaluateScript):
(WebCore::TimelineTimeConverter::reset): Deleted.

• inspector/InspectorTimelineAgent.h:

(WebCore::TimelineTimeConverter::TimelineTimeConverter): Deleted.
(WebCore::TimelineTimeConverter::fromMonotonicallyIncreasingTime): Deleted.
(WebCore::InspectorTimelineAgent::timeConverter): Deleted.

• inspector/TimelineRecordFactory.cpp:
• inspector/WorkerInspectorController.cpp:

(WebCore::WorkerInspectorController::WorkerInspectorController):
(WebCore::WorkerInspectorController::executionStopwatch): Add a shared stopwatch.

• inspector/WorkerInspectorController.h:

Source/WebInspectorUI:

Don't update the timeline's current time when the debugger is paused.

Start and end times for timeline records are now in seconds elapsed since timeline
recording started, rather than milliseconds since the epoch. Also convert code that
tracks page/resource load timings to use elapsed times rather than timestamps.

Add a workaround to preserve compatibility with old backends. Convert legacy timestamps
in multiple agents to elapsed times.

• UserInterface/Controllers/FrameResourceManager.js:

(WebInspector.FrameResourceManager.prototype.resourceRequestWillBeSent):
(WebInspector.FrameResourceManager.prototype.resourceRequestWasServedFromMemoryCache):
(WebInspector.FrameResourceManager.prototype.resourceRequestDidReceiveResponse):
(WebInspector.FrameResourceManager.prototype.resourceRequestDidReceiveData):
(WebInspector.FrameResourceManager.prototype.resourceRequestDidFinishLoading):
(WebInspector.FrameResourceManager.prototype.resourceRequestDidFailLoading):
(WebInspector.FrameResourceManager.prototype._addNewResourceToFrame):

• UserInterface/Controllers/ProbeManager.js:
• UserInterface/Controllers/TimelineManager.js:

(WebInspector.TimelineManager.prototype.computeElapsedTime): Forward to the active TimelineRecording.
(WebInspector.TimelineManager.prototype.eventRecorded.processRecord):
(WebInspector.TimelineManager.prototype.eventRecorded):
(WebInspector.TimelineManager.prototype.pageDidLoad):
(WebInspector.TimelineManager.prototype._loadNewRecording):

• UserInterface/Models/Probe.js:

(WebInspector.ProbeSample):

• UserInterface/Models/Resource.js:

(WebInspector.Resource.prototype.updateForRedirectResponse):
(WebInspector.Resource.prototype.updateForResponse):
(WebInspector.Resource.prototype.increaseSize):
(WebInspector.Resource.prototype.markAsFinished):
(WebInspector.Resource.prototype.markAsFailed):
(WebInspector.Resource.prototype.revertMarkAsFinished):

• UserInterface/Models/TimelineRecording.js:

(WebInspector.TimelineRecording.prototype.computeElapsedTime):

• UserInterface/Views/TimelineContentView.js:

(WebInspector.TimelineContentView.prototype._debuggerPaused):
(WebInspector.TimelineContentView.prototype._debuggerResumed):

Source/WTF:

• WTF.vcxproj/WTF.vcxproj:
• WTF.vcxproj/WTF.vcxproj.filters:
• WTF.xcodeproj/project.pbxproj:
• wtf/CMakeLists.txt:
• wtf/Stopwatch.h: Added. This implements a refcounted monotonic stopwatch.

(WTF::Stopwatch::create):
(WTF::Stopwatch::Stopwatch):
(WTF::Stopwatch::reset):
(WTF::Stopwatch::start):
(WTF::Stopwatch::stop):
(WTF::Stopwatch::elapsedTime):

Location:

trunk/Source/JavaScriptCore/profiler

Files:

• LegacyProfiler.cpp (modified) (7 diffs)
• LegacyProfiler.h (modified) (3 diffs)
• Profile.cpp (modified) (1 diff)
• ProfileGenerator.cpp (modified) (7 diffs)
• ProfileGenerator.h (modified) (6 diffs)

trunk/Source/JavaScriptCore/profiler/LegacyProfiler.cpp

@@ -33 +33 @@
 #include "CodeBlock.h"
 #include "CommonIdentifiers.h"
-#include "DebuggerCallFrame.h"
 #include "InternalFunction.h"
 #include "JSFunction.h"
@@ -51 +50 @@
 static CallIdentifier createCallIdentifierFromFunctionImp(ExecState*, JSObject*, const String& defaultSourceURL, unsigned defaultLineNumber, unsigned defaultColumnNumber);
 
-LegacyProfiler* LegacyProfiler::s_sharedLegacyProfiler = 0;
+LegacyProfiler* LegacyProfiler::s_sharedLegacyProfiler = nullptr;
 
 LegacyProfiler* LegacyProfiler::profiler()
@@ -58 +57 @@
         s_sharedLegacyProfiler = new LegacyProfiler();
     return s_sharedLegacyProfiler;
-}   
-
-void LegacyProfiler::startProfiling(ExecState* exec, const String& title)
+}
+
+void LegacyProfiler::startProfiling(ExecState* exec, const String& title, PassRefPtr<Stopwatch> stopwatch)
 {
     if (!exec)
@@ -76 +75 @@
 
     exec->vm().setEnabledProfiler(this);
-    RefPtr<ProfileGenerator> profileGenerator = ProfileGenerator::create(exec, title, ++ProfilesUID);
+    RefPtr<ProfileGenerator> profileGenerator = ProfileGenerator::create(exec, title, ++ProfilesUID, stopwatch);
     m_currentProfiles.append(profileGenerator);
 }
@@ -83 +82 @@
 {
     if (!exec)
-        return 0;
+        return nullptr;
 
     JSGlobalObject* origin = exec->lexicalGlobalObject();
@@ -95 +94 @@
             if (!m_currentProfiles.size())
                 exec->vm().setEnabledProfiler(nullptr);
-            
+
             return returnProfile;
         }
     }
 
-    return 0;
+    return nullptr;
 }
 
@@ -183 +182 @@
 
     callFunctionForProfilesWithGroup(std::bind(&ProfileGenerator::exceptionUnwind, std::placeholders::_1, handlerCallFrame, callIdentifier), m_currentProfiles, handlerCallFrame->lexicalGlobalObject()->profileGroup());
-}
-
-void LegacyProfiler::didPause(PassRefPtr<DebuggerCallFrame> prpCallFrame)
-{
-    if (m_currentProfiles.isEmpty())
-        return;
-
-    RefPtr<DebuggerCallFrame> callFrame = prpCallFrame;
-    CallIdentifier callIdentifier = createCallIdentifier(callFrame->exec(), JSValue(), StringImpl::empty(), 0, 0);
-
-    callFunctionForProfilesWithGroup(std::bind(&ProfileGenerator::didPause, std::placeholders::_1, callFrame, callIdentifier), m_currentProfiles, callFrame->vmEntryGlobalObject()->profileGroup());
-}
-
-void LegacyProfiler::didContinue(PassRefPtr<DebuggerCallFrame> prpCallFrame)
-{
-    if (m_currentProfiles.isEmpty())
-        return;
-
-    RefPtr<DebuggerCallFrame> callFrame = prpCallFrame;
-    CallIdentifier callIdentifier = createCallIdentifier(callFrame->exec(), JSValue(), StringImpl::empty(), 0, 0);
-
-    callFunctionForProfilesWithGroup(std::bind(&ProfileGenerator::didContinue, std::placeholders::_1, callFrame, callIdentifier), m_currentProfiles, callFrame->vmEntryGlobalObject()->profileGroup());
 }
 

trunk/Source/JavaScriptCore/profiler/LegacyProfiler.h

@@ -33 +33 @@
 #include <wtf/PassRefPtr.h>
 #include <wtf/RefPtr.h>
+#include <wtf/Stopwatch.h>
 #include <wtf/Vector.h>
 
 namespace JSC {
 
-class DebuggerCallFrame;
 class ExecState;
-class VM;
 class JSGlobalObject;
 class JSObject;
@@ -49 +48 @@
     WTF_MAKE_FAST_ALLOCATED;
 public:
-    JS_EXPORT_PRIVATE static LegacyProfiler* profiler(); 
+    JS_EXPORT_PRIVATE static LegacyProfiler* profiler();
     static CallIdentifier createCallIdentifier(ExecState*, JSValue, const WTF::String& sourceURL, unsigned defaultLineNumber, unsigned defaultColumnNumber);
 
-    JS_EXPORT_PRIVATE void startProfiling(ExecState*, const WTF::String& title);
+    JS_EXPORT_PRIVATE void startProfiling(ExecState*, const WTF::String& title, PassRefPtr<Stopwatch>);
     JS_EXPORT_PRIVATE PassRefPtr<Profile> stopProfiling(ExecState*, const WTF::String& title);
     void stopProfiling(JSGlobalObject*);
@@ -67 +66 @@
     void exceptionUnwind(ExecState* handlerCallFrame);
 
-    void didPause(PassRefPtr<DebuggerCallFrame>);
-    void didContinue(PassRefPtr<DebuggerCallFrame>);
-
     const Vector<RefPtr<ProfileGenerator>>& currentProfiles() { return m_currentProfiles; };
 

trunk/Source/JavaScriptCore/profiler/Profile.cpp

@@ -45 +45 @@
     // into the profiler will need to know which thread it is executing on.
     m_rootNode = ProfileNode::create(nullptr, CallIdentifier(ASCIILiteral("Thread_1"), String(), 0, 0), nullptr);
-    m_rootNode->appendCall(ProfileNode::Call(currentTime()));
+    m_rootNode->appendCall(ProfileNode::Call(0.0));
 }
 

trunk/Source/JavaScriptCore/profiler/ProfileGenerator.cpp

@@ -29 +29 @@
 #include "CallFrame.h"
 #include "CodeBlock.h"
-#include "Debugger.h"
 #include "JSGlobalObject.h"
 #include "JSStringRef.h"
@@ -41 +40 @@
 namespace JSC {
 
-PassRefPtr<ProfileGenerator> ProfileGenerator::create(ExecState* exec, const String& title, unsigned uid)
-{
-    return adoptRef(new ProfileGenerator(exec, title, uid));
-}
-
-ProfileGenerator::ProfileGenerator(ExecState* exec, const String& title, unsigned uid)
+PassRefPtr<ProfileGenerator> ProfileGenerator::create(ExecState* exec, const String& title, unsigned uid, PassRefPtr<Stopwatch> stopwatch)
+{
+    return adoptRef(new ProfileGenerator(exec, title, uid, stopwatch));
+}
+
+ProfileGenerator::ProfileGenerator(ExecState* exec, const String& title, unsigned uid, PassRefPtr<Stopwatch> stopwatch)
     : m_origin(exec ? exec->lexicalGlobalObject() : nullptr)
     , m_profileGroup(exec ? exec->lexicalGlobalObject()->profileGroup() : 0)
-    , m_debuggerPausedTimestamp(NAN)
+    , m_stopwatch(stopwatch)
     , m_foundConsoleStartParent(false)
     , m_suspended(false)
 {
-    if (Debugger* debugger = exec->lexicalGlobalObject()->debugger())
-        m_debuggerPausedTimestamp = debugger->isPaused() ? currentTime() : NAN;
-
     m_profile = Profile::create(title, uid);
     m_currentNode = m_rootNode = m_profile->rootNode();
@@ -86 +82 @@
         visitor->computeLineAndColumn(line, column);
         m_currentNode = ProfileNode::create(m_exec, LegacyProfiler::createCallIdentifier(m_exec, visitor->callee(), visitor->sourceURL(), line, column), m_rootNode.get());
-        m_currentNode->appendCall(ProfileNode::Call(currentTime()));
+        // Assume that profile times are relative to when the |console.profile| command is evaluated.
+        // This matches the logic in JSStartProfiling() and InspectorTimelineAgent::startFromConsole().
+        m_currentNode->appendCall(ProfileNode::Call(0.0));
         m_rootNode->spliceNode(m_currentNode.get());
 
@@ -119 +117 @@
 
     if (std::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 (!std::isnan(m_debuggerPausedTimestamp))
-        startTime = NAN;
+        startTime = m_stopwatch->elapsedTime();
 
     node->appendCall(ProfileNode::Call(startTime));
@@ -135 +128 @@
     ProfileNode::Call& last = node->lastCall();
 
-    // If the debugger is paused, ignore the interval that ends now.
-    if (!std::isnan(m_debuggerPausedTimestamp) && !std::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 (!std::isnan(m_debuggerPausedTimestamp)) {
-        last.setStartTime(m_debuggerPausedTimestamp);
-        last.setElapsedTime(0.0);
-        return;
-    }
-
-    // Otherwise, add the interval ending now to elapsed time.
     double previousElapsedTime = std::isnan(last.elapsedTime()) ? 0.0 : last.elapsedTime();
-    double newlyElapsedTime = currentTime() - last.startTime();
+    double newlyElapsedTime = m_stopwatch->elapsedTime() - last.startTime();
     last.setElapsedTime(previousElapsedTime + newlyElapsedTime);
 }
@@ -181 +161 @@
 
     m_currentNode = calleeNode;
-    beginCallEntry(calleeNode.get());
+    beginCallEntry(calleeNode.get(), m_stopwatch->elapsedTime());
 }
 
@@ -224 +204 @@
 }
 
-void ProfileGenerator::didPause(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&)
-{
-    ASSERT(std::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(!std::isnan(last.startTime()));
-
-        double previousElapsedTime = std::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(!std::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

@@ -30 +30 @@
 #include <wtf/RefCounted.h>
 #include <wtf/RefPtr.h>
+#include <wtf/Stopwatch.h>
 #include <wtf/text/WTFString.h>
 
@@ -43 +44 @@
     class ProfileGenerator : public RefCounted<ProfileGenerator>  {
     public:
-        static PassRefPtr<ProfileGenerator> create(ExecState*, const WTF::String& title, unsigned uid);
+        static PassRefPtr<ProfileGenerator> create(ExecState*, const WTF::String& title, unsigned uid, PassRefPtr<Stopwatch>);
 
         // Members
@@ -55 +56 @@
         void exceptionUnwind(ExecState* handlerCallFrame, const CallIdentifier&);
 
-        void didPause(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&);
-        void didContinue(PassRefPtr<DebuggerCallFrame>, const CallIdentifier&);
-
         void setIsSuspended(bool suspended) { ASSERT(m_suspended != suspended); m_suspended = suspended; }
 
@@ -63 +61 @@
 
     private:
-        ProfileGenerator(ExecState*, const WTF::String& title, unsigned uid);
+        ProfileGenerator(ExecState*, const WTF::String& title, unsigned uid, PassRefPtr<Stopwatch>);
         void addParentForConsoleStart(ExecState*);
 
@@ -69 +67 @@
         void removeProfileEnd();
 
-        void beginCallEntry(ProfileNode*, double startTime = NAN);
+        void beginCallEntry(ProfileNode*, double startTime);
         void endCallEntry(ProfileNode*);
 
@@ -75 +73 @@
         JSGlobalObject* m_origin;
         unsigned m_profileGroup;
-        // Timestamp is set to NAN when the debugger is not currently paused.
-        double m_debuggerPausedTimestamp;
+        RefPtr<Stopwatch> m_stopwatch;
         RefPtr<ProfileNode> m_rootNode;
         RefPtr<ProfileNode> m_currentNode;