mirror of
https://github.com/mozilla/gecko-dev.git
synced 2024-11-24 21:31:04 +00:00
Bug 1502686 - When fuzzyfox is enabled, first put it into an initializing state before telling TimeStamp is it enabled r=baku
This prevents a race condition where the JS Engine would get the Fuzzed Time before the dispatched job was run, and the time was zero and triggered an assertion. This patch also includes more verbose logging for additional debugging.
This commit is contained in:
Tom Ritter
parent
ecc8679b30
commit
055159557a
@ -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<uint32_t, Relaxed> 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<nsIPrefBranch> 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<nsIRunnable> 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
|
||||
|
||||
6
tools/profiler/core/ProfileBufferEntry.cpp
Normal file → Executable file
6
tools/profiler/core/ProfileBufferEntry.cpp
Normal file → Executable file
@ -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<CounterKeyedSample> CounterKeyedSamples;
|
||||
|
||||
static LazyLogModule sFuzzyfoxLog("Fuzzyfox");
|
||||
|
||||
typedef nsDataHashtable<nsUint64HashKey, CounterKeyedSamples> 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);
|
||||
|
||||
Loading…
Reference in New Issue
Block a user