From 9fcfb8add23042713165f761b4f098e14b9a823b Mon Sep 17 00:00:00 2001 From: Andreas Gampe Date: Thu, 4 Feb 2016 20:52:54 -0800 Subject: [PATCH] ART: Curb lock-verification-failure spam Just print one message per class. Also print a helpful message once. Bug: 26951356 Change-Id: I83702b67dc535d86e03835df7a72afda081c83be --- runtime/verifier/method_verifier.cc | 163 +++++++++++++++++++++-------------- runtime/verifier/method_verifier.h | 39 +++++---- runtime/verifier/register_line-inl.h | 6 +- runtime/verifier/register_line.cc | 50 +++++------ 4 files changed, 148 insertions(+), 110 deletions(-) diff --git a/runtime/verifier/method_verifier.cc b/runtime/verifier/method_verifier.cc index 56154c63a..c7ac17282 100644 --- a/runtime/verifier/method_verifier.cc +++ b/runtime/verifier/method_verifier.cc @@ -58,6 +58,10 @@ static constexpr bool kDebugVerify = false; // 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 @@ static bool HasNextMethod(ClassDataItemIterator* it) { 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 -void MethodVerifier::VerifyMethods(Thread* self, - ClassLinker* linker, - const DexFile* dex_file, - const DexFile::ClassDef* class_def, - ClassDataItemIterator* it, - Handle dex_cache, - Handle 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 dex_cache, + Handle 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(it)) { self->AllowThreadSuspension(); @@ -206,7 +225,7 @@ void MethodVerifier::VerifyMethods(Thread* self, } 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 @@ void MethodVerifier::VerifyMethods(Thread* self, 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 @@ MethodVerifier::FailureKind MethodVerifier::VerifyClass(Thread* self, while (it.HasNextStaticField() || it.HasNextInstanceField()) { it.Next(); } - size_t error_count = 0; - bool hard_fail = false; ClassLinker* linker = Runtime::Current()->GetClassLinker(); // Direct methods. - VerifyMethods(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(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(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); - - if (error_count == 0) { + MethodVerifier::FailureData data2 = VerifyMethods(self, + linker, + dex_file, + class_def, + &it, + dex_cache, + class_loader, + callbacks, + allow_soft_failures, + log_hard_failures, + false /* need precise constants */, + error); + + 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 @@ static bool IsLargeMethod(const DexFile::CodeItem* const code_item) { 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 dex_cache, @@ -334,7 +362,7 @@ MethodVerifier::FailureKind MethodVerifier::VerifyMethod(Thread* self, 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 @@ MethodVerifier::FailureKind MethodVerifier::VerifyMethod(Thread* self, 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 @@ MethodVerifier::FailureKind MethodVerifier::VerifyMethod(Thread* self, 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 @@ MethodVerifier::FailureKind MethodVerifier::VerifyMethod(Thread* self, *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 @@ MethodVerifier::FailureKind MethodVerifier::VerifyMethod(Thread* self, << (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 613d5af21..c7d1e6bc9 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 @@ class MethodVerifier { // 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 - static void VerifyMethods(Thread* self, - ClassLinker* linker, - const DexFile* dex_file, - const DexFile::ClassDef* class_def, - ClassDataItemIterator* it, - Handle dex_cache, - Handle 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 dex_cache, + Handle 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 @@ class MethodVerifier { * (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 dex_cache, Handle class_loader, diff --git a/runtime/verifier/register_line-inl.h b/runtime/verifier/register_line-inl.h index 08f85b35f..330c06ab4 100644 --- a/runtime/verifier/register_line-inl.h +++ b/runtime/verifier/register_line-inl.h @@ -178,9 +178,9 @@ inline void RegisterLine::VerifyMonitorStackEmpty(MethodVerifier* verifier) cons 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 37343b5ec..b7cde995c 100644 --- a/runtime/verifier/register_line.cc +++ b/runtime/verifier/register_line.cc @@ -348,9 +348,9 @@ void RegisterLine::PushMonitor(MethodVerifier* verifier, uint32_t reg_idx, int32 } 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 @@ void RegisterLine::PushMonitor(MethodVerifier* verifier, uint32_t reg_idx, int32 } 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 @@ void RegisterLine::PopMonitor(MethodVerifier* verifier, uint32_t reg_idx) { } 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 @@ void RegisterLine::PopMonitor(MethodVerifier* verifier, uint32_t reg_idx) { 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 @@ bool RegisterLine::MergeRegisters(MethodVerifier* verifier, const RegisterLine* 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 @@ bool RegisterLine::MergeRegisters(MethodVerifier* verifier, const RegisterLine* 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 @@ bool RegisterLine::MergeRegisters(MethodVerifier* verifier, const RegisterLine* // 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; } -- 2.11.0