Bug 1425462 Refactor the logging. draft
authorTom Ritter <tom@mozilla.com>
Wed, 24 Jan 2018 16:39:40 -0600
changeset 724417 f8877990df49108a1883258c6cdbc5b9d6571edd
parent 724416 24d5238a0aceb6a333378c912885c18746f16bf8
child 724418 50223c82296d05d2b5da5bab03aa70e6e06bee3f
push id96741
push userbmo:tom@mozilla.com
push dateWed, 24 Jan 2018 22:45:52 +0000
bugs1425462
milestone59.0a1
Bug 1425462 Refactor the logging. Make it less macro-based. Silence a few very verbose printing statements Add an additional note parameter to allow skipping the backtrace generation for high-frequency calls. Add caller detect for performance APIs MozReview-Commit-ID: Gvadyrr9ZhT
dom/events/Event.cpp
dom/performance/Performance.cpp
toolkit/components/resistfingerprinting/nsRFPService.cpp
toolkit/components/resistfingerprinting/nsRFPService.h
--- a/dom/events/Event.cpp
+++ b/dom/events/Event.cpp
@@ -1124,17 +1124,17 @@ Event::TimeStampImpl() const
     workers::WorkerPrivate* workerPrivate =
       workers::GetCurrentThreadWorkerPrivate();
     MOZ_ASSERT(workerPrivate);
 
     ret = workerPrivate->TimeStampToDOMHighRes(mEvent->mTimeStamp);
     origin = workerPrivate->CreationTime();
   }
 
-  return nsRFPService::ReduceTimePrecisionAsMSecs(ret, origin);
+  return nsRFPService::ReduceTimePrecisionAsMSecs(ret, origin, true, "skip-me");
 }
 
 double
 Event::TimeStamp() const
 {
   return TimeStampImpl();
 }
 
