Collect and output a few dex2oat statistics.
Not sure how useful this is. Suggestions welcome.
Change-Id: I339de66a9964d18b11a482f549e891a57831e10e
diff --git a/src/compiler.cc b/src/compiler.cc
index 647a8ed..2f9b3ed 100644
--- a/src/compiler.cc
+++ b/src/compiler.cc
@@ -42,6 +42,13 @@
: instruction_set_(instruction_set),
jni_compiler_(instruction_set),
image_(image),
+ dex_file_count_(0),
+ class_count_(0),
+ abstract_method_count_(0),
+ native_method_count_(0),
+ regular_method_count_(0),
+ instruction_count_(0),
+ start_ns_(NanoTime()),
image_classes_(image_classes) {
CHECK(!Runtime::Current()->IsStarted());
if (!image_) {
@@ -53,6 +60,18 @@
STLDeleteValues(&compiled_classes_);
STLDeleteValues(&compiled_methods_);
STLDeleteValues(&compiled_invoke_stubs_);
+ if (dex_file_count_ > 0) {
+ uint64_t duration_ns = NanoTime() - start_ns_;
+ uint64_t duration_ms = NsToMs(duration_ns);
+ LOG(INFO) << "Compiled files:" << dex_file_count_
+ << " classes:" << class_count_
+ << " methods:(abstract:" << abstract_method_count_
+ << " native:" << native_method_count_
+ << " regular:" << regular_method_count_ << ")"
+ << " instructions:" << instruction_count_
+ << " (took " << duration_ms << "ms, "
+ << (duration_ns/instruction_count_) << " ns/instruction)";
+ }
}
ByteArray* Compiler::CreateResolutionStub(InstructionSet instruction_set,
@@ -361,6 +380,7 @@
}
void Compiler::CompileDexFile(const ClassLoader* class_loader, const DexFile& dex_file) {
+ ++dex_file_count_;
for (size_t class_def_index = 0; class_def_index < dex_file.NumClassDefs(); class_def_index++) {
const DexFile::ClassDef& class_def = dex_file.GetClassDef(class_def_index);
CompileClass(class_def, class_loader, dex_file);
@@ -372,6 +392,7 @@
if (SkipClass(class_loader, dex_file, class_def)) {
return;
}
+ ++class_count_;
const byte* class_data = dex_file.GetClassData(class_def);
if (class_data == NULL) {
// empty class, probably a marker interface
@@ -404,14 +425,24 @@
uint32_t method_idx, const ClassLoader* class_loader,
const DexFile& dex_file) {
CompiledMethod* compiled_method = NULL;
+ uint64_t start_ns = NanoTime();
if ((access_flags & kAccNative) != 0) {
+ ++native_method_count_;
compiled_method = jni_compiler_.Compile(access_flags, method_idx, class_loader, dex_file);
CHECK(compiled_method != NULL);
} else if ((access_flags & kAccAbstract) != 0) {
+ ++abstract_method_count_;
} else {
+ ++regular_method_count_;
+ instruction_count_ += code_item->insns_size_in_code_units_;
compiled_method = oatCompileMethod(*this, code_item, access_flags, method_idx, class_loader,
dex_file, kThumb2);
- CHECK(compiled_method != NULL);
+ CHECK(compiled_method != NULL) << PrettyMethod(method_idx, dex_file);
+ }
+ uint64_t duration_ms = NsToMs(NanoTime() - start_ns);
+ if (duration_ms > 10) {
+ LOG(WARNING) << "Compilation of " << PrettyMethod(method_idx, dex_file)
+ << " took " << duration_ms << "ms";
}
if (compiled_method != NULL) {
@@ -441,7 +472,7 @@
static std::string MakeInvokeStubKey(bool is_static, const char* shorty) {
std::string key(shorty);
if (is_static) {
- key += "$"; // musn't be a shorty type character
+ key += "$"; // Must not be a shorty type character.
}
return key;
}
diff --git a/src/compiler.h b/src/compiler.h
index 89173eb..ddc05d5 100644
--- a/src/compiler.h
+++ b/src/compiler.h
@@ -147,6 +147,14 @@
bool image_;
+ size_t dex_file_count_;
+ size_t class_count_;
+ size_t abstract_method_count_;
+ size_t native_method_count_;
+ size_t regular_method_count_;
+ size_t instruction_count_;
+ uint64_t start_ns_;
+
const std::set<std::string>* image_classes_;
DISALLOW_COPY_AND_ASSIGN(Compiler);
diff --git a/src/dex2oat.cc b/src/dex2oat.cc
index 195c413..b3aec1a 100644
--- a/src/dex2oat.cc
+++ b/src/dex2oat.cc
@@ -19,6 +19,7 @@
#include "os.h"
#include "runtime.h"
#include "stringpiece.h"
+#include "timing_logger.h"
#include "zip_archive.h"
namespace art {
@@ -95,6 +96,7 @@
~Dex2Oat() {
delete runtime_;
+ LOG(INFO) << "dex2oat took " << NsToMs(NanoTime() - start_ns_) << "ms";
}
// Make a list of descriptors for classes to include in the image
@@ -217,7 +219,8 @@
private:
- explicit Dex2Oat(Runtime* runtime) : runtime_(runtime) {}
+ explicit Dex2Oat(Runtime* runtime) : runtime_(runtime), start_ns_(NanoTime()) {
+ }
static Runtime* CreateRuntime(Runtime::Options& options) {
Runtime* runtime = Runtime::Create(options, false);
@@ -337,13 +340,15 @@
return false;
}
- Runtime* runtime_;
static const InstructionSet instruction_set_ = kThumb2;
+ Runtime* runtime_;
+ uint64_t start_ns_;
+
DISALLOW_IMPLICIT_CONSTRUCTORS(Dex2Oat);
};
-bool parse_int(const char* in, int* out) {
+bool ParseInt(const char* in, int* out) {
char* end;
int result = strtol(in, &end, 10);
if (in == end || *end != '\0') {
@@ -386,7 +391,7 @@
dex_filenames.push_back(option.substr(strlen("--dex-file=")).data());
} else if (option.starts_with("--zip-fd=")) {
const char* zip_fd_str = option.substr(strlen("--zip-fd=")).data();
- if (!parse_int(zip_fd_str, &zip_fd)) {
+ if (!ParseInt(zip_fd_str, &zip_fd)) {
fprintf(stderr, "could not parse --zip-fd argument '%s' as an integer\n", zip_fd_str);
usage();
}
@@ -396,7 +401,7 @@
oat_filename = option.substr(strlen("--oat-file=")).data();
} else if (option.starts_with("--oat-fd=")) {
const char* oat_fd_str = option.substr(strlen("--oat-fd=")).data();
- if (!parse_int(oat_fd_str, &oat_fd)) {
+ if (!ParseInt(oat_fd_str, &oat_fd)) {
fprintf(stderr, "could not parse --oat-fd argument '%s' as an integer\n", oat_fd_str);
usage();
}
@@ -556,7 +561,7 @@
UniquePtr<Dex2Oat> dex2oat(Dex2Oat::Create(options));
- // If --image-classes was specified, calculate the full list classes to include in the image
+ // If --image-classes was specified, calculate the full list of classes to include in the image
UniquePtr<const std::set<std::string> > image_classes(NULL);
if (image_classes_filename != NULL) {
image_classes.reset(dex2oat->GetImageClassDescriptors(image_classes_filename));
@@ -610,8 +615,8 @@
}
// We wrote the oat file successfully, and want to keep it.
- LOG(INFO) << "Oat file written successfully " << oat_filename;
- LOG(INFO) << "Image written successfully " << image_filename;
+ LOG(INFO) << "Oat file written successfully: " << oat_filename;
+ LOG(INFO) << "Image written successfully: " << image_filename;
return EXIT_SUCCESS;
}
diff --git a/src/timing_logger.h b/src/timing_logger.h
index 2809f0f..78b168b 100644
--- a/src/timing_logger.h
+++ b/src/timing_logger.h
@@ -41,16 +41,12 @@
void Dump() {
LOG(INFO) << name_ << ": begin";
for (size_t i = 1; i < times_.size(); ++i) {
- LOG(INFO) << name_ << StringPrintf(": %8lld ms, ", ToMs(times_[i] - times_[i-1])) << labels_[i];
+ LOG(INFO) << name_ << StringPrintf(": %8lld ms, ", NsToMs(times_[i] - times_[i-1])) << labels_[i];
}
- LOG(INFO) << name_ << ": end, " << ToMs(times_.back() - times_.front()) << " ms";
+ LOG(INFO) << name_ << ": end, " << NsToMs(times_.back() - times_.front()) << " ms";
}
private:
- static uint64_t ToMs(uint64_t ns) {
- return ns/1000/1000;
- }
-
std::string name_;
std::vector<uint64_t> times_;
std::vector<std::string> labels_;
diff --git a/src/utils.cc b/src/utils.cc
index dbbca28..531424e 100644
--- a/src/utils.cc
+++ b/src/utils.cc
@@ -115,6 +115,10 @@
#endif
}
+uint64_t NsToMs(uint64_t ns) {
+ return ns/1000/1000;
+}
+
std::string PrettyDescriptor(const String* java_descriptor) {
if (java_descriptor == NULL) {
return "null";
diff --git a/src/utils.h b/src/utils.h
index 6a18138..8b22103 100644
--- a/src/utils.h
+++ b/src/utils.h
@@ -224,6 +224,9 @@
// Returns the current time in microseconds (using the POSIX CLOCK_THREAD_CPUTIME_ID).
uint64_t ThreadCpuMicroTime();
+// Converts the given number of nanoseconds to milliseconds.
+uint64_t NsToMs(uint64_t ns);
+
// Splits a string using the given delimiter character into a vector of
// strings. Empty strings will be omitted.
void Split(const std::string& s, char delim, std::vector<std::string>& result);