Identify the hung thread using the Wait Chain Traversal API

chrome/chrome_watcher/chrome_watcher_main.cc

 // Copyright (c) 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include <windows.h>
 #include <sddl.h>
 
 #include <utility>
 
 #include "base/at_exit.h"
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback_helpers.h"
 #include "base/command_line.h"
 #include "base/environment.h"
 #include "base/file_version_info.h"
 #include "base/files/file_path.h"
 #include "base/logging_win.h"
 #include "base/macros.h"
 #include "base/memory/ref_counted.h"
 #include "base/process/process.h"
 #include "base/run_loop.h"
 #include "base/sequenced_task_runner.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/string16.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_piece.h"
+#include "base/strings/string_util.h"
+#include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/thread.h"
 #include "base/time/time.h"
 #include "base/win/scoped_handle.h"
 #include "base/win/win_util.h"
 
 #include "chrome/chrome_watcher/chrome_watcher_main_api.h"
 #include "chrome/installer/util/util_constants.h"
 #include "components/browser_watcher/endsession_watcher_window_win.h"
 #include "components/browser_watcher/exit_code_watcher_win.h"
 #include "components/browser_watcher/window_hang_monitor_win.h"
 #include "third_party/kasko/kasko_features.h"
 
 #if BUILDFLAG(ENABLE_KASKO)
