Better -verbose:thread logging, and revert a CHECK.

Go back to the old scheme where we'd just refuse to take a suspend count
negative. (Like dalvik.)

Change-Id: I4d37189dff1ffc035a9b5d65d97710ef65ead2d3

2 files changed, 62 insertions, 31 deletions

diff --git a/src/thread.cc b/src/thread.cc
index ba81268..6fdeefd 100644
--- a/src/thread.cc
+++ b/src/thread.cc
@@ -158,15 +158,18 @@ void* Thread::CreateCallback(void* arg) {
 
   self->Attach(runtime);
 
-  String* thread_name = reinterpret_cast<String*>(gThread_name->GetObject(self->peer_));
-  if (thread_name != NULL) {
-    SetThreadName(thread_name->ToModifiedUtf8().c_str());
-  }
-
   // Wait until it's safe to start running code. (There may have been a suspend-all
   // in progress while we were starting up.)
   runtime->GetThreadList()->WaitForGo();
 
+  {
+    CHECK_EQ(self->GetState(), Thread::kRunnable);
+    String* thread_name = reinterpret_cast<String*>(gThread_name->GetObject(self->peer_));
+    if (thread_name != NULL) {
+      SetThreadName(thread_name->ToModifiedUtf8().c_str());
+    }
+  }
+
   Dbg::PostThreadStart(self);
 
   // Invoke the 'run' method of our java.lang.Thread.
@@ -224,13 +227,16 @@ void Thread::Create(Object* peer, size_t stack_size) {
   // and know that we're not racing to assign it.
   SetVmData(peer, native_thread);
 
-  pthread_t new_pthread;
-  pthread_attr_t attr;
-  CHECK_PTHREAD_CALL(pthread_attr_init, (&attr), "new thread");
-  CHECK_PTHREAD_CALL(pthread_attr_setdetachstate, (&attr, PTHREAD_CREATE_DETACHED), "PTHREAD_CREATE_DETACHED");
-  CHECK_PTHREAD_CALL(pthread_attr_setstacksize, (&attr, stack_size), stack_size);
-  CHECK_PTHREAD_CALL(pthread_create, (&new_pthread, &attr, Thread::CreateCallback, native_thread), "new thread");
-  CHECK_PTHREAD_CALL(pthread_attr_destroy, (&attr), "new thread");
+  {
+    ScopedThreadStateChange tsc(Thread::Current(), Thread::kVmWait);
+    pthread_t new_pthread;
+    pthread_attr_t attr;
+    CHECK_PTHREAD_CALL(pthread_attr_init, (&attr), "new thread");
+    CHECK_PTHREAD_CALL(pthread_attr_setdetachstate, (&attr, PTHREAD_CREATE_DETACHED), "PTHREAD_CREATE_DETACHED");
+    CHECK_PTHREAD_CALL(pthread_attr_setstacksize, (&attr, stack_size), stack_size);
+    CHECK_PTHREAD_CALL(pthread_create, (&new_pthread, &attr, Thread::CreateCallback, native_thread), "new thread");
+    CHECK_PTHREAD_CALL(pthread_attr_destroy, (&attr), "new thread");
+  }
 
   // Let the child know when it's safe to start running.
   Runtime::Current()->GetThreadList()->SignalGo(native_thread);
@@ -705,7 +711,9 @@ uint32_t Thread::LockOwnerFromThreadLock(Object* thread_lock) {
 }
 
 Thread::Thread()
-    : peer_(NULL),
+    : thin_lock_id_(0),
+      tid_(0),
+      peer_(NULL),
       top_of_managed_stack_(),
       top_of_managed_stack_pc_(0),
       wait_mutex_(new Mutex("Thread wait mutex")),
@@ -1473,11 +1481,15 @@ std::ostream& operator<<(std::ostream& os, const Thread::State& state) {
 }
 
 std::ostream& operator<<(std::ostream& os, const Thread& thread) {
-  os << "Thread[" << &thread
-     << ",tid=" << thread.GetTid()
-     << ",id=" << thread.GetThinLockId()
-     << ",state=" << thread.GetState()
-     << ",peer=" << thread.GetPeer()
+  os << "Thread[";
+  if (thread.GetThinLockId() != 0) {
+    // If we're in kStarting, we won't have a thin lock id or tid yet.
+    os << thread.GetThinLockId()
+       << ",tid=" << thread.GetTid() << ',';
+  }
+  os << thread.GetState()
+     << ",Thread*=" << &thread
+     << ",Object*=" << thread.GetPeer()
      << "]";
   return os;
 }
diff --git a/src/thread_list.cc b/src/thread_list.cc
index 91fc0f2..a77b8f6 100644
--- a/src/thread_list.cc
+++ b/src/thread_list.cc
@@ -88,19 +88,15 @@ void ThreadList::Dump(std::ostream& os) {
 
 void ThreadList::ModifySuspendCount(Thread* thread, int delta, bool for_debugger) {
 #ifndef NDEBUG
-  DCHECK(delta == -1 || delta == +1 || delta == thread->debug_suspend_count_) << delta;
-  DCHECK_GE(thread->suspend_count_, thread->debug_suspend_count_);
-  if (delta == -1) {
-    DCHECK_GT(thread->suspend_count_, 0);
-    if (for_debugger) {
-      DCHECK_GT(thread->debug_suspend_count_, 0);
-    }
-  }
-#else
+  DCHECK(delta == -1 || delta == +1 || delta == thread->debug_suspend_count_) << delta << " "
+                                                                              << *thread;
+  DCHECK_GE(thread->suspend_count_, thread->debug_suspend_count_) << *thread;
+#endif
   if (delta == -1 && thread->suspend_count_ <= 0) {
-    LOG(FATAL) << *thread << " suspend count already zero";
+    // This can happen if you attach a thread during a GC.
+    LOG(WARNING) << *thread << " suspend count already zero";
+    return;
   }
-#endif
   thread->suspend_count_ += delta;
   if (for_debugger) {
     thread->debug_suspend_count_ += delta;
@@ -375,8 +371,9 @@ void ThreadList::Register() {
   Thread* self = Thread::Current();
 
   if (verbose_) {
-    LOG(INFO) << "ThreadList::Register() " << *self;
-    self->Dump(std::cerr);
+    LogMessage log(__FILE__, __LINE__, INFO, -1);
+    log.stream() << "ThreadList::Register() " << *self << "\n";
+    self->Dump(log.stream());
   }
 
   ThreadListLocker locker(this);
@@ -454,6 +451,9 @@ void ThreadList::SignalGo(Thread* child) {
 
   {
     ThreadListLocker locker(this);
+    if (verbose_) {
+      LOG(INFO) << *self << " waiting for child " << *child << " to be in thread list...";
+    }
 
     // We wait for the child to tell us that it's in the thread list.
     while (child->GetState() != Thread::kStarting) {
@@ -466,6 +466,10 @@ void ThreadList::SignalGo(Thread* child) {
   self->SetState(Thread::kRunnable);
 
   // Tell the child that it's safe: it will see any future suspend request.
+  ThreadListLocker locker(this);
+  if (verbose_) {
+    LOG(INFO) << *self << " telling child " << *child << " it's safe to proceed...";
+  }
   child->SetState(Thread::kVmWait);
   thread_start_cond_.Broadcast();
 }
@@ -478,17 +482,32 @@ void ThreadList::WaitForGo() {
     ThreadListLocker locker(this);
 
     // Tell our parent that we're in the thread list.
+    if (verbose_) {
+      LOG(INFO) << *self << " telling parent that we're now in thread list...";
+    }
     self->SetState(Thread::kStarting);
     thread_start_cond_.Broadcast();
 
     // Wait until our parent tells us there's no suspend still pending
     // from before we were on the thread list.
+    if (verbose_) {
+      LOG(INFO) << *self << " waiting for parent's go-ahead...";
+    }
     while (self->GetState() != Thread::kVmWait) {
       thread_start_cond_.Wait(thread_list_lock_);
     }
   }
 
   // Enter the runnable state. We know that any pending suspend will affect us now.
+  if (verbose_) {
+    LOG(INFO) << *self << " entering runnable state...";
+  }
+  // Lock and unlock the heap lock. This ensures that if there was a GC in progress when we
+  // started, we wait until it's over. Which means that if there's now another GC pending, our
+  // suspend count is non-zero, so switching to the runnable state will suspend us.
+  // TODO: find a better solution!
+  Heap::Lock();
+  Heap::Unlock();
   self->SetState(Thread::kRunnable);
 }