OSDN Git Service

Add StopWatch for Hwbinder callback function
authorweichinweng <weichinweng@google.com>
Wed, 3 Mar 2021 02:19:19 +0000 (10:19 +0800)
committerweichinweng <weichinweng@google.com>
Thu, 8 Apr 2021 07:58:43 +0000 (15:58 +0800)
Add stopWatch feature to monitor HCI callbacks and audio client
callbacks.

Bug: 175754854
Test: atest BluetoothInstrumentationTests
Tag: #stability
Change-Id: I87b9aac85166f345629ea110653cc873ca24c079

audio_hal_interface/client_interface.cc
common/Android.bp
common/stop_watch_legacy.cc [new file with mode: 0644]
common/stop_watch_legacy.h [new file with mode: 0644]
hci/src/hci_layer_android.cc

index 94c4c71..9b7f75c 100644 (file)
@@ -24,6 +24,7 @@
 #include <hidl/MQDescriptor.h>
 #include <future>
 
+#include "common/stop_watch_legacy.h"
 #include "osi/include/log.h"
 
 namespace bluetooth {
@@ -34,6 +35,7 @@ using ::android::hardware::Return;
 using ::android::hardware::Void;
 using ::android::hardware::audio::common::V5_0::SourceMetadata;
 using ::android::hardware::bluetooth::audio::V2_0::IBluetoothAudioPort;
+using ::bluetooth::common::StopWatchLegacy;
 
 using DataMQ = ::android::hardware::MessageQueue<
     uint8_t, ::android::hardware::kSynchronizedReadWrite>;
@@ -72,6 +74,7 @@ class BluetoothAudioPortImpl : public IBluetoothAudioPort {
       : transport_instance_(transport_instance), provider_(provider) {}
 
   Return<void> startStream() override {
+    StopWatchLegacy(__func__);
     BluetoothAudioCtrlAck ack = transport_instance_->StartRequest();
     if (ack != BluetoothAudioCtrlAck::PENDING) {
       auto hidl_retval =
@@ -85,6 +88,7 @@ class BluetoothAudioPortImpl : public IBluetoothAudioPort {
   }
 
   Return<void> suspendStream() override {
+    StopWatchLegacy(__func__);
     BluetoothAudioCtrlAck ack = transport_instance_->SuspendRequest();
     if (ack != BluetoothAudioCtrlAck::PENDING) {
       auto hidl_retval =
@@ -98,12 +102,14 @@ class BluetoothAudioPortImpl : public IBluetoothAudioPort {
   }
 
   Return<void> stopStream() override {
+    StopWatchLegacy(__func__);
     transport_instance_->StopRequest();
     return Void();
   }
 
   Return<void> getPresentationPosition(
       getPresentationPosition_cb _hidl_cb) override {
+    StopWatchLegacy(__func__);
     uint64_t remote_delay_report_ns;
     uint64_t total_bytes_read;
     timespec data_position;
@@ -130,6 +136,7 @@ class BluetoothAudioPortImpl : public IBluetoothAudioPort {
   }
 
   Return<void> updateMetadata(const SourceMetadata& sourceMetadata) override {
+    StopWatchLegacy(__func__);
     LOG(INFO) << __func__ << ": " << sourceMetadata.tracks.size()
               << " track(s)";
     // refer to StreamOut.impl.h within Audio HAL (AUDIO_HAL_VERSION_5_0)
index 33a4db6..b22109b 100644 (file)
@@ -28,6 +28,7 @@ cc_library_static {
         "os_utils.cc",
         "repeating_timer.cc",
         "time_util.cc",
+        "stop_watch_legacy.cc",
     ],
     shared_libs: [
         "libcrypto",
diff --git a/common/stop_watch_legacy.cc b/common/stop_watch_legacy.cc
new file mode 100644 (file)
index 0000000..0327568
--- /dev/null
@@ -0,0 +1,85 @@
+/*
+ * Copyright 2020 The Android Open Source Project
+ *
+ * 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
+ *
+ *      http://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.
+ */
+
+#define LOG_TAG "BtStopWatchLegacy"
+
+#include "common/stop_watch_legacy.h"
+
+#include <iomanip>
+#include <sstream>
+#include <utility>
+
+#include <base/logging.h>
+#include "osi/include/log.h"
+
+namespace bluetooth {
+namespace common {
+
+static const int LOG_BUFFER_LENGTH = 10;
+static std::array<std::string, LOG_BUFFER_LENGTH> stopwatch_logs;
+static int current_buffer_index;
+
+void StopWatchLegacy::RecordLog(std::string log) {
+  if (current_buffer_index >= LOG_BUFFER_LENGTH) {
+    current_buffer_index = 0;
+  }
+  stopwatch_logs[current_buffer_index] = std::move(log);
+  current_buffer_index++;
+}
+
+void StopWatchLegacy::DumpStopWatchLog() {
+  LOG_INFO("=====================================");
+  LOG_INFO("bluetooth stopwatch log history:");
+  for (int i = 0; i < LOG_BUFFER_LENGTH; i++) {
+    if (current_buffer_index >= LOG_BUFFER_LENGTH) {
+      current_buffer_index = 0;
+    }
+    if (stopwatch_logs[current_buffer_index].empty()) {
+      break;
+    }
+    LOG_INFO("%s", stopwatch_logs[current_buffer_index].c_str());
+    current_buffer_index++;
+  }
+  LOG_INFO("=====================================");
+}
+
+StopWatchLegacy::StopWatchLegacy(std::string text)
+    : text_(std::move(text)),
+      start_time_(std::chrono::high_resolution_clock::now()) {
+  std::stringstream ss;
+  auto now = std::chrono::system_clock::now();
+  auto millis = std::chrono::duration_cast<std::chrono::milliseconds>(
+                    now.time_since_epoch()) %
+                1000;
+  auto now_time_t = std::chrono::system_clock::to_time_t(now);
+  ss << std::put_time(std::localtime(&now_time_t), "%Y-%m-%d %H:%M:%S");
+  ss << '.' << std::setfill('0') << std::setw(3) << millis.count();
+  start_timestamp_ = ss.str();
+
+  RecordLog(start_timestamp_ + ": " + text_);
+}
+
+StopWatchLegacy::~StopWatchLegacy() {
+  RecordLog(start_timestamp_ + ": " + text_ + ": took " +
+            std::to_string(static_cast<size_t>(
+                std::chrono::duration_cast<std::chrono::microseconds>(
+                    std::chrono::high_resolution_clock::now() - start_time_)
+                    .count())) +
+            " us");
+}
+
+}  // namespace common
+}  // namespace bluetooth
diff --git a/common/stop_watch_legacy.h b/common/stop_watch_legacy.h
new file mode 100644 (file)
index 0000000..b5cdc3d
--- /dev/null
@@ -0,0 +1,39 @@
+/*
+ * Copyright 2020 The Android Open Source Project
+ *
+ * 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
+ *
+ *      http://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.
+ */
+
+#pragma once
+
+#include <chrono>
+#include <string>
+
+namespace bluetooth {
+namespace common {
+
+class StopWatchLegacy {
+ public:
+  static void DumpStopWatchLog(void);
+  StopWatchLegacy(std::string text);
+  ~StopWatchLegacy();
+
+ private:
+  std::string text_;
+  std::chrono::time_point<std::chrono::high_resolution_clock> start_time_;
+  std::string start_timestamp_;
+  void RecordLog(std::string log);
+};
+
+}  // namespace common
+}  // namespace bluetooth
index f6b8386..79eb8f1 100644 (file)
 
 #include "hci_layer.h"
 
+#include <iomanip>
+
 #include <fcntl.h>
 #include <sys/stat.h>
 #include <sys/types.h>
 
-#include <base/location.h>
-#include <base/logging.h>
-#include "buffer_allocator.h"
-#include "osi/include/log.h"
-
 #include <android/hardware/bluetooth/1.0/IBluetoothHci.h>
 #include <android/hardware/bluetooth/1.0/IBluetoothHciCallbacks.h>
 #include <android/hardware/bluetooth/1.0/types.h>
 #include <android/hardware/bluetooth/1.1/IBluetoothHci.h>
 #include <android/hardware/bluetooth/1.1/IBluetoothHciCallbacks.h>
 
+#include <base/location.h>
+#include <base/logging.h>
+
+#include "buffer_allocator.h"
+#include "common/stop_watch_legacy.h"
+#include "osi/include/log.h"
+
 #define LOG_PATH "/data/misc/bluetooth/logs/firmware_events.log"
 #define LAST_LOG_PATH "/data/misc/bluetooth/logs/firmware_events.log.last"
 
@@ -44,6 +48,7 @@ using ::android::hardware::Return;
 using ::android::hardware::Void;
 using ::android::hardware::bluetooth::V1_0::HciPacket;
 using ::android::hardware::bluetooth::V1_0::Status;
+using ::bluetooth::common::StopWatchLegacy;
 
 using namespace ::android::hardware::bluetooth;
 
@@ -58,10 +63,27 @@ extern bool hci_is_root_inflammation_event_received();
 android::sp<V1_0::IBluetoothHci> btHci;
 android::sp<V1_1::IBluetoothHci> btHci_1_1;
 
+std::string GetTimerText(std::string func_name, const hidl_vec<uint8_t>& vec) {
+  std::stringstream ss;
+  const unsigned char* vec_char =
+      reinterpret_cast<const unsigned char*>(vec.data());
+  int length = 5;
+  if ((int)vec.size() < 5) {
+    length = vec.size();
+  }
+  for (int i = 0; i < length; i++) {
+    ss << std::setw(2) << std::setfill('0') << std::hex << (int)vec_char[i];
+  }
+  std::string text = func_name + ": len " + std::to_string(vec.size()) +
+                     ", 1st 5 bytes '" + ss.str() + "'";
+  return text;
+}
+
 class BluetoothHciDeathRecipient : public hidl_death_recipient {
  public:
   virtual void serviceDied(uint64_t /*cookie*/, const android::wp<::android::hidl::base::V1_0::IBase>& /*who*/) {
     LOG_ERROR("Bluetooth HAL service died!");
+    StopWatchLegacy::DumpStopWatchLog();
     hal_service_died();
   }
 };
@@ -102,24 +124,28 @@ class BluetoothHciCallbacks : public V1_1::IBluetoothHciCallbacks {
   }
 
   Return<void> hciEventReceived(const hidl_vec<uint8_t>& event) override {
+    StopWatchLegacy(GetTimerText(__func__, event));
     BT_HDR* packet = WrapPacketAndCopy(MSG_HC_TO_STACK_HCI_EVT, event);
     hci_event_received(FROM_HERE, packet);
     return Void();
   }
 
   Return<void> aclDataReceived(const hidl_vec<uint8_t>& data) override {
+    StopWatchLegacy(GetTimerText(__func__, data));
     BT_HDR* packet = WrapPacketAndCopy(MSG_HC_TO_STACK_HCI_ACL, data);
     acl_event_received(packet);
     return Void();
   }
 
   Return<void> scoDataReceived(const hidl_vec<uint8_t>& data) override {
+    StopWatchLegacy(GetTimerText(__func__, data));
     BT_HDR* packet = WrapPacketAndCopy(MSG_HC_TO_STACK_HCI_SCO, data);
     sco_data_received(packet);
     return Void();
   }
 
   Return<void> isoDataReceived(const hidl_vec<uint8_t>& data) override {
+    StopWatchLegacy(GetTimerText(__func__, data));
     BT_HDR* packet = WrapPacketAndCopy(MSG_HC_TO_STACK_HCI_ISO, data);
     iso_data_received(packet);
     return Void();