ART: Make kDebugVerifier a verbose flag
To aid in debugging efforts, finally introduce a verifier-debug
verbose-logging flag that takes over the compile-time kDebugVerifier
flag.
Collecting verification times from a well-known large app during
dex2oat via dump-timings shows a difference in the noise.
Logging of the steps is restricted to failure cases, to avoid
spam.
Test: m
Test: m test-art-host
Test: manual: dex2oat --runtime-arg -verbose:verifier-debug APK with failures
Change-Id: Icb998cc42a531b80f20f986625869505271b7c98
diff --git a/cmdline/cmdline_parser_test.cc b/cmdline/cmdline_parser_test.cc
index 1536339..c438c54 100644
--- a/cmdline/cmdline_parser_test.cc
+++ b/cmdline/cmdline_parser_test.cc
@@ -244,7 +244,7 @@
{
const char* log_args = "-verbose:"
"class,compiler,gc,heap,jdwp,jni,monitor,profiler,signals,simulator,startup,"
- "third-party-jni,threads,verifier";
+ "third-party-jni,threads,verifier,verifier-debug";
LogVerbosity log_verbosity = LogVerbosity();
log_verbosity.class_linker = true;
@@ -261,6 +261,7 @@
log_verbosity.third_party_jni = true;
log_verbosity.threads = true;
log_verbosity.verifier = true;
+ log_verbosity.verifier_debug = true;
EXPECT_SINGLE_PARSE_VALUE(log_verbosity, log_args, M::Verbose);
}
diff --git a/cmdline/cmdline_types.h b/cmdline/cmdline_types.h
index 37bdcdc..f12ef97 100644
--- a/cmdline/cmdline_types.h
+++ b/cmdline/cmdline_types.h
@@ -669,6 +669,8 @@
log_verbosity.threads = true;
} else if (verbose_options[j] == "verifier") {
log_verbosity.verifier = true;
+ } else if (verbose_options[j] == "verifier-debug") {
+ log_verbosity.verifier_debug = true;
} else if (verbose_options[j] == "image") {
log_verbosity.image = true;
} else if (verbose_options[j] == "systrace-locks") {
diff --git a/openjdkjvmti/OpenjdkJvmTi.cc b/openjdkjvmti/OpenjdkJvmTi.cc
index 62f723d..6b2d5d6 100644
--- a/openjdkjvmti/OpenjdkJvmTi.cc
+++ b/openjdkjvmti/OpenjdkJvmTi.cc
@@ -1437,6 +1437,7 @@
art::gLogVerbosity.third_party_jni = val;
art::gLogVerbosity.threads = val;
art::gLogVerbosity.verifier = val;
+ // Do not set verifier-debug.
art::gLogVerbosity.image = val;
// Note: can't switch systrace_lock_logging. That requires changing entrypoints.
diff --git a/runtime/base/logging.h b/runtime/base/logging.h
index 15f9353..5703b3c 100644
--- a/runtime/base/logging.h
+++ b/runtime/base/logging.h
@@ -53,6 +53,7 @@
bool third_party_jni; // Enabled with "-verbose:third-party-jni".
bool threads;
bool verifier;
+ bool verifier_debug; // Only works in debug builds.
bool image;
bool systrace_lock_logging; // Enabled with "-verbose:sys-locks".
bool agents;
diff --git a/runtime/verifier/method_verifier.cc b/runtime/verifier/method_verifier.cc
index fefb4f6..f1af252 100644
--- a/runtime/verifier/method_verifier.cc
+++ b/runtime/verifier/method_verifier.cc
@@ -61,8 +61,6 @@
using android::base::StringPrintf;
static constexpr bool kTimeVerifyMethod = !kIsDebugBuild;
-static constexpr bool kDebugVerify = false;
-// TODO: Add a constant to method_verifier to turn on verbose logging?
// On VLOG(verifier), should we dump the whole state when we run into a hard failure?
static constexpr bool kDumpRegLinesOnHardFailureIfVLOG = true;
@@ -408,6 +406,10 @@
verifier.DumpFailures(VLOG_STREAM(verifier) << "Soft verification failures in "
<< dex_file->PrettyMethod(method_idx) << "\n");
}
+ if (VLOG_IS_ON(verifier_debug)) {
+ std::cout << "\n" << verifier.info_messages_.str();
+ verifier.Dump(std::cout);
+ }
result.kind = FailureKind::kSoftFailure;
if (method != nullptr &&
!CanCompilerHandleVerificationFailure(verifier.encountered_failure_types_)) {
@@ -481,7 +483,7 @@
callbacks->ClassRejected(ref);
}
}
- if (VLOG_IS_ON(verifier)) {
+ if (VLOG_IS_ON(verifier) || VLOG_IS_ON(verifier_debug)) {
std::cout << "\n" << verifier.info_messages_.str();
verifier.Dump(std::cout);
}
@@ -1935,7 +1937,7 @@
GetInstructionFlags(insn_idx).ClearChanged();
}
- if (kDebugVerify) {
+ if (UNLIKELY(VLOG_IS_ON(verifier_debug))) {
/*
* Scan for dead code. There's nothing "evil" about dead code
* (besides the wasted space), but it indicates a flaw somewhere
@@ -2079,7 +2081,7 @@
int32_t branch_target = 0;
bool just_set_result = false;
- if (kDebugVerify) {
+ if (UNLIKELY(VLOG_IS_ON(verifier_debug))) {
// Generate processing back trace to debug verifier
LogVerifyInfo() << "Processing " << inst->DumpString(dex_file_) << "\n"
<< work_line_->Dump(this) << "\n";
@@ -5350,7 +5352,7 @@
}
} else {
RegisterLineArenaUniquePtr copy;
- if (kDebugVerify) {
+ if (UNLIKELY(VLOG_IS_ON(verifier_debug))) {
copy.reset(RegisterLine::Create(target_line->NumRegs(), this));
copy->CopyFromLine(target_line);
}
@@ -5358,7 +5360,7 @@
if (have_pending_hard_failure_) {
return false;
}
- if (kDebugVerify && changed) {
+ if (UNLIKELY(VLOG_IS_ON(verifier_debug)) && changed) {
LogVerifyInfo() << "Merging at [" << reinterpret_cast<void*>(work_insn_idx_) << "]"
<< " to [" << reinterpret_cast<void*>(next_insn) << "]: " << "\n"
<< copy->Dump(this) << " MERGE\n"