--- a/dom/performance/Performance.cpp
+++ b/dom/performance/Performance.cpp
@@ -127,17 +127,18 @@ Performance::Now()
   if (!mPerformanceService) {
     mPerformanceService = PerformanceService::GetOrCreate();
   }
 
   TimeDuration duration = TimeStamp::Now() - CreationTimeStamp();
   const double maxResolutionMs = 0.005;
   return nsRFPService::ReduceTimePrecisionAsMSecs(
     floor(duration.ToMilliseconds() / maxResolutionMs) * maxResolutionMs,
-    mPerformanceService->TimeOrigin(CreationTimeStamp()));
+    mPerformanceService->TimeOrigin(CreationTimeStamp()),
+    true, "skip-me");
 }
 
 DOMHighResTimeStamp
 Performance::TimeOrigin()
 {
   if (!mPerformanceService) {
     mPerformanceService = PerformanceService::GetOrCreate();
   }
--- a/toolkit/components/resistfingerprinting/nsRFPService.cpp
+++ b/toolkit/components/resistfingerprinting/nsRFPService.cpp
@@ -145,66 +145,154 @@ nsRFPService::IsTimerPrecisionReductionE
 {
   return (sPrivacyTimerPrecisionReduction || IsResistFingerprintingEnabled()) &&
          TimerResolution() != 0;
 }
 
 #if defined(DEBUG)
 #define INIT_STACKTRACE() \
   void* callstack[4]; \
-  int frames = backtrace(callstack, 4); \
-  char** thisCaller = backtrace_symbols(callstack, frames);
+  if (note == NULL || strcmp(note, "skip-me") != 0) { \
+    int frames = backtrace(callstack, 4); \
+    char** thisCaller = backtrace_symbols(callstack, frames);
+
+const char* CALLER(char** caller) {
+  if (strstr(caller[1], "Performance3Now") != NULL) 
+    return "performance.now()";
+  if (strstr(caller[1], "Performance10TimeOrigin") != NULL) 
+    return "performance.timeOrigin";
+
+  if (strstr(caller[3], "_ZN7mozilla3dom17PerformanceTiming20RedirectStartHighResEv") != NULL &&
+      strstr(caller[2], "_ZN7mozilla3dom17PerformanceTiming40TimeStampToReducedDOMHighResOrFetchStartENS_9TimeStampE") != NULL &&
+      strstr(caller[1], "17PerformanceTiming17FetchStartHighRes") != NULL)
+    return "redirectStartHighRes -> TimeStampToReducedDOMHighResOrFetchStart -> fetchStartHighRes";
+
+  if (strstr(caller[3], "_ZNK7mozilla3dom26PerformanceEntryComparator6EqualsEPKNS0_16PerformanceEntryES4_") != NULL &&
+      strstr(caller[2], "_ZNK7mozilla3dom25PerformanceResourceTiming9StartTimeEv") != NULL &&
+      strstr(caller[1], "_ZN7mozilla3dom17PerformanceTiming16AsyncOpenHighResEv") != NULL)
+    return "PerformanceEntryComparatorEquals -> StartTime -> AsyncOpenHighRes";
+
+  if (strstr(caller[3], "_ZNK7mozilla3dom26PerformanceEntryComparator8LessThanEPKNS0_16PerformanceEntryES4_") != NULL &&
+      strstr(caller[2], "_ZNK7mozilla3dom25PerformanceResourceTiming9StartTimeEv") != NULL &&
+      strstr(caller[1], "_ZN7mozilla3dom17PerformanceTiming16AsyncOpenHighResEv") != NULL)
+    return "PerformanceEntryComparatorLessThan -> StartTime -> AsyncOpenHighRes";
 
-#define CALLER(caller) \
-  ((strstr(caller[1], "Performance3Now") != NULL) ? "performance.now()" : \
-  ((strstr(caller[1], "Performance10TimeOrigin") != NULL) ? "performance.timeOrigin)" : \
-  ((strstr(caller[1], "PerformanceTiming15NavigationStartEv") != NULL) ? "performance.timing.navigationStart" : \
-  ((strstr(caller[1], "dom5Event13TimeStampImplEv") != NULL) ? "Event.timeStamp" : \
-  ((strstr(caller[3], "Animation21DispatchPlaybackEvent") != NULL && strstr(caller[2], "AnimationTimeline22GetCurrentTimeAsDouble") != NULL) ? "AnimationTimeline::GetCurrentTimeAsDouble" : \
-  ((strstr(caller[3], "Animation21DispatchPlaybackEvent") != NULL && strstr(caller[2], "Animation22GetCurrentTimeAsDouble") != NULL) ? "Animation::DispatchPlaybackEvent() -> Animation::GetCurrentTimeAsDouble()" : \
-  ""))))))
+  if (strstr(caller[1], "17PerformanceTimingC2EPNS0_11PerformanceEP15nsITimedChannelP14nsIHttpChanneld"))
+    return "PerformanceTiming ctor";
+  if (strstr(caller[1], "17PerformanceTiming15NavigationStartEv") != NULL) 
+    return "performance.timing.navigationStart";
+  if (strstr(caller[1], "17PerformanceTiming11DomComplete") != NULL)
+    return "performance.timing.domComplete";
+  if (strstr(caller[1], "17PerformanceTiming26DomContentLoadedEventStart") != NULL)
+    return "performance.timing.domContentLoadedEventstart";
+  if (strstr(caller[1], "17PerformanceTiming14DomInteractive") != NULL)
+    return "performance.timing.domInteractive";
+  if (strstr(caller[1], "17PerformanceTiming14UnloadEventEnd") != NULL)
+    return "performance.timing.unloadEventEnd";
+  if (strstr(caller[1], "17PerformanceTiming16UnloadEventStart") != NULL)
+    return "performance.timing.unloadEventStart";
+  if (strstr(caller[1], "17PerformanceTiming10DomLoading") != NULL)
+    return "performance.timing.domLoading";
+  if (strstr(caller[1], "17PerformanceTiming24DomContentLoadedEventEnd") != NULL)
+    return "performance.timing.domContentLoadedEventEnd";
+  if (strstr(caller[1], "17PerformanceTiming14LoadEventStart") != NULL)
+    return "performance.timing.loadEventStart";
+  if (strstr(caller[1], "17PerformanceTiming12LoadEventEnd") != NULL)
+    return "performance.timing.loadEventEnd";
+  if (strstr(caller[1], "17PerformanceTiming19TimeToNonBlankPaint") != NULL)
+    return "performance.timing.timeToNonBlankPaint";
+  if (strstr(caller[2], "17PerformanceTiming20ResponseStartHighRes") != NULL)
+    return "performance.timing.responseStart";
+  if (strstr(caller[1], "17PerformanceTiming18ResponseEndHighResEv") != NULL)
+    return "performance.timing.responseEnd";
+  if (strstr(caller[1], "17PerformanceTiming17ConnectEndHighResEv") != NULL)
+    return "performance.timing.connectEnd";
+  if (strstr(caller[1], "17PerformanceTiming19ConnectStartHighResEv") != NULL)
+    return "performance.timing.connectStart";
+  if (strstr(caller[1], "17PerformanceTiming22DomainLookupEndHighResEv") != NULL)
+    return "performance.timing.domainLookupEnd";
+  if (strstr(caller[2], "17PerformanceTiming24DomainLookupStartHighResEv") != NULL)
+    return "performance.timing.domainLookupStart";
+  if (strstr(caller[1], "17PerformanceTiming17FetchStartHighResEv") != NULL)
+    return "performance.timing.fetchStart";
+  
+
+  if (strstr(caller[1], "dom5Event13TimeStampImplEv") != NULL) 
+    return "Event.timeStamp";
+  
+  if (strstr(caller[3], "Animation21DispatchPlaybackEvent") != NULL && 
+      strstr(caller[2], "AnimationTimeline22GetCurrentTimeAsDouble") != NULL) 
+    return "AnimationTimeline::GetCurrentTimeAsDouble";
+  if (strstr(caller[3], "Animation21DispatchPlaybackEvent") != NULL && 
+      strstr(caller[2], "Animation22GetCurrentTimeAsDouble") != NULL) 
+    return "Animation::DispatchPlaybackEvent() -> Animation::GetCurrentTimeAsDouble()";
+  return "";
+}
 
 // I think these circumstances are okay
-#define CALLER_CAN_GO_BACKWARDS() \
-  ((strcmp("performance.now()", CALLER(lastCaller)) == 0 && \
-    strcmp("AnimationTimeline::GetCurrentTimeAsDouble", CALLER(thisCaller)) == 0) ? true : false \
-  )
+bool CALLER_CAN_GO_BACKWARDS(char** thisCaller, char** lastCaller) {
+  // Let's just not worry about this right now.
+  return true;
+
+  if (strcmp("performance.now()", CALLER(lastCaller)) == 0 && \
+    strcmp("AnimationTimeline::GetCurrentTimeAsDouble", CALLER(thisCaller)) == 0) 
+    return true;
+  if (strcmp("26PerformanceEntryComparator", thisCaller[3]) == 0)
+    return true;
+  return false;
+}
+
+// Silences a few select annoying, verbose entries
+bool SHOULD_PRINT(char** thisCaller) {
+  if (strcmp(CALLER(thisCaller), "performance.now()") == 0)
+    return false;
+  if (strcmp(CALLER(thisCaller), "Event.timeStamp") == 0)
+    return false;
+  return true;
+}
+
+
+//FIXME: if (timeOrigin != 0) {  is not a good conditional
 
 #define LOG_TIMESTAMP(aTime, timeOrigin) \
-  MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
-    ("Parent: %d Combined Timestamp: %f Raw: %f Caller: %s", XRE_IsParentProcess(), (aTime + timeOrigin), aTime, CALLER(thisCaller))); \
-  if (timeOrigin != 0) { \
-    if (aTime + timeOrigin < lastSeenTimestamp && !CALLER_CAN_GO_BACKWARDS()) { \
+    bool shouldPrint = SHOULD_PRINT(thisCaller); \
+    if (shouldPrint) \
       MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
-        ("===============> TIME WENT BACKWARDS!! Last: %f This: %f", lastSeenTimestamp, (aTime + timeOrigin))); \
-    } else if (aTime + timeOrigin < lastSeenTimestamp) { \
-      MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
-        ("               > Time went backwards, but we think its okay. Last: %f This: %f", lastSeenTimestamp, (aTime + timeOrigin))); \
-    } \
-    lastSeenTimestamp = (aTime + timeOrigin); \
-  }
+        ("Parent: %d Combined Timestamp: %f Raw: %f Jitter: %i Note: %s Caller: %s", XRE_IsParentProcess(), (aTime + timeOrigin), aTime, canJitter, note, CALLER(thisCaller))); \
+    if (timeOrigin != 0) { \
+      if (aTime + timeOrigin < lastSeenTimestamp && !CALLER_CAN_GO_BACKWARDS(thisCaller, lastCaller) && shouldPrint) { \
+        MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
+          ("===============> TIME WENT BACKWARDS!! Last: %f This: %f", lastSeenTimestamp, (aTime + timeOrigin))); \
+      } else if (aTime + timeOrigin < lastSeenTimestamp && shouldPrint) { \
+        MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, \
+          ("               > Time went backwards, but we think its okay. Last: %f This: %f", lastSeenTimestamp, (aTime + timeOrigin))); \
+      } \
+      lastSeenTimestamp = (aTime + timeOrigin); \
+    }
 
 #define PRINT_STACKTRACE() \
