Merge "leaudio: Improve dumpsys log for stream creation speed" into main am: 847a24cc38 (ccb7afe5) · Commits · e / os / android_packages_modules_Bluetooth

system/bta/le_audio/client.cc

+169 −26

Original line number	Diff line number	Diff line
		@@ -234,6 +234,120 @@ LeAudioGroupStateMachine::Callbacks* stateMachineCallbacks;
		DeviceGroupsCallbacks* device_group_callbacks;
		LeAudioIsoDataCallback* iso_data_callback;

		class StreamSpeedTracker {
		public:
		StreamSpeedTracker(void)
		: is_started_(false),
		group_id_(bluetooth::groups::kGroupUnknown),
		num_of_devices_(0),
		context_type_(LeAudioContextType::UNSPECIFIED),
		reconfig_start_ts_(0),
		setup_start_ts_(0),
		total_time_(0),
		reconfig_time_(0),
		stream_setup_time_(0) {}

		void Init(int group_id, LeAudioContextType context_type, int num_of_devices) {
		Reset();
		group_id_ = group_id;
		context_type_ = context_type;
		num_of_devices_ = num_of_devices;
		log::verbose("StreamSpeedTracker group_id: {}, context: {} #{}", group_id_,
		ToString(context_type_), num_of_devices);
		}

		void Reset(void) {
		log::verbose("StreamSpeedTracker group_id: {}", group_id_);
		is_started_ = false;
		group_id_ = bluetooth::groups::kGroupUnknown;
		reconfig_start_ts_ = setup_start_ts_ = total_time_ = reconfig_time_ = stream_setup_time_ =
		num_of_devices_ = 0;
		context_type_ = LeAudioContextType::UNSPECIFIED;
		}

		void ReconfigStarted(void) {
		log::verbose("StreamSpeedTracker group_id: {}", group_id_);
		reconfig_time_ = 0;
		is_started_ = true;
		reconfig_start_ts_ = bluetooth::common::time_get_os_boottime_us();
		}

		void StartStream(void) {
		log::verbose("StreamSpeedTracker group_id: {}", group_id_);
		setup_start_ts_ = bluetooth::common::time_get_os_boottime_us();
		is_started_ = true;
		}

		void ReconfigurationComplete(void) {
		reconfig_time_ = (bluetooth::common::time_get_os_boottime_us() - reconfig_start_ts_) / 1000;
		log::verbose("StreamSpeedTracker group_id: {}, {} reconfig time {} ms", group_id_,
		ToString(context_type_), reconfig_time_);
		}

		void StreamCreated(void) {
		stream_setup_time_ = (bluetooth::common::time_get_os_boottime_us() - setup_start_ts_) / 1000;
		log::verbose("StreamSpeedTracker group_id: {}, {} stream create time {} ms", group_id_,
		ToString(context_type_), stream_setup_time_);
		}

		void StopStreamSetup(void) {
		is_started_ = false;
		uint64_t start_ts = reconfig_time_ != 0 ? reconfig_start_ts_ : setup_start_ts_;
		total_time_ = (bluetooth::common::time_get_os_boottime_us() - start_ts) / 1000;
		clock_gettime(CLOCK_REALTIME, &end_ts_);
		log::verbose("StreamSpeedTracker group_id: {}, {} setup time {} ms", group_id_,
		ToString(context_type_), total_time_);
		}

		bool IsStarted(void) {
		if (is_started_) {
		log::verbose("StreamSpeedTracker group_id: {}, {} is_started_: {} ", group_id_,
		ToString(context_type_), is_started_);
		} else {
		log::verbose("StreamSpeedTracker not started ");
		}
		return is_started_;
		}

		void Dump(std::stringstream& stream) {
		char ts[20];
		std::strftime(ts, sizeof(ts), "%T", std::gmtime(&end_ts_.tv_sec));

		if (total_time_ < 900) {
		stream << "[ 🌟 ";
		} else if (total_time_ < 1500) {
		stream << "[ 🌤 ";
		} else if (total_time_ < 2500) {
		stream << "[ 🌧 ";
		} else {
		stream << "[ ❗ ";
		}

		stream << ts << ": Gid: " << group_id_ << "(#" << num_of_devices_ << "), " << context_type_
		<< ", ";
		auto hal_idle = total_time_ - stream_setup_time_ - reconfig_time_;
		if (reconfig_time_ != 0) {
		stream << "t:" << total_time_ << "ms (r:" << reconfig_time_ << "/s:" << stream_setup_time_
		<< "/hal:" << hal_idle << ")";
		} else {
		stream << "t:" << total_time_ << "ms (hal:" << hal_idle << ")";
		}
		stream << "]";
		}

		private:
		bool is_started_;
		int group_id_;
		int num_of_devices_;
		LeAudioContextType context_type_;
		struct timespec end_ts_;
		uint64_t reconfig_start_ts_;
		uint64_t setup_start_ts_;
		uint64_t total_time_;
		uint64_t reconfig_time_;
		uint64_t stream_setup_time_;
		};

		/*
		* Coordinatet Set Identification Profile (CSIP) based on CSIP 1.0
		* and Coordinatet Set Identification Service (CSIS) 1.0
		@@ -282,8 +396,6 @@ public:
		configuration_context_type_(LeAudioContextType::UNINITIALIZED),
		in_call_metadata_context_types_({.sink = AudioContexts(), .source = AudioContexts()}),
		local_metadata_context_types_({.sink = AudioContexts(), .source = AudioContexts()}),
		stream_setup_start_timestamp_(0),
		stream_setup_end_timestamp_(0),
		audio_receiver_state_(AudioState::IDLE),
		audio_sender_state_(AudioState::IDLE),
		in_call_(false),
		@@ -1031,7 +1143,7 @@ public:
		return groupStateMachine_->ConfigureStream(group, configuration_context_type_,
		remote_contexts, ccids);
		} else if (!group_is_streaming) {
		stream_setup_start_timestamp_ = bluetooth::common::time_get_os_boottime_us();
		speed_start_setup(group->group_id_, configuration_context_type, group->NumOfConnected());
		}

		/* If assistant have some connected delegators that needs to be informed
		@@ -1176,7 +1288,7 @@ public:
		pre_configuration_context_type_ = previous_context_type;
		group->SetPendingConfiguration();
		groupStateMachine_->StopStream(group);
		stream_setup_start_timestamp_ = bluetooth::common::time_get_os_boottime_us();
		speed_start_setup(group->group_id_, configuration_context_type_, group->NumOfConnected(), true);
		}

		void SetInCall(bool in_call) override {
		@@ -3396,7 +3508,7 @@ public:
		group->group_id_);
		scheduleAttachDeviceToTheStream(leAudioDevice->address_);
		} else {
		stream_setup_start_timestamp_ = bluetooth::common::time_get_os_boottime_us();
		speed_start_setup(group->group_id_, configuration_context_type_, 1);
		}
		}

		@@ -4059,9 +4171,10 @@ public:
		dprintf(fd, " Codec location: UNKNOWN\n");
		}

		stream << " Start time: ";
		for (auto t : stream_start_history_queue_) {
		stream << static_cast<int>(t) << " ms, ";
		stream << " Stream creation speed: ";
		for (auto t : stream_speed_history_) {
		t.Dump(stream);
		stream << ",";
		}
		stream << "\n";
		printCurrentStreamConfiguration(stream);
		@@ -5589,21 +5702,50 @@ public:
		}
		}

		void take_stream_time(void) {
		if (stream_setup_start_timestamp_ == 0) {
		void speed_start_setup(int group_id, LeAudioContextType context_type, int num_of_connected,
		bool is_reconfig = false) {
		log::verbose("is_started {} is_reconfig {} num_of_connected {}", speed_tracker_.IsStarted(),
		is_reconfig, num_of_connected);
		if (!speed_tracker_.IsStarted()) {
		speed_tracker_.Init(group_id, context_type, num_of_connected);
		}
		if (is_reconfig) {
		speed_tracker_.ReconfigStarted();
		} else {
		speed_tracker_.StartStream();
		}
		}

		void speed_stop_reconfig(void) {
		log::verbose("");
		if (!speed_tracker_.IsStarted()) {
		return;
		}
		speed_tracker_.ReconfigurationComplete();
		}

		if (stream_start_history_queue_.size() == 10) {
		stream_start_history_queue_.pop_back();
		void speed_stream_created() {
		log::verbose("");
		if (!speed_tracker_.IsStarted()) {
		return;
		}

		stream_setup_end_timestamp_ = bluetooth::common::time_get_os_boottime_us();
		stream_start_history_queue_.emplace_front(
		(stream_setup_end_timestamp_ - stream_setup_start_timestamp_) / 1000);
		speed_tracker_.StreamCreated();
		}

		stream_setup_end_timestamp_ = 0;
		stream_setup_start_timestamp_ = 0;
		void speed_stop_setup() {
		log::verbose("");
		if (!speed_tracker_.IsStarted()) {
		return;
		}

		if (stream_speed_history_.size() == 10) {
		stream_speed_history_.pop_back();
		}

		speed_tracker_.StopStreamSetup();
		stream_speed_history_.emplace_front(speed_tracker_);
		speed_tracker_.Reset();
		}

		void notifyGroupStreamStatus(int group_id, GroupStreamStatus groupStreamStatus) {
		@@ -5658,6 +5800,7 @@ public:
		*/
		CancelStreamingRequest();
		ReconfigurationComplete(previously_active_directions);
		speed_stop_reconfig();
		}

		void OnStateMachineStatusReportCb(int group_id, GroupStreamStatus status) {
		@@ -5676,8 +5819,7 @@ public:
		return;
		}

		take_stream_time();

		speed_stream_created();
		bluetooth::le_audio::MetricsCollector::Get()->OnStreamStarted(active_group_id_,
		configuration_context_type_);

		@@ -5699,6 +5841,7 @@ public:
		* Just stop streaming
		*/
		log::warn("Stopping stream for group {} as AF not interested.", group_id);
		speed_stop_setup();
		groupStateMachine_->StopStream(group);
		return;
		}
		@@ -5713,6 +5856,7 @@ public:
		"reconfigure to {}",
		ToString(group->GetConfigurationContextType()),
		ToString(configuration_context_type_));
		speed_stop_setup();
		initReconfiguration(group, group->GetConfigurationContextType());
		return;
		}
		@@ -5733,11 +5877,12 @@ public:
		if (audio_receiver_state_ == AudioState::READY_TO_START) {
		StartReceivingAudio(group_id);
		}

		speed_stop_setup();
		break;
		}
		case GroupStreamStatus::SUSPENDED:
		stream_setup_end_timestamp_ = 0;
		stream_setup_start_timestamp_ = 0;
		speed_tracker_.Reset();
		/** Stop Audio but don't release all the Audio resources */
		SuspendAudio();
		break;
		@@ -5811,8 +5956,7 @@ public:
		}
		}

		stream_setup_end_timestamp_ = 0;
		stream_setup_start_timestamp_ = 0;
		speed_tracker_.Reset();
		CancelStreamingRequest();

		if (group) {
		@@ -5879,9 +6023,8 @@ private:
		"persist.bluetooth.leaudio.allow.multiple.contexts";
		BidirectionalPair<AudioContexts> in_call_metadata_context_types_;
		BidirectionalPair<AudioContexts> local_metadata_context_types_;
		uint64_t stream_setup_start_timestamp_;
		uint64_t stream_setup_end_timestamp_;
		std::deque<uint64_t> stream_start_history_queue_;
		StreamSpeedTracker speed_tracker_;
		std::deque<StreamSpeedTracker> stream_speed_history_;

		/* Microphone (s) */
		AudioState audio_receiver_state_;