[IO Hangs]: Annotate ScopedBlockingCall with activity tracker.

Record timestamp and location in ScopedBlockingCall to show up in hang dumps.
This is useful to investigate hangs related to IO & flush.

Bug: 1058194
Change-Id: Iee336ad9ec88a9b5d34a5d2e1a1e2a80c8248fc7
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2091547
Commit-Queue: Etienne Pierre-Doray <etiennep@chromium.org>
Reviewed-by: Brian White <bcwhite@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#749648}

base/debug/activity_tracker.h

@@ -1276,6 +1276,8 @@ class BASE_EXPORT ScopedActivity
   ALWAYS_INLINE
   ScopedActivity(uint8_t action, uint32_t id, int32_t info)
       : ScopedActivity(GetProgramCounter(), action, id, info) {}
+  ScopedActivity(Location from_here, uint8_t action, uint32_t id, int32_t info)
+      : ScopedActivity(from_here.program_counter(), action, id, info) {}
   ScopedActivity() : ScopedActivity(0, 0, 0) {}
 
   // Changes the |action| and/or |info| of this activity on the stack. This

base/threading/scoped_blocking_call.cc

@@ -8,6 +8,7 @@
 #include "base/scoped_clear_last_error.h"
 #include "base/threading/thread_local.h"
 #include "base/threading/thread_restrictions.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "build/build_config.h"
 
@@ -15,6 +16,10 @@ namespace base {
 
 namespace {
 
+// The first 8 characters of sha1 of "ScopedBlockingCall".
+// echo -n "ScopedBlockingCall" | sha1sum
+constexpr uint32_t kActivityTrackerId = 0x11be9915;
+
 LazyInstance<ThreadLocalPointer<internal::BlockingObserver>>::Leaky
     tls_blocking_observer = LAZY_INSTANCE_INITIALIZER;
 
@@ -35,12 +40,14 @@ LazyInstance<ThreadLocalBoolean>::Leaky tls_construction_in_progress =
 namespace internal {
 
 UncheckedScopedBlockingCall::UncheckedScopedBlockingCall(
+    const Location& from_here,
     BlockingType blocking_type)
     : blocking_observer_(tls_blocking_observer.Get().Get()),
       previous_scoped_blocking_call_(tls_last_scoped_blocking_call.Get().Get()),
       is_will_block_(blocking_type == BlockingType::WILL_BLOCK ||
                      (previous_scoped_blocking_call_ &&
-                      previous_scoped_blocking_call_->is_will_block_)) {
+                      previous_scoped_blocking_call_->is_will_block_)),
+      scoped_activity_(from_here, 0, kActivityTrackerId, 0) {
   tls_last_scoped_blocking_call.Get().Set(this);
 
   if (blocking_observer_) {
@@ -51,6 +58,14 @@ UncheckedScopedBlockingCall::UncheckedScopedBlockingCall(
       blocking_observer_->BlockingTypeUpgraded();
     }
   }
+
+  if (scoped_activity_.IsRecorded()) {
+    // Also record the data for extended crash reporting.
+    const base::TimeTicks now = base::TimeTicks::Now();
+    auto& user_data = scoped_activity_.user_data();
+    user_data.SetUint("timestamp_us", now.since_origin().InMicroseconds());
+    user_data.SetUint("blocking_type", static_cast<uint64_t>(blocking_type));
+  }
 }
 
 UncheckedScopedBlockingCall::~UncheckedScopedBlockingCall() {
@@ -67,7 +82,7 @@ UncheckedScopedBlockingCall::~UncheckedScopedBlockingCall() {
 
 ScopedBlockingCall::ScopedBlockingCall(const Location& from_here,
                                        BlockingType blocking_type)
-    : UncheckedScopedBlockingCall(blocking_type) {
+    : UncheckedScopedBlockingCall(from_here, blocking_type) {
 #if DCHECK_IS_ON()
   DCHECK(!tls_construction_in_progress.Get().Get());
   tls_construction_in_progress.Get().Set(true);
@@ -91,7 +106,7 @@ namespace internal {
 ScopedBlockingCallWithBaseSyncPrimitives::
     ScopedBlockingCallWithBaseSyncPrimitives(const Location& from_here,
                                              BlockingType blocking_type)
-    : UncheckedScopedBlockingCall(blocking_type) {
+    : UncheckedScopedBlockingCall(from_here, blocking_type) {
 #if DCHECK_IS_ON()
   DCHECK(!tls_construction_in_progress.Get().Get());
   tls_construction_in_progress.Get().Set(true);

base/threading/scoped_blocking_call.h

@@ -6,6 +6,7 @@
 #define BASE_THREADING_SCOPED_BLOCKING_CALL_H
 
 #include "base/base_export.h"
+#include "base/debug/activity_tracker.h"
 #include "base/location.h"
 #include "base/logging.h"
 
@@ -35,7 +36,8 @@ class BlockingObserver;
 // ScopedBlockingCallWithBaseSyncPrimitives without assertions.
 class BASE_EXPORT UncheckedScopedBlockingCall {
  public:
-  explicit UncheckedScopedBlockingCall(BlockingType blocking_type);
+  explicit UncheckedScopedBlockingCall(const Location& from_here,
+                                       BlockingType blocking_type);
   ~UncheckedScopedBlockingCall();
 
  private:
@@ -48,6 +50,8 @@ class BASE_EXPORT UncheckedScopedBlockingCall {
   // ScopedBlockingCall was instantiated.
   const bool is_will_block_;
 
+  base::debug::ScopedActivity scoped_activity_;
+
   DISALLOW_COPY_AND_ASSIGN(UncheckedScopedBlockingCall);
 };
 

chrome/browser/metrics/thread_watcher_report_hang.cc

@@ -4,8 +4,10 @@
 
 #include "chrome/browser/metrics/thread_watcher_report_hang.h"
 
+#include "base/debug/activity_tracker.h"
 #include "base/debug/debugger.h"
 #include "base/debug/dump_without_crashing.h"
+#include "base/time/time.h"
 
 namespace metrics {
 
@@ -15,6 +17,16 @@ namespace metrics {
 NOINLINE void ReportThreadHang() {
   volatile const char* inhibit_comdat = __func__;
   ALLOW_UNUSED_LOCAL(inhibit_comdat);
+
+  // The first 8 characters of sha1 of "ReportThreadHang".
+  // echo -n "ReportThreadHang" | sha1sum
+  static constexpr uint32_t kActivityTrackerId = 0xceec103d;
+
+  base::debug::ScopedActivity scoped_activity(0, kActivityTrackerId, 0);
+  auto& user_data = scoped_activity.user_data();
+  const base::TimeTicks now = base::TimeTicks::Now();
+  user_data.SetUint("timestamp_us", now.since_origin().InMicroseconds());
+
 #if defined(NDEBUG)
   base::debug::DumpWithoutCrashing();
 #else