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

Commit ffdad57c authored by Chris Manton's avatar Chris Manton Committed by Automerger Merge Worker
Browse files

Add last `n` classic inquiry procedure stats am: 700b73fd am: e9ddd75a 

Original change: https://android-review.googlesource.com/c/platform/packages/modules/Bluetooth/+/2579835



Change-Id: I64b7c337891d6c2fe711042bcb0b5713b3fab3df
Signed-off-by: default avatarAutomerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>
parents 6ad33cb0 e9ddd75a

system/bta/dm/bta_dm_act.cc

+13 −10
Original line number Diff line number Diff line
@@ -845,8 +845,6 @@ void bta_dm_ci_rmt_oob_act(std::unique_ptr<tBTA_DM_CI_RMT_OOB> msg) { 
 *

 ******************************************************************************/

void bta_dm_search_start(tBTA_DM_MSG* p_data) {

  tBTM_INQUIRY_CMPL result = {};



  bta_dm_gattc_register();



  APPL_TRACE_DEBUG("%s avoid_scatter=%d", __func__,
@@ -857,14 +855,19 @@ void bta_dm_search_start(tBTA_DM_MSG* p_data) { 
  bta_dm_search_cb.p_search_cback = p_data->search.p_cback;

  bta_dm_search_cb.services = p_data->search.services;



  result.status = BTM_StartInquiry(bta_dm_inq_results_cb, bta_dm_inq_cmpl_cb);



  APPL_TRACE_EVENT("%s status=%d", __func__, result.status);

  if (result.status != BTM_CMD_STARTED) {

    LOG(ERROR) << __func__ << ": BTM_StartInquiry returned "

               << std::to_string(result.status);

    result.num_resp = 0;

    bta_dm_inq_cmpl_cb((void*)&result);

  const tBTM_STATUS btm_status =

      BTM_StartInquiry(bta_dm_inq_results_cb, bta_dm_inq_cmpl_cb);

  switch (btm_status) {

    case BTM_CMD_STARTED:

      // Completion callback will be executed when controller inquiry

      // timer pops or is cancelled by the user

      break;

    default:

      LOG_WARN("Unable to start device discovery search btm_status:%s",

               btm_status_text(btm_status).c_str());

      // Not started so completion callback is executed now

      bta_dm_inq_cmpl(0);

      break;

  }

}

system/main/shim/acl.cc

+25 −0
Original line number Diff line number Diff line
@@ -147,6 +147,17 @@ using OnDisconnect = std::function<void(HciHandle, hci::ErrorCode reason)>; 


constexpr char kConnectionDescriptorTimeFormat[] = "%Y-%m-%d %H:%M:%S";



constexpr unsigned MillisPerSecond = 1000;

std::string EpochMillisToString(long long time_ms) {

  time_t time_sec = time_ms / MillisPerSecond;

  struct tm tm;

  localtime_r(&time_sec, &tm);

  std::string s = common::StringFormatTime(kConnectionDescriptorTimeFormat, tm);

  return base::StringPrintf(

      "%s.%03u", s.c_str(),

      static_cast<unsigned int>(time_ms % MillisPerSecond));

}



inline bool IsRpa(const hci::AddressWithType address_with_type) {

  return address_with_type.GetAddressType() ==

             hci::AddressType::RANDOM_DEVICE_ADDRESS &&
@@ -1339,6 +1350,20 @@ void DumpsysNeighbor(int fd) { 
                    1000.0,

                btm_cb.neighbor.le_scan.results);

  }

  const auto copy = btm_cb.neighbor.inquiry_history_->Pull();

  LOG_DUMPSYS(fd, "Last %zu inquiry scans:", copy.size());

  for (const auto& it : copy) {

    LOG_DUMPSYS(fd,

                "  %s - %s duration_ms:%-5Lu num_resp:%-2u"

                " std:%-2u rssi:%-2u ext:%-2u %12s",

                EpochMillisToString(it.entry.start_time_ms).c_str(),

                EpochMillisToString(it.timestamp).c_str(),

                it.timestamp - it.entry.start_time_ms, it.entry.num_resp,

                it.entry.resp_type[BTM_INQ_RESULT_STANDARD],

                it.entry.resp_type[BTM_INQ_RESULT_WITH_RSSI],

                it.entry.resp_type[BTM_INQ_RESULT_EXTENDED],

                btm_inquiry_cmpl_status_text(it.entry.status).c_str());

  }

}

#undef DUMPSYS_TAG

system/stack/btm/btm_inq.cc

+94 −34
Original line number Diff line number Diff line
@@ -483,13 +483,32 @@ void BTM_CancelInquiry(void) { 


  CHECK(BTM_IsDeviceUp());



  btm_cb.neighbor.inquiry_history_->Push({

      .status = tBTM_INQUIRY_CMPL::CANCELED,

      .num_resp = btm_cb.btm_inq_vars.inq_cmpl_info.num_resp,

      .resp_type =

          {

              btm_cb.btm_inq_vars.inq_cmpl_info

                  .resp_type[BTM_INQ_RESULT_STANDARD],

              btm_cb.btm_inq_vars.inq_cmpl_info

                  .resp_type[BTM_INQ_RESULT_WITH_RSSI],

              btm_cb.btm_inq_vars.inq_cmpl_info

                  .resp_type[BTM_INQ_RESULT_EXTENDED],

          },

      .start_time_ms = btm_cb.neighbor.classic_inquiry.start_time_ms,

  });



  const auto end_time_ms = timestamper_in_milliseconds.GetTimestamp();

  BTM_LogHistory(

      kBtmLogTag, RawAddress::kEmpty, "Classic inquiry canceled",

      base::StringPrintf("duration_s:%6.3f results:%lu",

                         (timestamper_in_milliseconds.GetTimestamp() -

                          btm_cb.neighbor.classic_inquiry.start_time_ms) /

      base::StringPrintf(

          "duration_s:%6.3f results:%lu std:%u rssi:%u ext:%u",

          (end_time_ms - btm_cb.neighbor.classic_inquiry.start_time_ms) /

              1000.0,

                         btm_cb.neighbor.classic_inquiry.results));

          btm_cb.neighbor.classic_inquiry.results,

          p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_STANDARD],

          p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_WITH_RSSI],

          p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_EXTENDED]));

  btm_cb.neighbor.classic_inquiry = {};



  /* Only cancel if not in periodic mode, otherwise the caller should call
@@ -567,12 +586,18 @@ tBTM_STATUS BTM_StartInquiry(tBTM_INQ_RESULTS_CB* p_results_cb, 
        " state:%hhu counter:%u",

        btm_cb.btm_inq_vars.inq_active, btm_cb.btm_inq_vars.state,

        btm_cb.btm_inq_vars.inq_counter);

    btm_cb.neighbor.inquiry_history_->Push({

        .status = tBTM_INQUIRY_CMPL::NOT_STARTED,

    });

    return BTM_BUSY;

  }



  /*** Make sure the device is ready ***/

  if (!BTM_IsDeviceUp()) {

    LOG(ERROR) << __func__ << ": adapter is not up";

    btm_cb.neighbor.inquiry_history_->Push({

        .status = tBTM_INQUIRY_CMPL::NOT_STARTED,

    });

    return BTM_WRONG_MODE;

  }
