Add detailed timing stats to passes

Summary: Record cpu time and compute speedup & utilization.

Reviewed By: NTillmann

Differential Revision: D47940007

fbshipit-source-id: f379684e19e891200c63d7a2d927561485247ac5

libredex/PassManager.cpp

@@ -12,6 +12,7 @@
 #include <cinttypes>
 #include <cstdio>
 #include <cstdlib>
+#include <ctime>
 #include <fstream>
 #include <iostream>
 #include <json/json.h>
@@ -1333,6 +1334,9 @@ void PassManager::run_passes(DexStoresVector& stores, ConfigFiles& conf) {
 
     pre_pass_verifiers(pass, i);
 
+    double cpu_time;
+    std::chrono::duration<double> wall_time;
+
     {
       auto scoped_command_prof = profiler_info_pass == pass
                                      ? ScopedCommandProfiling::maybe_from_info(
@@ -1343,6 +1347,8 @@ void PassManager::run_passes(DexStoresVector& stores, ConfigFiles& conf) {
       jemalloc_util::ScopedProfiling malloc_prof(m_malloc_profile_pass == pass);
       auto maybe_track_violations =
           violatios_tracking.maybe_track(this, stores);
+      double cpu_time_start = ((double)std::clock()) / CLOCKS_PER_SEC;
+      auto wall_time_start = std::chrono::steady_clock::now();
       if (pass->is_cfg_legacy()) {
         // if this pass hasn't been updated to editable_cfg yet, clear_cfg. In
         // the future, once all editable cfg updates are done, this branch will
@@ -1360,6 +1366,8 @@ void PassManager::run_passes(DexStoresVector& stores, ConfigFiles& conf) {
         TRACE(PM, 2, "%s Pass uses editable cfg.\n", SHOW(pass->name()));
       }
       pass->run_pass(stores, conf, *this);
+      auto wall_time_end = std::chrono::steady_clock::now();
+      double cpu_time_end = ((double)std::clock()) / CLOCKS_PER_SEC;
 
       // Ensure the CFG is clean, e.g., no unreachable blocks.
       if (!pass->is_cfg_legacy()) {
@@ -1373,6 +1381,9 @@ void PassManager::run_passes(DexStoresVector& stores, ConfigFiles& conf) {
       }
 
       trace_cls.dump(pass->name());
+
+      cpu_time = cpu_time_end - cpu_time_start;
+      wall_time = wall_time_end - wall_time_start;
     }
 
     scoped_mem_stats.trace_log(this, pass);
@@ -1395,6 +1406,16 @@ void PassManager::run_passes(DexStoresVector& stores, ConfigFiles& conf) {
       break;
     }
 
+    set_metric("timing.cpu_time.100", (int64_t)(cpu_time * 100));
+    set_metric("timing.wall_time.100", (int64_t)(wall_time.count() * 100));
+    if (wall_time.count() != 0) {
+      set_metric("timing.speedup.100",
+                 (int64_t)(100.0 * cpu_time / wall_time.count()));
+      set_metric("timing.utilization.100",
+                 (int64_t)(100.0 * cpu_time / wall_time.count() /
+                           redex_parallel::default_num_threads()));
+    }
+
     m_current_pass_info = nullptr;
   }