Internal change

PiperOrigin-RevId: 369753540

cpp/platform/public/BUILD

@@ -32,9 +32,11 @@ cc_library(
         "future.h",
         "lockable.h",
         "logging.h",
+        "monitored_runnable.h",
         "multi_thread_executor.h",
         "mutex.h",
         "mutex_lock.h",
+        "pending_job_registry.h",
         "pipe.h",
         "scheduled_executor.h",
         "settable_future.h",

cpp/platform/public/monitored_runnable.h

@@ -0,0 +1,71 @@
+// Copyright 2020 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     https://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#ifndef PLATFORM_PUBLIC_MONITORED_RUNNABLE_H_
+#define PLATFORM_PUBLIC_MONITORED_RUNNABLE_H_
+
+#include <utility>
+
+#include "platform/base/runnable.h"
+#include "platform/public/logging.h"
+#include "platform/public/pending_job_registry.h"
+#include "platform/public/system_clock.h"
+#include "absl/time/time.h"
+
+namespace location {
+namespace nearby {
+
+// A runnable with extra logging
+// We log if the task has been waiting long on the executor or if it was running
+// for a long time. The latter isn't always an issue - some tasks are expected
+// to run for longer periods of time (minutes).
+class MonitoredRunnable {
+ public:
+  explicit MonitoredRunnable(Runnable&& runnable) : runnable_{runnable} {}
+  MonitoredRunnable(const std::string& name, Runnable&& runnable)
+      : name_{name}, runnable_{runnable} {
+    PendingJobRegistry::GetInstance().AddPendingJob(name_, post_time_);
+  }
+
+  void operator()() const {
+    auto start_time = SystemClock::ElapsedRealtime();
+    auto start_delay = start_time - post_time_;
+    if (start_delay >= kMinReportedStartDelay) {
+      NEARBY_LOGS(INFO) << "Task: \"" << name_ << "\" started after "
+                        << absl::ToInt64Seconds(start_delay) << " seconds";
+    }
+    PendingJobRegistry::GetInstance().RemovePendingJob(name_, post_time_);
+    PendingJobRegistry::GetInstance().AddRunningJob(name_, post_time_);
+    runnable_();
+    auto task_duration = SystemClock::ElapsedRealtime() - start_time;
+    if (task_duration >= kMinReportedTaskDuration) {
+      NEARBY_LOGS(INFO) << "Task: \"" << name_ << "\" finished after "
+                        << absl::ToInt64Seconds(task_duration) << " seconds";
+    }
+    PendingJobRegistry::GetInstance().RemoveRunningJob(name_, post_time_);
+    PendingJobRegistry::GetInstance().ListJobs();
+  }
+
+ private:
+  static constexpr absl::Duration kMinReportedStartDelay = absl::Seconds(5);
+  static constexpr absl::Duration kMinReportedTaskDuration = absl::Seconds(10);
+  const std::string name_;
+  Runnable runnable_;
+  absl::Time post_time_ = SystemClock::ElapsedRealtime();
+};
+
+}  // namespace nearby
+}  // namespace location
+
+#endif  // PLATFORM_PUBLIC_MONITORED_RUNNABLE_H_

cpp/platform/public/pending_job_registry.h

@@ -0,0 +1,102 @@
+// Copyright 2020 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     https://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#ifndef PLATFORM_PUBLIC_PENDING_JOB_REGISTRY_H_
+#define PLATFORM_PUBLIC_PENDING_JOB_REGISTRY_H_
+
+#include "platform/public/logging.h"
+#include "platform/public/mutex.h"
+#include "platform/public/mutex_lock.h"
+#include "platform/public/system_clock.h"
+#include "absl/base/thread_annotations.h"
+#include "absl/time/time.h"
+
+namespace location {
+namespace nearby {
+
+// A global registry of running tasks. The goal is to help us monitor
+// tasks that are either waiting too long for their turn or they never finish
+class PendingJobRegistry {
+ public:
+  static PendingJobRegistry& GetInstance() {
+    static PendingJobRegistry* instance = new PendingJobRegistry();
+    return *instance;
+  }
+
+  void AddPendingJob(const std::string& name, absl::Time post_time) {
+    MutexLock lock(&mutex_);
+    pending_jobs_.emplace(CreateKey(name, post_time), post_time);
+  }
+
+  void RemovePendingJob(const std::string& name, absl::Time post_time) {
+    MutexLock lock(&mutex_);
+    pending_jobs_.erase(CreateKey(name, post_time));
+  }
+
+  void AddRunningJob(const std::string& name, absl::Time post_time) {
+    MutexLock lock(&mutex_);
+    running_jobs_.emplace(CreateKey(name, post_time),
+                          SystemClock::ElapsedRealtime());
+  }
+
+  void RemoveRunningJob(const std::string& name, absl::Time post_time) {
+    MutexLock lock(&mutex_);
+    running_jobs_.erase(CreateKey(name, post_time));
+  }
+
+  void ListJobs() {
+    auto current_time = SystemClock::ElapsedRealtime();
+    if (current_time - list_jobs_time_ < kMinReportInterval) return;
+    MutexLock lock(&mutex_);
+    for (auto& job : pending_jobs_) {
+      auto age = current_time - job.second;
+      if (age >= kReportPendingJobsOlderThan) {
+        NEARBY_LOGS(INFO) << "Task \"" << job.first << "\" is waiting for "
+                          << absl::ToInt64Seconds(age) << " s";
+      }
+    }
+    for (auto& job : running_jobs_) {
+      auto age = current_time - job.second;
+      if (age >= kReportRunningJobsOlderThan) {
+        NEARBY_LOGS(INFO) << "Task \"" << job.first << "\" is running for "
+                          << absl::ToInt64Seconds(age) << " s";
+      }
+    }
+    list_jobs_time_ = current_time;
+  }
+
+ private:
+  PendingJobRegistry() = default;
+  static constexpr absl::Duration kMinReportInterval = absl::Seconds(60);
+  static constexpr absl::Duration kReportPendingJobsOlderThan =
+      absl::Seconds(40);
+  static constexpr absl::Duration kReportRunningJobsOlderThan =
+      absl::Seconds(60);
+
+  std::string CreateKey(const std::string& name, absl::Time post_time) {
+    return name + "." + std::to_string(absl::ToUnixNanos(post_time));
+  }
+
+  Mutex mutex_;
+  absl::flat_hash_map<const std::string, absl::Time> pending_jobs_
+      ABSL_GUARDED_BY(mutex_);
+  absl::flat_hash_map<const std::string, absl::Time> running_jobs_
+      ABSL_GUARDED_BY(mutex_);
+  absl::Time list_jobs_time_ = absl::UnixEpoch();
+};
+
+}  // namespace nearby
+}  // namespace location
+
+#endif  // PLATFORM_PUBLIC_PENDING_JOB_REGISTRY_H_

cpp/platform/public/scheduled_executor.h

@@ -25,6 +25,7 @@
 #include "platform/public/cancelable.h"
 #include "platform/public/cancellable_task.h"
 #include "platform/public/lockable.h"
+#include "platform/public/monitored_runnable.h"
 #include "platform/public/mutex.h"
 #include "platform/public/mutex_lock.h"
 #include "platform/public/thread_check_callable.h"
@@ -59,6 +60,14 @@ class ABSL_LOCKABLE ScheduledExecutor final : public Lockable {
     }
     return *this;
   }
