system/osi/src/metrics.cc

/******************************************************************************
 *
 *  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.
 *
 ******************************************************************************/
#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 "stack/include/btm_api_types.h"

#include "osi/src/protos/bluetooth.pb.h"

#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;
using clearcut::connectivity::ScanEvent;
using clearcut::connectivity::ScanEvent_ScanTechnologyType;
using clearcut::connectivity::ScanEvent_ScanEventType;
using clearcut::connectivity::WakeEvent;
using clearcut::connectivity::WakeEvent_WakeEventType;

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 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;
  }
}

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 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;
    }
  }
}

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;
}

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;
  }
}

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;
  }
}

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;
  }
}

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;
  }
}

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 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 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 {
    event->set_scan_event_type(ScanEvent::SCAN_EVENT_STOP);
  }
  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 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));
}

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;
}

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);
}

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 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__);
  if (!pimpl_->bluetooth_log_->SerializeToString(serialized)) {
    LOG_ERROR(LOG_TAG, "%s: error serializing metrics", __func__);
    return;
  }
  if (clear) {
    pimpl_->bluetooth_log_->Clear();
  }
}

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) {
    LOG_ERROR(LOG_TAG, "%s: error writing to dumpsys fd: %s (%d)", __func__,
              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