Bug 1358074 (part 3) - Don't measure process creation time on every profiler_start() call. r=mstange.
☠☠ backed out by 265931fd5e5a ☠ ☠
authorNicholas Nethercote <nnethercote@mozilla.com>
Fri, 21 Apr 2017 13:23:34 +1000
changeset 567054 adec21069065815d50cc16dba70bec4cd7cfefc8
parent 567053 9baa76979a717579ad43a9814d0fed9c73717b5a
child 567055 3221b215b080881d3a31b4b6464e3a529bb4d5d4
push id55429
push userbmo:hskupin@gmail.com
push dateMon, 24 Apr 2017 10:48:57 +0000
reviewersmstange
bugs1358074
milestone55.0a1
Bug 1358074 (part 3) - Don't measure process creation time on every profiler_start() call. r=mstange. We measure it in profiler_init(); there's not point overwriting it with the same value every time profiler_start() is called! The patch also renames mStartTime as mProcessStartTime to make things clearer.
tools/profiler/core/platform.cpp
tools/profiler/public/GeckoProfiler.h
--- a/tools/profiler/core/platform.cpp
+++ b/tools/profiler/core/platform.cpp
@@ -166,17 +166,17 @@ public:
     , mFrameNumber(0)
     , mLatestRecordedFrameNumber(0)
   {}
 
   #define GET_AND_SET(type_, name_) \
     type_ name_(LockRef) const { return m##name_; } \
     void Set##name_(LockRef, type_ a##name_) { m##name_ = a##name_; }
 
-  GET_AND_SET(TimeStamp, StartTime)
+  GET_AND_SET(TimeStamp, ProcessStartTime)
 
   GET_AND_SET(int, Entries)
 
   GET_AND_SET(double, Interval)
 
   Vector<std::string>& Features(LockRef) { return mFeatures; }
 
   Vector<std::string>& ThreadNameFilters(LockRef) { return mThreadNameFilters; }
@@ -227,18 +227,18 @@ public:
   GET_AND_SET(mozilla::ProfilerIOInterposeObserver*, InterposeObserver)
 
   GET_AND_SET(int, FrameNumber)
   GET_AND_SET(int, LatestRecordedFrameNumber)
 
   #undef GET_AND_SET
 
 private:
-  // When profiler_init() or profiler_start() was most recently called.
-  mozilla::TimeStamp mStartTime;
+  // The time that the process started.
+  mozilla::TimeStamp mProcessStartTime;
 
   // The number of entries in mBuffer. Zeroed when the profiler is inactive.
   int mEntries;
 
   // The interval between samples, measured in milliseconds. Zeroed when the
   // profiler is inactive.
   double mInterval;
 
@@ -1072,17 +1072,18 @@ DoSampleStackTrace(PS::LockRef aLock, Pr
 
 // This function is called for each sampling period with the current program
 // counter. It is called within a signal and so must be re-entrant.
 static void
 Tick(PS::LockRef aLock, ProfileBuffer* aBuffer, const TickSample& aSample)
 {
   aBuffer->addTagThreadId(aSample.mThreadId, aSample.mLastSample);
 
-  mozilla::TimeDuration delta = aSample.mTimeStamp - gPS->StartTime(aLock);
+  mozilla::TimeDuration delta =
+    aSample.mTimeStamp - gPS->ProcessStartTime(aLock);
   aBuffer->addTag(ProfileBufferEntry::Time(delta.ToMilliseconds()));
 
   NotNull<PseudoStack*> pseudoStack = aSample.mPseudoStack;
 
 #if defined(HAVE_NATIVE_UNWIND)
   if (gPS->FeatureStackWalk(aLock)) {
     DoNativeBacktrace(aLock, aBuffer, aSample);
   } else
@@ -1187,17 +1188,17 @@ StreamNameAndThreadId(JSONWriter& aWrite
 
 static void
 StreamTaskTracer(PS::LockRef aLock, SpliceableJSONWriter& aWriter)
 {
 #ifdef MOZ_TASK_TRACER
   aWriter.StartArrayProperty("data");
   {
     UniquePtr<nsTArray<nsCString>> data =
-      mozilla::tasktracer::GetLoggedData(gPS->StartTime(aLock));
+      mozilla::tasktracer::GetLoggedData(gPS->ProcessStartTime(aLock));
     for (uint32_t i = 0; i < data->Length(); ++i) {
       aWriter.StringElement((data->ElementAt(i)).get());
     }
   }
   aWriter.EndArray();
 
   aWriter.StartArrayProperty("threads");
   {
@@ -1236,20 +1237,20 @@ StreamMetaJSCustomObject(PS::LockRef aLo
 #endif
 
   aWriter.IntProperty("gcpoison", JS::IsGCPoisoning() ? 1 : 0);
 
   bool asyncStacks = Preferences::GetBool("javascript.options.asyncstack");
   aWriter.IntProperty("asyncstack", asyncStacks);
 
   // The "startTime" field holds the number of milliseconds since midnight
-  // January 1, 1970 GMT. This grotty code computes (Now - (Now - StartTime))
-  // to convert gPS->StartTime() into that form.
+  // January 1, 1970 GMT. This grotty code computes (Now - (Now -
+  // ProcessStartTime)) to convert gPS->ProcessStartTime() into that form.
   mozilla::TimeDuration delta =
-    mozilla::TimeStamp::Now() - gPS->StartTime(aLock);
+    mozilla::TimeStamp::Now() - gPS->ProcessStartTime(aLock);
   aWriter.DoubleProperty(
     "startTime", static_cast<double>(PR_Now()/1000.0 - delta.ToMilliseconds()));
 
   aWriter.IntProperty("processType", XRE_GetProcessType());
 
   nsresult res;
   nsCOMPtr<nsIHttpProtocolHandler> http =
     do_GetService(NS_NETWORK_PROTOCOL_CONTRACTID_PREFIX "http", &res);
@@ -1385,26 +1386,26 @@ locked_profiler_stream_json_for_this_pro
     gPS->SetIsPaused(aLock, true);
 
     const PS::ThreadVector& liveThreads = gPS->LiveThreads(aLock);
     for (size_t i = 0; i < liveThreads.size(); i++) {
       ThreadInfo* info = liveThreads.at(i);
       if (!info->IsBeingProfiled()) {
         continue;
       }
-      info->StreamJSON(gPS->Buffer(aLock), aWriter, gPS->StartTime(aLock),
-                       aSinceTime);
+      info->StreamJSON(gPS->Buffer(aLock), aWriter,
+                       gPS->ProcessStartTime(aLock), aSinceTime);
     }
 
     const PS::ThreadVector& deadThreads = gPS->DeadThreads(aLock);
     for (size_t i = 0; i < deadThreads.size(); i++) {
       ThreadInfo* info = deadThreads.at(i);
       MOZ_ASSERT(info->IsBeingProfiled());
-      info->StreamJSON(gPS->Buffer(aLock), aWriter, gPS->StartTime(aLock),
-                       aSinceTime);
+      info->StreamJSON(gPS->Buffer(aLock), aWriter,
+                       gPS->ProcessStartTime(aLock), aSinceTime);
     }
 
 #if defined(PROFILE_JAVA)
     if (gPS->FeatureJava(aLock)) {
       java::GeckoJavaSampler::Pause();
 
       aWriter.Start();
       {
@@ -1462,33 +1463,33 @@ ProfilerMarker::SetGeneration(uint32_t a
 }
 
 double
 ProfilerMarker::GetTime() const {
   return mTime;
 }
 
 void ProfilerMarker::StreamJSON(SpliceableJSONWriter& aWriter,
-                                const TimeStamp& aStartTime,
+                                const TimeStamp& aProcessStartTime,
                                 UniqueStacks& aUniqueStacks) const
 {
   // Schema:
   //   [name, time, data]
 
   aWriter.StartArrayElement();
   {
     aUniqueStacks.mUniqueStrings.WriteElement(aWriter, GetMarkerName());
     aWriter.DoubleElement(mTime);
     // TODO: Store the callsite for this marker if available:
     // if have location data
     //   b.NameValue(marker, "location", ...);
     if (mPayload) {
       aWriter.StartObjectElement();
       {
-          mPayload->StreamPayload(aWriter, aStartTime, aUniqueStacks);
+        mPayload->StreamPayload(aWriter, aProcessStartTime, aUniqueStacks);
       }
       aWriter.EndObject();
     }
   }
   aWriter.EndArray();
 }
 
 static void
@@ -1649,19 +1650,19 @@ SamplerThread::Run()
             continue;
           }
 
           // If the thread is asleep and has been sampled before in the same
           // sleep episode, find and copy the previous sample, as that's
           // cheaper than taking a new sample.
           if (info->Stack()->CanDuplicateLastSampleDueToSleep()) {
             bool dup_ok =
-              gPS->Buffer(lock)->DuplicateLastSample(info->ThreadId(),
-                                                     gPS->StartTime(lock),
-                                                     info->LastSample());
+              gPS->Buffer(lock)->DuplicateLastSample(
+                info->ThreadId(), gPS->ProcessStartTime(lock),
+                info->LastSample());
             if (dup_ok) {
               continue;
             }
           }
 
           // We only track responsiveness for the main thread.
           if (info->IsMainThread()) {
             info->GetThreadResponsiveness()->Update();
@@ -1981,17 +1982,17 @@ profiler_init(void* aStackTop)
   {
     PS::AutoLock lock(gPSMutex);
 
     // We've passed the possible failure point. Instantiate gPS, which
     // indicates that the profiler has initialized successfully.
     gPS = new PS();
 
     bool ignore;
-    gPS->SetStartTime(lock, mozilla::TimeStamp::ProcessCreation(ignore));
+    gPS->SetProcessStartTime(lock, mozilla::TimeStamp::ProcessCreation(ignore));
 
     locked_register_thread(lock, kMainThreadName, aStackTop);
 
     // Platform-specific initialization.
     PlatformInit(lock);
 
 #ifdef MOZ_TASK_TRACER
     mozilla::tasktracer::InitTaskTracer();
@@ -2314,19 +2315,16 @@ locked_profiler_start(PS::LockRef aLock,
     for (uint32_t i = 0; i < aFilterCount; i++) {
       LOG("- threads  = %s", aThreadNameFilters[i]);
     }
   }
 
   MOZ_RELEASE_ASSERT(NS_IsMainThread());
   MOZ_RELEASE_ASSERT(gPS && !gPS->IsActive(aLock));
 
-  bool ignore;
-  gPS->SetStartTime(aLock, mozilla::TimeStamp::ProcessCreation(ignore));
-
   // Fall back to the default value if the passed-in value is unreasonable.
   int entries = aEntries > 0 ? aEntries : PROFILE_DEFAULT_ENTRIES;
   gPS->SetEntries(aLock, entries);
 
   // Ditto.
   double interval = aInterval > 0 ? aInterval : PROFILE_DEFAULT_INTERVAL;
   gPS->SetInterval(aLock, interval);
 
@@ -2832,17 +2830,17 @@ profiler_time()
 {
   // This function runs both on and off the main thread.
 
   MOZ_RELEASE_ASSERT(gPS);
 
   PS::AutoLock lock(gPSMutex);
 
   mozilla::TimeDuration delta =
-    mozilla::TimeStamp::Now() - gPS->StartTime(lock);
+    mozilla::TimeStamp::Now() - gPS->ProcessStartTime(lock);
   return delta.ToMilliseconds();
 }
 
 UniqueProfilerBacktrace
 profiler_get_backtrace()
 {
   MOZ_RELEASE_ASSERT(NS_IsMainThread());
   MOZ_RELEASE_ASSERT(gPS);
@@ -2961,17 +2959,17 @@ locked_profiler_add_marker(PS::LockRef a
   PseudoStack *stack = tlsPseudoStack.get();
   if (!stack) {
     return;
   }
 
   mozilla::TimeStamp origin = (payload && !payload->GetStartTime().IsNull())
                             ? payload->GetStartTime()
                             : mozilla::TimeStamp::Now();
-  mozilla::TimeDuration delta = origin - gPS->StartTime(aLock);
+  mozilla::TimeDuration delta = origin - gPS->ProcessStartTime(aLock);
   stack->addMarker(aMarker, payload.release(), delta.ToMilliseconds());
 }
 
 void
 profiler_add_marker(const char* aMarker, ProfilerMarkerPayload* aPayload)
 {
   // This function runs both on and off the main thread.
 
@@ -3072,17 +3070,18 @@ profiler_clear_js_context()
 
   if (gPS->IsActive(lock)) {
     gPS->SetIsPaused(lock, true);
 
     // Flush this thread's ThreadInfo, if it is being profiled.
     ThreadInfo* info = FindLiveThreadInfo(lock);
     MOZ_RELEASE_ASSERT(info);
     if (info->IsBeingProfiled()) {
-      info->FlushSamplesAndMarkers(gPS->Buffer(lock), gPS->StartTime(lock));
+      info->FlushSamplesAndMarkers(gPS->Buffer(lock),
+                                   gPS->ProcessStartTime(lock));
     }
 
     gPS->SetIsPaused(lock, false);
   }
 
   // We don't call stack->stopJSSampling() here; there's no point doing
   // that for a JS thread that is in the process of disappearing.
 
--- a/tools/profiler/public/GeckoProfiler.h
+++ b/tools/profiler/public/GeckoProfiler.h
@@ -284,18 +284,18 @@ PROFILER_FUNC_VOID(profiler_thread_sleep
 PROFILER_FUNC_VOID(profiler_thread_wake())
 PROFILER_FUNC(bool profiler_thread_is_sleeping(), false)
 
 // Call by the JSRuntime's operation callback. This is used to start profiling
 // on auxiliary threads. Operates the same whether the profiler is active or
 // not.
 PROFILER_FUNC_VOID(profiler_js_interrupt_callback())
 
-// Gets the time since the last profiler_init() or profiler_start() call.
-// Operates the same whether the profiler is active or inactive.
+// The number of milliseconds since the process started. Operates the same
+// whether the profiler is active or inactive.
 PROFILER_FUNC(double profiler_time(), 0)
 
 PROFILER_FUNC_VOID(profiler_log(const char *str))
 
 // End of the functions defined whether the profiler is enabled or not.
 
 #if defined(MOZ_GECKO_PROFILER)