From eadc2ac493960b09395386f764be99a7948217ab Mon Sep 17 00:00:00 2001 From: Valentin Shergin Date: Mon, 27 Jan 2020 13:23:09 -0800 Subject: [PATCH] Fabric: Improving precision and type-safety of Telemetry Summary: Collecting Telemetry is a crucial part of building a performant UI framework; we do that but we need to improve it to make the data more reliable, actionable and trustful. Now we collect time points as the number of milliseconds from the start of the CLOCK_MONOTONIC epoch. That's fine but it also has problems: Sometimes a millisecond is an eternity. We have only 16 (or fewer) of them on each frame. What if some operation takes 1ms (according to telemetry) but we have to run it a dozen times? Does it mean that it's 12 ms in total? So, we lack precision. This is not type-safe. Do you know how many milliseconds in a microsecond? I don't. We multiply that on magical constants hoping that we copied that from some other place right. The current implementation is not cross-platform. We have ifdefs for iOS and Android and Unix and Windows (which is now implemented). So, this diff replaces that with using `std::chrono` which is part of the standard library that designed to fix all those concerns. We also define our type-aliases on top of that to express our concrete constrains: We use `std::chrono::steady_clock` as the base clock which is according to the standard using `clock_gettime(CLOCK_MONOTONIC, ... )` if available. So, it's fast and compatible (the same under the hood) with Android infra. We use nanoseconds when we store time durations (TelemetryDuration type). Changelog: [Internal] Fabric-specific internal change. Reviewed By: JoshuaGross, mdvacca Differential Revision: D19184569 fbshipit-source-id: 7a44688f4bb3bfc6e3009874f0075c531c8569a1 --- .../com/facebook/react/fabric/jni/Binding.cpp | 18 +-- .../fabric/mounting/MountingTelemetry.cpp | 106 +++++++++--------- .../fabric/mounting/MountingTelemetry.h | 42 +++---- .../mounting/tests/MountingTelemetryTest.cpp | 25 ++++- ReactCommon/utils/Telemetry.h | 65 +++++++++++ 5 files changed, 167 insertions(+), 89 deletions(-) create mode 100644 ReactCommon/utils/Telemetry.h diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp b/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp index 3bddb58f351..b3aec67b671 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp +++ b/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp @@ -560,7 +560,7 @@ void Binding::schedulerDidFinishTransaction( std::lock_guard lock(commitMutex_); SystraceSection s("FabricUIManagerBinding::schedulerDidFinishTransaction"); - long finishTransactionStartTime = monotonicTimeInMilliseconds(); + auto finishTransactionStartTime = telemetryTimePointNow(); jni::global_ref localJavaUIManager = getJavaUIManager(); if (!localJavaUIManager) { @@ -827,19 +827,19 @@ void Binding::schedulerDidFinishTransaction( jlong, jlong)>("scheduleMountItem"); - long finishTransactionEndTime = monotonicTimeInMilliseconds(); + auto finishTransactionEndTime = telemetryTimePointNow(); scheduleMountItem( localJavaUIManager, batch.get(), telemetry.getCommitNumber(), - telemetry.getCommitStartTime(), - telemetry.getDiffStartTime(), - telemetry.getDiffEndTime(), - telemetry.getLayoutStartTime(), - telemetry.getLayoutEndTime(), - finishTransactionStartTime, - finishTransactionEndTime); + telemetryTimePointToMilliseconds(telemetry.getCommitStartTime()), + telemetryTimePointToMilliseconds(telemetry.getDiffStartTime()), + telemetryTimePointToMilliseconds(telemetry.getDiffEndTime()), + telemetryTimePointToMilliseconds(telemetry.getLayoutStartTime()), + telemetryTimePointToMilliseconds(telemetry.getLayoutEndTime()), + telemetryTimePointToMilliseconds(finishTransactionStartTime), + telemetryTimePointToMilliseconds(finishTransactionEndTime)); } void Binding::setPixelDensity(float pointScaleFactor) { diff --git a/ReactCommon/fabric/mounting/MountingTelemetry.cpp b/ReactCommon/fabric/mounting/MountingTelemetry.cpp index a3f2f8bc2b7..07c79a704af 100644 --- a/ReactCommon/fabric/mounting/MountingTelemetry.cpp +++ b/ReactCommon/fabric/mounting/MountingTelemetry.cpp @@ -9,111 +9,109 @@ #include -#include - namespace facebook { namespace react { void MountingTelemetry::willCommit() { - assert(commitStartTime_ == kUndefinedTime); - assert(commitEndTime_ == kUndefinedTime); - commitStartTime_ = monotonicTimeInMilliseconds(); + assert(commitStartTime_ == kTelemetryUndefinedTimePoint); + assert(commitEndTime_ == kTelemetryUndefinedTimePoint); + commitStartTime_ = telemetryTimePointNow(); commitNumber_++; } void MountingTelemetry::didCommit() { - assert(commitStartTime_ != kUndefinedTime); - assert(commitEndTime_ == kUndefinedTime); - commitEndTime_ = monotonicTimeInMilliseconds(); + assert(commitStartTime_ != kTelemetryUndefinedTimePoint); + assert(commitEndTime_ == kTelemetryUndefinedTimePoint); + commitEndTime_ = telemetryTimePointNow(); } void MountingTelemetry::willDiff() { - assert(diffStartTime_ == kUndefinedTime); - assert(diffEndTime_ == kUndefinedTime); - diffStartTime_ = monotonicTimeInMilliseconds(); + assert(diffStartTime_ == kTelemetryUndefinedTimePoint); + assert(diffEndTime_ == kTelemetryUndefinedTimePoint); + diffStartTime_ = telemetryTimePointNow(); } void MountingTelemetry::didDiff() { - assert(diffStartTime_ != kUndefinedTime); - assert(diffEndTime_ == kUndefinedTime); - diffEndTime_ = monotonicTimeInMilliseconds(); + assert(diffStartTime_ != kTelemetryUndefinedTimePoint); + assert(diffEndTime_ == kTelemetryUndefinedTimePoint); + diffEndTime_ = telemetryTimePointNow(); } void MountingTelemetry::willLayout() { - assert(layoutStartTime_ == kUndefinedTime); - assert(layoutEndTime_ == kUndefinedTime); - layoutStartTime_ = monotonicTimeInMilliseconds(); + assert(layoutStartTime_ == kTelemetryUndefinedTimePoint); + assert(layoutEndTime_ == kTelemetryUndefinedTimePoint); + layoutStartTime_ = telemetryTimePointNow(); } void MountingTelemetry::didLayout() { - assert(layoutStartTime_ != kUndefinedTime); - assert(layoutEndTime_ == kUndefinedTime); - layoutEndTime_ = monotonicTimeInMilliseconds(); + assert(layoutStartTime_ != kTelemetryUndefinedTimePoint); + assert(layoutEndTime_ == kTelemetryUndefinedTimePoint); + layoutEndTime_ = telemetryTimePointNow(); } void MountingTelemetry::willMount() { - assert(mountStartTime_ == kUndefinedTime); - assert(mountEndTime_ == kUndefinedTime); - mountStartTime_ = monotonicTimeInMilliseconds(); + assert(mountStartTime_ == kTelemetryUndefinedTimePoint); + assert(mountEndTime_ == kTelemetryUndefinedTimePoint); + mountStartTime_ = telemetryTimePointNow(); } void MountingTelemetry::didMount() { - assert(mountStartTime_ != kUndefinedTime); - assert(mountEndTime_ == kUndefinedTime); - mountEndTime_ = monotonicTimeInMilliseconds(); + assert(mountStartTime_ != kTelemetryUndefinedTimePoint); + assert(mountEndTime_ == kTelemetryUndefinedTimePoint); + mountEndTime_ = telemetryTimePointNow(); } -int64_t MountingTelemetry::getDiffStartTime() const { - assert(diffStartTime_ != kUndefinedTime); - assert(diffEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getDiffStartTime() const { + assert(diffStartTime_ != kTelemetryUndefinedTimePoint); + assert(diffEndTime_ != kTelemetryUndefinedTimePoint); return diffStartTime_; } -int64_t MountingTelemetry::getDiffEndTime() const { - assert(diffStartTime_ != kUndefinedTime); - assert(diffEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getDiffEndTime() const { + assert(diffStartTime_ != kTelemetryUndefinedTimePoint); + assert(diffEndTime_ != kTelemetryUndefinedTimePoint); return diffEndTime_; } -int64_t MountingTelemetry::getCommitNumber() const { - return commitNumber_; -} - -int64_t MountingTelemetry::getCommitStartTime() const { - assert(commitStartTime_ != kUndefinedTime); - assert(commitEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getCommitStartTime() const { + assert(commitStartTime_ != kTelemetryUndefinedTimePoint); + assert(commitEndTime_ != kTelemetryUndefinedTimePoint); return commitStartTime_; } -int64_t MountingTelemetry::getCommitEndTime() const { - assert(commitStartTime_ != kUndefinedTime); - assert(commitEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getCommitEndTime() const { + assert(commitStartTime_ != kTelemetryUndefinedTimePoint); + assert(commitEndTime_ != kTelemetryUndefinedTimePoint); return commitEndTime_; } -int64_t MountingTelemetry::getLayoutStartTime() const { - assert(layoutStartTime_ != kUndefinedTime); - assert(layoutEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getLayoutStartTime() const { + assert(layoutStartTime_ != kTelemetryUndefinedTimePoint); + assert(layoutEndTime_ != kTelemetryUndefinedTimePoint); return layoutStartTime_; } -int64_t MountingTelemetry::getLayoutEndTime() const { - assert(layoutStartTime_ != kUndefinedTime); - assert(layoutEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getLayoutEndTime() const { + assert(layoutStartTime_ != kTelemetryUndefinedTimePoint); + assert(layoutEndTime_ != kTelemetryUndefinedTimePoint); return layoutEndTime_; } -int64_t MountingTelemetry::getMountStartTime() const { - assert(mountStartTime_ != kUndefinedTime); - assert(mountEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getMountStartTime() const { + assert(mountStartTime_ != kTelemetryUndefinedTimePoint); + assert(mountEndTime_ != kTelemetryUndefinedTimePoint); return mountStartTime_; } -int64_t MountingTelemetry::getMountEndTime() const { - assert(mountStartTime_ != kUndefinedTime); - assert(mountEndTime_ != kUndefinedTime); +TelemetryTimePoint MountingTelemetry::getMountEndTime() const { + assert(mountStartTime_ != kTelemetryUndefinedTimePoint); + assert(mountEndTime_ != kTelemetryUndefinedTimePoint); return mountEndTime_; } +int MountingTelemetry::getCommitNumber() const { + return commitNumber_; +} + } // namespace react } // namespace facebook diff --git a/ReactCommon/fabric/mounting/MountingTelemetry.h b/ReactCommon/fabric/mounting/MountingTelemetry.h index 97735a10c47..1a212d6e97b 100644 --- a/ReactCommon/fabric/mounting/MountingTelemetry.h +++ b/ReactCommon/fabric/mounting/MountingTelemetry.h @@ -7,8 +7,10 @@ #pragma once +#include #include -#include + +#include namespace facebook { namespace react { @@ -34,28 +36,28 @@ class MountingTelemetry final { /* * Reading */ - int64_t getDiffStartTime() const; - int64_t getDiffEndTime() const; - int64_t getLayoutStartTime() const; - int64_t getLayoutEndTime() const; - int64_t getCommitStartTime() const; - int64_t getCommitEndTime() const; - int64_t getCommitNumber() const; - int64_t getMountStartTime() const; - int64_t getMountEndTime() const; + TelemetryTimePoint getDiffStartTime() const; + TelemetryTimePoint getDiffEndTime() const; + TelemetryTimePoint getLayoutStartTime() const; + TelemetryTimePoint getLayoutEndTime() const; + TelemetryTimePoint getCommitStartTime() const; + TelemetryTimePoint getCommitEndTime() const; + TelemetryTimePoint getMountStartTime() const; + TelemetryTimePoint getMountEndTime() const; + + int getCommitNumber() const; private: - constexpr static int64_t kUndefinedTime = std::numeric_limits::max(); + TelemetryTimePoint diffStartTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint diffEndTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint commitStartTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint commitEndTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint layoutStartTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint layoutEndTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint mountStartTime_{kTelemetryUndefinedTimePoint}; + TelemetryTimePoint mountEndTime_{kTelemetryUndefinedTimePoint}; - int64_t diffStartTime_{kUndefinedTime}; - int64_t diffEndTime_{kUndefinedTime}; - int64_t commitNumber_{0}; - int64_t commitStartTime_{kUndefinedTime}; - int64_t commitEndTime_{kUndefinedTime}; - int64_t layoutStartTime_{kUndefinedTime}; - int64_t layoutEndTime_{kUndefinedTime}; - int64_t mountStartTime_{kUndefinedTime}; - int64_t mountEndTime_{kUndefinedTime}; + int commitNumber_{0}; }; } // namespace react diff --git a/ReactCommon/fabric/mounting/tests/MountingTelemetryTest.cpp b/ReactCommon/fabric/mounting/tests/MountingTelemetryTest.cpp index 391e1d088e8..025004cfcee 100644 --- a/ReactCommon/fabric/mounting/tests/MountingTelemetryTest.cpp +++ b/ReactCommon/fabric/mounting/tests/MountingTelemetryTest.cpp @@ -11,12 +11,25 @@ #include #include +#include using namespace facebook::react; #define EXPECT_EQ_WITH_THRESHOLD(a, b, threshold) \ EXPECT_TRUE((a >= b - threshold) && (a <= b + threshold)) +TEST(MountingTelemetryTest, timepoints) { + auto threshold = int64_t{30}; + + auto timepointA = telemetryTimePointNow(); + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + auto timepointB = telemetryTimePointNow(); + + auto duration = telemetryDurationToMilliseconds(timepointB - timepointA); + + EXPECT_EQ_WITH_THRESHOLD(duration, 100, threshold); +} + TEST(MountingTelemetryTest, normalUseCase) { auto threshold = int64_t{30}; auto telemetry = MountingTelemetry{}; @@ -35,12 +48,12 @@ TEST(MountingTelemetryTest, normalUseCase) { std::this_thread::sleep_for(std::chrono::milliseconds(100)); telemetry.didMount(); - auto commitDuration = - telemetry.getCommitEndTime() - telemetry.getCommitStartTime(); - auto layoutDuration = - telemetry.getLayoutEndTime() - telemetry.getLayoutStartTime(); - auto mountDuration = - telemetry.getMountEndTime() - telemetry.getMountStartTime(); + auto commitDuration = telemetryDurationToMilliseconds( + telemetry.getCommitEndTime() - telemetry.getCommitStartTime()); + auto layoutDuration = telemetryDurationToMilliseconds( + telemetry.getLayoutEndTime() - telemetry.getLayoutStartTime()); + auto mountDuration = telemetryDurationToMilliseconds( + telemetry.getMountEndTime() - telemetry.getMountStartTime()); EXPECT_EQ_WITH_THRESHOLD(commitDuration, 400, threshold); EXPECT_EQ_WITH_THRESHOLD(layoutDuration, 200, threshold); diff --git a/ReactCommon/utils/Telemetry.h b/ReactCommon/utils/Telemetry.h new file mode 100644 index 00000000000..4fbe7f912ca --- /dev/null +++ b/ReactCommon/utils/Telemetry.h @@ -0,0 +1,65 @@ +/* + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + */ + +#pragma once + +#include + +namespace facebook { +namespace react { + +/* + * Represents a monotonic clock suitable for measuring intervals. + */ +using TelemetryClock = std::chrono::steady_clock; + +/* + * Represents a point in time satisfied the requirements of TelemetryClock. + */ +using TelemetryTimePoint = TelemetryClock::time_point; + +/* + * Represents a time interval satisfied the requirements of TelemetryClock. + */ +using TelemetryDuration = std::chrono::nanoseconds; + +/* + * Represents a time point which never happens. + */ +static TelemetryTimePoint const kTelemetryUndefinedTimePoint = + TelemetryTimePoint::max(); + +/* + * Returns a time point representing the current point in time. + */ +static inline TelemetryTimePoint telemetryTimePointNow() { + return TelemetryClock::now(); +} + +/* + * Returns a number of milliseconds that passed from some epoch starting time + * point to a given time point. The epoch starting time point is not specified + * but stays the same for an application run. + */ +static inline int64_t telemetryTimePointToMilliseconds( + TelemetryTimePoint timePoint) { + return std::chrono::duration_cast( + timePoint - TelemetryTimePoint{}) + .count(); +} + +/* + * Returns a number of milliseconds that represents the given duration object. + */ +static inline int64_t telemetryDurationToMilliseconds( + TelemetryDuration duration) { + return std::chrono::duration_cast(duration) + .count(); +} + +} // namespace react +} // namespace facebook