@@ -594,8 +619,7 @@ tBTM_STATUS BTM_StartInquiry(tBTM_INQ_RESULTS_CB* p_results_cb, 
  btm_cb.btm_inq_vars.state = BTM_INQ_ACTIVE_STATE;

  btm_cb.btm_inq_vars.p_inq_cmpl_cb = p_cmpl_cb;

  btm_cb.btm_inq_vars.p_inq_results_cb = p_results_cb;

  btm_cb.btm_inq_vars.inq_cmpl_info.num_resp =

      0; /* Clear the results counter */

  btm_cb.btm_inq_vars.inq_cmpl_info = {}; /* Clear the results counter */

  btm_cb.btm_inq_vars.inq_active = btm_cb.btm_inq_vars.inqparms.mode;

  btm_cb.neighbor.classic_inquiry = {

      .start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
@@ -1311,8 +1335,21 @@ void btm_process_inq_results(const uint8_t* p, uint8_t hci_evt_len, 


      p_i->time_of_resp = bluetooth::common::time_get_os_boottime_ms();



      if (p_i->inq_count != p_inq->inq_counter)

        p_inq->inq_cmpl_info.num_resp++; /* A new response was found */

      if (p_i->inq_count != p_inq->inq_counter) {

        /* A new response was found */

        btm_cb.btm_inq_vars.inq_cmpl_info.num_resp++;

        switch (static_cast<tBTM_INQ_RESULT>(inq_res_mode)) {

          case BTM_INQ_RESULT_STANDARD:

          case BTM_INQ_RESULT_WITH_RSSI:

          case BTM_INQ_RESULT_EXTENDED:

            btm_cb.btm_inq_vars.inq_cmpl_info.resp_type[inq_res_mode]++;

            break;

          case BTM_INQ_RES_IGNORE_RSSI:

            btm_cb.btm_inq_vars.inq_cmpl_info

                .resp_type[BTM_INQ_RESULT_STANDARD]++;

            break;

        }

      }



      p_cur->inq_result_type |= BTM_INQ_RESULT_BR;

      if (p_i->inq_count != p_inq->inq_counter) {
@@ -1399,22 +1436,21 @@ void btm_sort_inq_result(void) { 
 *

 ******************************************************************************/

void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) {

  tBTM_CMPL_CB* p_inq_cb = btm_cb.btm_inq_vars.p_inq_cmpl_cb;

  tBTM_INQUIRY_VAR_ST* p_inq = &btm_cb.btm_inq_vars;



  p_inq->inqparms.mode &= ~(mode);

  const auto inq_active = p_inq->inq_active;



#if (BTM_INQ_DEBUG == TRUE)

  BTM_TRACE_DEBUG("btm_process_inq_complete inq_active:0x%x state:%d",

                  btm_cb.btm_inq_vars.inq_active, btm_cb.btm_inq_vars.state);

#endif

  btm_acl_update_inquiry_status(BTM_INQUIRY_COMPLETE);



  if (status != HCI_SUCCESS) {

    LOG_WARN("Received unexpected hci status:%s",

             hci_error_code_text(status).c_str());

  }



  /* Ignore any stray or late complete messages if the inquiry is not active */

  if (p_inq->inq_active) {

    p_inq->inq_cmpl_info.status =

        (tBTM_STATUS)((status == HCI_SUCCESS) ? BTM_SUCCESS

                                              : BTM_ERR_PROCESSING);

    p_inq->inq_cmpl_info.hci_status = status;



    /* Notify caller that the inquiry has completed; (periodic inquiries do not

     * send completion events */
@@ -1427,36 +1463,60 @@ void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) { 


      btm_clr_inq_result_flt();



      if ((p_inq->inq_cmpl_info.status == BTM_SUCCESS) &&

      if ((status == HCI_SUCCESS) &&

          controller_get_interface()->supports_rssi_with_inquiry_results()) {

        btm_sort_inq_result();

      }



      if (btm_cb.btm_inq_vars.p_inq_cmpl_cb) {

        (btm_cb.btm_inq_vars.p_inq_cmpl_cb)(

            (tBTM_INQUIRY_CMPL*)&p_inq->inq_cmpl_info);

      } else {

        LOG_WARN("No callback to return inquiry result");

      }



      btm_cb.neighbor.inquiry_history_->Push({

          .status = tBTM_INQUIRY_CMPL::TIMER_POPPED,

          .num_resp = btm_cb.btm_inq_vars.inq_cmpl_info.num_resp,

          .resp_type =

              {

                  btm_cb.btm_inq_vars.inq_cmpl_info

                      .resp_type[BTM_INQ_RESULT_STANDARD],

                  btm_cb.btm_inq_vars.inq_cmpl_info

                      .resp_type[BTM_INQ_RESULT_WITH_RSSI],

                  btm_cb.btm_inq_vars.inq_cmpl_info

                      .resp_type[BTM_INQ_RESULT_EXTENDED],

              },

          .start_time_ms = btm_cb.neighbor.classic_inquiry.start_time_ms,

      });

      const auto end_time_ms = timestamper_in_milliseconds.GetTimestamp();

      BTM_LogHistory(

          kBtmLogTag, RawAddress::kEmpty, "Classic inquiry complete",

          base::StringPrintf(

              "duration_s:%6.3f results:%lu inq_active:0x%02x std:%u rssi:%u "

              "ext:%u status:%s",

              (end_time_ms - btm_cb.neighbor.classic_inquiry.start_time_ms) /

                  1000.0,

              btm_cb.neighbor.classic_inquiry.results, inq_active,

              p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_STANDARD],

              p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_WITH_RSSI],

              p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_EXTENDED],

              hci_error_code_text(status).c_str()));



      btm_cb.neighbor.classic_inquiry.start_time_ms = 0;

      /* Clear the results callback if set */

      p_inq->p_inq_results_cb = NULL;

      p_inq->inq_active = BTM_INQUIRY_INACTIVE;

      p_inq->p_inq_cmpl_cb = NULL;



      /* If we have a callback registered for inquiry complete, call it */

      BTM_TRACE_DEBUG("BTM Inq Compl Callback: status 0x%02x, num results %d",

                      p_inq->inq_cmpl_info.status,

                      p_inq->inq_cmpl_info.num_resp);



      if (p_inq_cb) (p_inq_cb)((tBTM_INQUIRY_CMPL*)&p_inq->inq_cmpl_info);

      BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Classic inquiry complete",

                     base::StringPrintf(

                         "duration_s:%6.3f results:%lu inq_active:0x%02x",

                         (timestamper_in_milliseconds.GetTimestamp() -

                          btm_cb.neighbor.classic_inquiry.start_time_ms) /

                             1000.0,

                         btm_cb.neighbor.classic_inquiry.results, inq_active));

      btm_cb.neighbor.classic_inquiry.start_time_ms = 0;

    } else {

      LOG_INFO(

          "Inquiry params is not clear so not sending callback inq_parms:%u",

          btm_cb.btm_inq_vars.inqparms.mode);

    }

  } else {

    LOG_ERROR("Received inquiry complete when no inquiry was active");

  }

  BTM_TRACE_DEBUG("inq_active:0x%x state:%d", btm_cb.btm_inq_vars.inq_active,

                  btm_cb.btm_inq_vars.state);

}