-  if (strcmp(CALLER(thisCaller), "") == 0) { \
-    for (int i = 0; i < frames; ++i) { \
-      MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, ("  %s\n", thisCaller[i])); \
+    if (strcmp(CALLER(thisCaller), "") == 0) { \
+      for (int i = 0; i < frames; ++i) { \
+        MOZ_LOG(gResistFingerprintingLog, LogLevel::Debug, ("  %s\n", thisCaller[i])); \
+      } \
     } \
-  } \
-  if (timeOrigin != 0) { \
-    free(lastCaller); \
-    lastCaller = thisCaller; \
-  }
+    if (timeOrigin != 0) { \
+      free(lastCaller); \
+      lastCaller = thisCaller; \
+    } \
+  } // end the 'skip-me' note test
 
 static double lastSeenTimestamp = 0;
 static char** lastCaller = NULL;
 #endif
 
 /* static */
 double
-nsRFPService::ReduceTimePrecisionAsMSecs(double aTime, double timeOrigin /* = 0 */, bool canJitter /* = true */)
+nsRFPService::ReduceTimePrecisionAsMSecs(double aTime, double timeOrigin /* = 0 */, 
+  bool canJitter /* = true */, char* note /* = NULL */)
 {
 #if defined(DEBUG)
   INIT_STACKTRACE();
   LOG_TIMESTAMP(aTime, timeOrigin);
   PRINT_STACKTRACE();
 #endif
 
   if (!IsTimerPrecisionReductionEnabled()) {
@@ -228,17 +316,18 @@ nsRFPService::ReduceTimePrecisionAsMSecs
     clamped += r1 * 2 * jitterResolutionMSec - jitterResolutionMSec;
   }
 
   return clamped;
 }
 
 /* static */
 double
