Bug 1313326 - Part 5: Use correct child event timestamps. r=dexter, f=chutten
☠☠ backed out by c7b0d1ae6e34 ☠ ☠
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Tue, 28 Feb 2017 16:52:53 +0100
changeset 345335 49a7a91b73ccf43451e9da4c5d78792d5ef30837
parent 345334 bc61502be42e77e1dac46183c7a9075768f8292d
child 345336 e2395b3b1e16f0631700f917bdac5633132be68d
push id31436
push userkwierso@gmail.com
push dateThu, 02 Mar 2017 01:18:52 +0000
treeherdermozilla-central@e91de6fb2b3d [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdexter
bugs1313326
milestone54.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1313326 - Part 5: Use correct child event timestamps. r=dexter, f=chutten
toolkit/components/telemetry/TelemetryEvent.cpp
toolkit/components/telemetry/ipc/TelemetryComms.h
toolkit/components/telemetry/ipc/TelemetryIPCAccumulator.cpp
toolkit/components/telemetry/ipc/TelemetryIPCAccumulator.h
toolkit/components/telemetry/tests/unit/test_ChildEvents.js
--- a/toolkit/components/telemetry/TelemetryEvent.cpp
+++ b/toolkit/components/telemetry/TelemetryEvent.cpp
@@ -26,16 +26,17 @@
 #include "ipc/TelemetryIPCAccumulator.h"
 
 using mozilla::StaticMutex;
 using mozilla::StaticMutexAutoLock;
 using mozilla::ArrayLength;
 using mozilla::Maybe;
 using mozilla::Nothing;
 using mozilla::StaticAutoPtr;
+using mozilla::TimeStamp;
 using mozilla::Telemetry::Common::AutoHashtable;
 using mozilla::Telemetry::Common::IsExpiredVersion;
 using mozilla::Telemetry::Common::CanRecordDataset;
 using mozilla::Telemetry::Common::IsInDataset;
 using mozilla::Telemetry::Common::MsSinceProcessStart;
 using mozilla::Telemetry::Common::LogToBrowserConsole;
 using mozilla::Telemetry::Common::CanRecordInProcess;
 using mozilla::Telemetry::EventExtraEntry;
@@ -578,36 +579,34 @@ TelemetryEvent::SetCanRecordExtended(boo
 nsresult
 TelemetryEvent::RecordChildEvents(GeckoProcessType aProcessType,
                                   const nsTArray<mozilla::Telemetry::ChildEventData>& aEvents)
 {
   MOZ_ASSERT(XRE_IsParentProcess());
   StaticMutexAutoLock locker(gTelemetryEventsMutex);
   for (uint32_t i = 0; i < aEvents.Length(); ++i) {
     const mozilla::Telemetry::ChildEventData e = aEvents[i];
-    ::RecordEvent(locker, aProcessType, e.timestamp, e.category, e.method, e.object, e.value, e.extra);
+
+    // Timestamps from child processes are absolute. We fix them up here to be
+    // relative to the main process start time.
+    // This allows us to put events from all processes on the same timeline.
+    bool inconsistent = false;
+    double relativeTimestamp = (e.timestamp - TimeStamp::ProcessCreation(inconsistent)).ToMilliseconds();
+
+    ::RecordEvent(locker, aProcessType, relativeTimestamp, e.category, e.method, e.object, e.value, e.extra);
   }
   return NS_OK;
 }
 
 nsresult
 TelemetryEvent::RecordEvent(const nsACString& aCategory, const nsACString& aMethod,
                             const nsACString& aObject, JS::HandleValue aValue,
                             JS::HandleValue aExtra, JSContext* cx,
                             uint8_t optional_argc)
 {
-  // Get the current time.
-  double timestamp = -1;
-  nsresult rv = MsSinceProcessStart(&timestamp);
-  if (NS_FAILED(rv)) {
-    LogToBrowserConsole(nsIScriptError::warningFlag,
-                        NS_LITERAL_STRING("Failed to get time since process start."));
-    return NS_OK;
-  }
-
   // Check value argument.
   if ((optional_argc > 0) && !aValue.isNull() && !aValue.isString()) {
     LogToBrowserConsole(nsIScriptError::warningFlag,
                         NS_LITERAL_STRING("Invalid type for value parameter."));
     return NS_OK;
   }
 
   // Extract value parameter.
@@ -686,25 +685,32 @@ TelemetryEvent::RecordEvent(const nsACSt
   RecordEventResult res;
   if (!XRE_IsParentProcess()) {
     {
       StaticMutexAutoLock lock(gTelemetryEventsMutex);
       res = ::ShouldRecordChildEvent(lock, aCategory, aMethod, aObject);
     }
 
     if (res == RecordEventResult::Ok) {
-      TelemetryIPCAccumulator::RecordChildEvent(timestamp, aCategory, aMethod, aObject, value, extra);
+      TelemetryIPCAccumulator::RecordChildEvent(TimeStamp::NowLoRes(), aCategory,
+                                                aMethod, aObject, value, extra);
     }
   } else {
     StaticMutexAutoLock lock(gTelemetryEventsMutex);
 
     if (!gInitDone) {
       return NS_ERROR_FAILURE;
     }
 
+    // Get the current time.
+    double timestamp = -1;
+    if (NS_WARN_IF(NS_FAILED(MsSinceProcessStart(&timestamp)))) {
+      return NS_ERROR_FAILURE;
+    }
+
     res = ::RecordEvent(lock, GeckoProcessType_Default, timestamp, aCategory, aMethod, aObject, value, extra);
   }
 
   // Trigger warnings or errors where needed.
   switch (res) {
     case RecordEventResult::UnknownEvent: {
       JS_ReportErrorASCII(cx, R"(Unknown event: ["%s", "%s", "%s"])",
                           PromiseFlatCString(aCategory).get(),
--- a/toolkit/components/telemetry/ipc/TelemetryComms.h
+++ b/toolkit/components/telemetry/ipc/TelemetryComms.h
@@ -4,16 +4,17 @@
  */
 
 #ifndef Telemetry_Comms_h__
 #define Telemetry_Comms_h__
 
 #include "ipc/IPCMessageUtils.h"
 #include "nsITelemetry.h"
 #include "nsVariant.h"
+#include "mozilla/TimeStamp.h"
 
 namespace mozilla {
 namespace Telemetry {
 
 // Histogram accumulation types.
 enum HistogramID : uint32_t;
 
 struct Accumulation
@@ -60,17 +61,17 @@ struct KeyedScalarAction
 };
 
 struct EventExtraEntry {
   nsCString key;
   nsCString value;
 };
 
 struct ChildEventData {
-  double timestamp;
+  mozilla::TimeStamp timestamp;
   nsCString category;
   nsCString method;
   nsCString object;
   mozilla::Maybe<nsCString> value;
   nsTArray<EventExtraEntry> extra;
 };
 
 } // namespace Telemetry
--- a/toolkit/components/telemetry/ipc/TelemetryIPCAccumulator.cpp
+++ b/toolkit/components/telemetry/ipc/TelemetryIPCAccumulator.cpp
@@ -174,17 +174,17 @@ TelemetryIPCAccumulator::RecordChildKeye
   }
   // Store the action.
   gChildKeyedScalarsActions->AppendElement(
     KeyedScalarAction{aId, aAction, NS_ConvertUTF16toUTF8(aKey), Some(aValue)});
   ArmIPCTimer(locker);
 }
 
 void
-TelemetryIPCAccumulator::RecordChildEvent(double timestamp,
+TelemetryIPCAccumulator::RecordChildEvent(const mozilla::TimeStamp& timestamp,
                                           const nsACString& category,
                                           const nsACString& method,
                                           const nsACString& object,
                                           const mozilla::Maybe<nsCString>& value,
                                           const nsTArray<mozilla::Telemetry::EventExtraEntry>& extra)
 {
   StaticMutexAutoLock locker(gTelemetryIPCAccumulatorMutex);
 
--- a/toolkit/components/telemetry/ipc/TelemetryIPCAccumulator.h
+++ b/toolkit/components/telemetry/ipc/TelemetryIPCAccumulator.h
@@ -11,33 +11,36 @@
 #include "TelemetryComms.h"
 
 class nsIRunnable;
 class nsITimer;
 class nsAString;
 class nsCString;
 
 namespace mozilla {
+
+class TimeStamp;
+
 namespace TelemetryIPCAccumulator {
 
 // Histogram accumulation functions.
 void AccumulateChildHistogram(mozilla::Telemetry::HistogramID aId, uint32_t aSample);
 void AccumulateChildKeyedHistogram(mozilla::Telemetry::HistogramID aId, const nsCString& aKey,
                                    uint32_t aSample);
 
 // Scalar accumulation functions.
 void RecordChildScalarAction(mozilla::Telemetry::ScalarID aId,
                              mozilla::Telemetry::ScalarActionType aAction,
                              const mozilla::Telemetry::ScalarVariant& aValue);
 
 void RecordChildKeyedScalarAction(mozilla::Telemetry::ScalarID aId, const nsAString& aKey,
                                   mozilla::Telemetry::ScalarActionType aAction,
                                   const mozilla::Telemetry::ScalarVariant& aValue);
 
-void RecordChildEvent(double timestamp,
+void RecordChildEvent(const mozilla::TimeStamp& timestamp,
                       const nsACString& category,
                       const nsACString& method,
                       const nsACString& object,
                       const mozilla::Maybe<nsCString>& value,
                       const nsTArray<mozilla::Telemetry::EventExtraEntry>& extra);
 
 void IPCTimerFired(nsITimer* aTimer, void* aClosure);
 void DeInitializeGlobalState();
--- a/toolkit/components/telemetry/tests/unit/test_ChildEvents.js
+++ b/toolkit/components/telemetry/tests/unit/test_ChildEvents.js
@@ -70,51 +70,65 @@ add_task(function*() {
   yield TelemetryController.testSetup();
   // Make sure we don't generate unexpected pings due to pref changes.
   yield setEmptyPrefWatchlist();
   // Enable recording for the test event category.
   Telemetry.setEventRecordingEnabled("telemetry.test", true);
 
   // Run test in child, don't wait for it to finish: just wait for the
   // MESSAGE_CHILD_TEST_DONE.
+  const timestampBeforeChildEvents = Telemetry.msSinceProcessStart();
   run_test_in_child("test_ChildEvents.js");
   yield do_await_remote_message(MESSAGE_CHILD_TEST_DONE);
 
   // Once events are set by the content process, they don't immediately get
   // sent to the parent process. Wait for the Telemetry IPC Timer to trigger
   // and batch send the data back to the parent process.
   yield waitForContentEvents();
+  const timestampAfterChildEvents = Telemetry.msSinceProcessStart();
 
   // Also record some events in the parent.
   RECORDED_PARENT_EVENTS.forEach(e => Telemetry.recordEvent(...e));
   UNRECORDED_PARENT_EVENTS.forEach(e => Telemetry.recordEvent(...e));
 
   // Get an "environment-changed" ping rather than a "test-ping", as
   // event measurements are only supported in subsession pings.
   const payload = TelemetrySession.getPayload("environment-change");
 
-  // Validate the event data.
+  // Validate the event data is present in the payload.
   Assert.ok("processes" in payload, "Should have processes section");
   Assert.ok("parent" in payload.processes, "Should have main process section");
   Assert.ok("events" in payload.processes.parent, "Main process section should have events.");
   Assert.ok("content" in payload.processes, "Should have child process section");
   Assert.ok("events" in payload.processes.content, "Child process section should have events.");
 
+  // Check that the expected events are present from the content process.
   let contentEvents = payload.processes.content.events.map(e => e.slice(1));
   Assert.equal(contentEvents.length, RECORDED_CONTENT_EVENTS.length, "Should match expected event count.");
   for (let i = 0; i < RECORDED_CONTENT_EVENTS.length; ++i) {
     Assert.deepEqual(contentEvents[i], RECORDED_CONTENT_EVENTS[i], "Should have recorded expected event.");
   }
 
+  // Check that the expected events are present from the parent process.
   let parentEvents = payload.processes.parent.events.map(e => e.slice(1));
   Assert.equal(parentEvents.length, RECORDED_PARENT_EVENTS.length, "Should match expected event count.");
   for (let i = 0; i < RECORDED_PARENT_EVENTS.length; ++i) {
     Assert.deepEqual(parentEvents[i], RECORDED_PARENT_EVENTS[i], "Should have recorded expected event.");
   }
 
+  // Check that the event timestamps are in the expected ranges.
+  let contentTimestamps = payload.processes.content.events.map(e => e[0]);
+  let parentTimestamps = payload.processes.parent.events.map(e => e[0]);
+
+  Assert.ok(contentTimestamps.every(ts => (ts > Math.floor(timestampBeforeChildEvents)) &&
+                                          (ts < timestampAfterChildEvents)),
+            "All content event timestamps should be in the expected time range.");
+  Assert.ok(parentTimestamps.every(ts => (ts >= Math.floor(timestampAfterChildEvents))),
+            "All parent event timestamps should be in the expected time range.");
+
   // Make sure all events are cleared from storage properly.
   let snapshot =
       Telemetry.snapshotBuiltinEvents(Ci.nsITelemetry.DATASET_RELEASE_CHANNEL_OPTIN, true);
   Assert.greaterOrEqual(Object.keys(snapshot).length, 2, "Should have events from at least two processes.");
   snapshot =
       Telemetry.snapshotBuiltinEvents(Ci.nsITelemetry.DATASET_RELEASE_CHANNEL_OPTIN, true);
   Assert.equal(Object.keys(snapshot).length, 0, "Should have cleared all events from storage.");
 });