diff --git a/toolkit/components/fuzzyfox/Fuzzyfox.cpp b/toolkit/components/fuzzyfox/Fuzzyfox.cpp index 4bbbc515cff0..1c37ec5dc6f5 100644 --- a/toolkit/components/fuzzyfox/Fuzzyfox.cpp +++ b/toolkit/components/fuzzyfox/Fuzzyfox.cpp @@ -42,6 +42,7 @@ static LazyLogModule sFuzzyfoxLog("Fuzzyfox"); #define FUZZYFOX_CLOCKGRAIN_PREF "privacy.fuzzyfox.clockgrainus" #define FUZZYFOX_CLOCKGRAIN_PREF_DEFAULT 100 +static bool sFuzzyfoxInitializing; Atomic Fuzzyfox::sFuzzyfoxClockGrain; NS_IMPL_ISUPPORTS_INHERITED(Fuzzyfox, Runnable, nsIObserver) @@ -75,9 +76,9 @@ Fuzzyfox::Fuzzyfox() Preferences::GetBool(FUZZYFOX_ENABLED_PREF, FUZZYFOX_ENABLED_PREF_DEFAULT); LOG(Info, ("PT(%p) Created Fuzzyfox, FuzzyFox is now %s \n", - this, (fuzzyfoxEnabled ? "enabled" : "disabled"))); + this, (fuzzyfoxEnabled ? "initializing" : "disabled"))); - TimeStamp::SetFuzzyfoxEnabled(fuzzyfoxEnabled); + sFuzzyfoxInitializing = fuzzyfoxEnabled; // Should I see if these fail? And do what? nsCOMPtr prefs = do_GetService(NS_PREFSERVICE_CONTRACTID); @@ -106,13 +107,12 @@ Fuzzyfox::Observe(nsISupports* aObject, const char* aTopic, Preferences::GetBool(FUZZYFOX_ENABLED_PREF, FUZZYFOX_ENABLED_PREF_DEFAULT); LOG(Info, ("PT(%p) Observed a pref change, FuzzyFox is now %s \n", - this, (fuzzyfoxEnabled ? "enabled" : "disabled"))); + this, (fuzzyfoxEnabled ? "initializing" : "disabled"))); - TimeStamp::SetFuzzyfoxEnabled(fuzzyfoxEnabled); + sFuzzyfoxInitializing = fuzzyfoxEnabled; - - if (TimeStamp::GetFuzzyfoxEnabled()) { + if (sFuzzyfoxInitializing) { // Queue a runnable nsCOMPtr r = this; SystemGroup::Dispatch(TaskCategory::Other, r.forget()); @@ -135,12 +135,12 @@ NS_IMETHODIMP Fuzzyfox::Run() { MOZ_ASSERT(NS_IsMainThread()); - if (!TimeStamp::GetFuzzyfoxEnabled()) { + if (!sFuzzyfoxInitializing && !TimeStamp::GetFuzzyfoxEnabled()) { LOG(Info, ("[FuzzyfoxEvent] PT(%p) Fuzzyfox is shut down, doing nothing \n", this)); return NS_OK; } - if (mStartTime == 0) { + if (sFuzzyfoxInitializing) { // This is the first time we are running afer enabling FuzzyFox. We need // to prevent time from going backwards, so for the first run we round the time up // to the next grain. @@ -153,6 +153,10 @@ Fuzzyfox::Run() LOG(Info, ("[FuzzyfoxEvent] PT(%p) Going to start Fuzzyfox, queuing up the job \n", this)); + // Now that we've updated the timestamps, we can let everyone know Fuzzyfox is ready to use + TimeStamp::SetFuzzyfoxEnabled(true); + sFuzzyfoxInitializing = false; + DISPATCH_AND_RETURN(); } @@ -168,7 +172,7 @@ Fuzzyfox::Run() // If that happens, then repeat the current time. // We use mSanityCheck just to be sure (and will eventually remove it.) MOZ_ASSERT(mSanityCheck); - LOG(Debug, ("[FuzzyfoxEvent] PT(%p) endTime < mStartTime mStartTime %" PRIu64 " endTime %" PRIu64 " \n", + LOG(Warning, ("[FuzzyfoxEvent] Unusual!! PT(%p) endTime < mStartTime mStartTime %" PRIu64 " endTime %" PRIu64 " \n", this, mStartTime, endTime)); mSanityCheck = true; @@ -176,10 +180,12 @@ Fuzzyfox::Run() } uint64_t actualRunDuration = endTime - mStartTime; + LOG(Verbose, ("[FuzzyfoxEvent] PT(%p) mDuration: %" PRIu32 " endTime: %" PRIu64 " mStartTime: %" PRIu64 " actualRunDuration: %" PRIu64 " \n", + this, mDuration, endTime, mStartTime, actualRunDuration)); if (actualRunDuration > mDuration) { // We ran over our budget! uint64_t over = actualRunDuration - mDuration; - LOG(Verbose, ("[FuzzyfoxEvent] PT(%p) Overran budget of %" PRIu32 " by %" PRIu64 " \n", + LOG(Debug, ("[FuzzyfoxEvent] PT(%p) Overran budget of %" PRIu32 " by %" PRIu64 " \n", this, mDuration, over)); uint64_t nextDuration = PickDuration(); @@ -193,7 +199,7 @@ Fuzzyfox::Run() } else { // Didn't go over budget remaining = mDuration - actualRunDuration; - LOG(Verbose, ("[FuzzyfoxEvent] PT(%p) Finishing budget of %" PRIu32 " with %" PRIu64 " \n", + LOG(Debug, ("[FuzzyfoxEvent] PT(%p) Finishing budget of %" PRIu32 " with %" PRIu64 " \n", this, mDuration, remaining)); } mSanityCheck = false; @@ -230,6 +236,9 @@ Fuzzyfox::Run() mStartTime = ActualTime(); mDuration = PickDuration(); + LOG(Verbose, ("[FuzzyfoxEvent] PT(%p) For next time mDuration: %" PRIu32 " mStartTime: %" PRIu64 " \n", + this, mDuration, mStartTime)); + DISPATCH_AND_RETURN(); } @@ -270,10 +279,10 @@ Fuzzyfox::UpdateClocks(uint64_t aNewTime, TimeStamp aNewTimeStamp) { // newTime is the new canonical time for this scope! #ifndef XP_WIN - LOG(Verbose, ("[Time] New time is %" PRIu64 " (compare to %" PRIu64 ") and timestamp is %" PRIu64 " (compare to %" PRIu64 ")\n", + LOG(Debug, ("[Time] New time is %" PRIu64 " (compare to %" PRIu64 ") and timestamp is %" PRIu64 " (compare to %" PRIu64 ")\n", aNewTime, ActualTime(), aNewTimeStamp.mValue.mTimeStamp, TimeStamp::NowUnfuzzed().mValue.mTimeStamp)); #else - LOG(Verbose, ("[Time] New time is %" PRIu64 " (compare to %" PRIu64 ") \n", aNewTime, ActualTime())); + LOG(Debug, ("[Time] New time is %" PRIu64 " (compare to %" PRIu64 ") \n", aNewTime, ActualTime())); #endif // Fire notifications diff --git a/tools/profiler/core/ProfileBufferEntry.cpp b/tools/profiler/core/ProfileBufferEntry.cpp old mode 100644 new mode 100755 index 6b1249fa04ed..a5b9e90c2d00 --- a/tools/profiler/core/ProfileBufferEntry.cpp +++ b/tools/profiler/core/ProfileBufferEntry.cpp @@ -8,6 +8,7 @@ #include "platform.h" #include "mozilla/HashFunctions.h" #include "mozilla/Sprintf.h" +#include "mozilla/Logging.h" #include "nsThreadUtils.h" #include "nsXULAppAPI.h" @@ -1215,6 +1216,7 @@ struct CounterKeyedSample typedef nsTArray CounterKeyedSamples; +static LazyLogModule sFuzzyfoxLog("Fuzzyfox"); typedef nsDataHashtable CounterMap; @@ -1347,6 +1349,10 @@ ProfileBuffer::StreamCountersToJSON(SpliceableJSONWriter& aWriter, for (size_t i = 0; i < size; i++) { // Encode as deltas, and only encode if different than the last sample if (i == 0 || samples[i].mNumber != previousNumber || samples[i].mCount != previousCount) { + if (i != 0 && samples[i].mTime >= samples[i - 1].mTime) { + MOZ_LOG(sFuzzyfoxLog, mozilla::LogLevel::Error, + ("Fuzzyfox Profiler Assertion: %f >= %f", samples[i].mTime, samples[i - 1].mTime)); + } MOZ_ASSERT(i == 0 || samples[i].mTime >= samples[i - 1].mTime); MOZ_ASSERT(samples[i].mNumber >= previousNumber);