Tracking time spent on measuring text in TransactionTelemetry

Summary:
Now we not only measure how many times we measured text but also measure how much time it takes. This way we can see which portion of the layout process is spent by layout itself (and measuring embedded components).

Changelog: [Internal] Fabric-specific internal change.

Reviewed By: mdvacca

Differential Revision: D26827447

fbshipit-source-id: e0b09fcacc86aed50dd94b48458215adbb0a60ef

ReactCommon/react/renderer/components/text/ParagraphShadowNode.cpp

@@ -14,7 +14,6 @@
 #include <react/renderer/components/view/ViewShadowNode.h>
 #include <react/renderer/components/view/conversions.h>
 #include <react/renderer/graphics/rounding.h>
-#include <react/renderer/mounting/TransactionTelemetry.h>
 
 #include "ParagraphState.h"
 
@@ -140,11 +139,6 @@ Size ParagraphShadowNode::measureContent(
     attributedString.appendFragment({string, textAttributes, {}});
   }
 
-  auto telemetry = TransactionTelemetry::threadLocalTelemetry();
-  if (telemetry) {
-    telemetry->didMeasureText();
-  }
-
   return textLayoutManager_
       ->measure(
           AttributedStringBox{attributedString},

ReactCommon/react/renderer/mounting/TransactionTelemetry.cpp

@@ -56,8 +56,18 @@ void TransactionTelemetry::willLayout() {
   layoutStartTime_ = telemetryTimePointNow();
 }
 
+void TransactionTelemetry::willMeasureText() {
+  react_native_assert(
+      lastTextMeasureStartTime_ == kTelemetryUndefinedTimePoint);
+  lastTextMeasureStartTime_ = telemetryTimePointNow();
+}
+
 void TransactionTelemetry::didMeasureText() {
   numberOfTextMeasurements_++;
+  react_native_assert(
+      lastTextMeasureStartTime_ != kTelemetryUndefinedTimePoint);
+  textMeasureTime_ += telemetryTimePointNow() - lastTextMeasureStartTime_;
+  lastTextMeasureStartTime_ = kTelemetryUndefinedTimePoint;
 }
 
 void TransactionTelemetry::didLayout() {
@@ -130,6 +140,10 @@ TelemetryTimePoint TransactionTelemetry::getMountEndTime() const {
   return mountEndTime_;
 }
 
+TelemetryDuration TransactionTelemetry::getTextMeasureTime() const {
+  return textMeasureTime_;
+}
+
 int TransactionTelemetry::getNumberOfTextMeasurements() const {
   return numberOfTextMeasurements_;
 }

ReactCommon/react/renderer/mounting/TransactionTelemetry.h

@@ -36,6 +36,7 @@ class TransactionTelemetry final {
   void willCommit();
   void didCommit();
   void willLayout();
+  void willMeasureText();
   void didMeasureText();
   void didLayout();
   void willMount();
@@ -55,6 +56,7 @@ class TransactionTelemetry final {
   TelemetryTimePoint getMountStartTime() const;
   TelemetryTimePoint getMountEndTime() const;
 
+  TelemetryDuration getTextMeasureTime() const;
   int getNumberOfTextMeasurements() const;
   int getRevisionNumber() const;
 
@@ -68,6 +70,9 @@ class TransactionTelemetry final {
   TelemetryTimePoint mountStartTime_{kTelemetryUndefinedTimePoint};
   TelemetryTimePoint mountEndTime_{kTelemetryUndefinedTimePoint};
 
+  TelemetryTimePoint lastTextMeasureStartTime_{kTelemetryUndefinedTimePoint};
+  TelemetryDuration textMeasureTime_{0};
+
   int numberOfTextMeasurements_{0};
   int revisionNumber_{0};
 };

ReactCommon/react/renderer/mounting/tests/TransactionTelemetryTest.cpp

@@ -49,8 +49,16 @@ TEST(TransactionTelemetryTest, normalUseCase) {
   telemetry.willLayout();
   sleep<TelemetryClock>(0.2);
 
-  telemetry.didMeasureText();
+  TransactionTelemetry::threadLocalTelemetry()->willMeasureText();
+  sleep<TelemetryClock>(0.1);
   TransactionTelemetry::threadLocalTelemetry()->didMeasureText();
+
+  TransactionTelemetry::threadLocalTelemetry()->willMeasureText();
+  sleep<TelemetryClock>(0.2);
+  TransactionTelemetry::threadLocalTelemetry()->didMeasureText();
+
+  TransactionTelemetry::threadLocalTelemetry()->willMeasureText();
+  sleep<TelemetryClock>(0.3);
   TransactionTelemetry::threadLocalTelemetry()->didMeasureText();
 
   telemetry.didLayout();
@@ -74,11 +82,15 @@ TEST(TransactionTelemetryTest, normalUseCase) {
   auto mountDuration = telemetryDurationToMilliseconds(
       telemetry.getMountEndTime() - telemetry.getMountStartTime());
 
-  EXPECT_EQ_WITH_THRESHOLD(commitDuration, 400, threshold);
-  EXPECT_EQ_WITH_THRESHOLD(layoutDuration, 200, threshold);
+  EXPECT_EQ_WITH_THRESHOLD(commitDuration, 1000, threshold);
+  EXPECT_EQ_WITH_THRESHOLD(layoutDuration, 800, threshold);
   EXPECT_EQ_WITH_THRESHOLD(mountDuration, 100, threshold);
 
   EXPECT_EQ(telemetry.getNumberOfTextMeasurements(), 3);
+  EXPECT_EQ_WITH_THRESHOLD(
+      telemetryDurationToMilliseconds(telemetry.getTextMeasureTime()),
+      600,
+      threshold);
   EXPECT_EQ(telemetry.getRevisionNumber(), 42);
 }
 

ReactCommon/react/renderer/textlayoutmanager/Android.mk

@@ -11,7 +11,7 @@ LOCAL_MODULE := react_render_textlayoutmanager
 
 LOCAL_SRC_FILES := $(wildcard $(LOCAL_PATH)/*.cpp $(LOCAL_PATH)/platform/android/react/renderer/textlayoutmanager/*.cpp)
 
-LOCAL_SHARED_LIBRARIES := libfolly_futures libreactnativeutilsjni libreact_utils libfb libfbjni libreact_render_uimanager libreact_render_componentregistry libreact_render_attributedstring libfolly_json libyoga libfolly_json libreact_render_core libreact_render_debug libreact_render_graphics libreact_debug
+LOCAL_SHARED_LIBRARIES := libfolly_futures libreactnativeutilsjni libreact_utils libfb libfbjni libreact_render_uimanager libreact_render_componentregistry libreact_render_attributedstring libreact_render_mounting libfolly_json libyoga libfolly_json libreact_render_core libreact_render_debug libreact_render_graphics libreact_debug
 
 LOCAL_STATIC_LIBRARIES :=
 
@@ -34,6 +34,7 @@ $(call import-module,react/renderer/componentregistry)
 $(call import-module,react/renderer/core)
 $(call import-module,react/renderer/attributedstring)
 $(call import-module,react/renderer/debug)
+$(call import-module,react/renderer/mounting)
 $(call import-module,react/renderer/graphics)
 $(call import-module,react/renderer/uimanager)
 $(call import-module,react/utils)

ReactCommon/react/renderer/textlayoutmanager/BUCK

@@ -129,6 +129,7 @@ rn_xplat_cxx_library(
         react_native_xplat_target("react/renderer/debug:debug"),
         react_native_xplat_target("react/renderer/graphics:graphics"),
         react_native_xplat_target("react/renderer/uimanager:uimanager"),
+        react_native_xplat_target("react/renderer/mounting:mounting"),
         react_native_xplat_target("react/renderer/componentregistry:componentregistry"),
     ],
 )

ReactCommon/react/renderer/textlayoutmanager/platform/android/react/renderer/textlayoutmanager/TextLayoutManager.cpp

@@ -12,6 +12,7 @@
 #include <react/jni/ReadableNativeMap.h>
 #include <react/renderer/attributedstring/conversions.h>
 #include <react/renderer/core/conversions.h>
+#include <react/renderer/mounting/TransactionTelemetry.h>
 #include <react/utils/LayoutManager.h>
 
 using namespace facebook::jni;
@@ -34,8 +35,19 @@ TextMeasurement TextLayoutManager::measure(
   auto measurement = measureCache_.get(
       {attributedString, paragraphAttributes, layoutConstraints},
       [&](TextMeasureCacheKey const &key) {
-        return doMeasure(
-            attributedString, paragraphAttributes, layoutConstraints);
+        auto telemetry = TransactionTelemetry::threadLocalTelemetry();
+        if (telemetry) {
+          telemetry->willMeasureText();
+        }
+
+        auto measurement =
+            doMeasure(attributedString, paragraphAttributes, layoutConstraints);
+
+        if (telemetry) {
+          telemetry->didMeasureText();
+        }
+
+        return measurement;
       });
 
   measurement.size = layoutConstraints.clamp(measurement.size);

ReactCommon/react/renderer/textlayoutmanager/platform/ios/TextLayoutManager.mm

@@ -6,6 +6,7 @@
  */
 
 #include "TextLayoutManager.h"
+#include <react/renderer/mounting/TransactionTelemetry.h>
 #include <react/utils/ManagedObjectWrapper.h>
 
 #import "RCTTextLayoutManager.h"
@@ -39,9 +40,20 @@ TextMeasurement TextLayoutManager::measure(
 
       measurement = measureCache_.get(
           {attributedString, paragraphAttributes, layoutConstraints}, [&](TextMeasureCacheKey const &key) {
-            return [textLayoutManager measureAttributedString:attributedString
-                                          paragraphAttributes:paragraphAttributes
-                                            layoutConstraints:layoutConstraints];
+            auto telemetry = TransactionTelemetry::threadLocalTelemetry();
+            if (telemetry) {
+              telemetry->willMeasureText();
+            }
+
+            auto measurement = [textLayoutManager measureAttributedString:attributedString
+                                                      paragraphAttributes:paragraphAttributes
+                                                        layoutConstraints:layoutConstraints];
+
+            if (telemetry) {
+              telemetry->didMeasureText();
+            }
+
+            return measurement;
           });
       break;
     }
@@ -50,9 +62,19 @@ TextMeasurement TextLayoutManager::measure(
       NSAttributedString *nsAttributedString =
           (NSAttributedString *)unwrapManagedObject(attributedStringBox.getOpaquePointer());
 
+      auto telemetry = TransactionTelemetry::threadLocalTelemetry();
+      if (telemetry) {
+        telemetry->willMeasureText();
+      }
+
       measurement = [textLayoutManager measureNSAttributedString:nsAttributedString
                                              paragraphAttributes:paragraphAttributes
                                                layoutConstraints:layoutConstraints];
+
+      if (telemetry) {
+        telemetry->didMeasureText();
+      }
+
       break;
     }
   }