More verbose logs for JDWP events

Logs more information about the JDWP event being reported with VLOG(jdwp). This
helps mainly when debugging JDWP with -verbose:jdwp option.

Change-Id: I49495bdab03dbcbdc0b6c00a8df718bfedbad91d

1 files changed, 100 insertions, 73 deletions

diff --git a/runtime/jdwp/jdwp_event.cc b/runtime/jdwp/jdwp_event.cc
index cb2c420dbb..86c84e8b0f 100644
--- a/runtime/jdwp/jdwp_event.cc
+++ b/runtime/jdwp/jdwp_event.cc
@@ -397,7 +397,7 @@ static JdwpEvent** AllocMatchList(size_t event_count) {
  * Run through the list and remove any entries with an expired "count" mod
  * from the event list, then free the match list.
  */
-void JdwpState::CleanupMatchList(JdwpEvent** match_list, int match_count) {
+void JdwpState::CleanupMatchList(JdwpEvent** match_list, size_t match_count) {
   JdwpEvent** ppEvent = match_list;
 
   while (match_count--) {
@@ -405,7 +405,8 @@ void JdwpState::CleanupMatchList(JdwpEvent** match_list, int match_count) {
 
     for (int i = 0; i < pEvent->modCount; i++) {
       if (pEvent->mods[i].modKind == MK_COUNT && pEvent->mods[i].count.count == 0) {
-        VLOG(jdwp) << "##### Removing expired event";
+        VLOG(jdwp) << StringPrintf("##### Removing expired event (requestId=%#" PRIx32 ")",
+                                   pEvent->requestId);
         UnregisterEvent(pEvent);
         EventFree(pEvent);
         break;
@@ -445,7 +446,7 @@ static bool PatternMatch(const char* pattern, const std::string& target) {
  * If we find a Count mod before rejecting an event, we decrement it.  We
  * need to do this even if later mods cause us to ignore the event.
  */
-static bool ModsMatch(JdwpEvent* pEvent, ModBasket* basket)
+static bool ModsMatch(JdwpEvent* pEvent, const ModBasket& basket)
     SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
   JdwpEventMod* pMod = pEvent->mods;
 
@@ -462,53 +463,53 @@ static bool ModsMatch(JdwpEvent* pEvent, ModBasket* basket)
       CHECK(false);  // should not be getting these
       break;
     case MK_THREAD_ONLY:
-      if (pMod->threadOnly.threadId != basket->threadId) {
+      if (pMod->threadOnly.threadId != basket.threadId) {
         return false;
       }
       break;
     case MK_CLASS_ONLY:
-      if (!Dbg::MatchType(basket->classId, pMod->classOnly.refTypeId)) {
+      if (!Dbg::MatchType(basket.classId, pMod->classOnly.refTypeId)) {
         return false;
       }
       break;
     case MK_CLASS_MATCH:
-      if (!PatternMatch(pMod->classMatch.classPattern, basket->className)) {
+      if (!PatternMatch(pMod->classMatch.classPattern, basket.className)) {
         return false;
       }
       break;
     case MK_CLASS_EXCLUDE:
-      if (PatternMatch(pMod->classMatch.classPattern, basket->className)) {
+      if (PatternMatch(pMod->classMatch.classPattern, basket.className)) {
         return false;
       }
       break;
     case MK_LOCATION_ONLY:
-      if (pMod->locationOnly.loc != *basket->pLoc) {
+      if (pMod->locationOnly.loc != *basket.pLoc) {
         return false;
       }
       break;
     case MK_EXCEPTION_ONLY:
-      if (pMod->exceptionOnly.refTypeId != 0 && !Dbg::MatchType(basket->excepClassId, pMod->exceptionOnly.refTypeId)) {
+      if (pMod->exceptionOnly.refTypeId != 0 && !Dbg::MatchType(basket.excepClassId, pMod->exceptionOnly.refTypeId)) {
         return false;
       }
-      if ((basket->caught && !pMod->exceptionOnly.caught) || (!basket->caught && !pMod->exceptionOnly.uncaught)) {
+      if ((basket.caught && !pMod->exceptionOnly.caught) || (!basket.caught && !pMod->exceptionOnly.uncaught)) {
         return false;
       }
       break;
     case MK_FIELD_ONLY:
-      if (pMod->fieldOnly.fieldId != basket->fieldId) {
+      if (pMod->fieldOnly.fieldId != basket.fieldId) {
         return false;
       }
-      if (!Dbg::MatchType(basket->fieldTypeID, pMod->fieldOnly.refTypeId)) {
+      if (!Dbg::MatchType(basket.fieldTypeID, pMod->fieldOnly.refTypeId)) {
         return false;
       }
       break;
     case MK_STEP:
-      if (pMod->step.threadId != basket->threadId) {
+      if (pMod->step.threadId != basket.threadId) {
         return false;
       }
       break;
     case MK_INSTANCE_ONLY:
-      if (pMod->instanceOnly.objectId != basket->thisPtr) {
+      if (pMod->instanceOnly.objectId != basket.thisPtr) {
         return false;
       }
       break;
@@ -530,19 +531,16 @@ static bool ModsMatch(JdwpEvent* pEvent, ModBasket* basket)
  * DO NOT call this multiple times for the same eventKind, as Count mods are
  * decremented during the scan.
  */
-void JdwpState::FindMatchingEvents(JdwpEventKind eventKind, ModBasket* basket,
-                                   JdwpEvent** match_list, int* pMatchCount) {
+void JdwpState::FindMatchingEvents(JdwpEventKind eventKind, const ModBasket& basket,
+                                   JdwpEvent** match_list, size_t* pMatchCount) {
   /* start after the existing entries */
   match_list += *pMatchCount;
 
-  JdwpEvent* pEvent = event_list_;
-  while (pEvent != NULL) {
+  for (JdwpEvent* pEvent = event_list_; pEvent != nullptr; pEvent = pEvent->next) {
     if (pEvent->eventKind == eventKind && ModsMatch(pEvent, basket)) {
       *match_list++ = pEvent;
       (*pMatchCount)++;
     }
-
-    pEvent = pEvent->next;
   }
 }
 
@@ -774,6 +772,22 @@ bool JdwpState::PostVMStart() {
   return true;
 }
 
+static void LogMatchingEventsAndThread(JdwpEvent** match_list, size_t match_count,
+                                       const ModBasket& basket)
+    SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
+  for (size_t i = 0; i < match_count; ++i) {
+    JdwpEvent* pEvent = match_list[i];
+    VLOG(jdwp) << "EVENT #" << i << ": " << pEvent->eventKind
+               << StringPrintf(" (requestId=%#" PRIx32 ")", pEvent->requestId);
+  }
+  std::string thread_name;
+  JdwpError error = Dbg::GetThreadName(basket.threadId, thread_name);
+  if (error != JDWP::ERR_NONE) {
+    thread_name = "<unknown>";
+  }
+  VLOG(jdwp) << StringPrintf("  thread=%#" PRIx64, basket.threadId) << " " << thread_name;
+}
+
 /*
  * A location of interest has been reached.  This handles:
  *   Breakpoint
@@ -829,39 +843,40 @@ bool JdwpState::PostLocationEvent(const JdwpLocation* pLoc, ObjectId thisPtr, in
     return false;
   }
 
-  int match_count = 0;
+  size_t match_count = 0;
   ExpandBuf* pReq = NULL;
   JdwpSuspendPolicy suspend_policy = SP_NONE;
   {
     MutexLock mu(Thread::Current(), event_list_lock_);
     JdwpEvent** match_list = AllocMatchList(event_list_size_);
     if ((eventFlags & Dbg::kBreakpoint) != 0) {
-      FindMatchingEvents(EK_BREAKPOINT, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_BREAKPOINT, basket, match_list, &match_count);
     }
     if ((eventFlags & Dbg::kSingleStep) != 0) {
-      FindMatchingEvents(EK_SINGLE_STEP, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_SINGLE_STEP, basket, match_list, &match_count);
     }
     if ((eventFlags & Dbg::kMethodEntry) != 0) {
-      FindMatchingEvents(EK_METHOD_ENTRY, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_METHOD_ENTRY, basket, match_list, &match_count);
     }
     if ((eventFlags & Dbg::kMethodExit) != 0) {
-      FindMatchingEvents(EK_METHOD_EXIT, &basket, match_list, &match_count);
-      FindMatchingEvents(EK_METHOD_EXIT_WITH_RETURN_VALUE, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_METHOD_EXIT, basket, match_list, &match_count);
+      FindMatchingEvents(EK_METHOD_EXIT_WITH_RETURN_VALUE, basket, match_list, &match_count);
     }
     if (match_count != 0) {
-      VLOG(jdwp) << "EVENT: " << match_list[0]->eventKind << "(" << match_count << " total) "
-                 << basket.className << "." << Dbg::GetMethodName(pLoc->method_id)
-                 << StringPrintf(" thread=%#" PRIx64 "  dex_pc=%#" PRIx64 ")",
-                                 basket.threadId, pLoc->dex_pc);
-
       suspend_policy = scanSuspendPolicy(match_list, match_count);
-      VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+
+      if (VLOG_IS_ON(jdwp)) {
+        LogMatchingEventsAndThread(match_list, match_count, basket);
+        VLOG(jdwp) << "  location=" << *pLoc;
+        VLOG(jdwp) << StringPrintf("  this=%#" PRIx64, basket.thisPtr);
+        VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+      }
 
       pReq = eventPrep();
       expandBufAdd1(pReq, suspend_policy);
       expandBufAdd4BE(pReq, match_count);
 
-      for (int i = 0; i < match_count; i++) {
+      for (size_t i = 0; i < match_count; i++) {
         expandBufAdd1(pReq, match_list[i]->eventKind);
         expandBufAdd4BE(pReq, match_list[i]->requestId);
         expandBufAdd8BE(pReq, basket.threadId);
@@ -892,6 +907,8 @@ bool JdwpState::PostFieldEvent(const JdwpLocation* pLoc, RefTypeId typeId, Field
   basket.fieldTypeID = typeId;
   basket.fieldId = fieldId;
 
+  DCHECK_EQ(fieldValue != nullptr, is_modification);
+
   if (InvokeInProgress()) {
     VLOG(jdwp) << "Not posting field event during invoke";
     return false;
@@ -912,7 +929,7 @@ bool JdwpState::PostFieldEvent(const JdwpLocation* pLoc, RefTypeId typeId, Field
     return false;
   }
 
-  int match_count = 0;
+  size_t match_count = 0;
   ExpandBuf* pReq = NULL;
   JdwpSuspendPolicy suspend_policy = SP_NONE;
   {
@@ -920,24 +937,29 @@ bool JdwpState::PostFieldEvent(const JdwpLocation* pLoc, RefTypeId typeId, Field
     JdwpEvent** match_list = AllocMatchList(event_list_size_);
 
     if (is_modification) {
-      FindMatchingEvents(EK_FIELD_MODIFICATION, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_FIELD_MODIFICATION, basket, match_list, &match_count);
     } else {
-      FindMatchingEvents(EK_FIELD_ACCESS, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_FIELD_ACCESS, basket, match_list, &match_count);
     }
     if (match_count != 0) {
-      VLOG(jdwp) << "EVENT: " << match_list[0]->eventKind << "(" << match_count << " total) "
-                 << basket.className << "." << Dbg::GetMethodName(pLoc->method_id)
-                 << StringPrintf(" thread=%#" PRIx64 "  dex_pc=%#" PRIx64 ")",
-                                 basket.threadId, pLoc->dex_pc);
-
       suspend_policy = scanSuspendPolicy(match_list, match_count);
-      VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+
+      if (VLOG_IS_ON(jdwp)) {
+        LogMatchingEventsAndThread(match_list, match_count, basket);
+        VLOG(jdwp) << "  location=" << *pLoc;
+        VLOG(jdwp) << StringPrintf("  this=%#" PRIx64, basket.thisPtr);
+        VLOG(jdwp) << StringPrintf("  type=%#" PRIx64, basket.fieldTypeID) << " "
+                   << Dbg::GetClassName(basket.fieldTypeID);
+        VLOG(jdwp) << StringPrintf("  field=%#" PRIx32, basket.fieldId) << " "
+                   << Dbg::GetFieldName(basket.fieldId);
+        VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+      }
 
       pReq = eventPrep();
       expandBufAdd1(pReq, suspend_policy);
       expandBufAdd4BE(pReq, match_count);
 
-      for (int i = 0; i < match_count; i++) {
+      for (size_t i = 0; i < match_count; i++) {
         expandBufAdd1(pReq, match_list[i]->eventKind);
         expandBufAdd4BE(pReq, match_list[i]->requestId);
         expandBufAdd8BE(pReq, basket.threadId);
@@ -984,30 +1006,31 @@ bool JdwpState::PostThreadChange(ObjectId threadId, bool start) {
 
   ExpandBuf* pReq = NULL;
   JdwpSuspendPolicy suspend_policy = SP_NONE;
-  int match_count = 0;
+  size_t match_count = 0;
   {
     // Don't allow the list to be updated while we scan it.
     MutexLock mu(Thread::Current(), event_list_lock_);
     JdwpEvent** match_list = AllocMatchList(event_list_size_);
 
     if (start) {
-      FindMatchingEvents(EK_THREAD_START, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_THREAD_START, basket, match_list, &match_count);
     } else {
-      FindMatchingEvents(EK_THREAD_DEATH, &basket, match_list, &match_count);
+      FindMatchingEvents(EK_THREAD_DEATH, basket, match_list, &match_count);
     }
 
     if (match_count != 0) {
-      VLOG(jdwp) << "EVENT: " << match_list[0]->eventKind << "(" << match_count << " total) "
-                 << StringPrintf("thread=%#" PRIx64, basket.threadId) << ")";
-
       suspend_policy = scanSuspendPolicy(match_list, match_count);
-      VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+
+      if (VLOG_IS_ON(jdwp)) {
+        LogMatchingEventsAndThread(match_list, match_count, basket);
+        VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+      }
 
       pReq = eventPrep();
       expandBufAdd1(pReq, suspend_policy);
       expandBufAdd4BE(pReq, match_count);
 
-      for (int i = 0; i < match_count; i++) {
+      for (size_t i = 0; i < match_count; i++) {
         expandBufAdd1(pReq, match_list[i]->eventKind);
         expandBufAdd4BE(pReq, match_list[i]->requestId);
         expandBufAdd8BE(pReq, basket.threadId);
@@ -1072,33 +1095,35 @@ bool JdwpState::PostException(const JdwpLocation* pThrowLoc,
     return false;
   }
 
-  int match_count = 0;
+  size_t match_count = 0;
   ExpandBuf* pReq = NULL;
   JdwpSuspendPolicy suspend_policy = SP_NONE;
   {
     MutexLock mu(Thread::Current(), event_list_lock_);
     JdwpEvent** match_list = AllocMatchList(event_list_size_);
-    FindMatchingEvents(EK_EXCEPTION, &basket, match_list, &match_count);
+    FindMatchingEvents(EK_EXCEPTION, basket, match_list, &match_count);
     if (match_count != 0) {
-      VLOG(jdwp) << "EVENT: " << match_list[0]->eventKind << "(" << match_count << " total)"
-                 << StringPrintf(" thread=%#" PRIx64, basket.threadId)
-                 << StringPrintf(" exceptId=%#" PRIx64, exceptionId)
-                 << " caught=" << basket.caught << ")"
-                 << "  throw: " << *pThrowLoc;
-      if (pCatchLoc->class_id == 0) {
-        VLOG(jdwp) << "  catch: (not caught)";
-      } else {
-        VLOG(jdwp) << "  catch: " << *pCatchLoc;
-      }
-
       suspend_policy = scanSuspendPolicy(match_list, match_count);
-      VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+
+      if (VLOG_IS_ON(jdwp)) {
+        LogMatchingEventsAndThread(match_list, match_count, basket);
+        VLOG(jdwp) << "  throwLocation=" << *pThrowLoc;
+        if (pCatchLoc->class_id == 0) {
+          VLOG(jdwp) << "  catchLocation=uncaught";
+        } else {
+          VLOG(jdwp) << "  catchLocation=" << *pCatchLoc;
+        }
+        VLOG(jdwp) << StringPrintf("  this=%#" PRIx64, basket.thisPtr);
+        VLOG(jdwp) << StringPrintf("  exceptionClass=%#" PRIx64, basket.excepClassId) << " "
+                   << Dbg::GetClassName(basket.excepClassId);
+        VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+      }
 
       pReq = eventPrep();
       expandBufAdd1(pReq, suspend_policy);
       expandBufAdd4BE(pReq, match_count);
 
-      for (int i = 0; i < match_count; i++) {
+      for (size_t i = 0; i < match_count; i++) {
         expandBufAdd1(pReq, match_list[i]->eventKind);
         expandBufAdd4BE(pReq, match_list[i]->requestId);
         expandBufAdd8BE(pReq, basket.threadId);
@@ -1142,17 +1167,19 @@ bool JdwpState::PostClassPrepare(JdwpTypeTag tag, RefTypeId refTypeId, const std
 
   ExpandBuf* pReq = NULL;
   JdwpSuspendPolicy suspend_policy = SP_NONE;
-  int match_count = 0;
+  size_t match_count = 0;
   {
     MutexLock mu(Thread::Current(), event_list_lock_);
     JdwpEvent** match_list = AllocMatchList(event_list_size_);
-    FindMatchingEvents(EK_CLASS_PREPARE, &basket, match_list, &match_count);
+    FindMatchingEvents(EK_CLASS_PREPARE, basket, match_list, &match_count);
     if (match_count != 0) {
-      VLOG(jdwp) << "EVENT: " << match_list[0]->eventKind << "(" << match_count << " total) "
-                 << StringPrintf("thread=%#" PRIx64, basket.threadId) << ") " << signature;
-
       suspend_policy = scanSuspendPolicy(match_list, match_count);
-      VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+
+      if (VLOG_IS_ON(jdwp)) {
+        LogMatchingEventsAndThread(match_list, match_count, basket);
+        VLOG(jdwp) << StringPrintf("  type=%#" PRIx64, basket.classId)<< " " << signature;
+        VLOG(jdwp) << "  suspend_policy=" << suspend_policy;
+      }
 
       if (basket.threadId == debug_thread_id_) {
         /*
@@ -1171,7 +1198,7 @@ bool JdwpState::PostClassPrepare(JdwpTypeTag tag, RefTypeId refTypeId, const std
       expandBufAdd1(pReq, suspend_policy);
       expandBufAdd4BE(pReq, match_count);
 
-      for (int i = 0; i < match_count; i++) {
+      for (size_t i = 0; i < match_count; i++) {
         expandBufAdd1(pReq, match_list[i]->eventKind);
         expandBufAdd4BE(pReq, match_list[i]->requestId);
         expandBufAdd8BE(pReq, basket.threadId);