From 69a1452dde60cfb80c637bf9fe0547c93f00e91f Mon Sep 17 00:00:00 2001
From: weichinweng <weichinweng@google.com>
Date: Wed, 3 Mar 2021 10:19:19 +0800
Subject: [PATCH] Add StopWatch for Hwbinder callback function
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 | 7 ++
system/common/Android.bp | 1 +
system/common/stop_watch_legacy.cc | 85 +++++++++++++++++++
system/common/stop_watch_legacy.h | 39 +++++++++
system/hci/src/hci_layer_android.cc | 36 ++++++--
5 files changed, 163 insertions(+), 5 deletions(-)
create mode 100644 system/common/stop_watch_legacy.cc
create mode 100644 system/common/stop_watch_legacy.h
diff --git a/system/audio_hal_interface/client_interface.cc b/system/audio_hal_interface/client_interface.cc
index 94c4c71ca59..9b7f75ca53b 100644
--- a/system/audio_hal_interface/client_interface.cc
+++ b/system/audio_hal_interface/client_interface.cc
@@ -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)
diff --git a/system/common/Android.bp b/system/common/Android.bp
index 7cab6f4f948..2539959ed89 100644
--- a/system/common/Android.bp
+++ b/system/common/Android.bp
@@ -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/system/common/stop_watch_legacy.cc b/system/common/stop_watch_legacy.cc
new file mode 100644
index 00000000000..0327568e978
--- /dev/null
+++ b/system/common/stop_watch_legacy.cc
@@ -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/system/common/stop_watch_legacy.h b/system/common/stop_watch_legacy.h
new file mode 100644
index 00000000000..b5cdc3dd07d
--- /dev/null
+++ b/system/common/stop_watch_legacy.h
@@ -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
diff --git a/system/hci/src/hci_layer_android.cc b/system/hci/src/hci_layer_android.cc
index f6b83868087..79eb8f1a653 100644
--- a/system/hci/src/hci_layer_android.cc
+++ b/system/hci/src/hci_layer_android.cc
@@ -20,21 +20,25 @@
#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();
--
GitLab