diff --git a/core/hdd/src/wlan_hdd_trace.c b/core/hdd/src/wlan_hdd_trace.c index 37c141cf9aa3..e45a42d02b6b 100644 --- a/core/hdd/src/wlan_hdd_trace.c +++ b/core/hdd/src/wlan_hdd_trace.c @@ -54,12 +54,14 @@ static void hdd_trace_dump(void *mac, tp_qdf_trace_record record, uint16_t index) { if (TRACE_CODE_HDD_RX_SME_MSG == record->code) - hdd_err("%04d %012llu S%d %-14s %-30s(0x%x)", - index, record->time, record->session, "RX SME MSG:", + hdd_err("%04d %012llu %s S%d %-14s %-30s(0x%x)", + index, record->qtime, record->time, record->session, + "RX SME MSG:", get_e_roam_cmd_status_str(record->data), record->data); else - hdd_err("%04d %012llu S%d %-14s %-30s(0x%x)", - index, record->time, record->session, "HDD Event:", + hdd_err("%04d %012llu %s S%d %-14s %-30s(0x%x)", + index, record->qtime, record->time, record->session, + "HDD Event:", hdd_trace_event_string(record->code), record->data); } diff --git a/core/mac/src/cfg/cfg_api.c b/core/mac/src/cfg/cfg_api.c index 8b15ba20a42f..2d347853fdd4 100644 --- a/core/mac/src/cfg/cfg_api.c +++ b/core/mac/src/cfg/cfg_api.c @@ -919,8 +919,6 @@ static void notify(tpAniSirGlobal pMac, uint16_t cfgId, uint32_t ntfMask) mmhMsg.bodyval = (uint32_t) cfgId; mmhMsg.bodyptr = NULL; - MTRACE(mac_trace_msg_tx(pMac, NO_SESSION, mmhMsg.type)); - if ((ntfMask & CFG_CTL_NTF_SCH) != 0) sch_post_message(pMac, &mmhMsg); diff --git a/core/mac/src/pe/lim/lim_trace.c b/core/mac/src/pe/lim/lim_trace.c index 1598724f5bc5..830bf29bb961 100644 --- a/core/mac/src/pe/lim/lim_trace.c +++ b/core/mac/src/pe/lim/lim_trace.c @@ -132,23 +132,28 @@ void lim_trace_dump(tpAniSirGlobal pMac, tp_qdf_trace_record pRecord, switch (pRecord->code) { case TRACE_CODE_MLM_STATE: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "MLM State:", - lim_trace_get_mlm_state_string((uint16_t) pRecord->data), + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "MLM State:", + lim_trace_get_mlm_state_string( + (uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_SME_STATE: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "SME State:", - lim_trace_get_sme_state_string((uint16_t) pRecord->data), + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "SME State:", + lim_trace_get_sme_state_string( + (uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_TX_MGMT: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "TX Mgmt:", - frameSubtypeStr[pRecord->data], pRecord->data); + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "TX Mgmt:", frameSubtypeStr[pRecord->data], + pRecord->data); break; case TRACE_CODE_RX_MGMT: @@ -158,9 +163,9 @@ void lim_trace_dump(tpAniSirGlobal pMac, tp_qdf_trace_record pRecord, LIM_TRACE_GET_SUBTYPE(pRecord->data)); } else { lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(%d) SN: %d", - recIndex, pRecord->time, pRecord->session, - "RX Mgmt:", + "%04d %012llu %s S%d %-14s %-30s(%d) SN: %d", + recIndex, pRecord->qtime, pRecord->time, + pRecord->session, "RX Mgmt:", frameSubtypeStr[LIM_TRACE_GET_SUBTYPE (pRecord->data)], LIM_TRACE_GET_SUBTYPE(pRecord->data), @@ -168,127 +173,131 @@ void lim_trace_dump(tpAniSirGlobal pMac, tp_qdf_trace_record pRecord, } break; case TRACE_CODE_RX_MGMT_DROP: - lim_log(pMac, LOG1, "%04d %012llu S%d %-14s %-30s(%d)", - recIndex, pRecord->time, pRecord->session, - "Drop RX Mgmt:", - __lim_trace_get_mgmt_drop_reason_string((uint16_t) pRecord-> - data), pRecord->data); + lim_log(pMac, LOG1, "%04d %012llu %s S%d %-14s %-30s(%d)", + recIndex, pRecord->qtime, pRecord->time, + pRecord->session, "Drop RX Mgmt:", + __lim_trace_get_mgmt_drop_reason_string( + (uint16_t) pRecord->data), + pRecord->data); break; case TRACE_CODE_RX_MGMT_TSF: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s0x%x(%d)", - recIndex, pRecord->time, pRecord->session, - "RX Mgmt TSF:", " ", pRecord->data, pRecord->data); + "%04d %012llu %s S%d %-14s %-30s0x%x(%d)", + recIndex, pRecord->qtime, pRecord->time, + pRecord->session, "RX Mgmt TSF:", " ", + pRecord->data, pRecord->data); break; case TRACE_CODE_TX_COMPLETE: - lim_log(pMac, LOG1, "%04d %012llu S%d %-14s %d", recIndex, - pRecord->time, pRecord->session, "TX Complete", - pRecord->data); + lim_log(pMac, LOG1, "%04d %012llu %s S%d %-14s %d", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "TX Complete", pRecord->data); break; case TRACE_CODE_TX_SME_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "TX SME Msg:", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "TX SME Msg:", mac_trace_get_sme_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_RX_SME_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, - LIM_TRACE_GET_DEFRD_OR_DROPPED(pRecord-> - data) ? "Def/Drp LIM Msg:" - : "RX Sme Msg:", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + LIM_TRACE_GET_DEFRD_OR_DROPPED( + pRecord->data) ? "Def/Drp LIM Msg:" : "RX Sme Msg:", mac_trace_get_sme_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_TX_WMA_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "TX WMA Msg:", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "TX WMA Msg:", mac_trace_get_wma_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_RX_WMA_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, - LIM_TRACE_GET_DEFRD_OR_DROPPED(pRecord-> - data) ? "Def/Drp LIM Msg:" - : "RX WMA Msg:", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + LIM_TRACE_GET_DEFRD_OR_DROPPED( + pRecord->data) ? "Def/Drp LIM Msg:" : "RX WMA Msg:", mac_trace_get_wma_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_TX_LIM_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "TX LIM Msg:", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "TX LIM Msg:", mac_trace_get_lim_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_RX_LIM_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, - LIM_TRACE_GET_DEFRD_OR_DROPPED(pRecord-> - data) ? "Def/Drp LIM Msg:" - : "RX LIM Msg", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + LIM_TRACE_GET_DEFRD_OR_DROPPED( + pRecord->data) ? "Def/Drp LIM Msg:" : "RX LIM Msg", mac_trace_get_lim_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_TX_CFG_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x) ", recIndex, - pRecord->time, pRecord->session, "TX CFG Msg:", + "%04d %012llu %s S%d %-14s %-30s(0x%x) ", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "TX CFG Msg:", mac_trace_get_cfg_msg_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_RX_CFG_MSG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x) ", recIndex, - pRecord->time, pRecord->session, - LIM_TRACE_GET_DEFRD_OR_DROPPED(pRecord-> - data) ? "Def/Drp LIM Msg:" - : "RX CFG Msg:", - mac_trace_get_cfg_msg_string((uint16_t) - MAC_TRACE_GET_MSG_ID(pRecord-> - data)), + "%04d %012llu %s S%d %-14s %-30s(0x%x) ", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + LIM_TRACE_GET_DEFRD_OR_DROPPED( + pRecord->data) ? "Def/Drp LIM Msg:" : "RX CFG Msg:", + mac_trace_get_cfg_msg_string( + (uint16_t)MAC_TRACE_GET_MSG_ID(pRecord->data)), pRecord->data); break; case TRACE_CODE_TIMER_ACTIVATE: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "Timer Actvtd", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "Timer Actvtd", __lim_trace_get_timer_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_TIMER_DEACTIVATE: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", recIndex, - pRecord->time, pRecord->session, "Timer DeActvtd", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", recIndex, + pRecord->qtime, pRecord->time, pRecord->session, + "Timer DeActvtd", __lim_trace_get_timer_string((uint16_t) pRecord->data), pRecord->data); break; case TRACE_CODE_INFO_LOG: lim_log(pMac, LOG1, - "%04d %012llu S%d %-14s %-30s(0x%x)", - recIndex, pRecord->time, pRecord->session, - "INFORMATION_LOG", + "%04d %012llu %s S%d %-14s %-30s(0x%x)", + recIndex, pRecord->qtime, pRecord->time, + pRecord->session, "INFORMATION_LOG", mac_trace_get_info_log_string((uint16_t) pRecord->data), pRecord->data); break; default: - lim_log(pMac, LOG1, "%04d %012llu S%d %-14s(%d) (0x%x)", - recIndex, pRecord->time, pRecord->session, - "Unknown Code", pRecord->code, pRecord->data); + lim_log(pMac, LOG1, "%04d %012llu %s S%d %-14s(%d) (0x%x)", + recIndex, pRecord->qtime, pRecord->time, + pRecord->session, "Unknown Code", + pRecord->code, pRecord->data); break; } } diff --git a/core/sme/src/common/sme_trace.c b/core/sme/src/common/sme_trace.c index 7837ac1873d1..751dcca1cfa8 100644 --- a/core/sme/src/common/sme_trace.c +++ b/core/sme/src/common/sme_trace.c @@ -210,29 +210,29 @@ static void sme_trace_dump(tpAniSirGlobal mac_ctx, tp_qdf_trace_record record, { switch (record->code) { case TRACE_CODE_SME_COMMAND: - sms_log(mac_ctx, LOG1, "%04d %012llu S%d %-14s %-30s(0x%x)", - rec_index, record->time, record->session, + sms_log(mac_ctx, LOG1, "%04d %012llu %s S%d %-14s %-30s(0x%x)", + rec_index, record->qtime, record->time, record->session, "SME COMMAND:", sme_trace_get_command_string(record->data), record->data); break; case TRACE_CODE_SME_TX_WMA_MSG: - sms_log(mac_ctx, LOG1, "%04d %012llu S%d %-14s %-30s(0x%x)", - rec_index, record->time, record->session, + sms_log(mac_ctx, LOG1, "%04d %012llu %s S%d %-14s %-30s(0x%x)", + rec_index, record->qtime, record->time, record->session, "TX WMA Msg:", mac_trace_get_wma_msg_string((uint16_t)record->data), record->data); break; case TRACE_CODE_SME_RX_WMA_MSG: - sms_log(mac_ctx, LOG1, "%04d %012llu S%d %-14s %-30s(0x%x)", - rec_index, record->time, record->session, + sms_log(mac_ctx, LOG1, "%04d %012llu %s S%d %-14s %-30s(0x%x)", + rec_index, record->qtime, record->time, record->session, "RX WMA Msg:", mac_trace_get_sme_msg_string((uint16_t)record->data), record->data); break; default: - sms_log(mac_ctx, LOG1, "%04d %012llu S%d %-14s %-30s(0x%x)", - rec_index, record->time, record->session, + sms_log(mac_ctx, LOG1, "%04d %012llu %s S%d %-14s %-30s(0x%x)", + rec_index, record->qtime, record->time, record->session, "RX HDD MSG:", sme_trace_get_rx_msg_string(record->code), record->data); diff --git a/core/utils/logging/src/wlan_logging_sock_svc.c b/core/utils/logging/src/wlan_logging_sock_svc.c index 29935a77d5a9..25322afbf05e 100644 --- a/core/utils/logging/src/wlan_logging_sock_svc.c +++ b/core/utils/logging/src/wlan_logging_sock_svc.c @@ -314,7 +314,8 @@ static int wlan_add_user_log_radio_time_stamp(char *tbuf, size_t tbuf_sz, } #else /** - * wlan_add_user_log_radio_time_stamp() - add radio and time stamp in log buffer + * wlan_add_user_log_radio_time_stamp() - add radio, firmware timestamp and + * logcat timestamp in log buffer * @tbuf: Pointer to time stamp buffer * @tbuf_sz: Time buffer size * @ts: Time stamp value @@ -323,6 +324,9 @@ static int wlan_add_user_log_radio_time_stamp(char *tbuf, size_t tbuf_sz, * For adrastea time stamp QTIMER raw tick which will be used by cnss_diag * to convert it into user visible time stamp * + * Also add logcat timestamp so that driver logs and + * logcat logs can be co-related + * * For discrete solution e.g rome use system tick and convert it into * seconds.milli seconds * @@ -334,13 +338,16 @@ static int wlan_add_user_log_radio_time_stamp(char *tbuf, size_t tbuf_sz, { int tlen; uint32_t rem; + char time_buf[20]; + + qdf_get_time_of_the_day_in_hr_min_sec_usec(time_buf, sizeof(time_buf)); rem = do_div(ts, QDF_MC_TIMER_TO_SEC_UNIT); - tlen = scnprintf(tbuf, tbuf_sz, "R%d: [%s][%lu.%06lu] ", radio, + tlen = scnprintf(tbuf, tbuf_sz, "R%d: [%.6s][%lu.%06lu] %s ", radio, ((in_irq() ? "irq" : in_softirq() ? "soft_irq" : current->comm)), (unsigned long) ts, - (unsigned long)rem); + (unsigned long)rem, time_buf); return tlen; } #endif @@ -349,7 +356,7 @@ int wlan_log_to_user(QDF_TRACE_LEVEL log_level, char *to_be_sent, int length) { /* Add the current time stamp */ char *ptr; - char tbuf[50]; + char tbuf[60]; int tlen; int total_log_len; unsigned int *pfilled_length; @@ -444,7 +451,7 @@ int wlan_log_to_user(QDF_TRACE_LEVEL log_level, char *to_be_sent, int length) if (gwlan_logging.log_fe_to_console && ((QDF_TRACE_LEVEL_FATAL == log_level) || (QDF_TRACE_LEVEL_ERROR == log_level))) { - pr_info("%s\n", to_be_sent); + pr_info("%s %s\n", tbuf, to_be_sent); } return 0;