+#include "base/win/wait_chain.h"
 #include "components/crash/content/app/crashpad.h"
 #include "syzygy/kasko/api/reporter.h"
 #endif
 
 namespace {
 
 // Use the same log facility as Chrome for convenience.
 // {7FE69228-633E-4f06-80C1-527FEA23E3A7}
 const GUID kChromeWatcherTraceProviderName = {
     0x7fe69228, 0x633e, 0x4f06,
@@ skipping 171 matching lines @@
   std::string env_var;
   if (env->GetVar(kKaskoCrashReportBaseDir, &env_var)) {
     base::string16 wide_env_var;
     base::UTF8ToWide(env_var.c_str(), env_var.size(), &wide_env_var);
     *base_dir = base::FilePath(wide_env_var);
   } else {
     *base_dir = base::FilePath(browser_data_directory);
   }
 }
 
+void AddCrashKey(const wchar_t* key,
+                 const wchar_t* value,
+                 std::vector<kasko::api::CrashKey>* crash_keys) {
+  DCHECK(key);
+  DCHECK(value);
+  DCHECK(crash_keys);
+
+  kasko::api::CrashKey crash_key;
+  base::wcslcpy(crash_key.name, key, kasko::api::CrashKey::kNameMaxLength - 1);

[grt (UTC plus 2), 2016/04/12 14:31:12]

why "- 1" here and below? based on my read of string_util.h and crash_key.h, i
think you're short-changing yourself by one character.

[Patrick Monette, 2016/04/12 19:13:00]

Done.

+  base::wcslcpy(crash_key.value, value,
+                kasko::api::CrashKey::kValueMaxLength - 1);
+  crash_keys->push_back(crash_key);

[grt (UTC plus 2), 2016/04/12 14:31:12]

this is doing extra copies of the strings (once into |crash_key| then once into
the vector). you can do away with one of them with:
  crash_keys->resize(crash_keys->size() + 1);
  kasko::api::CrashKey& crash_key = crash_keys->back();
  base::wcslcpy(crash_key.name, ...);
  base::wcslcpy(crash_key.value, ...);

[Patrick Monette, 2016/04/12 19:13:00]

Done.

+}
+
 void DumpHungBrowserProcess(DWORD main_thread_id,
                             const base::string16& channel,
                             const base::Process& process) {
   // Read the Crashpad module annotations for the process.
   std::vector<kasko::api::CrashKey> annotations;
   crash_reporter::ReadMainModuleAnnotationsForKasko(process, &annotations);
 
   // Add a special crash key to distinguish reports generated for a hung
   // process.
-  annotations.push_back(kasko::api::CrashKey{L"hung-process", L"1"});
+  AddCrashKey(L"hung-process", L"1", &annotations);
+
+  // Use the Wait Chain Traversal API to determine the hung thread. Defaults to
+  // UI thread on error. The wait chain may point to a different thread in a
+  // different process for the hung thread.
+  DWORD hung_thread_id = main_thread_id;
+  base::Process hung_process = process.Duplicate();
+
+  base::win::WaitChain wait_chain;
+  bool is_deadlock = false;
+  if (base::win::GetThreadWaitChain(main_thread_id, &wait_chain,
+                                    &is_deadlock)) {
+    // The last thread in the wait chain is nominated as the hung thread.
+    base::win::WaitChain::reverse_iterator it;

[grt (UTC plus 2), 2016/04/12 14:31:12]

This is a perfect use of <algorithm> and a lambda:
    auto it = std::find_if(wait_chain.rbegin(), wait_chain.rend(),
                           [](WAITCHAIN_NODE_INFO& node) {
                             return node.ObjectType == WctThreadType;
                           });
using the algorithms is often more efficient than working with the iterators
directly since the impl can check the validity of the iterators once rather than
N times.

[Patrick Monette, 2016/04/12 19:13:00]

Good idea. Done.

+    for (it = wait_chain.rbegin(); it != wait_chain.rend(); ++it) {
+      if (it->ObjectType == WctThreadType)
+        break;
+    }
+    DCHECK(it != wait_chain.rend());
+
+    // DO NOT COMMIT: I'll add the same check as Pierre-Antoine for the process
+    // id race.
+    hung_process = base::Process::Open(it->ThreadObject.ProcessId);
+    hung_thread_id = it->ThreadObject.ThreadId;
+
+    // The entire wait chain is added to the crash report via crash keys.
+    //
+    // As an example (key : value):
+    // hung-process-is-deadlock  : false
+    // hung-process-wait-chain-00 : Thread #10242 with status Blocked
+    // hung-process-wait-chain-01 : Lock of type ThreadWait with status Owned
+    // hung-process-wait-chain-02 : Thread #77221 with status Blocked
+    //
+    AddCrashKey(L"hung-process-is-deadlock", is_deadlock ? L"true" : L"false",
+                &annotations);
+    for (size_t i = 0; i < wait_chain.size(); i++) {
+      AddCrashKey(
+          base::StringPrintf(L"hung-process-wait-chain-%02zu", i).c_str(),

[grt (UTC plus 2), 2016/04/12 14:31:12]

#include "base/format_macros.h"
L"hung-process-wait-chain-%02" PRIuS
(i knew this existed, but it took me a bloody long time to find. :-) )

[Patrick Monette, 2016/04/12 19:13:00]

Done. 

+          base::win::WaitChainNodeToString(wait_chain[i]).c_str(),
+          &annotations);
+    }
+  }
 
   std::vector<const base::char16*> key_buffers;
   std::vector<const base::char16*> value_buffers;
   for (const auto& crash_key : annotations) {
     key_buffers.push_back(crash_key.name);
     value_buffers.push_back(crash_key.value);
   }
   key_buffers.push_back(nullptr);
   value_buffers.push_back(nullptr);
 
-  // Synthesize an exception for the main thread. Populate the record with the
+  // Synthesize an exception for the hung thread. Populate the record with the
   // current context of the thread to get the stack trace bucketed on the crash
   // backend.
   CONTEXT thread_context = {};
   EXCEPTION_RECORD exception_record = {};
   exception_record.ExceptionCode = EXCEPTION_ARRAY_BOUNDS_EXCEEDED;
   EXCEPTION_POINTERS exception_pointers = {&exception_record, &thread_context};
 
-  base::win::ScopedHandle main_thread(::OpenThread(
+  base::win::ScopedHandle hung_thread(::OpenThread(
       THREAD_SUSPEND_RESUME | THREAD_GET_CONTEXT | THREAD_QUERY_INFORMATION,
-      FALSE, main_thread_id));
+      FALSE, hung_thread_id));
 
   bool have_context = false;
-  if (main_thread.IsValid()) {
-    DWORD suspend_count = ::SuspendThread(main_thread.Get());
+  if (hung_thread.IsValid()) {
+    DWORD suspend_count = ::SuspendThread(hung_thread.Get());
     const DWORD kSuspendFailed = static_cast<DWORD>(-1);
     if (suspend_count != kSuspendFailed) {
       // Best effort capture of the context.
       thread_context.ContextFlags = CONTEXT_FLOATING_POINT | CONTEXT_SEGMENTS |
                                     CONTEXT_INTEGER | CONTEXT_CONTROL;
-      if (::GetThreadContext(main_thread.Get(), &thread_context) == TRUE)
+      if (::GetThreadContext(hung_thread.Get(), &thread_context) == TRUE)
         have_context = true;
 
-      ::ResumeThread(main_thread.Get());
+      ::ResumeThread(hung_thread.Get());
     }
   }
 
   // TODO(erikwright): Make the dump-type channel-dependent.
   if (have_context) {
     kasko::api::SendReportForProcess(
-        process.Handle(), main_thread_id, &exception_pointers,
+        hung_process.Handle(), hung_thread_id, &exception_pointers,
         kasko::api::LARGER_DUMP_TYPE, key_buffers.data(), value_buffers.data());
   } else {
-    kasko::api::SendReportForProcess(process.Handle(), 0, nullptr,
+    kasko::api::SendReportForProcess(hung_process.Handle(), 0, nullptr,
                                      kasko::api::LARGER_DUMP_TYPE,
                                      key_buffers.data(), value_buffers.data());
   }
 }
 
 void LoggedDeregisterEventSource(HANDLE event_source_handle) {
   if (!::DeregisterEventSource(event_source_handle))
     DPLOG(ERROR) << "DeregisterEventSource";
 }
 
@@ skipping 138 matching lines @@
 
   // Wind logging down.
   logging::LogEventProvider::Uninitialize();
 
   return 0;
 }
 
 static_assert(
     std::is_same<decltype(&WatcherMain), ChromeWatcherMainFunction>::value,
     "WatcherMain() has wrong type");