/*******************************************************************************

system/stack/btm/btm_int_types.h

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


constexpr size_t kMaxLogSize = 255;

constexpr size_t kBtmLogHistoryBufferSize = 200;

constexpr size_t kMaxInquiryScanHistory = 10;



extern bluetooth::common::TimestamperInMilliseconds timestamper_in_milliseconds;
@@ -313,6 +314,11 @@ typedef struct tBTM_CB { 
      long long start_time_ms;

      unsigned long results;

    } classic_inquiry, le_scan, le_inquiry, le_observe, le_legacy_scan;

    std::unique_ptr<

        bluetooth::common::TimestampedCircularBuffer<tBTM_INQUIRY_CMPL>>

        inquiry_history_ = std::make_unique<

            bluetooth::common::TimestampedCircularBuffer<tBTM_INQUIRY_CMPL>>(

            kMaxInquiryScanHistory);

  } neighbor;



  void Init(uint8_t initial_security_mode) {

system/stack/btm/neighbor_inquiry.h

+34 −3
Original line number Diff line number Diff line
@@ -86,13 +86,14 @@ enum : uint16_t { 
};



/* Define inquiry results mode */

enum : uint8_t {

typedef enum : uint8_t {

  BTM_INQ_RESULT_STANDARD = 0,

  BTM_INQ_RESULT_WITH_RSSI = 1,

  BTM_INQ_RESULT_EXTENDED = 2,

  /* RSSI value not supplied (ignore it) */

  BTM_INQ_RES_IGNORE_RSSI = 0x7f,

};

} tBTM_INQ_RESULT;

