Add StopWatch for Hwbinder callback function (69a1452d) · Commits · e / os / android_packages_modules_Bluetooth

system/audio_hal_interface/client_interface.cc

+7 −0

Original line number	Diff line number	Diff line
		@@ -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)

system/common/Android.bp

+1 −0

Original line number	Diff line number	Diff line
		@@ -28,6 +28,7 @@ cc_library_static {
		"os_utils.cc",
		"repeating_timer.cc",
		"time_util.cc",
		"stop_watch_legacy.cc",
		],
		shared_libs: [
		"libcrypto",

system/common/stop_watch_legacy.cc

0 → 100644

+85 −0

Original line number	Diff line number	Diff line
		/*
		* 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

system/common/stop_watch_legacy.h

0 → 100644

+39 −0

Original line number	Diff line number	Diff line
		/*
		* 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

system/hci/src/hci_layer_android.cc

+31 −5

Original line number	Diff line number	Diff line
		@@ -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();