+  void Execute(const std::string& name, Runnable&& runnable)
+      ABSL_LOCKS_EXCLUDED(mutex_) {
+    MutexLock lock(&mutex_);
+    if (impl_)
+      impl_->Execute(MonitoredRunnable(
+          name, ThreadCheckRunnable(this, std::move(runnable))));
+  }
+
   void Execute(Runnable&& runnable) ABSL_LOCKS_EXCLUDED(mutex_) {
     MutexLock lock(&mutex_);
     if (impl_) impl_->Execute(ThreadCheckRunnable(this, std::move(runnable)));

cpp/platform/public/single_thread_executor_test.cc

@@ -16,6 +16,7 @@
 
 #include <atomic>
 #include <functional>
+#include <string>
 
 #include "platform/base/exception.h"
 #include "gtest/gtest.h"
@@ -47,6 +48,24 @@ TEST(SingleThreadExecutorTest, CanExecute) {
   EXPECT_TRUE(done);
 }
 
+TEST(SingleThreadExecutorTest, CanExecuteNamedTask) {
+  absl::CondVar cond;
+  std::atomic_bool done = false;
+  SingleThreadExecutor executor;
+  executor.Execute("my task", [&done, &cond]() {
+    done = true;
+    cond.SignalAll();
+  });
+  absl::Mutex mutex;
+  {
+    absl::MutexLock lock(&mutex);
+    if (!done) {
+      cond.WaitWithTimeout(&mutex, absl::Seconds(1));
+    }
+  }
+  EXPECT_TRUE(done);
+}
+
 TEST(SingleThreadExecutorTest, JobsExecuteInOrder) {
   std::vector<int> results;
   SingleThreadExecutor executor;

cpp/platform/public/submittable_executor.h

@@ -26,6 +26,7 @@
 #include "platform/base/runnable.h"
 #include "platform/public/future.h"
 #include "platform/public/lockable.h"
+#include "platform/public/monitored_runnable.h"
 #include "platform/public/mutex.h"
 #include "platform/public/mutex_lock.h"
 #include "platform/public/thread_check_callable.h"
@@ -57,9 +58,19 @@ class ABSL_LOCKABLE SubmittableExecutor : public api::SubmittableExecutor,
     }
     return *this;
   }
+  void Execute(const std::string& name, Runnable&& runnable)
+      ABSL_LOCKS_EXCLUDED(mutex_) {
+    MutexLock lock(&mutex_);
+    if (impl_)
+      impl_->Execute(MonitoredRunnable(
+          name, ThreadCheckRunnable(this, std::move(runnable))));
+  }
+
   void Execute(Runnable&& runnable) ABSL_LOCKS_EXCLUDED(mutex_) override {
     MutexLock lock(&mutex_);
-    if (impl_) impl_->Execute(ThreadCheckRunnable(this, std::move(runnable)));
+    if (impl_)
+      impl_->Execute(
+          MonitoredRunnable(ThreadCheckRunnable(this, std::move(runnable))));
   }
 
   int GetTid(int index) const ABSL_LOCKS_EXCLUDED(mutex_) override {