OSDN Git Service

ART: Curb lock-verification-failure spam
authorAndreas Gampe <agampe@google.com>
Fri, 5 Feb 2016 04:52:54 +0000 (20:52 -0800)
committerAndreas Gampe <agampe@google.com>
Fri, 5 Feb 2016 23:52:18 +0000 (15:52 -0800)
Just print one message per class. Also print a helpful message once.

Bug: 26951356
Change-Id: I83702b67dc535d86e03835df7a72afda081c83be

runtime/verifier/method_verifier.cc
runtime/verifier/method_verifier.h
runtime/verifier/register_line-inl.h
runtime/verifier/register_line.cc

index 56154c6..c7ac172 100644 (file)
@@ -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 <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 @@ 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<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);
-
-  if (error_count == 0) {
+  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);
+
+  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<mirror::DexCache> 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;
 }
 
index 613d5af..c7d1e6b 100644 (file)
@@ -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 <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 @@ 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<mirror::DexCache> dex_cache,
                                   Handle<mirror::ClassLoader> class_loader,
index 08f85b3..330c06a 100644 (file)
@@ -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);
     }
   }
 }
index 37343b5..b7cde99 100644 (file)
@@ -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;
             }