Remove the global engine entry timestamp

jason-simmons · jason-simmons · commit d64f4e997c02 · 2020-05-06T18:33:18.000-07:00
The engine was using a global to store a timestamp representing the
launch of the engine.  This timestamp is initialized with a JNI call
on Android and during shell setup on other platforms.  Later the
timestamp is added to a FlutterEngineMainEnter timeline event used to
measure engine startup time in benchmarks.

This PR removes the global and the JNI call and moves the timestamp
into the settings object.
diff --git a/ci/licenses_golden/licenses_flutter b/ci/licenses_golden/licenses_flutter
@@ -559,8 +559,6 @@ FILE: ../../../flutter/runtime/service_protocol.cc
 FILE: ../../../flutter/runtime/service_protocol.h
 FILE: ../../../flutter/runtime/skia_concurrent_executor.cc
 FILE: ../../../flutter/runtime/skia_concurrent_executor.h
-FILE: ../../../flutter/runtime/start_up.cc
-FILE: ../../../flutter/runtime/start_up.h
 FILE: ../../../flutter/runtime/test_font_data.cc
 FILE: ../../../flutter/runtime/test_font_data.h
 FILE: ../../../flutter/runtime/window_data.cc
diff --git a/common/settings.h b/common/settings.h
@@ -8,6 +8,7 @@
 #include <fcntl.h>
 #include <stdint.h>
 
+#include <chrono>
 #include <memory>
 #include <string>
 #include <vector>
@@ -207,6 +208,11 @@ struct Settings {
   /// https://github.com/dart-lang/sdk/blob/ca64509108b3e7219c50d6c52877c85ab6a35ff2/runtime/vm/flag_list.h#L150
   int64_t old_gen_heap_size = -1;
 
+  /// A timestamp representing when the engine started. The value is based
+  /// on the clock used by the Dart timeline APIs. This timestamp is used
+  /// to log a timeline event that tracks the latency of engine startup.
+  std::chrono::microseconds engine_start_timestamp = {};
+
   std::string ToString() const;
 };
 
diff --git a/runtime/BUILD.gn b/runtime/BUILD.gn
@@ -70,8 +70,6 @@ source_set("runtime") {
     "service_protocol.h",
     "skia_concurrent_executor.cc",
     "skia_concurrent_executor.h",
-    "start_up.cc",
-    "start_up.h",
     "window_data.cc",
     "window_data.h",
   ]
diff --git a/runtime/dart_vm.cc b/runtime/dart_vm.cc
@@ -25,7 +25,6 @@
 #include "flutter/runtime/dart_isolate.h"
 #include "flutter/runtime/dart_service_isolate.h"
 #include "flutter/runtime/ptrace_ios.h"
-#include "flutter/runtime/start_up.h"
 #include "third_party/dart/runtime/include/bin/dart_io_api.h"
 #include "third_party/skia/include/core/SkExecutor.h"
 #include "third_party/tonic/converter/dart_converter.h"
