Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 144a2679 authored by weichinweng's avatar weichinweng
Browse files

stopwatch: improve stopwatch problems 

* For command timeout case, will print the stopwatch log.
* For startup_timer_expired case, will print the stopwatch log.
* Add record initializationComplete function into stopwatch log.
* For the stopwatch can't correctly dump log if the array is not full
  case, fix it.

bug: 190786398
Test: atest BluetoothInstrumentationTests & Manually
Tag: #stability
Change-Id: I8a66897ca46f593e18e231c43e8873ff0db08288
Merged-In: Ie59dbc0bd2f574761eed7aac695cbff07948d8e2
parent dd76b04b

system/common/stop_watch_legacy.cc

+16 −1
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ 
#include "common/stop_watch_legacy.h"



#include <iomanip>

#include <mutex>

#include <sstream>

#include <utility>
@@ -31,16 +32,29 @@ namespace common { 
static const int LOG_BUFFER_LENGTH = 10;

static std::array<StopWatchLog, LOG_BUFFER_LENGTH> stopwatch_logs;

static int current_buffer_index;

static std::recursive_mutex stopwatch_log_mutex;



void StopWatchLegacy::RecordLog(StopWatchLog log) {

  std::unique_lock<std::recursive_mutex> lock(stopwatch_log_mutex, std::defer_lock);

  if (!lock.try_lock()) {

    LOG_INFO("try_lock fail. log content: %s, took %zu us", log.message.c_str(),

             static_cast<size_t>(

                 std::chrono::duration_cast<std::chrono::microseconds>(

                     stopwatch_logs[current_buffer_index].end_timestamp -

                     stopwatch_logs[current_buffer_index].start_timestamp)

                     .count()));

    return;

  }

  if (current_buffer_index >= LOG_BUFFER_LENGTH) {

    current_buffer_index = 0;

  }

  stopwatch_logs[current_buffer_index] = std::move(log);

  current_buffer_index++;

  lock.unlock();

}



void StopWatchLegacy::DumpStopWatchLog() {

  std::lock_guard<std::recursive_mutex> lock(stopwatch_log_mutex);

  LOG_INFO("=====================================");

  LOG_INFO("bluetooth stopwatch log history:");

  for (int i = 0; i < LOG_BUFFER_LENGTH; i++) {
@@ -48,7 +62,8 @@ void StopWatchLegacy::DumpStopWatchLog() { 
      current_buffer_index = 0;

    }

    if (stopwatch_logs[current_buffer_index].message.empty()) {

      break;

      current_buffer_index++;

      continue;

    }

    std::stringstream ss;

    auto now = stopwatch_logs[current_buffer_index].timestamp;

system/gd/common/stop_watch.cc

+16 −1
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ 
#include "common/stop_watch.h"



#include <iomanip>

#include <mutex>

#include <sstream>

#include <utility>
@@ -31,16 +32,29 @@ namespace common { 
static const int LOG_BUFFER_LENGTH = 10;

static std::array<StopWatchLog, LOG_BUFFER_LENGTH> stopwatch_logs;

static int current_buffer_index;

static std::recursive_mutex stopwatch_log_mutex;



void StopWatch::RecordLog(StopWatchLog log) {

  std::unique_lock<std::recursive_mutex> lock(stopwatch_log_mutex, std::defer_lock);

  if (!lock.try_lock()) {

    LOG_INFO("try_lock fail. log content: %s, took %zu us", log.message.c_str(),

             static_cast<size_t>(

                 std::chrono::duration_cast<std::chrono::microseconds>(

                     stopwatch_logs[current_buffer_index].end_timestamp -

                     stopwatch_logs[current_buffer_index].start_timestamp)

                     .count()));

    return;

  }

  if (current_buffer_index >= LOG_BUFFER_LENGTH) {

    current_buffer_index = 0;

  }

  stopwatch_logs[current_buffer_index] = std::move(log);

  current_buffer_index++;

  lock.unlock();

}



void StopWatch::DumpStopWatchLog() {

  std::lock_guard<std::recursive_mutex> lock(stopwatch_log_mutex);

  LOG_INFO("=====================================");

  LOG_INFO("bluetooth stopwatch log history:");

  for (int i = 0; i < LOG_BUFFER_LENGTH; i++) {
@@ -48,7 +62,8 @@ void StopWatch::DumpStopWatchLog() { 
      current_buffer_index = 0;

    }

    if (stopwatch_logs[current_buffer_index].message.empty()) {

      break;

      current_buffer_index++;

      continue;

    }

    std::stringstream ss;

    auto now = stopwatch_logs[current_buffer_index].timestamp;

system/gd/hal/hci_hal_android_hidl.cc

+1 −0
Original line number Diff line number Diff line
@@ -83,6 +83,7 @@ class InternalHciCallbacks : public IBluetoothHciCallbacks { 
  }



  Return<void> initializationComplete(HidlStatus status) {

    common::StopWatch(__func__);

    ASSERT(status == HidlStatus::SUCCESS);

    init_promise_->set_value();

    return Void();

system/gd/hci/hci_layer.cc

+2 −0
Original line number Diff line number Diff line
@@ -18,6 +18,7 @@ 


#include "common/bind.h"

#include "common/init_flags.h"

#include "common/stop_watch.h"

#include "hci/hci_metrics_logging.h"

#include "os/alarm.h"

#include "os/metrics.h"
@@ -181,6 +182,7 @@ struct HciLayer::impl { 
  }



  void on_hci_timeout(OpCode op_code) {

    common::StopWatch::DumpStopWatchLog();

    LOG_ERROR("Timed out waiting for 0x%02hx (%s)", op_code, OpCodeText(op_code).c_str());

    // TODO: LogMetricHciTimeoutEvent(static_cast<uint32_t>(op_code));

system/hci/src/hci_layer.cc

+5 −0
Original line number Diff line number Diff line
@@ -42,6 +42,7 @@ 
#include "common/message_loop_thread.h"

#include "common/metrics.h"

#include "common/once_timer.h"

#include "common/stop_watch_legacy.h"

#include "hci_inject.h"

#include "hci_internals.h"

#include "hcidefs.h"
@@ -58,6 +59,7 @@ 


using bluetooth::common::MessageLoopThread;

using bluetooth::common::OnceTimer;

using bluetooth::common::StopWatchLegacy;



extern void hci_initialize();

extern void hci_transmit(BT_HDR* packet);
@@ -376,6 +378,8 @@ static void event_finish_startup(UNUSED_ATTR void* context) { 
static void startup_timer_expired(UNUSED_ATTR void* context) {

  LOG_ERROR("%s", __func__);



  StopWatchLegacy::DumpStopWatchLog();



  LOG_EVENT_INT(BT_HCI_TIMEOUT_TAG_NUM, HCI_STARTUP_TIMED_OUT);



  hci_close();
@@ -522,6 +526,7 @@ static void command_timed_out_log_info(void* original_wait_entry) { 
// Print debugging information and quit. Don't dereference original_wait_entry.

static void command_timed_out(void* original_wait_entry) {

  LOG_ERROR("%s", __func__);

  StopWatchLegacy::DumpStopWatchLog();

  std::unique_lock<std::recursive_timed_mutex> lock(

      commands_pending_response_mutex, std::defer_lock);

  if (!lock.try_lock_for(std::chrono::milliseconds(