ART: Curb lock-verification-failure spam
Just print one message per class. Also print a helpful message once.
Bug: 26951356
Change-Id: I83702b67dc535d86e03835df7a72afda081c83be
diff --git a/runtime/verifier/method_verifier.cc b/runtime/verifier/method_verifier.cc
index 56154c6..c7ac172 100644
--- a/runtime/verifier/method_verifier.cc
+++ b/runtime/verifier/method_verifier.cc
@@ -58,6 +58,10 @@
// On VLOG(verifier), should we dump the whole state when we run into a hard failure?
static constexpr bool kDumpRegLinesOnHardFailureIfVLOG = true;
+// We print a warning blurb about "dx --no-optimize" when we find monitor-locking issues. Make
+// sure we only print this once.
+static bool gPrintedDxMonitorText = false;
+
PcToRegisterLineTable::PcToRegisterLineTable(ScopedArenaAllocator& arena)
: register_lines_(arena.Adapter(kArenaAllocVerifier)) {}
@@ -166,23 +170,38 @@
return kDirect ? it->HasNextDirectMethod() : it->HasNextVirtualMethod();
}
+static MethodVerifier::FailureKind FailureKindMax(MethodVerifier::FailureKind fk1,
+ MethodVerifier::FailureKind fk2) {
+ static_assert(MethodVerifier::FailureKind::kNoFailure <
+ MethodVerifier::FailureKind::kSoftFailure
+ && MethodVerifier::FailureKind::kSoftFailure <
+ MethodVerifier::FailureKind::kHardFailure,
+ "Unexpected FailureKind order");
+ return std::max(fk1, fk2);
+}
+
+void MethodVerifier::FailureData::Merge(const MethodVerifier::FailureData& fd) {
+ kind = FailureKindMax(kind, fd.kind);
+ types |= fd.types;
+}
+
template <bool kDirect>
-void MethodVerifier::VerifyMethods(Thread* self,
- ClassLinker* linker,
- const DexFile* dex_file,
- const DexFile::ClassDef* class_def,
- ClassDataItemIterator* it,
- Handle<mirror::DexCache> dex_cache,
- Handle<mirror::ClassLoader> class_loader,
- CompilerCallbacks* callbacks,
- bool allow_soft_failures,
- bool log_hard_failures,
- bool need_precise_constants,
- bool* hard_fail,
- size_t* error_count,
- std::string* error_string) {
+MethodVerifier::FailureData MethodVerifier::VerifyMethods(Thread* self,
+ ClassLinker* linker,
+ const DexFile* dex_file,
+ const DexFile::ClassDef* class_def,
+ ClassDataItemIterator* it,
+ Handle<mirror::DexCache> dex_cache,
+ Handle<mirror::ClassLoader> class_loader,
+ CompilerCallbacks* callbacks,
+ bool allow_soft_failures,
+ bool log_hard_failures,
+ bool need_precise_constants,
+ std::string* error_string) {
DCHECK(it != nullptr);
+ MethodVerifier::FailureData failure_data;
+
int64_t previous_method_idx = -1;
while (HasNextMethod<kDirect>(it)) {
self->AllowThreadSuspension();
@@ -206,7 +225,7 @@
}
StackHandleScope<1> hs(self);
std::string hard_failure_msg;
- MethodVerifier::FailureKind result = VerifyMethod(self,
+ MethodVerifier::FailureData result = VerifyMethod(self,
method_idx,
dex_file,
dex_cache,
@@ -220,24 +239,24 @@
log_hard_failures,
need_precise_constants,
&hard_failure_msg);
- if (result != kNoFailure) {
- if (result == kHardFailure) {
- if (*error_count > 0) {
- *error_string += "\n";
- }
- if (!*hard_fail) {
- *error_string += "Verifier rejected class ";
- *error_string += PrettyDescriptor(dex_file->GetClassDescriptor(*class_def));
- *error_string += ":";
- }
- *error_string += " ";
- *error_string += hard_failure_msg;
- *hard_fail = true;
+ if (result.kind == kHardFailure) {
+ if (failure_data.kind == kHardFailure) {
+ // If we logged an error before, we need a newline.
+ *error_string += "\n";
+ } else {
+ // If we didn't log a hard failure before, print the header of the message.
+ *error_string += "Verifier rejected class ";
+ *error_string += PrettyDescriptor(dex_file->GetClassDescriptor(*class_def));
+ *error_string += ":";
}
- *error_count = *error_count + 1;
+ *error_string += " ";
+ *error_string += hard_failure_msg;
}
+ failure_data.Merge(result);
it->Next();
}
+
+ return failure_data;
}
MethodVerifier::FailureKind MethodVerifier::VerifyClass(Thread* self,
@@ -268,44 +287,53 @@
while (it.HasNextStaticField() || it.HasNextInstanceField()) {
it.Next();
}
- size_t error_count = 0;
- bool hard_fail = false;
ClassLinker* linker = Runtime::Current()->GetClassLinker();
// Direct methods.
- VerifyMethods<true>(self,
- linker,
- dex_file,
- class_def,
- &it,
- dex_cache,
- class_loader,
- callbacks,
- allow_soft_failures,
- log_hard_failures,
- false /* need precise constants */,
- &hard_fail,
- &error_count,
- error);
+ MethodVerifier::FailureData data1 = VerifyMethods<true>(self,
+ linker,
+ dex_file,
+ class_def,
+ &it,
+ dex_cache,
+ class_loader,
+ callbacks,
+ allow_soft_failures,
+ log_hard_failures,
+ false /* need precise constants */,
+ error);
// Virtual methods.
- VerifyMethods<false>(self,
- linker,
- dex_file,
- class_def,
- &it,
- dex_cache,
- class_loader,
- callbacks,
- allow_soft_failures,
- log_hard_failures,
- false /* need precise constants */,
- &hard_fail,
- &error_count,
- error);
+ MethodVerifier::FailureData data2 = VerifyMethods<false>(self,
+ linker,
+ dex_file,
+ class_def,
+ &it,
+ dex_cache,
+ class_loader,
+ callbacks,
+ allow_soft_failures,
+ log_hard_failures,
+ false /* need precise constants */,
+ error);
- if (error_count == 0) {
+ data1.Merge(data2);
+
+ if (data1.kind == kNoFailure) {
return kNoFailure;
} else {
- return hard_fail ? kHardFailure : kSoftFailure;
+ if ((data1.types & VERIFY_ERROR_LOCKING) != 0) {
+ // Print a warning about expected slow-down. Use a string temporary to print one contiguous
+ // warning.
+ std::string tmp =
+ StringPrintf("Class %s failed lock verification and will run slower.",
+ PrettyDescriptor(dex_file->GetClassDescriptor(*class_def)).c_str());
+ if (!gPrintedDxMonitorText) {
+ tmp = tmp + "\nCommon causes for lock verification issues are non-optimized dex code\n"
+ "and incorrect proguard optimizations.";
+ gPrintedDxMonitorText = true;
+ }
+ LOG(WARNING) << tmp;
+ }
+ return data1.kind;
}
}
@@ -320,7 +348,7 @@
return registers_size * insns_size > 4*1024*1024;
}
-MethodVerifier::FailureKind MethodVerifier::VerifyMethod(Thread* self,
+MethodVerifier::FailureData MethodVerifier::VerifyMethod(Thread* self,
uint32_t method_idx,
const DexFile* dex_file,
Handle<mirror::DexCache> dex_cache,
@@ -334,7 +362,7 @@
bool log_hard_failures,
bool need_precise_constants,
std::string* hard_failure_msg) {
- MethodVerifier::FailureKind result = kNoFailure;
+ MethodVerifier::FailureData result;
uint64_t start_ns = kTimeVerifyMethod ? NanoTime() : 0;
MethodVerifier verifier(self, dex_file, dex_cache, class_loader, class_def, code_item,
@@ -355,7 +383,7 @@
verifier.DumpFailures(VLOG_STREAM(verifier) << "Soft verification failures in "
<< PrettyMethod(method_idx, *dex_file) << "\n");
}
- result = kSoftFailure;
+ result.kind = kSoftFailure;
}
} else {
// Bad method data.
@@ -364,7 +392,7 @@
if (UNLIKELY(verifier.have_pending_experimental_failure_)) {
// Failed due to being forced into interpreter. This is ok because
// we just want to skip verification.
- result = kSoftFailure;
+ result.kind = kSoftFailure;
} else {
CHECK(verifier.have_pending_hard_failure_);
if (VLOG_IS_ON(verifier) || log_hard_failures) {
@@ -376,7 +404,7 @@
*hard_failure_msg =
verifier.failure_messages_[verifier.failure_messages_.size() - 1]->str();
}
- result = kHardFailure;
+ result.kind = kHardFailure;
if (callbacks != nullptr) {
// Let the interested party know that we failed the class.
@@ -397,6 +425,7 @@
<< (IsLargeMethod(code_item) ? " (large method)" : "");
}
}
+ result.types = verifier.encountered_failure_types_;
return result;
}
diff --git a/runtime/verifier/method_verifier.h b/runtime/verifier/method_verifier.h
index 613d5af..c7d1e6b 100644
--- a/runtime/verifier/method_verifier.h
+++ b/runtime/verifier/method_verifier.h
@@ -25,6 +25,7 @@
#include "base/macros.h"
#include "base/scoped_arena_containers.h"
#include "base/stl_util.h"
+#include "base/value_object.h"
#include "dex_file.h"
#include "handle.h"
#include "instruction_flags.h"
@@ -344,23 +345,31 @@
// Adds the given string to the end of the last failure message.
void AppendToLastFailMessage(std::string);
+ // Verification result for method(s). Includes a (maximum) failure kind, and (the union of)
+ // all failure types.
+ struct FailureData : ValueObject {
+ FailureKind kind = kNoFailure;
+ uint32_t types = 0U;
+
+ // Merge src into this. Uses the most severe failure kind, and the union of types.
+ void Merge(const FailureData& src);
+ };
+
// Verify all direct or virtual methods of a class. The method assumes that the iterator is
// positioned correctly, and the iterator will be updated.
template <bool kDirect>
- static void VerifyMethods(Thread* self,
- ClassLinker* linker,
- const DexFile* dex_file,
- const DexFile::ClassDef* class_def,
- ClassDataItemIterator* it,
- Handle<mirror::DexCache> dex_cache,
- Handle<mirror::ClassLoader> class_loader,
- CompilerCallbacks* callbacks,
- bool allow_soft_failures,
- bool log_hard_failures,
- bool need_precise_constants,
- bool* hard_fail,
- size_t* error_count,
- std::string* error_string)
+ static FailureData VerifyMethods(Thread* self,
+ ClassLinker* linker,
+ const DexFile* dex_file,
+ const DexFile::ClassDef* class_def,
+ ClassDataItemIterator* it,
+ Handle<mirror::DexCache> dex_cache,
+ Handle<mirror::ClassLoader> class_loader,
+ CompilerCallbacks* callbacks,
+ bool allow_soft_failures,
+ bool log_hard_failures,
+ bool need_precise_constants,
+ std::string* error_string)
SHARED_REQUIRES(Locks::mutator_lock_);
/*
@@ -374,7 +383,7 @@
* (3) Iterate through the method, checking type safety and looking
* for code flow problems.
*/
- static FailureKind VerifyMethod(Thread* self, uint32_t method_idx,
+ static FailureData VerifyMethod(Thread* self, uint32_t method_idx,
const DexFile* dex_file,
Handle<mirror::DexCache> dex_cache,
Handle<mirror::ClassLoader> class_loader,
diff --git a/runtime/verifier/register_line-inl.h b/runtime/verifier/register_line-inl.h
index 08f85b3..330c06a 100644
--- a/runtime/verifier/register_line-inl.h
+++ b/runtime/verifier/register_line-inl.h
@@ -178,9 +178,9 @@
if (MonitorStackDepth() != 0) {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "expected empty monitor stack in "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "expected empty monitor stack in "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
}
}
diff --git a/runtime/verifier/register_line.cc b/runtime/verifier/register_line.cc
index 37343b5..b7cde99 100644
--- a/runtime/verifier/register_line.cc
+++ b/runtime/verifier/register_line.cc
@@ -348,9 +348,9 @@
} else if (monitors_.size() >= 32) {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "monitor-enter stack overflow while verifying "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "monitor-enter stack overflow while verifying "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
} else {
if (SetRegToLockDepth(reg_idx, monitors_.size())) {
@@ -364,9 +364,9 @@
} else {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "unexpected monitor-enter on register v" << reg_idx << " in "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "unexpected monitor-enter on register v" << reg_idx << " in "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
}
}
@@ -379,9 +379,9 @@
} else if (monitors_.empty()) {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "monitor-exit stack underflow while verifying "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "monitor-exit stack underflow while verifying "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
} else {
monitors_.pop_back();
@@ -400,9 +400,9 @@
if (!success) {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "monitor-exit not unlocking the top of the monitor stack while verifying "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "monitor-exit not unlocking the top of the monitor stack while verifying "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
} else {
// Record the register was unlocked. This clears all aliases, thus it will also clear the
@@ -453,10 +453,10 @@
if (monitors_.size() != incoming_line->monitors_.size()) {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "mismatched stack depths (depth=" << MonitorStackDepth()
- << ", incoming depth=" << incoming_line->MonitorStackDepth() << ") in "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "mismatched stack depths (depth=" << MonitorStackDepth()
+ << ", incoming depth=" << incoming_line->MonitorStackDepth() << ") in "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
} else if (reg_to_lock_depths_ != incoming_line->reg_to_lock_depths_) {
for (uint32_t idx = 0; idx < num_regs_; idx++) {
@@ -488,10 +488,10 @@
reg_to_lock_depths_)) {
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "mismatched stack depths for register v" << idx
- << ": " << depths << " != " << incoming_depths << " in "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "mismatched stack depths for register v" << idx
+ << ": " << depths << " != " << incoming_depths << " in "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
break;
}
@@ -530,11 +530,11 @@
// No aliases for both current and incoming, we'll lose information.
verifier->Fail(VERIFY_ERROR_LOCKING);
if (kDumpLockFailures) {
- LOG(WARNING) << "mismatched lock levels for register v" << idx << ": "
- << std::hex << locked_levels << std::dec << " != "
- << std::hex << incoming_locked_levels << std::dec << " in "
- << PrettyMethod(verifier->GetMethodReference().dex_method_index,
- *verifier->GetMethodReference().dex_file);
+ VLOG(verifier) << "mismatched lock levels for register v" << idx << ": "
+ << std::hex << locked_levels << std::dec << " != "
+ << std::hex << incoming_locked_levels << std::dec << " in "
+ << PrettyMethod(verifier->GetMethodReference().dex_method_index,
+ *verifier->GetMethodReference().dex_file);
}
break;
}