Add ProfileSaver stats and dump them during SigQuit

Bug: 27516906

(cherry picked from commit c19c1c2e1def1f4f5ab5fd9e71b1a6f76d42988f)

Change-Id: I7d2b1091c3523805ef0f87df42feed1098678aad
diff --git a/runtime/jit/jit.cc b/runtime/jit/jit.cc
index 2a66847..e68058d 100644
--- a/runtime/jit/jit.cc
+++ b/runtime/jit/jit.cc
@@ -119,6 +119,11 @@
   memory_use_.PrintMemoryUse(os);
 }
 
+void Jit::DumpForSigQuit(std::ostream& os) {
+  DumpInfo(os);
+  ProfileSaver::DumpInstanceInfo(os);
+}
+
 void Jit::AddTimingLogger(const TimingLogger& logger) {
   cumulative_timings_.AddLogger(logger);
 }
@@ -297,7 +302,7 @@
 
 void Jit::StopProfileSaver() {
   if (save_profiling_info_ && ProfileSaver::IsStarted()) {
-    ProfileSaver::Stop();
+    ProfileSaver::Stop(dump_info_on_shutdown_);
   }
 }
 
diff --git a/runtime/jit/jit.h b/runtime/jit/jit.h
index ff3acf6..8198c18 100644
--- a/runtime/jit/jit.h
+++ b/runtime/jit/jit.h
@@ -127,9 +127,7 @@
                          const std::string& app_dir);
   void StopProfileSaver();
 
-  void DumpForSigQuit(std::ostream& os) REQUIRES(!lock_) {
-    DumpInfo(os);
-  }
+  void DumpForSigQuit(std::ostream& os) REQUIRES(!lock_);
 
   static void NewTypeLoadedIfUsingJit(mirror::Class* type)
       SHARED_REQUIRES(Locks::mutator_lock_);
diff --git a/runtime/jit/offline_profiling_info.cc b/runtime/jit/offline_profiling_info.cc
index f181ca3..e805ce1 100644
--- a/runtime/jit/offline_profiling_info.cc
+++ b/runtime/jit/offline_profiling_info.cc
@@ -52,9 +52,13 @@
 bool ProfileCompilationInfo::SaveProfilingInfo(
     const std::string& filename,
     const std::vector<ArtMethod*>& methods,
-    const std::set<DexCacheResolvedClasses>& resolved_classes) {
+    const std::set<DexCacheResolvedClasses>& resolved_classes,
+    uint64_t* bytes_written) {
   if (methods.empty() && resolved_classes.empty()) {
     VLOG(profiler) << "No info to save to " << filename;
+    if (bytes_written != nullptr) {
+      *bytes_written = 0;
+    }
     return true;
   }
 
@@ -99,6 +103,9 @@
   if (result) {
     VLOG(profiler) << "Successfully saved profile info to " << filename
         << " Size: " << GetFileSizeBytes(filename);
+    if (bytes_written != nullptr) {
+      *bytes_written = GetFileSizeBytes(filename);
+    }
   } else {
     VLOG(profiler) << "Failed to save profile info to " << filename;
   }
diff --git a/runtime/jit/offline_profiling_info.h b/runtime/jit/offline_profiling_info.h
index df03244..fb07f8c 100644
--- a/runtime/jit/offline_profiling_info.h
+++ b/runtime/jit/offline_profiling_info.h
@@ -46,7 +46,8 @@
   // If not (the locking is not blocking), the function does not save and returns false.
   static bool SaveProfilingInfo(const std::string& filename,
                                 const std::vector<ArtMethod*>& methods,
-                                const std::set<DexCacheResolvedClasses>& resolved_classes);
+                                const std::set<DexCacheResolvedClasses>& resolved_classes,
+                                uint64_t* bytes_written = nullptr);
 
   // Loads profile information from the given file descriptor.
   bool Load(int fd);
diff --git a/runtime/jit/profile_saver.cc b/runtime/jit/profile_saver.cc
index a2876f8..fd33248 100644
--- a/runtime/jit/profile_saver.cc
+++ b/runtime/jit/profile_saver.cc
@@ -56,7 +56,15 @@
       shutting_down_(false),
       first_profile_(true),
       wait_lock_("ProfileSaver wait lock"),