-nsRFPService::ReduceTimePrecisionAsUSecs(double aTime, double timeOrigin /* = 0 */, bool canJitter /* = true */)
+nsRFPService::ReduceTimePrecisionAsUSecs(double aTime, double timeOrigin /* = 0 */, 
+  bool canJitter /* = true */, char* note /* = NULL */)
 {
 #if defined(DEBUG)
   INIT_STACKTRACE();
   LOG_TIMESTAMP(aTime / 1000.0, timeOrigin);
   PRINT_STACKTRACE();
 #endif
 
   if (!IsTimerPrecisionReductionEnabled()) {
@@ -269,17 +358,18 @@ nsRFPService::ReduceTimePrecisionAsUSecs
 uint32_t
 nsRFPService::CalculateTargetVideoResolution(uint32_t aVideoQuality)
 {
   return aVideoQuality * NSToIntCeil(aVideoQuality * 16 / 9.0);
 }
 
 /* static */
 double
-nsRFPService::ReduceTimePrecisionAsSecs(double aTime, double timeOrigin /* = 0 */, bool canJitter /* = true */)
+nsRFPService::ReduceTimePrecisionAsSecs(double aTime, double timeOrigin /* = 0 */, 
+  bool canJitter /* = true */, char* note /* = NULL */)
 {
 #if defined(DEBUG)
   INIT_STACKTRACE();
   LOG_TIMESTAMP(aTime * 1000.0, timeOrigin);
   PRINT_STACKTRACE();
 #endif
 
   if (!IsTimerPrecisionReductionEnabled()) {
--- a/toolkit/components/resistfingerprinting/nsRFPService.h
+++ b/toolkit/components/resistfingerprinting/nsRFPService.h
@@ -156,19 +156,22 @@ public:
   NS_DECL_ISUPPORTS
   NS_DECL_NSIOBSERVER
 
   static nsRFPService* GetOrCreate();
   static bool IsResistFingerprintingEnabled();
   static bool IsTimerPrecisionReductionEnabled();
 
   // The following Reduce methods can be called off main thread.
-  static double ReduceTimePrecisionAsMSecs(double aTime, double timeOrigin = 0, bool canJitter = true);
-  static double ReduceTimePrecisionAsUSecs(double aTime, double timeOrigin = 0, bool canJitter = true);
-  static double ReduceTimePrecisionAsSecs(double aTime, double timeOrigin = 0, bool canJitter = true);
+  static double ReduceTimePrecisionAsMSecs(
+    double aTime, double timeOrigin = 0, bool canJitter = true, char* note = NULL);
+  static double ReduceTimePrecisionAsUSecs(
+    double aTime, double timeOrigin = 0, bool canJitter = true, char* note = NULL);
+  static double ReduceTimePrecisionAsSecs(
+    double aTime, double timeOrigin = 0, bool canJitter = true, char* note = NULL);
 
   // This method calculates the video resolution (i.e. height x width) based
   // on the video quality (480p, 720p, etc).
   static uint32_t CalculateTargetVideoResolution(uint32_t aVideoQuality);
 
   // Methods for getting spoofed media statistics and the return value will
   // depend on the video resolution.
   static uint32_t GetSpoofedTotalFrames(double aTime);