diff --git a/system/btif/include/btif_a2dp.h b/system/btif/include/btif_a2dp.h index f701614e771075cad7caecdc20d03fbbd5595ea5..26f370a078962809f5c913c81b8b378ec8e96085 100644 --- a/system/btif/include/btif_a2dp.h +++ b/system/btif/include/btif_a2dp.h @@ -58,8 +58,4 @@ void btif_a2dp_on_offload_started(tBTA_AV_STATUS status); // information. void btif_debug_a2dp_dump(int fd); -// Update the A2DP-related metrics. -// This function should be called before collecting the metrics. -void btif_update_a2dp_metrics(void); - #endif /* BTIF_A2DP_H */ diff --git a/system/btif/src/bluetooth.cc b/system/btif/src/bluetooth.cc index 20c3209864c257becd5e6ee661183e0135db3ace..085453ff8cf9ad4c69638c998a0f168baa00af5c 100644 --- a/system/btif/src/bluetooth.cc +++ b/system/btif/src/bluetooth.cc @@ -298,8 +298,8 @@ static int read_energy_info() { static void dump(int fd, const char** arguments) { if (arguments != NULL && arguments[0] != NULL) { if (strncmp(arguments[0], "--proto-bin", 11) == 0) { - btif_update_a2dp_metrics(); - metrics_write(fd, true); + system_bt_osi::BluetoothMetricsLogger::GetInstance()->WriteBase64(fd, + true); return; } } diff --git a/system/btif/src/btif_a2dp.cc b/system/btif/src/btif_a2dp.cc index 7494ba9c78c206d44d8a7fdbe3250a6cf860eaf5..90c650446b1fc6efcd5cdccec46adc2209dfae06 100644 --- a/system/btif/src/btif_a2dp.cc +++ b/system/btif/src/btif_a2dp.cc @@ -121,8 +121,3 @@ void btif_debug_a2dp_dump(int fd) { btif_a2dp_source_debug_dump(fd); btif_a2dp_sink_debug_dump(fd); } - -void btif_update_a2dp_metrics(void) { - btif_a2dp_source_update_metrics(); - btif_a2dp_sink_update_metrics(); -} diff --git a/system/btif/src/btif_a2dp_sink.cc b/system/btif/src/btif_a2dp_sink.cc index 3baaeeeebc9c7612e25cf16821bbaca8e1f88cce..116de2f7d9a399ede28d8a7102c1a62158a2a003 100644 --- a/system/btif/src/btif_a2dp_sink.cc +++ b/system/btif/src/btif_a2dp_sink.cc @@ -552,10 +552,6 @@ void btif_a2dp_sink_debug_dump(UNUSED_ATTR int fd) { // Nothing to do } -void btif_a2dp_sink_update_metrics(void) { - // Nothing to do -} - void btif_a2dp_sink_set_focus_state_req(btif_a2dp_sink_focus_state_t state) { tBTIF_MEDIA_SINK_FOCUS_UPDATE* p_buf = reinterpret_cast<tBTIF_MEDIA_SINK_FOCUS_UPDATE*>( diff --git a/system/btif/src/btif_a2dp_source.cc b/system/btif/src/btif_a2dp_source.cc index b6077fc66d0c1a47d7b28e711f7db9ee7da919e2..443d62dd50dc77a02897154ce8206413cb005800 100644 --- a/system/btif/src/btif_a2dp_source.cc +++ b/system/btif/src/btif_a2dp_source.cc @@ -22,6 +22,7 @@ #include <base/logging.h> #include <limits.h> #include <string.h> +#include <algorithm> #include "audio_a2dp_hw.h" #include "bt_common.h" @@ -42,6 +43,9 @@ #include "osi/include/time.h" #include "uipc.h" +using system_bt_osi::BluetoothMetricsLogger; +using system_bt_osi::A2dpSessionMetrics; + /** * The typical runlevel of the tx queue size is ~1 buffer * but due to link flow control or thread preemption in lower @@ -118,6 +122,7 @@ typedef struct { typedef struct { uint64_t session_start_us; + uint64_t session_end_us; scheduling_stats_t tx_queue_enqueue_stats; scheduling_stats_t tx_queue_dequeue_stats; @@ -153,6 +158,7 @@ typedef struct { const tA2DP_ENCODER_INTERFACE* encoder_interface; period_ms_t encoder_interval_ms; /* Local copy of the encoder interval */ btif_media_stats_t stats; + btif_media_stats_t accumulated_stats; } tBTIF_A2DP_SOURCE_CB; static tBTIF_A2DP_SOURCE_CB btif_a2dp_source_cb; @@ -194,6 +200,55 @@ UNUSED_ATTR static const char* dump_media_event(uint16_t event) { return "UNKNOWN A2DP SOURCE EVENT"; } +void btif_a2dp_source_accumulate_scheduling_stats(scheduling_stats_t* src, + scheduling_stats_t* dst) { + dst->total_updates += src->total_updates; + dst->last_update_us = src->last_update_us; + dst->overdue_scheduling_count += src->overdue_scheduling_count; + dst->total_overdue_scheduling_delta_us += + src->total_overdue_scheduling_delta_us; + dst->max_overdue_scheduling_delta_us = + std::max(dst->max_overdue_scheduling_delta_us, + src->max_overdue_scheduling_delta_us); + dst->premature_scheduling_count += src->premature_scheduling_count; + dst->total_premature_scheduling_delta_us += + src->total_premature_scheduling_delta_us; + dst->max_premature_scheduling_delta_us = + std::max(dst->max_premature_scheduling_delta_us, + src->max_premature_scheduling_delta_us); + dst->exact_scheduling_count += src->exact_scheduling_count; + dst->total_scheduling_time_us += src->total_scheduling_time_us; +} + +void btif_a2dp_source_accumulate_stats(btif_media_stats_t* src, + btif_media_stats_t* dst) { + dst->tx_queue_total_frames += src->tx_queue_total_frames; + dst->tx_queue_max_frames_per_packet = std::max( + dst->tx_queue_max_frames_per_packet, src->tx_queue_max_frames_per_packet); + dst->tx_queue_total_queueing_time_us += src->tx_queue_total_queueing_time_us; + dst->tx_queue_max_queueing_time_us = std::max( + dst->tx_queue_max_queueing_time_us, src->tx_queue_max_queueing_time_us); + dst->tx_queue_total_readbuf_calls += src->tx_queue_total_readbuf_calls; + dst->tx_queue_last_readbuf_us = src->tx_queue_last_readbuf_us; + dst->tx_queue_total_flushed_messages += src->tx_queue_total_flushed_messages; + dst->tx_queue_last_flushed_us = src->tx_queue_last_flushed_us; + dst->tx_queue_total_dropped_messages += src->tx_queue_total_dropped_messages; + dst->tx_queue_max_dropped_messages = std::max( + dst->tx_queue_max_dropped_messages, src->tx_queue_max_dropped_messages); + dst->tx_queue_dropouts += src->tx_queue_dropouts; + dst->tx_queue_last_dropouts_us = src->tx_queue_last_dropouts_us; + dst->media_read_total_underflow_bytes += + src->media_read_total_underflow_bytes; + dst->media_read_total_underflow_count += + src->media_read_total_underflow_count; + dst->media_read_last_underflow_us = src->media_read_last_underflow_us; + btif_a2dp_source_accumulate_scheduling_stats(&src->tx_queue_enqueue_stats, + &dst->tx_queue_enqueue_stats); + btif_a2dp_source_accumulate_scheduling_stats(&src->tx_queue_dequeue_stats, + &dst->tx_queue_dequeue_stats); + memset(src, 0, sizeof(btif_media_stats_t)); +} + bool btif_a2dp_source_startup(void) { if (btif_a2dp_source_state != BTIF_A2DP_SOURCE_STATE_OFF) { APPL_TRACE_ERROR("%s: A2DP Source media task already running", __func__); @@ -214,7 +269,6 @@ bool btif_a2dp_source_startup(void) { return false; } - btif_a2dp_source_cb.stats.session_start_us = time_get_os_boottime_us(); btif_a2dp_source_cb.tx_audio_queue = fixed_queue_new(SIZE_MAX); btif_a2dp_source_cb.cmd_msg_queue = fixed_queue_new(SIZE_MAX); @@ -236,6 +290,8 @@ static void btif_a2dp_source_startup_delayed(UNUSED_ATTR void* context) { raise_priority_a2dp(TASK_HIGH_MEDIA); btif_a2dp_control_init(); btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_RUNNING; + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_BREDR, 0); } void btif_a2dp_source_shutdown(void) { @@ -268,6 +324,8 @@ static void btif_a2dp_source_shutdown_delayed(UNUSED_ATTR void* context) { btif_a2dp_source_cb.tx_audio_queue = NULL; btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_OFF; + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd("A2DP_SHUTDOWN", + 0); } bool btif_a2dp_source_media_task_is_running(void) { @@ -333,6 +391,9 @@ void btif_a2dp_source_start_audio_req(void) { p_buf->event = BTIF_MEDIA_AUDIO_TX_START; fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf); + memset(&btif_a2dp_source_cb.stats, 0, sizeof(btif_media_stats_t)); + btif_a2dp_source_cb.stats.session_start_us = time_get_os_boottime_us(); + btif_a2dp_source_cb.stats.session_end_us = 0; } void btif_a2dp_source_stop_audio_req(void) { @@ -350,8 +411,13 @@ void btif_a2dp_source_stop_audio_req(void) { * after the "BTIF_AV_CLEANUP_REQ_EVT -> btif_a2dp_source_shutdown()" * processing during the shutdown of the Bluetooth stack. */ - if (btif_a2dp_source_cb.cmd_msg_queue != NULL) + if (btif_a2dp_source_cb.cmd_msg_queue != NULL) { fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf); + } + btif_a2dp_source_cb.stats.session_end_us = time_get_os_boottime_us(); + btif_a2dp_source_update_metrics(); + btif_a2dp_source_accumulate_stats(&btif_a2dp_source_cb.stats, + &btif_a2dp_source_cb.accumulated_stats); } static void btif_a2dp_source_encoder_init(void) { @@ -649,8 +715,8 @@ static bool btif_a2dp_source_enqueue_callback(BT_HDR* p_buf, size_t frames_n) { // Flush all queued buffers size_t drop_n = fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue); - if (btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages < drop_n) - btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages = drop_n; + btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages = std::max( + drop_n, btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages); while (fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue)) { btif_a2dp_source_cb.stats.tx_queue_total_dropped_messages++; osi_free(fixed_queue_try_dequeue(btif_a2dp_source_cb.tx_audio_queue)); @@ -663,8 +729,8 @@ static bool btif_a2dp_source_enqueue_callback(BT_HDR* p_buf, size_t frames_n) { /* Update the statistics */ btif_a2dp_source_cb.stats.tx_queue_total_frames += frames_n; - if (frames_n > btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet) - btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet = frames_n; + btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet = std::max( + frames_n, btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet); CHECK(btif_a2dp_source_cb.encoder_interface != NULL); update_scheduling_stats(&btif_a2dp_source_cb.stats.tx_queue_enqueue_stats, now_us, @@ -752,8 +818,8 @@ static void update_scheduling_stats(scheduling_stats_t* stats, uint64_t now_us, uint64_t delta_us = now_us - deadline_us; // Ignore extreme outliers if (delta_us < 10 * expected_delta) { - if (stats->max_overdue_scheduling_delta_us < delta_us) - stats->max_overdue_scheduling_delta_us = delta_us; + stats->max_overdue_scheduling_delta_us = + std::max(delta_us, stats->max_overdue_scheduling_delta_us); stats->total_overdue_scheduling_delta_us += delta_us; stats->overdue_scheduling_count++; stats->total_scheduling_time_us += now_us - last_us; @@ -763,8 +829,8 @@ static void update_scheduling_stats(scheduling_stats_t* stats, uint64_t now_us, uint64_t delta_us = deadline_us - now_us; // Ignore extreme outliers if (delta_us < 10 * expected_delta) { - if (stats->max_premature_scheduling_delta_us < delta_us) - stats->max_premature_scheduling_delta_us = delta_us; + stats->max_premature_scheduling_delta_us = + std::max(delta_us, stats->max_premature_scheduling_delta_us); stats->total_premature_scheduling_delta_us += delta_us; stats->premature_scheduling_count++; stats->total_scheduling_time_us += now_us - last_us; @@ -777,10 +843,15 @@ static void update_scheduling_stats(scheduling_stats_t* stats, uint64_t now_us, } void btif_a2dp_source_debug_dump(int fd) { + btif_a2dp_source_accumulate_stats(&btif_a2dp_source_cb.stats, + &btif_a2dp_source_cb.accumulated_stats); uint64_t now_us = time_get_os_boottime_us(); - btif_media_stats_t* stats = &btif_a2dp_source_cb.stats; - scheduling_stats_t* enqueue_stats = &stats->tx_queue_enqueue_stats; - scheduling_stats_t* dequeue_stats = &stats->tx_queue_dequeue_stats; + btif_media_stats_t* accumulated_stats = + &btif_a2dp_source_cb.accumulated_stats; + scheduling_stats_t* enqueue_stats = + &accumulated_stats->tx_queue_enqueue_stats; + scheduling_stats_t* dequeue_stats = + &accumulated_stats->tx_queue_dequeue_stats; size_t ave_size; uint64_t ave_time_us; @@ -791,7 +862,7 @@ void btif_a2dp_source_debug_dump(int fd) { " Counts (enqueue/dequeue/readbuf) : %zu / " "%zu / %zu\n", enqueue_stats->total_updates, dequeue_stats->total_updates, - stats->tx_queue_total_readbuf_calls); + accumulated_stats->tx_queue_total_readbuf_calls); dprintf( fd, @@ -803,57 +874,64 @@ void btif_a2dp_source_debug_dump(int fd) { (dequeue_stats->last_update_us > 0) ? (unsigned long long)(now_us - dequeue_stats->last_update_us) / 1000 : 0, - (stats->tx_queue_last_readbuf_us > 0) - ? (unsigned long long)(now_us - stats->tx_queue_last_readbuf_us) / + (accumulated_stats->tx_queue_last_readbuf_us > 0) + ? (unsigned long long)(now_us - + accumulated_stats->tx_queue_last_readbuf_us) / 1000 : 0); ave_size = 0; if (enqueue_stats->total_updates != 0) - ave_size = stats->tx_queue_total_frames / enqueue_stats->total_updates; + ave_size = + accumulated_stats->tx_queue_total_frames / enqueue_stats->total_updates; dprintf(fd, " Frames per packet (total/max/ave) : %zu / " "%zu / %zu\n", - stats->tx_queue_total_frames, stats->tx_queue_max_frames_per_packet, - ave_size); + accumulated_stats->tx_queue_total_frames, + accumulated_stats->tx_queue_max_frames_per_packet, ave_size); dprintf(fd, " Counts (flushed/dropped/dropouts) : %zu / " "%zu / %zu\n", - stats->tx_queue_total_flushed_messages, - stats->tx_queue_total_dropped_messages, stats->tx_queue_dropouts); + accumulated_stats->tx_queue_total_flushed_messages, + accumulated_stats->tx_queue_total_dropped_messages, + accumulated_stats->tx_queue_dropouts); dprintf(fd, " Counts (max dropped) : %zu\n", - stats->tx_queue_max_dropped_messages); + accumulated_stats->tx_queue_max_dropped_messages); dprintf( fd, " Last update time ago in ms (flushed/dropped) : %llu / " "%llu\n", - (stats->tx_queue_last_flushed_us > 0) - ? (unsigned long long)(now_us - stats->tx_queue_last_flushed_us) / + (accumulated_stats->tx_queue_last_flushed_us > 0) + ? (unsigned long long)(now_us - + accumulated_stats->tx_queue_last_flushed_us) / 1000 : 0, - (stats->tx_queue_last_dropouts_us > 0) - ? (unsigned long long)(now_us - stats->tx_queue_last_dropouts_us) / + (accumulated_stats->tx_queue_last_dropouts_us > 0) + ? (unsigned long long)(now_us - + accumulated_stats->tx_queue_last_dropouts_us) / 1000 : 0); dprintf(fd, " Counts (underflow) : %zu\n", - stats->media_read_total_underflow_count); + accumulated_stats->media_read_total_underflow_count); dprintf(fd, " Bytes (underflow) : %zu\n", - stats->media_read_total_underflow_bytes); + accumulated_stats->media_read_total_underflow_bytes); - dprintf( - fd, " Last update time ago in ms (underflow) : %llu\n", - (stats->media_read_last_underflow_us > 0) - ? (unsigned long long)(now_us - stats->media_read_last_underflow_us) / - 1000 - : 0); + dprintf(fd, + " Last update time ago in ms (underflow) : %llu\n", + (accumulated_stats->media_read_last_underflow_us > 0) + ? (unsigned long long)(now_us - + accumulated_stats + ->media_read_last_underflow_us) / + 1000 + : 0); // // TxQueue enqueue stats @@ -939,54 +1017,40 @@ void btif_a2dp_source_debug_dump(int fd) { } void btif_a2dp_source_update_metrics(void) { - uint64_t now_us = time_get_os_boottime_us(); btif_media_stats_t* stats = &btif_a2dp_source_cb.stats; scheduling_stats_t* dequeue_stats = &stats->tx_queue_dequeue_stats; - int32_t media_timer_min_ms = 0; - int32_t media_timer_max_ms = 0; - int32_t media_timer_avg_ms = 0; - int32_t buffer_overruns_max_count = 0; - int32_t buffer_overruns_total = 0; - float buffer_underruns_average = 0.0; - int32_t buffer_underruns_count = 0; - - int64_t session_duration_sec = - (now_us - stats->session_start_us) / (1000 * 1000); - - /* NOTE: Disconnect reason is unused */ - const char* disconnect_reason = NULL; - uint32_t device_class = BTM_COD_MAJOR_AUDIO; + A2dpSessionMetrics metrics; + int64_t session_end_us = stats->session_end_us == 0 + ? time_get_os_boottime_us() + : stats->session_end_us; + metrics.audio_duration_ms = (session_end_us - stats->session_start_us) / 1000; if (dequeue_stats->total_updates > 1) { - media_timer_min_ms = + metrics.media_timer_min_ms = btif_a2dp_source_cb.encoder_interval_ms - (dequeue_stats->max_premature_scheduling_delta_us / 1000); - media_timer_max_ms = + metrics.media_timer_max_ms = btif_a2dp_source_cb.encoder_interval_ms + (dequeue_stats->max_overdue_scheduling_delta_us / 1000); - uint64_t total_scheduling_count = - dequeue_stats->overdue_scheduling_count + - dequeue_stats->premature_scheduling_count + - dequeue_stats->exact_scheduling_count; - if (total_scheduling_count > 0) { - media_timer_avg_ms = dequeue_stats->total_scheduling_time_us / - (1000 * total_scheduling_count); + metrics.total_scheduling_count = dequeue_stats->overdue_scheduling_count + + dequeue_stats->premature_scheduling_count + + dequeue_stats->exact_scheduling_count; + if (metrics.total_scheduling_count > 0) { + metrics.media_timer_avg_ms = dequeue_stats->total_scheduling_time_us / + (1000 * metrics.total_scheduling_count); } - buffer_overruns_max_count = stats->tx_queue_max_dropped_messages; - buffer_overruns_total = stats->tx_queue_total_dropped_messages; - buffer_underruns_count = stats->media_read_total_underflow_count; - if (buffer_underruns_count > 0) { - buffer_underruns_average = - stats->media_read_total_underflow_bytes / buffer_underruns_count; + metrics.buffer_overruns_max_count = stats->tx_queue_max_dropped_messages; + metrics.buffer_overruns_total = stats->tx_queue_total_dropped_messages; + metrics.buffer_underruns_count = stats->media_read_total_underflow_count; + if (metrics.buffer_underruns_count > 0) { + metrics.buffer_underruns_average = + stats->media_read_total_underflow_bytes / + metrics.buffer_underruns_count; } } - - metrics_a2dp_session( - session_duration_sec, disconnect_reason, device_class, media_timer_min_ms, - media_timer_max_ms, media_timer_avg_ms, buffer_overruns_max_count, - buffer_overruns_total, buffer_underruns_average, buffer_underruns_count); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics); } static void btm_read_rssi_cb(void* data) { diff --git a/system/btif/src/btif_dm.cc b/system/btif/src/btif_dm.cc index 09fbd0b2f99d3706281461b9d29fcaec99016aa7..2a725fd85b1caeef366551059a3ea5eecf29e3a5 100644 --- a/system/btif/src/btif_dm.cc +++ b/system/btif/src/btif_dm.cc @@ -3301,26 +3301,27 @@ static void btif_stats_add_bond_event(const bt_bdaddr_t* bd_addr, int type; btif_get_device_type(bd_addr->address, &type); - device_type_t device_type; + system_bt_osi::device_type_t device_type; switch (type) { case BT_DEVICE_TYPE_BREDR: - device_type = DEVICE_TYPE_BREDR; + device_type = system_bt_osi::DEVICE_TYPE_BREDR; break; case BT_DEVICE_TYPE_BLE: - device_type = DEVICE_TYPE_LE; + device_type = system_bt_osi::DEVICE_TYPE_LE; break; case BT_DEVICE_TYPE_DUMO: - device_type = DEVICE_TYPE_DUMO; + device_type = system_bt_osi::DEVICE_TYPE_DUMO; break; default: - device_type = DEVICE_TYPE_UNKNOWN; + device_type = system_bt_osi::DEVICE_TYPE_UNKNOWN; break; } uint32_t cod = get_cod(bd_addr); uint64_t ts = event->timestamp.tv_sec * 1000 + event->timestamp.tv_nsec / 1000000; - metrics_pair_event(0, ts, cod, device_type); + system_bt_osi::BluetoothMetricsLogger::GetInstance()->LogPairEvent( + 0, ts, cod, device_type); } void btif_debug_bond_event_dump(int fd) { diff --git a/system/osi/Android.mk b/system/osi/Android.mk index cd176b72309d20abbf8fad6676206c9f2f22c746..27dd82d34a31e38286712b7472df10f968f98eaf 100644 --- a/system/osi/Android.mk +++ b/system/osi/Android.mk @@ -66,6 +66,7 @@ btosiCommonTestSrc := \ ./test/hash_map_utils_test.cc \ ./test/leaky_bonded_queue_test.cc \ ./test/list_test.cc \ + ./test/metrics_test.cc \ ./test/properties_test.cc \ ./test/rand_test.cc \ ./test/reactor_test.cc \ @@ -77,6 +78,7 @@ btosiCommonTestSrc := \ btosiCommonIncludes := \ $(LOCAL_PATH)/.. \ + $(LOCAL_PATH)/../include \ $(LOCAL_PATH)/../utils/include \ $(LOCAL_PATH)/../stack/include \ $(bluetooth_C_INCLUDES) diff --git a/system/osi/BUILD.gn b/system/osi/BUILD.gn index a60b2fbe17ee9efb737d9fbdd9f04b7b42d1ba1c..3ae61307875150c12b28af0aa45fcce5c026e3d4 100644 --- a/system/osi/BUILD.gn +++ b/system/osi/BUILD.gn @@ -90,6 +90,7 @@ executable("net_test_osi") { deps = [ "//osi", "//third_party/googletest:gtest_main", + "//third_party/googletest:gmock_main", "//third_party/libchrome:base", ] diff --git a/system/osi/include/metrics.h b/system/osi/include/metrics.h index abe2225a7a15e687d670bdcb314bc1a6e5992b2d..e2bc6cbc4a1ae39cbdf1a042f5d178567d6d4409 100644 --- a/system/osi/include/metrics.h +++ b/system/osi/include/metrics.h @@ -19,6 +19,12 @@ #pragma once #include <stdint.h> +#include <memory> +#include <string> + +namespace system_bt_osi { + +// Typedefs to hide protobuf definition to the rest of stack typedef enum { DEVICE_TYPE_UNKNOWN, @@ -27,26 +33,12 @@ typedef enum { DEVICE_TYPE_DUMO, } device_type_t; -// Record a pairing event at Unix epoch time |timestamp_ms| -// |device_class| and |device_type| denote the type of device paired. -// |disconnect_reason| is the HCI reason for pairing disconnection, -// see stack/include/hcidefs.h -void metrics_pair_event(uint32_t disconnect_reason, uint64_t timestamp_ms, - uint32_t device_class, device_type_t device_type); - typedef enum { WAKE_EVENT_UNKNOWN, WAKE_EVENT_ACQUIRED, WAKE_EVENT_RELEASED, } wake_event_type_t; -// Record a wake event at Unix epoch time |timestamp_ms|. -// |type| specifies whether it was acquired or relased, -// |requestor| if provided is the service requesting the wake lock. -// |name| is the name of the wake lock held. -void metrics_wake_event(wake_event_type_t type, const char* requestor, - const char* name, uint64_t timestamp_ms); - typedef enum { SCAN_TYPE_UNKNOWN, SCAN_TECH_TYPE_LE, @@ -54,36 +46,207 @@ typedef enum { SCAN_TECH_TYPE_BOTH, } scan_tech_t; -// Record a scan event at Unix epoch time |timestamp_ms|. -// |start| is true if this is the beginning of the scan. -// |initiator| is a unique ID identifying the app starting the scan. -// |type| is whether the scan reports BR/EDR, LE, or both. -// |results| is the number of results to be reported. -void metrics_scan_event(bool start, const char* initator, scan_tech_t type, - uint32_t results, uint64_t timestamp_ms); - -// Record A2DP session information. -// |session_duration_sec| is the session duration (in seconds). -// |device_class| is the device class of the paired device. -// |media_timer_min_ms| is the minimum scheduled time (in milliseconds) -// of the media timer. -// |media_timer_max_ms| is the maximum scheduled time (in milliseconds) -// of the media timer. -// |media_timer_avg_ms| is the average scheduled time (in milliseconds) -// of the media timer. -// |buffer_overruns_max_count| - TODO - not clear what this is. -// |buffer_overruns_total| is the number of times the media buffer with -// audio data has overrun. -// |buffer_underruns_average| - TODO - not clear what this is. -// |buffer_underruns_count| is the number of times there was no enough -// audio data to add to the media buffer. -void metrics_a2dp_session( - int64_t session_duration_sec, const char* disconnect_reason, - uint32_t device_class, int32_t media_timer_min_ms, - int32_t media_timer_max_ms, int32_t media_timer_avg_ms, - int32_t buffer_overruns_max_count, int32_t buffer_overruns_total, - float buffer_underruns_average, int32_t buffer_underruns_count); - -// Writes the metrics, in packed protobuf format, into the descriptor |fd|. -// If |clear| is true, metrics events are cleared afterwards. -void metrics_write(int fd, bool clear); +typedef enum { + CONNECTION_TECHNOLOGY_TYPE_UNKNOWN, + CONNECTION_TECHNOLOGY_TYPE_LE, + CONNECTION_TECHNOLOGY_TYPE_BREDR, +} connection_tech_t; + +/* Values of A2DP metrics that we care about + * + * audio_duration_ms : sum of audio duration (in milliseconds). + * device_class: device class of the paired device. + * media_timer_min_ms : minimum scheduled time (in milliseconds) + * of the media timer. + * media_timer_max_ms: maximum scheduled time (in milliseconds) + * of the media timer. + * media_timer_avg_ms: average scheduled time (in milliseconds) + * of the media timer. + * buffer_overruns_max_count: TODO - not clear what this is. + * buffer_overruns_total : number of times the media buffer with + * audio data has overrun + * buffer_underruns_average: TODO - not clear what this is. + * buffer_underruns_count: number of times there was no enough + * audio data to add to the media buffer. + * NOTE: Negative values are invalid +*/ +class A2dpSessionMetrics { + public: + A2dpSessionMetrics() {} + + /* + * Update the metrics value in the current metrics object using the metrics + * objects supplied + */ + void Update(const A2dpSessionMetrics& metrics); + + /* + * Compare whether two metrics objects are equal + */ + bool operator==(const A2dpSessionMetrics& rhs) const; + + /* + * Initialize all values to -1 which is invalid in order to make a distinction + * between 0 and invalid values + */ + int64_t audio_duration_ms = -1; + int32_t media_timer_min_ms = -1; + int32_t media_timer_max_ms = -1; + int32_t media_timer_avg_ms = -1; + int64_t total_scheduling_count = -1; + int32_t buffer_overruns_max_count = -1; + int32_t buffer_overruns_total = -1; + float buffer_underruns_average = -1; + int32_t buffer_underruns_count = -1; +}; + +class BluetoothMetricsLogger { + public: + static BluetoothMetricsLogger* GetInstance() { + static BluetoothMetricsLogger* instance = new BluetoothMetricsLogger(); + return instance; + } + + /* + * Record a pairing event + * + * Parameters: + * timestamp_ms: Unix epoch time in milliseconds + * device_class: class of remote device + * device_type: type of remote device + * disconnect_reason: HCI reason for pairing disconnection. + * See: stack/include/hcidefs.h + */ + void LogPairEvent(uint32_t disconnect_reason, uint64_t timestamp_ms, + uint32_t device_class, device_type_t device_type); + + /* + * Record a wake event + * + * Parameters: + * timestamp_ms: Unix epoch time in milliseconds + * type: whether it was acquired or released + * requestor: if provided is the service requesting the wake lock + * name: the name of the wake lock held + */ + void LogWakeEvent(wake_event_type_t type, const std::string& requestor, + const std::string& name, uint64_t timestamp_ms); + + /* + * Record a scan event + * + * Parameters + * timestamp_ms : Unix epoch time in milliseconds + * start : true if this is the beginning of the scan + * initiator: a unique ID identifying the app starting the scan + * type: whether the scan reports BR/EDR, LE, or both. + * results: number of results to be reported. + */ + void LogScanEvent(bool start, const std::string& initator, scan_tech_t type, + uint32_t results, uint64_t timestamp_ms); + + /* + * Start logging a Bluetooth session + * + * A Bluetooth session is defined a a connection between this device and + * another remote device which may include multiple profiles and protocols + * + * Only one Bluetooth session can exist at one time. Calling this method twice + * without LogBluetoothSessionEnd will result in logging a premature end of + * current Bluetooth session + * + * Parameters: + * connection_tech_type : type of connection technology + * timestamp_ms : the timestamp for session start, 0 means now + * + */ + void LogBluetoothSessionStart(connection_tech_t connection_tech_type, + uint64_t timestamp_ms); + + /* + * Stop logging a Bluetooth session and pushes it to the log queue + * + * If no Bluetooth session exist, this method exits immediately + * + * Parameters: + * disconnect_reason : A string representation of disconnect reason + * timestamp_ms : the timestamp of session end, 0 means now + * + */ + void LogBluetoothSessionEnd(const std::string& disconnect_reason, + uint64_t timestamp_ms); + + /* + * Log information about remote device in a current Bluetooth session + * + * If a Bluetooth session does not exist, create one with default parameter + * and timestamp now + * + * Parameters: + * device_class : device_class defined in btm_api_types.h + * device_type : type of remote device + */ + void LogBluetoothSessionDeviceInfo(uint32_t device_class, + device_type_t device_type); + + /* + * Log A2DP Audio Session Information + * + * - Repeated calls to this method will override previous metrics if in the + * same Bluetooth connection + * - If a Bluetooth session does not exist, create one with default parameter + * and timestamp now + * + * Parameters: + * a2dp_session_metrics - pointer to struct holding a2dp stats + * + */ + void LogA2dpSession(const A2dpSessionMetrics& a2dp_session_metrics); + + /* + * Writes the metrics, in base64 protobuf format, into the descriptor FD + * If CLEAR is true, metrics events are cleared afterwards. + */ + void WriteBase64(int fd, bool clear); + void WriteBase64String(std::string* serialized, bool clear); + void WriteString(std::string* serialized, bool clear); + + /* + * Reset the metrics logger by cleaning up its staging queues and existing + * protobuf objects. + */ + void Reset(); + + private: + BluetoothMetricsLogger(); + + /* + * When a Bluetooth session is on and the user initiates a metrics dump, we + * need to be able to upload whatever we have first. This method breaks the + * ongoing Bluetooth session into two sessions with the previous one labeled + * as "METRICS_DUMP" for the disconnect reason. + */ + void CutoffSession(); + + /* + * Build the internal metrics object using information gathered + */ + void Build(); + + /* + * Reset objects related to current Bluetooth session + */ + void ResetSession(); + + /* + * Reset the underlining BluetoothLog object + */ + void ResetLog(); + + /* + * PIMPL style implementation to hide internal dependencies + */ + struct impl; + std::unique_ptr<impl> const pimpl_; +}; +} diff --git a/system/osi/src/metrics.cc b/system/osi/src/metrics.cc index 8f188291e2f828fc80d8f28950cb8e012cfbf9cf..e5f9b55b6936154768c14b3f7bd2704c624bef12 100644 --- a/system/osi/src/metrics.cc +++ b/system/osi/src/metrics.cc @@ -15,25 +15,36 @@ * limitations under the License. * ******************************************************************************/ - #define LOG_TAG "bt_osi_metrics" -#include "osi/include/metrics.h" +#include <unistd.h> +#include <algorithm> +#include <cerrno> +#include <chrono> +#include <cstdint> +#include <cstring> +#include <memory> +#include <mutex> -#include <errno.h> +#include <base/base64.h> +#include <base/logging.h> +#include "osi/include/leaky_bonded_queue.h" #include "osi/include/log.h" #include "osi/include/osi.h" +#include "osi/include/time.h" +#include "stack/include/btm_api_types.h" #include "osi/src/protos/bluetooth.pb.h" -#include <base/base64.h> -#include <google/protobuf/text_format.h> -#include <mutex> +#include "osi/include/metrics.h" + +namespace system_bt_osi { using clearcut::connectivity::A2DPSession; using clearcut::connectivity::BluetoothLog; using clearcut::connectivity::BluetoothSession; +using clearcut::connectivity::BluetoothSession_ConnectionTechnologyType; using clearcut::connectivity::DeviceInfo; using clearcut::connectivity::DeviceInfo_DeviceType; using clearcut::connectivity::PairEvent; @@ -43,141 +54,345 @@ using clearcut::connectivity::ScanEvent_ScanEventType; using clearcut::connectivity::WakeEvent; using clearcut::connectivity::WakeEvent_WakeEventType; -BluetoothLog* pending; -std::mutex log_lock; +namespace { +// Maximum number of log entries for each repeated field +const size_t global_max_num_bluetooth_session = 50; +const size_t global_max_num_pair_event = 50; +const size_t global_max_num_wake_event = 50; +const size_t global_max_num_scan_event = 50; +const std::string global_next_session_start_without_ending_previous = + "NEXT_SESSION_START_WITHOUT_ENDING_PREVIOUS"; +const std::string global_metrics_dump = "METRICS_DUMP"; +} + +/* + * Get current OS boot time in millisecond + */ +static int64_t time_get_os_boottime_ms(void) { + return time_get_os_boottime_us() / 1000; +} -static void lazy_initialize(void) { - if (pending == nullptr) { - pending = BluetoothLog::default_instance().New(); +static float combine_averages(float avg_a, int64_t ct_a, float avg_b, + int64_t ct_b) { + if (ct_a > 0 && ct_b > 0) { + return (avg_a * ct_a + avg_b * ct_b) / (ct_a + ct_b); + } else if (ct_b > 0) { + return avg_b; + } else { + return avg_a; } } -void metrics_pair_event(uint32_t disconnect_reason, uint64_t timestamp_ms, - uint32_t device_class, device_type_t device_type) { - std::lock_guard<std::mutex> lock(log_lock); - lazy_initialize(); +static int32_t combine_averages(int32_t avg_a, int64_t ct_a, int32_t avg_b, + int64_t ct_b) { + if (ct_a > 0 && ct_b > 0) { + return (avg_a * ct_a + avg_b * ct_b) / (ct_a + ct_b); + } else if (ct_b > 0) { + return avg_b; + } else { + return avg_a; + } +} - PairEvent* event = pending->add_pair_event(); +void A2dpSessionMetrics::Update(const A2dpSessionMetrics& metrics) { + if (metrics.audio_duration_ms > 0) { + audio_duration_ms = std::max(static_cast<int64_t>(0), audio_duration_ms); + audio_duration_ms += metrics.audio_duration_ms; + } + if (metrics.media_timer_min_ms > 0) { + if (media_timer_min_ms < 0) { + media_timer_min_ms = metrics.media_timer_min_ms; + } else { + media_timer_min_ms = + std::min(media_timer_min_ms, metrics.media_timer_min_ms); + } + } + if (metrics.media_timer_max_ms > 0) { + media_timer_max_ms = + std::max(media_timer_max_ms, metrics.media_timer_max_ms); + } + if (metrics.media_timer_avg_ms > 0 && metrics.total_scheduling_count > 0) { + if (media_timer_avg_ms < 0 || total_scheduling_count < 0) { + media_timer_avg_ms = metrics.media_timer_avg_ms; + total_scheduling_count = metrics.total_scheduling_count; + } else { + media_timer_avg_ms = combine_averages( + media_timer_avg_ms, total_scheduling_count, + metrics.media_timer_avg_ms, metrics.total_scheduling_count); + total_scheduling_count += metrics.total_scheduling_count; + } + } + if (metrics.buffer_overruns_max_count > 0) { + buffer_overruns_max_count = + std::max(buffer_overruns_max_count, metrics.buffer_overruns_max_count); + } + if (metrics.buffer_overruns_total > 0) { + buffer_overruns_total = + std::max(static_cast<int32_t>(0), buffer_overruns_total); + buffer_overruns_total += metrics.buffer_overruns_total; + } + if (metrics.buffer_underruns_average > 0 && + metrics.buffer_underruns_count > 0) { + if (buffer_underruns_average < 0 || buffer_underruns_count < 0) { + buffer_underruns_average = metrics.buffer_underruns_average; + buffer_underruns_count = metrics.buffer_underruns_count; + } else { + buffer_underruns_average = combine_averages( + metrics.buffer_underruns_average, metrics.buffer_underruns_count, + buffer_underruns_average, buffer_underruns_count); + buffer_underruns_count += metrics.buffer_underruns_count; + } + } +} - DeviceInfo* info = event->mutable_device_paired_with(); +bool A2dpSessionMetrics::operator==(const A2dpSessionMetrics& rhs) const { + return audio_duration_ms == rhs.audio_duration_ms && + media_timer_min_ms == rhs.media_timer_min_ms && + media_timer_max_ms == rhs.media_timer_max_ms && + media_timer_avg_ms == rhs.media_timer_avg_ms && + total_scheduling_count == rhs.total_scheduling_count && + buffer_overruns_max_count == rhs.buffer_overruns_max_count && + buffer_overruns_total == rhs.buffer_overruns_total && + buffer_underruns_average == rhs.buffer_underruns_average && + buffer_underruns_count == rhs.buffer_underruns_count; +} - info->set_device_class(device_class); +static DeviceInfo_DeviceType get_device_type(device_type_t type) { + switch (type) { + case DEVICE_TYPE_BREDR: + return DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR; + case DEVICE_TYPE_LE: + return DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_LE; + case DEVICE_TYPE_DUMO: + return DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_DUMO; + case DEVICE_TYPE_UNKNOWN: + default: + return DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_UNKNOWN; + } +} - DeviceInfo_DeviceType type = DeviceInfo::DEVICE_TYPE_UNKNOWN; +static BluetoothSession_ConnectionTechnologyType get_connection_tech_type( + connection_tech_t type) { + switch (type) { + case CONNECTION_TECHNOLOGY_TYPE_LE: + return BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_LE; + case CONNECTION_TECHNOLOGY_TYPE_BREDR: + return BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR; + case CONNECTION_TECHNOLOGY_TYPE_UNKNOWN: + default: + return BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_UNKNOWN; + } +} - if (device_type == DEVICE_TYPE_BREDR) type = DeviceInfo::DEVICE_TYPE_BREDR; - if (device_type == DEVICE_TYPE_LE) type = DeviceInfo::DEVICE_TYPE_LE; - if (device_type == DEVICE_TYPE_DUMO) type = DeviceInfo::DEVICE_TYPE_DUMO; +static ScanEvent_ScanTechnologyType get_scan_tech_type(scan_tech_t type) { + switch (type) { + case SCAN_TECH_TYPE_LE: + return ScanEvent_ScanTechnologyType:: + ScanEvent_ScanTechnologyType_SCAN_TECH_TYPE_LE; + case SCAN_TECH_TYPE_BREDR: + return ScanEvent_ScanTechnologyType:: + ScanEvent_ScanTechnologyType_SCAN_TECH_TYPE_BREDR; + case SCAN_TECH_TYPE_BOTH: + return ScanEvent_ScanTechnologyType:: + ScanEvent_ScanTechnologyType_SCAN_TECH_TYPE_BOTH; + case SCAN_TYPE_UNKNOWN: + default: + return ScanEvent_ScanTechnologyType:: + ScanEvent_ScanTechnologyType_SCAN_TYPE_UNKNOWN; + } +} - info->set_device_type(type); +static WakeEvent_WakeEventType get_wake_event_type(wake_event_type_t type) { + switch (type) { + case WAKE_EVENT_ACQUIRED: + return WakeEvent_WakeEventType::WakeEvent_WakeEventType_ACQUIRED; + case WAKE_EVENT_RELEASED: + return WakeEvent_WakeEventType::WakeEvent_WakeEventType_RELEASED; + case WAKE_EVENT_UNKNOWN: + default: + return WakeEvent_WakeEventType::WakeEvent_WakeEventType_UNKNOWN; + } +} - event->set_disconnect_reason(disconnect_reason); +struct BluetoothMetricsLogger::impl { + impl(size_t max_bluetooth_session, size_t max_pair_event, + size_t max_wake_event, size_t max_scan_event) + : bt_session_queue_( + new LeakyBondedQueue<BluetoothSession>(max_bluetooth_session)), + pair_event_queue_(new LeakyBondedQueue<PairEvent>(max_pair_event)), + wake_event_queue_(new LeakyBondedQueue<WakeEvent>(max_wake_event)), + scan_event_queue_(new LeakyBondedQueue<ScanEvent>(max_scan_event)) { + bluetooth_log_ = BluetoothLog::default_instance().New(); + bluetooth_session_ = nullptr; + bluetooth_session_start_time_ms_ = 0; + a2dp_session_metrics_ = A2dpSessionMetrics(); + } + /* Bluetooth log lock protected */ + BluetoothLog* bluetooth_log_; + std::recursive_mutex bluetooth_log_lock_; + /* End Bluetooth log lock protected */ + /* Bluetooth session lock protected */ + BluetoothSession* bluetooth_session_; + uint64_t bluetooth_session_start_time_ms_; + A2dpSessionMetrics a2dp_session_metrics_; + std::recursive_mutex bluetooth_session_lock_; + /* End bluetooth session lock protected */ + std::unique_ptr<LeakyBondedQueue<BluetoothSession>> bt_session_queue_; + std::unique_ptr<LeakyBondedQueue<PairEvent>> pair_event_queue_; + std::unique_ptr<LeakyBondedQueue<WakeEvent>> wake_event_queue_; + std::unique_ptr<LeakyBondedQueue<ScanEvent>> scan_event_queue_; +}; + +BluetoothMetricsLogger::BluetoothMetricsLogger() + : pimpl_(new impl(global_max_num_bluetooth_session, + global_max_num_pair_event, global_max_num_wake_event, + global_max_num_scan_event)) {} + +void BluetoothMetricsLogger::LogPairEvent(uint32_t disconnect_reason, + uint64_t timestamp_ms, + uint32_t device_class, + device_type_t device_type) { + PairEvent* event = new PairEvent(); + DeviceInfo* info = event->mutable_device_paired_with(); + info->set_device_class(device_class); + info->set_device_type(get_device_type(device_type)); + event->set_disconnect_reason(disconnect_reason); event->set_event_time_millis(timestamp_ms); + pimpl_->pair_event_queue_->Enqueue(event); } -void metrics_wake_event(wake_event_type_t type, const char* requestor, - const char* name, uint64_t timestamp_ms) { - std::lock_guard<std::mutex> lock(log_lock); - lazy_initialize(); - - WakeEvent* event = pending->add_wake_event(); - - WakeEvent_WakeEventType waketype = WakeEvent::UNKNOWN; - - if (type == WAKE_EVENT_ACQUIRED) waketype = WakeEvent::ACQUIRED; - if (type == WAKE_EVENT_RELEASED) waketype = WakeEvent::RELEASED; - - event->set_wake_event_type(waketype); - - if (requestor) event->set_requestor(requestor); - - if (name) event->set_name(name); - +void BluetoothMetricsLogger::LogWakeEvent(wake_event_type_t type, + const std::string& requestor, + const std::string& name, + uint64_t timestamp_ms) { + WakeEvent* event = new WakeEvent(); + event->set_wake_event_type(get_wake_event_type(type)); + event->set_requestor(requestor); + event->set_name(name); event->set_event_time_millis(timestamp_ms); + pimpl_->wake_event_queue_->Enqueue(event); } -void metrics_scan_event(bool start, const char* initator, scan_tech_t type, - uint32_t results, uint64_t timestamp_ms) { - std::lock_guard<std::mutex> lock(log_lock); - lazy_initialize(); - - ScanEvent* event = pending->add_scan_event(); - - if (start) +void BluetoothMetricsLogger::LogScanEvent(bool start, + const std::string& initator, + scan_tech_t type, uint32_t results, + uint64_t timestamp_ms) { + ScanEvent* event = new ScanEvent(); + if (start) { event->set_scan_event_type(ScanEvent::SCAN_EVENT_START); - else + } else { event->set_scan_event_type(ScanEvent::SCAN_EVENT_STOP); - - if (initator) event->set_initiator(initator); - - ScanEvent::ScanTechnologyType scantype = ScanEvent::SCAN_TYPE_UNKNOWN; - - if (type == SCAN_TECH_TYPE_LE) scantype = ScanEvent::SCAN_TECH_TYPE_LE; - if (type == SCAN_TECH_TYPE_BREDR) scantype = ScanEvent::SCAN_TECH_TYPE_BREDR; - if (type == SCAN_TECH_TYPE_BOTH) scantype = ScanEvent::SCAN_TECH_TYPE_BOTH; - - event->set_scan_technology_type(scantype); - + } + event->set_initiator(initator); + event->set_scan_technology_type(get_scan_tech_type(type)); event->set_number_results(results); - event->set_event_time_millis(timestamp_ms); + pimpl_->scan_event_queue_->Enqueue(event); } -void metrics_a2dp_session( - int64_t session_duration_sec, const char* disconnect_reason, - uint32_t device_class, int32_t media_timer_min_ms, - int32_t media_timer_max_ms, int32_t media_timer_avg_ms, - int32_t buffer_overruns_max_count, int32_t buffer_overruns_total, - float buffer_underruns_average, int32_t buffer_underruns_count) { - std::lock_guard<std::mutex> lock(log_lock); - lazy_initialize(); - - BluetoothSession* bt_session = pending->add_session(); - - // Set connection type: for A2DP it is always BR/EDR - BluetoothSession::ConnectionTechnologyType conn_type = - BluetoothSession::CONNECTION_TECHNOLOGY_TYPE_BREDR; - bt_session->set_connection_technology_type(conn_type); +void BluetoothMetricsLogger::LogBluetoothSessionStart( + connection_tech_t connection_tech_type, uint64_t timestamp_ms) { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_session_lock_); + if (pimpl_->bluetooth_session_ != nullptr) { + LogBluetoothSessionEnd(global_next_session_start_without_ending_previous, + 0); + } + if (timestamp_ms == 0) { + timestamp_ms = time_get_os_boottime_ms(); + } + pimpl_->bluetooth_session_start_time_ms_ = timestamp_ms; + pimpl_->bluetooth_session_ = new BluetoothSession(); + pimpl_->bluetooth_session_->set_connection_technology_type( + get_connection_tech_type(connection_tech_type)); +} - bt_session->set_session_duration_sec(session_duration_sec); - if (disconnect_reason != NULL) - bt_session->set_disconnect_reason(disconnect_reason); +void BluetoothMetricsLogger::LogBluetoothSessionEnd( + const std::string& disconnect_reason, uint64_t timestamp_ms) { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_session_lock_); + if (pimpl_->bluetooth_session_ == nullptr) { + return; + } + if (timestamp_ms == 0) { + timestamp_ms = time_get_os_boottime_ms(); + } + int64_t session_duration_sec = + (timestamp_ms - pimpl_->bluetooth_session_start_time_ms_) / 1000; + pimpl_->bluetooth_session_->set_session_duration_sec(session_duration_sec); + pimpl_->bluetooth_session_->set_disconnect_reason(disconnect_reason); + pimpl_->bt_session_queue_->Enqueue(pimpl_->bluetooth_session_); + pimpl_->bluetooth_session_ = nullptr; +} - // Set device: class and type are pre-defined - DeviceInfo* info = bt_session->mutable_device_connected_to(); +void BluetoothMetricsLogger::LogBluetoothSessionDeviceInfo( + uint32_t device_class, device_type_t device_type) { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_session_lock_); + if (pimpl_->bluetooth_session_ == nullptr) { + LogBluetoothSessionStart(CONNECTION_TECHNOLOGY_TYPE_UNKNOWN, 0); + } + DeviceInfo* info = pimpl_->bluetooth_session_->mutable_device_connected_to(); info->set_device_class(device_class); info->set_device_type(DeviceInfo::DEVICE_TYPE_BREDR); +} - A2DPSession* a2dp_session = bt_session->mutable_a2dp_session(); - a2dp_session->set_media_timer_min_millis(media_timer_min_ms); - a2dp_session->set_media_timer_max_millis(media_timer_max_ms); - a2dp_session->set_media_timer_avg_millis(media_timer_avg_ms); - a2dp_session->set_buffer_overruns_max_count(buffer_overruns_max_count); - a2dp_session->set_buffer_overruns_total(buffer_overruns_total); - a2dp_session->set_buffer_underruns_average(buffer_underruns_average); - a2dp_session->set_buffer_underruns_count(buffer_underruns_count); +void BluetoothMetricsLogger::LogA2dpSession( + const A2dpSessionMetrics& a2dp_session_metrics) { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_session_lock_); + if (pimpl_->bluetooth_session_ == nullptr) { + // When no bluetooth session exist, create one on system's behalf + // Set connection type: for A2DP it is always BR/EDR + LogBluetoothSessionStart(CONNECTION_TECHNOLOGY_TYPE_BREDR, 0); + LogBluetoothSessionDeviceInfo(BTM_COD_MAJOR_AUDIO, DEVICE_TYPE_BREDR); + } + // Accumulate metrics + pimpl_->a2dp_session_metrics_.Update(a2dp_session_metrics); + // Get or allocate new A2DP session object + A2DPSession* a2dp_session = + pimpl_->bluetooth_session_->mutable_a2dp_session(); + a2dp_session->set_audio_duration_millis( + pimpl_->a2dp_session_metrics_.audio_duration_ms); + a2dp_session->set_media_timer_min_millis( + pimpl_->a2dp_session_metrics_.media_timer_min_ms); + a2dp_session->set_media_timer_max_millis( + pimpl_->a2dp_session_metrics_.media_timer_max_ms); + a2dp_session->set_media_timer_avg_millis( + pimpl_->a2dp_session_metrics_.media_timer_avg_ms); + a2dp_session->set_buffer_overruns_max_count( + pimpl_->a2dp_session_metrics_.buffer_overruns_max_count); + a2dp_session->set_buffer_overruns_total( + pimpl_->a2dp_session_metrics_.buffer_overruns_total); + a2dp_session->set_buffer_underruns_average( + pimpl_->a2dp_session_metrics_.buffer_underruns_average); + a2dp_session->set_buffer_underruns_count( + pimpl_->a2dp_session_metrics_.buffer_underruns_count); } -void metrics_write(int fd, bool clear) { - log_lock.lock(); +void BluetoothMetricsLogger::WriteString(std::string* serialized, bool clear) { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_log_lock_); + LOG_DEBUG(LOG_TAG, "%s building metrics", __func__); + Build(); LOG_DEBUG(LOG_TAG, "%s serializing metrics", __func__); - lazy_initialize(); - - std::string serialized; - if (!pending->SerializeToString(&serialized)) { + if (!pimpl_->bluetooth_log_->SerializeToString(serialized)) { LOG_ERROR(LOG_TAG, "%s: error serializing metrics", __func__); return; } - if (clear) { - pending->Clear(); + pimpl_->bluetooth_log_->Clear(); } - log_lock.unlock(); +} - std::string protoBase64; - base::Base64Encode(serialized, &protoBase64); +void BluetoothMetricsLogger::WriteBase64String(std::string* serialized, + bool clear) { + this->WriteString(serialized, clear); + base::Base64Encode(*serialized, serialized); +} +void BluetoothMetricsLogger::WriteBase64(int fd, bool clear) { + std::string protoBase64; + this->WriteBase64String(&protoBase64, clear); ssize_t ret; OSI_NO_INTR(ret = write(fd, protoBase64.c_str(), protoBase64.size())); if (ret == -1) { @@ -185,3 +400,79 @@ void metrics_write(int fd, bool clear) { strerror(errno), errno); } } + +void BluetoothMetricsLogger::CutoffSession() { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_session_lock_); + if (pimpl_->bluetooth_session_ != nullptr) { + BluetoothSession* new_bt_session = + new BluetoothSession(*pimpl_->bluetooth_session_); + new_bt_session->clear_a2dp_session(); + new_bt_session->clear_rfcomm_session(); + LogBluetoothSessionEnd(global_metrics_dump, 0); + pimpl_->bluetooth_session_ = new_bt_session; + pimpl_->bluetooth_session_start_time_ms_ = time_get_os_boottime_ms(); + pimpl_->a2dp_session_metrics_ = A2dpSessionMetrics(); + } +} + +void BluetoothMetricsLogger::Build() { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_log_lock_); + CutoffSession(); + BluetoothLog* bluetooth_log = pimpl_->bluetooth_log_; + while (!pimpl_->bt_session_queue_->Empty() && + static_cast<size_t>(bluetooth_log->session_size()) <= + pimpl_->bt_session_queue_->Capacity()) { + bluetooth_log->mutable_session()->AddAllocated( + pimpl_->bt_session_queue_->Dequeue()); + } + while (!pimpl_->pair_event_queue_->Empty() && + static_cast<size_t>(bluetooth_log->pair_event_size()) <= + pimpl_->pair_event_queue_->Capacity()) { + bluetooth_log->mutable_pair_event()->AddAllocated( + pimpl_->pair_event_queue_->Dequeue()); + } + while (!pimpl_->scan_event_queue_->Empty() && + static_cast<size_t>(bluetooth_log->scan_event_size()) <= + pimpl_->scan_event_queue_->Capacity()) { + bluetooth_log->mutable_scan_event()->AddAllocated( + pimpl_->scan_event_queue_->Dequeue()); + } + while (!pimpl_->wake_event_queue_->Empty() && + static_cast<size_t>(bluetooth_log->wake_event_size()) <= + pimpl_->wake_event_queue_->Capacity()) { + bluetooth_log->mutable_wake_event()->AddAllocated( + pimpl_->wake_event_queue_->Dequeue()); + } + while (!pimpl_->bt_session_queue_->Empty() && + static_cast<size_t>(bluetooth_log->wake_event_size()) <= + pimpl_->wake_event_queue_->Capacity()) { + bluetooth_log->mutable_wake_event()->AddAllocated( + pimpl_->wake_event_queue_->Dequeue()); + } +} + +void BluetoothMetricsLogger::ResetSession() { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_session_lock_); + if (pimpl_->bluetooth_session_ != nullptr) { + delete pimpl_->bluetooth_session_; + pimpl_->bluetooth_session_ = nullptr; + } + pimpl_->bluetooth_session_start_time_ms_ = 0; + pimpl_->a2dp_session_metrics_ = A2dpSessionMetrics(); +} + +void BluetoothMetricsLogger::ResetLog() { + std::lock_guard<std::recursive_mutex> lock(pimpl_->bluetooth_log_lock_); + pimpl_->bluetooth_log_->Clear(); +} + +void BluetoothMetricsLogger::Reset() { + ResetSession(); + ResetLog(); + pimpl_->bt_session_queue_->Clear(); + pimpl_->pair_event_queue_->Clear(); + pimpl_->wake_event_queue_->Clear(); + pimpl_->scan_event_queue_->Clear(); +} + +} // namespace system_bt_osi diff --git a/system/osi/src/metrics_linux.cc b/system/osi/src/metrics_linux.cc index 6c4cc9467cbff308a43f4e1faf7c1420671a630c..d858667d43d748ea9c99a65bffea9890f2c6c245 100644 --- a/system/osi/src/metrics_linux.cc +++ b/system/osi/src/metrics_linux.cc @@ -15,35 +15,190 @@ * limitations under the License. * ******************************************************************************/ - #define LOG_TAG "bt_osi_metrics" +#include <unistd.h> +#include <algorithm> +#include <cerrno> +#include <chrono> +#include <cstdint> +#include <cstring> +#include <memory> +#include <mutex> + +#include <base/base64.h> +#include <base/logging.h> + +#include "osi/include/leaky_bonded_queue.h" +#include "osi/include/log.h" +#include "osi/include/osi.h" +#include "osi/include/time.h" + #include "osi/include/metrics.h" -void metrics_pair_event(uint32_t disconnect_reason, uint64_t timestamp_ms, - uint32_t device_class, device_type_t device_type) { - // TODO(jpawlowski): implement +namespace system_bt_osi { + +// Maximum number of log entries for each repeated field +#define MAX_NUM_BLUETOOTH_SESSION 50 +#define MAX_NUM_PAIR_EVENT 50 +#define MAX_NUM_WAKE_EVENT 50 +#define MAX_NUM_SCAN_EVENT 50 + +static float combine_averages(float avg_a, int64_t ct_a, float avg_b, + int64_t ct_b) { + if (ct_a > 0 && ct_b > 0) { + return (avg_a * ct_a + avg_b * ct_b) / (ct_a + ct_b); + } else if (ct_b > 0) { + return avg_b; + } else { + return avg_a; + } } -void metrics_wake_event(wake_event_type_t type, const char* requestor, - const char* name, uint64_t timestamp_ms) { - // TODO(jpawlowski): implement +static int32_t combine_averages(int32_t avg_a, int64_t ct_a, int32_t avg_b, + int64_t ct_b) { + if (ct_a > 0 && ct_b > 0) { + return (avg_a * ct_a + avg_b * ct_b) / (ct_a + ct_b); + } else if (ct_b > 0) { + return avg_b; + } else { + return avg_a; + } } -void metrics_scan_event(bool start, const char* initator, scan_tech_t type, - uint32_t results, uint64_t timestamp_ms) { - // TODO(jpawlowski): implement +void A2dpSessionMetrics::Update(const A2dpSessionMetrics& metrics) { + if (metrics.audio_duration_ms > 0) { + audio_duration_ms = std::max(static_cast<int64_t>(0), audio_duration_ms); + audio_duration_ms += metrics.audio_duration_ms; + } + if (metrics.media_timer_min_ms > 0) { + if (media_timer_min_ms < 0) { + media_timer_min_ms = metrics.media_timer_min_ms; + } else { + media_timer_min_ms = + std::min(media_timer_min_ms, metrics.media_timer_min_ms); + } + } + if (metrics.media_timer_max_ms > 0) { + media_timer_max_ms = + std::max(media_timer_max_ms, metrics.media_timer_max_ms); + } + if (metrics.media_timer_avg_ms > 0 && metrics.total_scheduling_count > 0) { + if (media_timer_avg_ms < 0 || total_scheduling_count < 0) { + media_timer_avg_ms = metrics.media_timer_avg_ms; + total_scheduling_count = metrics.total_scheduling_count; + } else { + media_timer_avg_ms = combine_averages( + media_timer_avg_ms, total_scheduling_count, + metrics.media_timer_avg_ms, metrics.total_scheduling_count); + total_scheduling_count += metrics.total_scheduling_count; + } + } + if (metrics.buffer_overruns_max_count > 0) { + buffer_overruns_max_count = + std::max(buffer_overruns_max_count, metrics.buffer_overruns_max_count); + } + if (metrics.buffer_overruns_total > 0) { + buffer_overruns_total = + std::max(static_cast<int32_t>(0), buffer_overruns_total); + buffer_overruns_total += metrics.buffer_overruns_total; + } + if (metrics.buffer_underruns_average > 0 && + metrics.buffer_underruns_count > 0) { + if (buffer_underruns_average < 0 || buffer_underruns_count < 0) { + buffer_underruns_average = metrics.buffer_underruns_average; + buffer_underruns_count = metrics.buffer_underruns_count; + } else { + buffer_underruns_average = combine_averages( + metrics.buffer_underruns_average, metrics.buffer_underruns_count, + buffer_underruns_average, buffer_underruns_count); + buffer_underruns_count += metrics.buffer_underruns_count; + } + } } -void metrics_a2dp_session( - int64_t session_duration_sec, const char* disconnect_reason, - uint32_t device_class, int32_t media_timer_min_ms, - int32_t media_timer_max_ms, int32_t media_timer_avg_ms, - int32_t buffer_overruns_max_count, int32_t buffer_overruns_total, - float buffer_underruns_average, int32_t buffer_underruns_count) { - // TODO(jpawlowski): implement +bool A2dpSessionMetrics::operator==(const A2dpSessionMetrics& rhs) const { + return audio_duration_ms == rhs.audio_duration_ms && + media_timer_min_ms == rhs.media_timer_min_ms && + media_timer_max_ms == rhs.media_timer_max_ms && + media_timer_avg_ms == rhs.media_timer_avg_ms && + total_scheduling_count == rhs.total_scheduling_count && + buffer_overruns_max_count == rhs.buffer_overruns_max_count && + buffer_overruns_total == rhs.buffer_overruns_total && + buffer_underruns_average == rhs.buffer_underruns_average && + buffer_underruns_count == rhs.buffer_underruns_count; } -void metrics_write(int fd, bool clear) { - // TODO(jpawlowski): implement +struct BluetoothMetricsLogger::impl { + // TODO(siyuanh): Implement for linux +}; + +BluetoothMetricsLogger::BluetoothMetricsLogger() : pimpl_(new impl) {} + +void BluetoothMetricsLogger::LogPairEvent(uint32_t disconnect_reason, + uint64_t timestamp_ms, + uint32_t device_class, + device_type_t device_type) { + // TODO(siyuanh): Implement for linux } + +void BluetoothMetricsLogger::LogWakeEvent(wake_event_type_t type, + const std::string& requestor, + const std::string& name, + uint64_t timestamp_ms) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::LogScanEvent(bool start, + const std::string& initator, + scan_tech_t type, uint32_t results, + uint64_t timestamp_ms) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::LogBluetoothSessionStart( + connection_tech_t connection_tech_type, uint64_t timestamp_ms) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::LogBluetoothSessionEnd( + const std::string& disconnect_reason, uint64_t timestamp_ms) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::LogBluetoothSessionDeviceInfo( + uint32_t device_class, device_type_t device_type) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::LogA2dpSession( + const A2dpSessionMetrics& a2dp_session_metrics) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::WriteString(std::string* serialized, bool clear) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::WriteBase64String(std::string* serialized, + bool clear) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::WriteBase64(int fd, bool clear) { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::CutoffSession() { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::Build() { + // TODO(siyuanh): Implement for linux +} + +void BluetoothMetricsLogger::Reset() { + // TODO(siyuanh): Implement for linux +} + +} // namespace system_bt_osi diff --git a/system/osi/src/protos/bluetooth.proto b/system/osi/src/protos/bluetooth.proto index d8aa823ce531ce5925c89d165f3af8ab26e9924f..23f83fdaf7941f67a1aeaa0684d8c6d878a31e84 100644 --- a/system/osi/src/protos/bluetooth.proto +++ b/system/osi/src/protos/bluetooth.proto @@ -74,7 +74,7 @@ message BluetoothSession { // The information about the RFComm session. optional RFCommSession rfcomm_session = 6; - // The information about the A2DP session. + // The information about the A2DP audio session. optional A2DPSession a2dp_session = 7; } @@ -86,7 +86,7 @@ message RFCommSession { optional int32 tx_bytes = 2; } -// Session information that gets logged for every A2DP session. +// Session information that gets logged for A2DP session. message A2DPSession { // Media timer in milliseconds. optional int32 media_timer_min_millis = 1; @@ -108,6 +108,9 @@ message A2DPSession { // Buffer underruns count. optional int32 buffer_underruns_count = 7; + + // Total audio time in this A2DP session + optional int64 audio_duration_millis = 8; } message PairEvent { diff --git a/system/osi/src/wakelock.cc b/system/osi/src/wakelock.cc index d52825e274dfa08c87577b13285061a80da184e2..7aa7004003d71673d13086f117bc44a8db55bd47 100644 --- a/system/osi/src/wakelock.cc +++ b/system/osi/src/wakelock.cc @@ -41,6 +41,8 @@ #include "osi/include/thread.h" #include "osi/include/wakelock.h" +using system_bt_osi::BluetoothMetricsLogger; + static bt_os_callouts_t* wakelock_os_callouts = NULL; static bool is_native = true; @@ -275,7 +277,8 @@ static void update_wakelock_acquired_stats(bt_status_t acquired_status) { wakelock_stats.acquired_count++; wakelock_stats.last_acquired_timestamp_ms = now_ms; - metrics_wake_event(WAKE_EVENT_ACQUIRED, NULL, WAKE_LOCK_ID, now_ms); + BluetoothMetricsLogger::GetInstance()->LogWakeEvent( + system_bt_osi::WAKE_EVENT_ACQUIRED, "", WAKE_LOCK_ID, now_ms); } // @@ -316,7 +319,8 @@ static void update_wakelock_released_stats(bt_status_t released_status) { wakelock_stats.last_acquired_interval_ms = delta_ms; wakelock_stats.total_acquired_interval_ms += delta_ms; - metrics_wake_event(WAKE_EVENT_RELEASED, NULL, WAKE_LOCK_ID, now_ms); + BluetoothMetricsLogger::GetInstance()->LogWakeEvent( + system_bt_osi::WAKE_EVENT_RELEASED, "", WAKE_LOCK_ID, now_ms); } void wakelock_debug_dump(int fd) { diff --git a/system/osi/test/metrics_test.cc b/system/osi/test/metrics_test.cc new file mode 100644 index 0000000000000000000000000000000000000000..ce4057e42e7e3c70472aa1056f8c58bcccd6e875 --- /dev/null +++ b/system/osi/test/metrics_test.cc @@ -0,0 +1,749 @@ +/****************************************************************************** + * + * Copyright (C) 2016 Google, Inc. + * + * 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. + * + ******************************************************************************/ +#include <chrono> +#include <cstdint> +#include <string> +#include <thread> +#include <vector> + +#include <gmock/gmock.h> +#include <gtest/gtest.h> + +#include <base/logging.h> + +#include "osi/include/metrics.h" +#include "osi/include/time.h" +#include "osi/src/protos/bluetooth.pb.h" + +#define BTM_COD_MAJOR_AUDIO_TEST 0x04 + +namespace testing { + +using clearcut::connectivity::A2DPSession; +using clearcut::connectivity::BluetoothLog; +using clearcut::connectivity::BluetoothSession; +using clearcut::connectivity::BluetoothSession_ConnectionTechnologyType; +using clearcut::connectivity::DeviceInfo; +using clearcut::connectivity::DeviceInfo_DeviceType; +using clearcut::connectivity::PairEvent; +using clearcut::connectivity::RFCommSession; +using clearcut::connectivity::ScanEvent; +using clearcut::connectivity::ScanEvent_ScanTechnologyType; +using clearcut::connectivity::ScanEvent_ScanEventType; +using clearcut::connectivity::WakeEvent; +using clearcut::connectivity::WakeEvent_WakeEventType; +using system_bt_osi::BluetoothMetricsLogger; +using system_bt_osi::A2dpSessionMetrics; + +/* + * Get current OS boot time in ms + */ +static int64_t time_get_os_boottime_ms(void) { + return time_get_os_boottime_us() / 1000; +} + +static void sleep_ms(int64_t t) { + std::this_thread::sleep_for(std::chrono::milliseconds(t)); +} + +DeviceInfo* MakeDeviceInfo(int32_t device_class, + DeviceInfo_DeviceType device_type) { + DeviceInfo* info = new DeviceInfo(); + info->set_device_class(device_class); + info->set_device_type(device_type); + return info; +} + +PairEvent* MakePairEvent(int32_t disconnect_reason, int64_t timestamp_ms, + DeviceInfo* device_info) { + PairEvent* event = new PairEvent(); + event->set_disconnect_reason(disconnect_reason); + event->set_event_time_millis(timestamp_ms); + if (device_info) event->set_allocated_device_paired_with(device_info); + return event; +} + +WakeEvent* MakeWakeEvent(WakeEvent_WakeEventType event_type, + const std::string& requestor, const std::string& name, + int64_t timestamp_ms) { + WakeEvent* event = new WakeEvent(); + event->set_wake_event_type(event_type); + event->set_requestor(requestor); + event->set_name(name); + event->set_event_time_millis(timestamp_ms); + return event; +} + +ScanEvent* MakeScanEvent(ScanEvent_ScanEventType event_type, + const std::string& initiator, + ScanEvent_ScanTechnologyType tech_type, + int32_t num_results, int64_t timestamp_ms) { + ScanEvent* event = new ScanEvent(); + event->set_scan_event_type(event_type); + event->set_initiator(initiator); + event->set_scan_technology_type(tech_type); + event->set_number_results(num_results); + event->set_event_time_millis(timestamp_ms); + return event; +} + +A2DPSession* MakeA2DPSession(const A2dpSessionMetrics& metrics) { + A2DPSession* session = new A2DPSession(); + session->set_media_timer_min_millis(metrics.media_timer_min_ms); + session->set_media_timer_max_millis(metrics.media_timer_max_ms); + session->set_media_timer_avg_millis(metrics.media_timer_avg_ms); + session->set_buffer_overruns_max_count(metrics.buffer_overruns_max_count); + session->set_buffer_overruns_total(metrics.buffer_overruns_total); + session->set_buffer_underruns_average(metrics.buffer_underruns_average); + session->set_buffer_underruns_count(metrics.buffer_underruns_count); + session->set_audio_duration_millis(metrics.audio_duration_ms); + return session; +} + +BluetoothSession* MakeBluetoothSession( + int64_t session_duration_sec, + BluetoothSession_ConnectionTechnologyType conn_type, + const std::string& disconnect_reason, DeviceInfo* device_info, + RFCommSession* rfcomm_session, A2DPSession* a2dp_session) { + BluetoothSession* session = new BluetoothSession(); + if (a2dp_session) session->set_allocated_a2dp_session(a2dp_session); + if (rfcomm_session) session->set_allocated_rfcomm_session(rfcomm_session); + if (device_info) session->set_allocated_device_connected_to(device_info); + session->set_session_duration_sec(session_duration_sec); + session->set_connection_technology_type(conn_type); + session->set_disconnect_reason(disconnect_reason); + return session; +} + +BluetoothLog* MakeBluetoothLog(std::vector<BluetoothSession*> bt_sessions, + std::vector<PairEvent*> pair_events, + std::vector<WakeEvent*> wake_events, + std::vector<ScanEvent*> scan_events) { + BluetoothLog* bt_log = new BluetoothLog(); + for (BluetoothSession* session : bt_sessions) { + bt_log->mutable_session()->AddAllocated(session); + } + bt_sessions.clear(); + for (PairEvent* event : pair_events) { + bt_log->mutable_pair_event()->AddAllocated(event); + } + pair_events.clear(); + for (WakeEvent* event : wake_events) { + bt_log->mutable_wake_event()->AddAllocated(event); + } + wake_events.clear(); + for (ScanEvent* event : scan_events) { + bt_log->mutable_scan_event()->AddAllocated(event); + } + scan_events.clear(); + return bt_log; +} + +void GenerateWakeEvents(int start, int end, + std::vector<WakeEvent*>* wake_events) { + for (int i = start; i < end; ++i) { + wake_events->push_back(MakeWakeEvent( + i % 2 == 0 ? WakeEvent_WakeEventType::WakeEvent_WakeEventType_ACQUIRED + : WakeEvent_WakeEventType::WakeEvent_WakeEventType_RELEASED, + "TEST_REQ", "TEST_NAME", i)); + } +} + +#define COMPARE_A2DP_METRICS(a, b) \ + do { \ + EXPECT_EQ(a.audio_duration_ms, b.audio_duration_ms); \ + EXPECT_EQ(a.media_timer_min_ms, b.media_timer_min_ms); \ + EXPECT_EQ(a.media_timer_max_ms, b.media_timer_max_ms); \ + EXPECT_EQ(a.media_timer_avg_ms, b.media_timer_avg_ms); \ + EXPECT_EQ(a.total_scheduling_count, b.total_scheduling_count); \ + EXPECT_EQ(a.buffer_overruns_max_count, b.buffer_overruns_max_count); \ + EXPECT_EQ(a.buffer_overruns_total, b.buffer_overruns_total); \ + EXPECT_THAT(a.buffer_underruns_average, \ + FloatNear(b.buffer_underruns_average, 0.01)); \ + a.buffer_underruns_average = b.buffer_underruns_average; \ + EXPECT_EQ(a.buffer_underruns_count, b.buffer_underruns_count); \ + } while (0) + +/* + * metrics_sum = metrics1 + metrics2 + */ +TEST(BluetoothA2DPSessionMetricsTest, TestUpdateNormal) { + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics1.audio_duration_ms = 10; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 35; + metrics1.media_timer_min_ms = 10; + metrics2.media_timer_min_ms = 25; + metrics_sum.media_timer_min_ms = 10; + metrics1.media_timer_max_ms = 100; + metrics2.media_timer_max_ms = 200; + metrics_sum.media_timer_max_ms = 200; + metrics1.media_timer_avg_ms = 50; + metrics1.total_scheduling_count = 50; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics_sum.media_timer_avg_ms = 75; + metrics_sum.total_scheduling_count = 100; + metrics1.buffer_overruns_max_count = 70; + metrics2.buffer_overruns_max_count = 80; + metrics_sum.buffer_overruns_max_count = 80; + metrics1.buffer_underruns_average = 80; + metrics1.buffer_underruns_count = 1200; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 113.33333333; + metrics_sum.buffer_underruns_count = 3600; + metrics1.Update(metrics2); + COMPARE_A2DP_METRICS(metrics1, metrics_sum); + EXPECT_TRUE(metrics1 == metrics_sum); + EXPECT_EQ(metrics1, metrics_sum); +} + +TEST(BluetoothA2DPSessionMetricsTest, TestUpdateNew) { + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 25; + metrics2.media_timer_min_ms = 25; + metrics_sum.media_timer_min_ms = 25; + metrics2.media_timer_max_ms = 200; + metrics_sum.media_timer_max_ms = 200; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics_sum.media_timer_avg_ms = 100; + metrics_sum.total_scheduling_count = 50; + metrics2.buffer_overruns_max_count = 80; + metrics_sum.buffer_overruns_max_count = 80; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 130; + metrics_sum.buffer_underruns_count = 2400; + metrics1.Update(metrics2); + COMPARE_A2DP_METRICS(metrics1, metrics_sum); + EXPECT_TRUE(metrics1 == metrics_sum); + EXPECT_EQ(metrics1, metrics_sum); +} + +TEST(BluetoothA2DPSessionMetricsTest, TestNullUpdate) { + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 25; + metrics2.media_timer_min_ms = 25; + metrics_sum.media_timer_min_ms = 25; + metrics2.media_timer_max_ms = 200; + metrics_sum.media_timer_max_ms = 200; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics_sum.media_timer_avg_ms = 100; + metrics_sum.total_scheduling_count = 50; + metrics2.buffer_overruns_max_count = 80; + metrics_sum.buffer_overruns_max_count = 80; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 130; + metrics_sum.buffer_underruns_count = 2400; + metrics2.Update(metrics1); + COMPARE_A2DP_METRICS(metrics2, metrics_sum); + EXPECT_TRUE(metrics2 == metrics_sum); + EXPECT_EQ(metrics2, metrics_sum); +} + +TEST(BluetoothA2DPSessionMetricsTest, TestPartialUpdate) { + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics1.audio_duration_ms = 10; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 35; + metrics1.media_timer_min_ms = 10; + metrics_sum.media_timer_min_ms = 10; + metrics1.media_timer_max_ms = 100; + metrics_sum.media_timer_max_ms = 100; + metrics1.media_timer_avg_ms = 50; + metrics1.total_scheduling_count = 50; + metrics2.media_timer_avg_ms = 100; + metrics_sum.media_timer_avg_ms = 50; + metrics_sum.total_scheduling_count = 50; + metrics1.buffer_overruns_max_count = 70; + metrics_sum.buffer_overruns_max_count = 70; + metrics1.buffer_underruns_average = 80; + metrics1.buffer_underruns_count = 1200; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 80; + metrics_sum.buffer_underruns_count = 1200; + metrics1.Update(metrics2); + COMPARE_A2DP_METRICS(metrics1, metrics_sum); + EXPECT_TRUE(metrics1 == metrics_sum); + EXPECT_EQ(metrics1, metrics_sum); +} + +class BluetoothMetricsLoggerTest : public Test { + protected: + // Use to hold test protos + std::vector<PairEvent*> pair_events_; + std::vector<WakeEvent*> wake_events_; + std::vector<ScanEvent*> scan_events_; + std::vector<BluetoothSession*> bt_sessions_; + BluetoothLog* bt_log_; + std::string bt_log_str_; + std::string bt_log_ascii_str_; + + void UpdateLog() { + for (BluetoothSession* session : bt_sessions_) { + bt_log_->mutable_session()->AddAllocated(session); + } + bt_sessions_.clear(); + for (PairEvent* event : pair_events_) { + bt_log_->mutable_pair_event()->AddAllocated(event); + } + pair_events_.clear(); + for (WakeEvent* event : wake_events_) { + bt_log_->mutable_wake_event()->AddAllocated(event); + } + wake_events_.clear(); + for (ScanEvent* event : scan_events_) { + bt_log_->mutable_scan_event()->AddAllocated(event); + } + scan_events_.clear(); + bt_log_->SerializeToString(&bt_log_str_); + } + + void ClearLog() { + for (BluetoothSession* session : bt_sessions_) { + session->Clear(); + delete session; + } + bt_sessions_.clear(); + for (PairEvent* event : pair_events_) { + event->Clear(); + delete event; + } + pair_events_.clear(); + for (WakeEvent* event : wake_events_) { + event->Clear(); + delete event; + } + wake_events_.clear(); + for (ScanEvent* event : scan_events_) { + event->Clear(); + delete event; + } + scan_events_.clear(); + bt_log_->Clear(); + } + + void SetUp() { + bt_log_ = new BluetoothLog(); + // Clear existing metrics entries, if any + BluetoothMetricsLogger::GetInstance()->Reset(); + } + void TearDown() { + // Clear remaining metrics entries, if any + BluetoothMetricsLogger::GetInstance()->Reset(); + ClearLog(); + delete bt_log_; + } + + public: +}; + +TEST_F(BluetoothMetricsLoggerTest, PairEventTest) { + pair_events_.push_back(MakePairEvent( + 35, 12345, + MakeDeviceInfo( + 42, DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR))); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogPairEvent( + 35, 12345, 42, system_bt_osi::DEVICE_TYPE_BREDR); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +TEST_F(BluetoothMetricsLoggerTest, WakeEventTest) { + wake_events_.push_back( + MakeWakeEvent(WakeEvent_WakeEventType::WakeEvent_WakeEventType_ACQUIRED, + "TEST_REQ", "TEST_NAME", 12345)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogWakeEvent( + system_bt_osi::WAKE_EVENT_ACQUIRED, "TEST_REQ", "TEST_NAME", 12345); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +TEST_F(BluetoothMetricsLoggerTest, WakeEvent500Test) { + GenerateWakeEvents(450, 500, &wake_events_); + UpdateLog(); + for (int i = 0; i < 500; ++i) { + BluetoothMetricsLogger::GetInstance()->LogWakeEvent( + i % 2 == 0 ? system_bt_osi::WAKE_EVENT_ACQUIRED + : system_bt_osi::WAKE_EVENT_RELEASED, + "TEST_REQ", "TEST_NAME", i); + } + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +TEST_F(BluetoothMetricsLoggerTest, ScanEventTest) { + scan_events_.push_back(MakeScanEvent( + ScanEvent_ScanEventType::ScanEvent_ScanEventType_SCAN_EVENT_STOP, + "TEST_INITIATOR", ScanEvent_ScanTechnologyType:: + ScanEvent_ScanTechnologyType_SCAN_TECH_TYPE_BREDR, + 42, 123456)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogScanEvent( + false, "TEST_INITIATOR", system_bt_osi::SCAN_TECH_TYPE_BREDR, 42, 123456); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +TEST_F(BluetoothMetricsLoggerTest, BluetoothSessionTest) { + bt_sessions_.push_back(MakeBluetoothSession( + 10, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_LE, + "TEST_DISCONNECT", nullptr, nullptr, nullptr)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_LE, 123456); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd( + "TEST_DISCONNECT", 133456); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +TEST_F(BluetoothMetricsLoggerTest, BluetoothSessionDumpBeforeEndTest) { + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_LE, + "METRICS_DUMP", nullptr, nullptr, nullptr)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_LE, time_get_os_boottime_ms()); + sleep_ms(1000); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +TEST_F(BluetoothMetricsLoggerTest, BluetoothSessionStartBeforeEndTest) { + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_UNKNOWN, + "NEXT_SESSION_START_WITHOUT_ENDING_PREVIOUS", nullptr, nullptr, nullptr)); + bt_sessions_.push_back(MakeBluetoothSession( + 2, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_LE, + "METRICS_DUMP", nullptr, nullptr, nullptr)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_UNKNOWN, 0); + sleep_ms(1000); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_LE, 0); + sleep_ms(2000); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +/* + * Test Case: A2DPSessionTwoUpdatesTest + * + * 1. Create Instance + * 2. LogBluetoothSessionStart + * 3. LogBluetoothSessionDeviceInfo + * 4. LogA2dpSession + * 5. LogA2dpSession + * 6. LogBluetoothSessionEnd + * 7. WriteString + * + */ +TEST_F(BluetoothMetricsLoggerTest, A2DPSessionTwoUpdatesTest) { + /* Same metrics from BluetoothA2DPSessionMetricsTest.TestUpdateNormal */ + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics1.audio_duration_ms = 10; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 35; + metrics1.media_timer_min_ms = 10; + metrics2.media_timer_min_ms = 25; + metrics_sum.media_timer_min_ms = 10; + metrics1.media_timer_max_ms = 100; + metrics2.media_timer_max_ms = 200; + metrics_sum.media_timer_max_ms = 200; + metrics1.media_timer_avg_ms = 50; + metrics1.total_scheduling_count = 50; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics_sum.media_timer_avg_ms = 75; + metrics_sum.total_scheduling_count = 100; + metrics1.buffer_overruns_max_count = 70; + metrics2.buffer_overruns_max_count = 80; + metrics_sum.buffer_overruns_max_count = 80; + metrics1.buffer_underruns_average = 80; + metrics1.buffer_underruns_count = 1200; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 113.33333333; + metrics_sum.buffer_underruns_count = 3600; + DeviceInfo* info = MakeDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, + DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR); + A2DPSession* session = MakeA2DPSession(metrics_sum); + bt_sessions_.push_back(MakeBluetoothSession( + 10, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR, + "TEST_DISCONNECT", info, nullptr, session)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_BREDR, 123456); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, system_bt_osi::DEVICE_TYPE_BREDR); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics1); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics2); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd( + "TEST_DISCONNECT", 133456); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +/* + * Test Case: A2DPSessionTwoUpdatesSeparatedbyDumpTest + * + * 1. Create Instance + * 2. LogBluetoothSessionStart + * 3. LogBluetoothSessionDeviceInfo + * 4. LogA2dpSession + * 5. WriteString + * 6. LogA2dpSession + * 7. LogBluetoothSessionEnd + * 8. WriteString + * + */ +TEST_F(BluetoothMetricsLoggerTest, A2DPSessionTwoUpdatesSeparatedbyDumpTest) { + /* Same metrics from BluetoothA2DPSessionMetricsTest.TestUpdateNormal */ + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + metrics1.audio_duration_ms = 10; + metrics2.audio_duration_ms = 25; + metrics1.media_timer_min_ms = 10; + metrics2.media_timer_min_ms = 25; + metrics1.media_timer_max_ms = 100; + metrics2.media_timer_max_ms = 200; + metrics1.media_timer_avg_ms = 50; + metrics1.total_scheduling_count = 50; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics1.buffer_overruns_max_count = 70; + metrics2.buffer_overruns_max_count = 80; + metrics1.buffer_underruns_average = 80; + metrics1.buffer_underruns_count = 1200; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + DeviceInfo* info = MakeDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, + DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR); + A2DPSession* session = MakeA2DPSession(metrics1); + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR, + "METRICS_DUMP", info, nullptr, session)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_BREDR, 0); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, system_bt_osi::DEVICE_TYPE_BREDR); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics1); + sleep_ms(1000); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); + ClearLog(); + info = MakeDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, + DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR); + session = MakeA2DPSession(metrics2); + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR, + "TEST_DISCONNECT", info, nullptr, session)); + UpdateLog(); + sleep_ms(1000); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics2); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd( + "TEST_DISCONNECT", 0); + msg_str.clear(); + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +/* + * Test Case 1: A2DPSessionOnlyTest + * + * 1. Create Instance + * 4. LogA2dpSession + * 5. WriteString + * 6. LogA2dpSession + * 8. WriteString + * + */ +TEST_F(BluetoothMetricsLoggerTest, A2DPSessionOnlyTest) { + /* Same metrics from BluetoothA2DPSessionMetricsTest.TestUpdateNormal */ + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics1.audio_duration_ms = 10; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 35; + metrics1.media_timer_min_ms = 10; + metrics2.media_timer_min_ms = 25; + metrics_sum.media_timer_min_ms = 10; + metrics1.media_timer_max_ms = 100; + metrics2.media_timer_max_ms = 200; + metrics_sum.media_timer_max_ms = 200; + metrics1.media_timer_avg_ms = 50; + metrics1.total_scheduling_count = 50; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics_sum.media_timer_avg_ms = 75; + metrics_sum.total_scheduling_count = 100; + metrics1.buffer_overruns_max_count = 70; + metrics2.buffer_overruns_max_count = 80; + metrics_sum.buffer_overruns_max_count = 80; + metrics1.buffer_underruns_average = 80; + metrics1.buffer_underruns_count = 1200; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 113.33333333; + metrics_sum.buffer_underruns_count = 3600; + DeviceInfo* info = MakeDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, + DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR); + A2DPSession* session = MakeA2DPSession(metrics_sum); + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR, + "METRICS_DUMP", info, nullptr, session)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics1); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics2); + sleep_ms(1000); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} + +/* + * Test Case: A2DPSessionDumpBeforeTwoUpdatesTest + * + * 1. Create Instance + * 2. LogBluetoothSessionStart + * 3. LogBluetoothSessionDeviceInfo + * 5. WriteString + * 6. LogA2dpSession + * 7. LogA2dpSession + * 8. LogBluetoothSessionEnd + * 9. WriteString + * + */ +TEST_F(BluetoothMetricsLoggerTest, A2DPSessionDumpBeforeTwoUpdatesTest) { + /* Same metrics from BluetoothA2DPSessionMetricsTest.TestUpdateNormal */ + A2dpSessionMetrics metrics1; + A2dpSessionMetrics metrics2; + A2dpSessionMetrics metrics_sum; + metrics1.audio_duration_ms = 10; + metrics2.audio_duration_ms = 25; + metrics_sum.audio_duration_ms = 35; + metrics1.media_timer_min_ms = 10; + metrics2.media_timer_min_ms = 25; + metrics_sum.media_timer_min_ms = 10; + metrics1.media_timer_max_ms = 100; + metrics2.media_timer_max_ms = 200; + metrics_sum.media_timer_max_ms = 200; + metrics1.media_timer_avg_ms = 50; + metrics1.total_scheduling_count = 50; + metrics2.media_timer_avg_ms = 100; + metrics2.total_scheduling_count = 50; + metrics_sum.media_timer_avg_ms = 75; + metrics_sum.total_scheduling_count = 100; + metrics1.buffer_overruns_max_count = 70; + metrics2.buffer_overruns_max_count = 80; + metrics_sum.buffer_overruns_max_count = 80; + metrics1.buffer_underruns_average = 80; + metrics1.buffer_underruns_count = 1200; + metrics2.buffer_underruns_average = 130; + metrics2.buffer_underruns_count = 2400; + metrics_sum.buffer_underruns_average = 113.33333333; + metrics_sum.buffer_underruns_count = 3600; + DeviceInfo* info = MakeDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, + DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR); + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR, + "METRICS_DUMP", info, nullptr, nullptr)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart( + system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_BREDR, 0); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, system_bt_osi::DEVICE_TYPE_BREDR); + sleep_ms(1000); + std::string msg_str; + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); + ClearLog(); + info = MakeDeviceInfo( + BTM_COD_MAJOR_AUDIO_TEST, + DeviceInfo_DeviceType::DeviceInfo_DeviceType_DEVICE_TYPE_BREDR); + A2DPSession* session = MakeA2DPSession(metrics_sum); + bt_sessions_.push_back(MakeBluetoothSession( + 1, + BluetoothSession_ConnectionTechnologyType:: + BluetoothSession_ConnectionTechnologyType_CONNECTION_TECHNOLOGY_TYPE_BREDR, + "TEST_DISCONNECT", info, nullptr, session)); + UpdateLog(); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics1); + BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics2); + sleep_ms(1000); + BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd( + "TEST_DISCONNECT", 0); + msg_str.clear(); + BluetoothMetricsLogger::GetInstance()->WriteString(&msg_str, true); + EXPECT_THAT(msg_str, StrEq(bt_log_str_)); +} +}