-      period_condition_("ProfileSaver period condition", wait_lock_) {
+      period_condition_("ProfileSaver period condition", wait_lock_),
+      total_bytes_written_(0),
+      total_number_of_writes_(0),
+      total_number_of_code_cache_queries_(0),
+      total_number_of_skipped_writes_(0),
+      total_number_of_failed_writes_(0),
+      total_ns_of_sleep_(0),
+      total_ns_of_work_(0),
+      total_number_of_foreign_dex_marks_(0) {
   AddTrackedLocations(output_filename, code_paths);
   app_data_dir_ = "";
   if (!app_data_dir.empty()) {
@@ -96,11 +104,13 @@
       MutexLock mu(self, wait_lock_);
       period_condition_.TimedWait(self, sleep_time_ms, 0);
     }
-
+    total_ns_of_sleep_ += sleep_time_ms;
     if (ShuttingDown(self)) {
       break;
     }
 
+    uint64_t start = NanoTime();
+
     if (!ProcessProfilingInfo() && save_period_ms < kMaxBackoffMs) {
       // If we don't need to save now it is less likely that we will need to do
       // so in the future. Increase the time between saves according to the
@@ -111,6 +121,8 @@
       save_period_ms = kSavePeriodMs;
     }
     first_iteration = false;
+
+    total_ns_of_work_ += (NanoTime() - start);
   }
 }
 
@@ -122,10 +134,10 @@
     VLOG(profiler) << "Not enough time has passed since the last code cache update."
         << "Last update: " << last_update_time_ns
         << " Last save: " << code_cache_last_update_time_ns_;
+    total_number_of_skipped_writes_++;
     return false;
   }
 
-  uint64_t start = NanoTime();
   code_cache_last_update_time_ns_ = last_update_time_ns;
   SafeMap<std::string, std::set<std::string>> tracked_locations;
   {
@@ -143,11 +155,13 @@
     {
       ScopedObjectAccess soa(Thread::Current());
       jit_code_cache_->GetCompiledArtMethods(locations, methods);
+      total_number_of_code_cache_queries_++;
     }
     // Always save for the first one for loaded classes profile.
     if (methods.size() < kMinimumNrOrMethodsToSave && !first_profile_) {
       VLOG(profiler) << "Not enough information to save to: " << filename
           <<" Nr of methods: " << methods.size();
+      total_number_of_skipped_writes_++;
       return false;
     }
 
@@ -157,12 +171,19 @@
       resolved_classes = class_linker->GetResolvedClasses(/*ignore boot classes*/true);
     }
 
-    if (!ProfileCompilationInfo::SaveProfilingInfo(filename, methods, resolved_classes)) {
+    uint64_t bytes_written;
+    if (!ProfileCompilationInfo::SaveProfilingInfo(filename, methods,
+                                                   resolved_classes,
+                                                   &bytes_written)) {
       LOG(WARNING) << "Could not save profiling info to " << filename;
+      total_number_of_failed_writes_++;
       return false;
+    } else {
+      if (bytes_written > 0) {
+        total_number_of_writes_++;
+        total_bytes_written_ += bytes_written;
+      }
     }
-
-    VLOG(profiler) << "Profile process time: " << PrettyDuration(NanoTime() - start);
   }
   first_profile_ = false;
   return true;
@@ -219,7 +240,7 @@
       "Profile saver thread");
 }
 
-void ProfileSaver::Stop() {
+void ProfileSaver::Stop(bool dump_info) {
   ProfileSaver* profile_saver = nullptr;
   pthread_t profiler_pthread = 0U;
 
@@ -237,6 +258,9 @@
       return;
     }
     instance_->shutting_down_ = true;
+    if (dump_info) {
+      instance_->DumpInfo(LOG(INFO));
+    }
   }
 
   {
@@ -283,7 +307,9 @@
   std::string app_data_dir;
   {
     MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
-    DCHECK(instance_ != nullptr);
+    if (instance_ == nullptr) {
+      return;
+    }
     // Make a copy so that we don't hold the lock while doing I/O.
     for (const auto& it : instance_->tracked_dex_base_locations_) {
       app_code_paths.insert(it.second.begin(), it.second.end());
@@ -292,24 +318,30 @@
     app_data_dir = instance_->app_data_dir_;
   }
 
-  MaybeRecordDexUseInternal(dex_location,
-                            app_code_paths,
-                            foreign_dex_profile_path,
-                            app_data_dir);
+  bool mark_created = MaybeRecordDexUseInternal(dex_location,
+                                                app_code_paths,
+                                                foreign_dex_profile_path,
+                                                app_data_dir);
+  if (mark_created) {
+    MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
+    if (instance_ != nullptr) {
+      instance_->total_number_of_foreign_dex_marks_++;
+    }
+  }
 }
 
-void ProfileSaver::MaybeRecordDexUseInternal(
+bool ProfileSaver::MaybeRecordDexUseInternal(
       const std::string& dex_location,
       const std::set<std::string>& app_code_paths,
       const std::string& foreign_dex_profile_path,
       const std::string& app_data_dir) {
   if (dex_location.empty()) {
     LOG(WARNING) << "Asked to record foreign dex use with an empty dex location.";
-    return;
+    return false;
   }
   if (foreign_dex_profile_path.empty()) {
     LOG(WARNING) << "Asked to record foreign dex use without a valid profile path ";
-    return;
+    return false;
   }
 
   UniqueCPtr<const char[]> dex_location_real_path(realpath(dex_location.c_str(), nullptr));
@@ -322,12 +354,12 @@
 
   if (dex_location_real_path_str.compare(0, app_data_dir.length(), app_data_dir) == 0) {
     // The dex location is under the application folder. Nothing to record.
-    return;
+    return false;
   }
 
   if (app_code_paths.find(dex_location) != app_code_paths.end()) {
     // The dex location belongs to the application code paths. Nothing to record.
-    return;
+    return false;
   }
   // Do another round of checks with the real paths.
   // Note that we could cache all the real locations in the saver (since it's an expensive
@@ -344,7 +376,7 @@
         : real_app_code_location.get());
     if (real_app_code_location_str == dex_location_real_path_str) {
       // The dex location belongs to the application code paths. Nothing to record.
-      return;
+      return false;
     }
   }
 
@@ -362,12 +394,33 @@
     if (close(fd) != 0) {
       PLOG(WARNING) << "Could not close file after flagging foreign dex use " << flag_path;
     }
+    return true;
   } else {
     if (errno != EEXIST) {
       // Another app could have already created the file.
       PLOG(WARNING) << "Could not create foreign dex use mark " << flag_path;
+      return false;
     }
+    return true;
   }
 }
 