@@ -426,14 +425,15 @@ DartVM::DartVM(std::shared_ptr<const DartVMData> vm_data,
     // the very first frame gives us a good idea about Flutter's startup time.
     // Use a duration event so about:tracing will consider this event when
     // deciding the earliest event to use as time 0.
-    if (engine_main_enter_ts != 0) {
-      Dart_TimelineEvent("FlutterEngineMainEnter",  // label
-                         engine_main_enter_ts,      // timestamp0
-                         Dart_TimelineGetMicros(),  // timestamp1_or_async_id
-                         Dart_Timeline_Event_Duration,  // event type
-                         0,                             // argument_count
-                         nullptr,                       // argument_names
-                         nullptr                        // argument_values
+    if (settings_.engine_start_timestamp.count()) {
+      Dart_TimelineEvent(
+          "FlutterEngineMainEnter",                  // label
+          settings_.engine_start_timestamp.count(),  // timestamp0
+          Dart_TimelineGetMicros(),                  // timestamp1_or_async_id
+          Dart_Timeline_Event_Duration,              // event type
+          0,                                         // argument_count
+          nullptr,                                   // argument_names
+          nullptr                                    // argument_values
       );
     }
   }
diff --git a/runtime/start_up.cc b/runtime/start_up.cc
diff --git a/runtime/start_up.h b/runtime/start_up.h
diff --git a/shell/common/shell.cc b/shell/common/shell.cc
@@ -20,7 +20,6 @@
 #include "flutter/fml/trace_event.h"
 #include "flutter/fml/unique_fd.h"
 #include "flutter/runtime/dart_vm.h"
-#include "flutter/runtime/start_up.h"
 #include "flutter/shell/common/engine.h"
 #include "flutter/shell/common/persistent_cache.h"
 #include "flutter/shell/common/skia_event_tracer_impl.h"
@@ -175,12 +174,6 @@ std::unique_ptr<Shell> Shell::CreateShellOnPlatformThread(
   return shell;
 }
 
-static void RecordStartupTimestamp() {
-  if (engine_main_enter_ts == 0) {
-    engine_main_enter_ts = Dart_TimelineGetMicros();
-  }
-}
-
 static void Tokenize(const std::string& input,
                      std::vector<std::string>* results,
                      char delimiter) {
@@ -197,7 +190,7 @@ static void Tokenize(const std::string& input,
 // TODO(chinmaygarde): The unfortunate side effect of this call is that settings
 // that cause shell initialization failures will still lead to some of their
 // settings being applied.
-static void PerformInitializationTasks(const Settings& settings) {
+static void PerformInitializationTasks(Settings& settings) {
   {
     fml::LogSettings log_settings;
     log_settings.min_log_level =
@@ -207,7 +200,10 @@ static void PerformInitializationTasks(const Settings& settings) {
 
   static std::once_flag gShellSettingsInitialization = {};
   std::call_once(gShellSettingsInitialization, [&settings] {
-    RecordStartupTimestamp();
+    if (settings.engine_start_timestamp.count() == 0) {
+      settings.engine_start_timestamp =
+          std::chrono::microseconds(Dart_TimelineGetMicros());
+    }
 
     tonic::SetLogHandler(
         [](const char* message) { FML_LOG(ERROR) << message; });
diff --git a/shell/platform/android/flutter_main.cc b/shell/platform/android/flutter_main.cc
@@ -18,7 +18,6 @@
 #include "flutter/fml/size.h"
 #include "flutter/lib/ui/plugins/callback_cache.h"
 #include "flutter/runtime/dart_vm.h"
-#include "flutter/runtime/start_up.h"
 #include "flutter/shell/common/shell.h"
 #include "flutter/shell/common/switches.h"
 #include "third_party/dart/runtime/include/dart_tools_api.h"
@@ -62,7 +61,8 @@ void FlutterMain::Init(JNIEnv* env,
                        jobjectArray jargs,
                        jstring kernelPath,
                        jstring appStoragePath,
-                       jstring engineCachesPath) {
+                       jstring engineCachesPath,
+                       jlong initTimeMillis) {
   std::vector<std::string> args;
   args.push_back("flutter");
   for (auto& arg : fml::jni::StringArrayToVector(env, jargs)) {
@@ -72,6 +72,10 @@ void FlutterMain::Init(JNIEnv* env,
 
   auto settings = SettingsFromCommandLine(command_line);
 
+  int64_t init_time_micros = initTimeMillis * 1000;
+  settings.engine_start_timestamp =
+      std::chrono::microseconds(Dart_TimelineGetMicros() - init_time_micros);
+
   // Restore the callback cache.
   // TODO(chinmaygarde): Route all cache file access through FML and remove this
   // setter.
@@ -151,27 +155,14 @@ void FlutterMain::SetupObservatoryUriCallback(JNIEnv* env) {
       });
 }
 
-static void RecordStartTimestamp(JNIEnv* env,
-                                 jclass jcaller,
-                                 jlong initTimeMillis) {
-  int64_t initTimeMicros =
-      static_cast<int64_t>(initTimeMillis) * static_cast<int64_t>(1000);
-  flutter::engine_main_enter_ts = Dart_TimelineGetMicros() - initTimeMicros;
-}
-
 bool FlutterMain::Register(JNIEnv* env) {
   static const JNINativeMethod methods[] = {
       {
           .name = "nativeInit",
           .signature = "(Landroid/content/Context;[Ljava/lang/String;Ljava/"
-                       "lang/String;Ljava/lang/String;Ljava/lang/String;)V",
+                       "lang/String;Ljava/lang/String;Ljava/lang/String;J)V",
           .fnPtr = reinterpret_cast<void*>(&Init),
       },
-      {
-          .name = "nativeRecordStartTimestamp",
-          .signature = "(J)V",
-          .fnPtr = reinterpret_cast<void*>(&RecordStartTimestamp),
-      },
   };
 
   jclass clazz = env->FindClass("io/flutter/embedding/engine/FlutterJNI");
diff --git a/shell/platform/android/flutter_main.h b/shell/platform/android/flutter_main.h
@@ -35,7 +35,8 @@ class FlutterMain {
                    jobjectArray jargs,
                    jstring kernelPath,
                    jstring appStoragePath,
-                   jstring engineCachesPath);
+                   jstring engineCachesPath,
+                   jlong initTimeMillis);
 
   void SetupObservatoryUriCallback(JNIEnv* env);
 
diff --git a/shell/platform/android/io/flutter/embedding/engine/FlutterJNI.java b/shell/platform/android/io/flutter/embedding/engine/FlutterJNI.java
@@ -103,10 +103,8 @@ public static native void nativeInit(
       @NonNull String[] args,
       @Nullable String bundlePath,
       @NonNull String appStoragePath,
-      @NonNull String engineCachesPath);
-
-  // TODO(mattcarroll): add javadocs
-  public static native void nativeRecordStartTimestamp(long initTimeMillis);
+      @NonNull String engineCachesPath,
+      long initTimeMillis);
 
   // TODO(mattcarroll): add javadocs
   @UiThread
diff --git a/shell/platform/android/io/flutter/embedding/engine/loader/FlutterLoader.java b/shell/platform/android/io/flutter/embedding/engine/loader/FlutterLoader.java
@@ -78,6 +78,7 @@ public static FlutterLoader getInstance() {
   private boolean initialized = false;
   @Nullable private ResourceExtractor resourceExtractor;
   @Nullable private Settings settings;
+  private long initStartTimestampMillis;
 
   /**
    * Starts initialization of the native system.
@@ -113,23 +114,14 @@ public void startInitialization(@NonNull Context applicationContext, @NonNull Se
 
     this.settings = settings;
 
-    long initStartTimestampMillis = SystemClock.uptimeMillis();
-    initConfig(applicationContext);
+    initStartTimestampMillis = SystemClock.uptimeMillis();
     initResources(applicationContext);
 
     System.loadLibrary("flutter");
 
     VsyncWaiter.getInstance(
             (WindowManager) applicationContext.getSystemService(Context.WINDOW_SERVICE))
         .init();
-
-    // We record the initialization time using SystemClock because at the start of the
-    // initialization we have not yet loaded the native library to call into dart_tools_api.h.
-    // To get Timeline timestamp of the start of initialization we simply subtract the delta
-    // from the Timeline timestamp at the current moment (the assumption is that the overhead
-    // of the JNI call is negligible).
-    long initTimeMillis = SystemClock.uptimeMillis() - initStartTimestampMillis;
-    FlutterJNI.nativeRecordStartTimestamp(initTimeMillis);
   }
 
   /**
@@ -202,12 +194,14 @@ public void ensureInitializationComplete(
 
       String appStoragePath = PathUtils.getFilesDir(applicationContext);
       String engineCachesPath = PathUtils.getCacheDirectory(applicationContext);
+      long initTimeMillis = SystemClock.uptimeMillis() - initStartTimestampMillis;
       FlutterJNI.nativeInit(
           applicationContext,
           shellArgs.toArray(new String[0]),
           kernelPath,
           appStoragePath,
-          engineCachesPath);
+          engineCachesPath,
+          initTimeMillis);
 
       initialized = true;
     } catch (Exception e) {

Original file line number	Diff line number	Diff line change
`@@ -70,8 +70,6 @@ source_set("runtime") {`
`70`	`70`	`"service_protocol.h",`
`71`	`71`	`"skia_concurrent_executor.cc",`
`72`	`72`	`"skia_concurrent_executor.h",`
`73`		`- "start_up.cc",`
`74`		`- "start_up.h",`
`75`	`73`	`"window_data.cc",`
`76`	`74`	`"window_data.h",`
`77`	`75`	`]`