constexpr size_t kMaxNumberInquiryResults = BTM_INQ_RESULT_EXTENDED + 1;



/* These are the fields returned in each device's response to the inquiry.  It

 * is returned in the results callback if registered.
@@ -181,10 +182,40 @@ typedef struct /* contains the parameters passed to the inquiry functions */ 


/* Structure returned with inquiry complete callback */

typedef struct {

  tBTM_STATUS status;

  // Possible inquiry completion status

  enum STATUS {

    CANCELED,      // Expected user API cancel

    TIMER_POPPED,  // Expected controller initiated timeout

    NOT_STARTED,   // Unexpected controller unable to execute inquiry command

    SSP_ACTIVE,    // Unexpected secure simple pairing is operational

  };

  STATUS status;

  tHCI_STATUS hci_status;

  uint8_t num_resp; /* Number of results from the current inquiry */

  unsigned resp_type[kMaxNumberInquiryResults];

  long long start_time_ms;

} tBTM_INQUIRY_CMPL;



#ifndef CASE_RETURN_TEXT

#define CASE_RETURN_TEXT(code) \

  case code:                   \

    return #code

#endif



inline std::string btm_inquiry_cmpl_status_text(

    const tBTM_INQUIRY_CMPL::STATUS& status) {

  switch (status) {

    CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::CANCELED);

    CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::TIMER_POPPED);

    CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::NOT_STARTED);

    CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::SSP_ACTIVE);

    default:

      return std::string("UNKNOWN[") + std::to_string(status) +

             std::string("]");

  }

}

#undef CASE_RETURN_TEXT



/* Structure returned with remote name  request */

typedef struct {

  tBTM_STATUS status;