stopwatch: improve stopwatch problems

* For command timeout case, will print the stopwatch log.
* For startup_timer_expired case, will print the stopwatch log.
* Add record initializationComplete function into stopwatch log.
* For the stopwatch can't correctly dump log if the array is not full
  case, fix it.

bug: 190786398
Test: atest BluetoothInstrumentationTests & Manually
Tag: #stability
Change-Id: I8a66897ca46f593e18e231c43e8873ff0db08288
Merged-In: Ie59dbc0bd2f574761eed7aac695cbff07948d8e2

diff --git a/common/stop_watch_legacy.cc b/common/stop_watch_legacy.cc
index 8fb3617..a2bb562 100644 (file)
--- a/common/stop_watch_legacy.cc
+++ b/common/stop_watch_legacy.cc
@@ -19,6 +19,7 @@
 #include "common/stop_watch_legacy.h"
 
 #include <iomanip>
+#include <mutex>
 #include <sstream>
 #include <utility>
 
@@ -31,16 +32,29 @@ namespace common {
 static const int LOG_BUFFER_LENGTH = 10;
 static std::array<StopWatchLog, LOG_BUFFER_LENGTH> stopwatch_logs;
 static int current_buffer_index;
+static std::recursive_mutex stopwatch_log_mutex;
 
 void StopWatchLegacy::RecordLog(StopWatchLog log) {
+  std::unique_lock<std::recursive_mutex> lock(stopwatch_log_mutex, std::defer_lock);
+  if (!lock.try_lock()) {
+    LOG_INFO("try_lock fail. log content: %s, took %zu us", log.message.c_str(),
+             static_cast<size_t>(
+                 std::chrono::duration_cast<std::chrono::microseconds>(
+                     stopwatch_logs[current_buffer_index].end_timestamp -
+                     stopwatch_logs[current_buffer_index].start_timestamp)
+                     .count()));
+    return;
+  }
   if (current_buffer_index >= LOG_BUFFER_LENGTH) {
     current_buffer_index = 0;
   }
   stopwatch_logs[current_buffer_index] = std::move(log);
   current_buffer_index++;
+  lock.unlock();
 }
 
 void StopWatchLegacy::DumpStopWatchLog() {
+  std::lock_guard<std::recursive_mutex> lock(stopwatch_log_mutex);
   LOG_INFO("=====================================");
   LOG_INFO("bluetooth stopwatch log history:");
   for (int i = 0; i < LOG_BUFFER_LENGTH; i++) {
@@ -48,7 +62,8 @@ void StopWatchLegacy::DumpStopWatchLog() {
       current_buffer_index = 0;
     }
     if (stopwatch_logs[current_buffer_index].message.empty()) {
-      break;
+      current_buffer_index++;
+      continue;
     }
     std::stringstream ss;
     auto now = stopwatch_logs[current_buffer_index].timestamp;

diff --git a/gd/common/stop_watch.cc b/gd/common/stop_watch.cc
index 4d26d94..5c556c6 100644 (file)
--- a/gd/common/stop_watch.cc
+++ b/gd/common/stop_watch.cc
@@ -19,6 +19,7 @@
 #include "common/stop_watch.h"
 
 #include <iomanip>
+#include <mutex>
 #include <sstream>
 #include <utility>
 
@@ -31,16 +32,29 @@ namespace common {
 static const int LOG_BUFFER_LENGTH = 10;
 static std::array<StopWatchLog, LOG_BUFFER_LENGTH> stopwatch_logs;
 static int current_buffer_index;
+static std::recursive_mutex stopwatch_log_mutex;
 
 void StopWatch::RecordLog(StopWatchLog log) {
+  std::unique_lock<std::recursive_mutex> lock(stopwatch_log_mutex, std::defer_lock);
+  if (!lock.try_lock()) {
+    LOG_INFO("try_lock fail. log content: %s, took %zu us", log.message.c_str(),
+             static_cast<size_t>(
+                 std::chrono::duration_cast<std::chrono::microseconds>(
+                     stopwatch_logs[current_buffer_index].end_timestamp -
+                     stopwatch_logs[current_buffer_index].start_timestamp)
+                     .count()));
+    return;
+  }
   if (current_buffer_index >= LOG_BUFFER_LENGTH) {
     current_buffer_index = 0;
   }
   stopwatch_logs[current_buffer_index] = std::move(log);
   current_buffer_index++;
+  lock.unlock();
 }
 
 void StopWatch::DumpStopWatchLog() {
+  std::lock_guard<std::recursive_mutex> lock(stopwatch_log_mutex);
   LOG_INFO("=====================================");
   LOG_INFO("bluetooth stopwatch log history:");
   for (int i = 0; i < LOG_BUFFER_LENGTH; i++) {
@@ -48,7 +62,8 @@ void StopWatch::DumpStopWatchLog() {
       current_buffer_index = 0;
     }
     if (stopwatch_logs[current_buffer_index].message.empty()) {
-      break;
+      current_buffer_index++;
+      continue;
     }
     std::stringstream ss;
     auto now = stopwatch_logs[current_buffer_index].timestamp;

diff --git a/gd/hal/hci_hal_android_hidl.cc b/gd/hal/hci_hal_android_hidl.cc
index 0195237..4979ef0 100644 (file)
--- a/gd/hal/hci_hal_android_hidl.cc
+++ b/gd/hal/hci_hal_android_hidl.cc
@@ -83,6 +83,7 @@ class InternalHciCallbacks : public IBluetoothHciCallbacks {
   }
 
   Return<void> initializationComplete(HidlStatus status) {
+    common::StopWatch(__func__);
     ASSERT(status == HidlStatus::SUCCESS);
     init_promise_->set_value();
     return Void();

diff --git a/gd/hci/hci_layer.cc b/gd/hci/hci_layer.cc
index ac5ea35..dae1f4d 100644 (file)
--- a/gd/hci/hci_layer.cc
+++ b/gd/hci/hci_layer.cc
@@ -18,6 +18,7 @@
 
 #include "common/bind.h"
 #include "common/init_flags.h"
+#include "common/stop_watch.h"
 #include "hci/hci_metrics_logging.h"
 #include "os/alarm.h"
 #include "os/metrics.h"
@@ -181,6 +182,7 @@ struct HciLayer::impl {
   }
 
   void on_hci_timeout(OpCode op_code) {
+    common::StopWatch::DumpStopWatchLog();
     LOG_ERROR("Timed out waiting for 0x%02hx (%s)", op_code, OpCodeText(op_code).c_str());
     // TODO: LogMetricHciTimeoutEvent(static_cast<uint32_t>(op_code));
 

diff --git a/hci/src/hci_layer.cc b/hci/src/hci_layer.cc
index 0b6686c..1cd3a49 100644 (file)
--- a/hci/src/hci_layer.cc
+++ b/hci/src/hci_layer.cc
@@ -42,6 +42,7 @@
 #include "common/message_loop_thread.h"
 #include "common/metrics.h"
 #include "common/once_timer.h"
+#include "common/stop_watch_legacy.h"
 #include "hci_inject.h"
 #include "hci_internals.h"
 #include "hcidefs.h"
@@ -58,6 +59,7 @@
 
 using bluetooth::common::MessageLoopThread;
 using bluetooth::common::OnceTimer;
+using bluetooth::common::StopWatchLegacy;
 
 extern void hci_initialize();
 extern void hci_transmit(BT_HDR* packet);
@@ -376,6 +378,8 @@ static void event_finish_startup(UNUSED_ATTR void* context) {
 static void startup_timer_expired(UNUSED_ATTR void* context) {
   LOG_ERROR("%s", __func__);
 
+  StopWatchLegacy::DumpStopWatchLog();
+
   LOG_EVENT_INT(BT_HCI_TIMEOUT_TAG_NUM, HCI_STARTUP_TIMED_OUT);
 
   hci_close();
@@ -522,6 +526,7 @@ static void command_timed_out_log_info(void* original_wait_entry) {
 // Print debugging information and quit. Don't dereference original_wait_entry.
 static void command_timed_out(void* original_wait_entry) {
   LOG_ERROR("%s", __func__);
+  StopWatchLegacy::DumpStopWatchLog();
   std::unique_lock<std::recursive_timed_mutex> lock(
       commands_pending_response_mutex, std::defer_lock);
   if (!lock.try_lock_for(std::chrono::milliseconds(

diff --git a/hci/src/hci_layer_android.cc b/hci/src/hci_layer_android.cc
index 79eb8f1..bba7834 100644 (file)
--- a/hci/src/hci_layer_android.cc
+++ b/hci/src/hci_layer_android.cc
@@ -110,6 +110,7 @@ class BluetoothHciCallbacks : public V1_1::IBluetoothHciCallbacks {
   }
 
   Return<void> initializationComplete(Status status) override {
+    StopWatchLegacy(__func__);
     if (hci_is_root_inflammation_event_received()) {
       // Ignore the initializationComplete here as we have already received
       // root inflammation event earlier.