qcacld-3.0: Add hr:min:sec:usec timeformat to driver logs

qcacld-2.0 to qcacld-3.0 propagation

Driver logs timestamp format is different from logcat logs,
it's not user understandable and difficult to correlate with other logs.

This fix includes
1. Add hr:min:sec:usec timeformat to wlan logger and kernel logs
2. Remove SIR_CFG_PARAM_UPDATE_IND MTRACE log which is seen
   frequent in MTRACE dumps

Change-Id: I45e5d28fbeccd757648f05ce4e593d8ca4fe7804
CRS-Fixed: 1049125

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

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

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

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

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;