commit 74584e6b65b6d5949afa9de664b05f453d42872b
author Eric Holk <eholk@google.com> Thu Feb 18 14:39:17 2021 -0800
committer Treehugger Robot <treehugger-gerrit@google.com> Mon Feb 22 22:28:15 2021 +0000
tree 7d4ff8395607f4d64b393e91b5db7d6c1ee45adb
parent 27b8cb7bb6ba85ca0a903f02c7d38b9f24636af7

[metrics] Add ClassLoadingTotalTime counter

This keeps track of how much time we spend in the class loading
process.

Testing instructions:

   adb shell setprop dalvik.vm.metrics.write-to-log true
   adb shell stop && adb shell start
   adb logcat -e "ART internal metrics"

Observer ClassLoadingTotalTime in internal metrics report. Example:

    *** ART internal metrics ***
      Metadata:
        timestamp_since_start_ms: 34555
        session_id: 2710488913234081424
        uid: 10065
        compilation_reason: Unknown
        compiler_filter: (unspecified)
      Metrics:
        ClassLoadingTotalTime: count = 120959
        ClassVerificationTotalTime: count = 216121
        JitMethodCompileTime: range = 0...1000000, buckets: 4482,10,2,3
    *** Done dumping ART internal metrics ***

Bug: 177591870
Test: Manual, see above
Change-Id: I24f0c94ab6af5e6cd9b0dc32122f2905c36cf3b7

libartbase/base/metrics/metrics.h

diff --git a/libartbase/base/metrics/metrics.h b/libartbase/base/metrics/metrics.h
index f6eed56..ee6b1f8 100644
--- a/libartbase/base/metrics/metrics.h
+++ b/libartbase/base/metrics/metrics.h
@@ -35,7 +35,9 @@
 #pragma clang diagnostic error "-Wconversion"
 
 // COUNTER(counter_name)
-#define ART_COUNTERS(COUNTER) COUNTER(ClassVerificationTotalTime)
+#define ART_COUNTERS(COUNTER)    \
+  COUNTER(ClassLoadingTotalTime) \
+  COUNTER(ClassVerificationTotalTime)
 
 // HISTOGRAM(counter_name, num_buckets, minimum_value, maximum_value)
 //

libartbase/base/metrics/metrics_test.cc

diff --git a/libartbase/base/metrics/metrics_test.cc b/libartbase/base/metrics/metrics_test.cc
index 4643f14..44a3b60 100644
--- a/libartbase/base/metrics/metrics_test.cc
+++ b/libartbase/base/metrics/metrics_test.cc
@@ -215,13 +215,13 @@
   // Make sure the resulting string lists all the counters.
   const std::string result = backend.GetAndResetBuffer();
 #define COUNTER(name) \
-  EXPECT_NE(result.find(DatumName(DatumId::k##name)), std::string::npos)
+  EXPECT_NE(result.find(DatumName(DatumId::k##name)), std::string::npos);
   ART_COUNTERS(COUNTER);
 #undef COUNTER
 
   // Make sure the resulting string lists all the histograms.
 #define HISTOGRAM(name, num_buckets, minimum_value, maximum_value) \
-  EXPECT_NE(result.find(DatumName(DatumId::k##name)), std::string::npos)
+  EXPECT_NE(result.find(DatumName(DatumId::k##name)), std::string::npos);
   ART_HISTOGRAMS(HISTOGRAM);
 #undef HISTOGRAM
 }

runtime/class_linker.cc

diff --git a/runtime/class_linker.cc b/runtime/class_linker.cc
index d4f2e30..b98708e 100644
--- a/runtime/class_linker.cc
+++ b/runtime/class_linker.cc
@@ -43,6 +43,7 @@
 #include "base/hash_set.h"
 #include "base/leb128.h"
 #include "base/logging.h"
+#include "base/metrics/metrics.h"
 #include "base/mutex-inl.h"
 #include "base/os.h"
 #include "base/quasi_atomic.h"
@@ -3065,6 +3066,7 @@
                                                const dex::ClassDef& dex_class_def) {
   ScopedDefiningClass sdc(self);
   StackHandleScope<3> hs(self);
+  metrics::AutoTimer timer{GetMetrics()->ClassLoadingTotalTime()};
   auto klass = hs.NewHandle<mirror::Class>(nullptr);
 
   // Load the class from the dex file.