+void ProfileSaver::DumpInstanceInfo(std::ostream& os) {
+  MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
+  if (instance_ != nullptr) {
+    instance_->DumpInfo(os);
+  }
+}
+
+void ProfileSaver::DumpInfo(std::ostream& os) {
+  os << "ProfileSaver total_bytes_written=" << total_bytes_written_ << '\n'
+     << "ProfileSaver total_number_of_writes=" << total_number_of_writes_ << '\n'
+     << "ProfileSaver total_number_of_code_cache_queries=" << total_number_of_code_cache_queries_ << '\n'
+     << "ProfileSaver total_number_of_skipped_writes=" << total_number_of_skipped_writes_ << '\n'
+     << "ProfileSaver total_number_of_failed_writes=" << total_number_of_failed_writes_ << '\n'
+     << "ProfileSaver total_ms_of_sleep=" << (total_ns_of_sleep_ / kMilisecondsToNano) << '\n'
+     << "ProfileSaver total_ms_of_work=" << (total_ns_of_work_ / kMilisecondsToNano) << '\n'
+     << "ProfileSaver total_number_of_foreign_dex_marks=" << total_number_of_foreign_dex_marks_ << '\n';
+}
+
 }   // namespace art
diff --git a/runtime/jit/profile_saver.h b/runtime/jit/profile_saver.h
index e7eab95..48ab1ad 100644
--- a/runtime/jit/profile_saver.h
+++ b/runtime/jit/profile_saver.h
@@ -37,7 +37,7 @@
 
   // Stops the profile saver thread.
   // NO_THREAD_SAFETY_ANALYSIS for static function calling into member function with excludes lock.
-  static void Stop()
+  static void Stop(bool dump_info_)
       REQUIRES(!Locks::profiler_lock_, !wait_lock_)
       NO_THREAD_SAFETY_ANALYSIS;
 
@@ -46,6 +46,9 @@
 
   static void NotifyDexUse(const std::string& dex_location);
 
+  // If the profile saver is running, dumps statistics to the `os`. Otherwise it does nothing.
+  static void DumpInstanceInfo(std::ostream& os);
+
  private:
   ProfileSaver(const std::string& output_filename,
                jit::JitCodeCache* jit_code_cache,
@@ -70,12 +73,14 @@
                            const std::vector<std::string>& code_paths)
       REQUIRES(Locks::profiler_lock_);
 
-  static void MaybeRecordDexUseInternal(
+  static bool MaybeRecordDexUseInternal(
       const std::string& dex_location,
       const std::set<std::string>& tracked_locations,
       const std::string& foreign_dex_profile_path,
       const std::string& app_data_dir);
 
+  void DumpInfo(std::ostream& os);
+
   // The only instance of the saver.
   static ProfileSaver* instance_ GUARDED_BY(Locks::profiler_lock_);
   // Profile saver thread.
@@ -94,6 +99,15 @@
   Mutex wait_lock_ DEFAULT_MUTEX_ACQUIRED_AFTER;
   ConditionVariable period_condition_ GUARDED_BY(wait_lock_);
 
+  uint64_t total_bytes_written_;
+  uint64_t total_number_of_writes_;
+  uint64_t total_number_of_code_cache_queries_;
+  uint64_t total_number_of_skipped_writes_;
+  uint64_t total_number_of_failed_writes_;
+  uint64_t total_ns_of_sleep_;
+  uint64_t total_ns_of_work_;
+  uint64_t total_number_of_foreign_dex_marks_;
+
   DISALLOW_COPY_AND_ASSIGN(ProfileSaver);
 };