HS 2.0R2: Add GAS operation duration statistics into debug

Signed-off-by: Jouni Malinen <jouni@qca.qualcomm.com>

wpa_supplicant/gas_query.c

@@ -42,6 +42,7 @@ struct gas_query_pending {
 	struct wpabuf *req;
 	struct wpabuf *adv_proto;
 	struct wpabuf *resp;
+	struct os_reltime last_oper;
 	void (*cb)(void *ctx, const u8 *dst, u8 dialog_token,
 		   enum gas_query_result result,
 		   const struct wpabuf *adv_proto,
@@ -64,6 +65,16 @@ static void gas_query_tx_comeback_timeout(void *eloop_data, void *user_ctx);
 static void gas_query_timeout(void *eloop_data, void *user_ctx);
 
 
+static int ms_from_time(struct os_reltime *last)
+{
+	struct os_reltime now, res;
+
+	os_get_reltime(&now);
+	os_reltime_sub(&now, last, &res);
+	return res.sec * 1000 + res.usec / 1000;
+}
+
+
 /**
  * gas_query_init - Initialize GAS query component
  * @wpa_s: Pointer to wpa_supplicant data
@@ -199,6 +210,7 @@ static void gas_query_tx_status(struct wpa_supplicant *wpa_s,
 {
 	struct gas_query_pending *query;
 	struct gas_query *gas = wpa_s->gas;
+	int dur;
 
 	if (gas->current == NULL) {
 		wpa_printf(MSG_DEBUG, "GAS: Unexpected TX status: freq=%u dst="
@@ -209,13 +221,15 @@ static void gas_query_tx_status(struct wpa_supplicant *wpa_s,
 
 	query = gas->current;
 
+	dur = ms_from_time(&query->last_oper);
 	wpa_printf(MSG_DEBUG, "GAS: TX status: freq=%u dst=" MACSTR
-		   " result=%d query=%p dialog_token=%u",
-		   freq, MAC2STR(dst), result, query, query->dialog_token);
+		   " result=%d query=%p dialog_token=%u dur=%d ms",
+		   freq, MAC2STR(dst), result, query, query->dialog_token, dur);
 	if (os_memcmp(dst, query->addr, ETH_ALEN) != 0) {
 		wpa_printf(MSG_DEBUG, "GAS: TX status for unexpected destination");
 		return;
 	}
+	os_get_reltime(&query->last_oper);
 
 	if (result == OFFCHANNEL_SEND_ACTION_SUCCESS) {
 		eloop_cancel_timeout(gas_query_timeout, gas, query);
@@ -251,6 +265,7 @@ static int gas_query_tx(struct gas_query *gas, struct gas_query_pending *query,
 		u8 *categ = wpabuf_mhead_u8(req);
 		*categ = WLAN_ACTION_PROTECTED_DUAL;
 	}
+	os_get_reltime(&query->last_oper);
 	res = offchannel_send_action(gas->wpa_s, query->freq, query->addr,
 				     gas->wpa_s->own_addr, query->addr,
 				     wpabuf_head(req), wpabuf_len(req), 1000,
@@ -452,6 +467,9 @@ int gas_query_rx(struct gas_query *gas, const u8 *da, const u8 *sa,
 		return -1;
 	}
 
+	wpa_printf(MSG_DEBUG, "GAS: Response in %d ms from " MACSTR,
+		   ms_from_time(&query->last_oper), MAC2STR(sa));
+
 	if (query->wait_comeback && action == WLAN_PA_GAS_INITIAL_RESP) {
 		wpa_printf(MSG_DEBUG, "GAS: Unexpected initial response from "
 			   MACSTR " dialog token %u when waiting for comeback "

wpa_supplicant/hs20_supplicant.c

@@ -284,6 +284,15 @@ static void hs20_continue_icon_fetch(void *eloop_ctx, void *sock_ctx)
 static void hs20_osu_icon_fetch_result(struct wpa_supplicant *wpa_s, int res)
 {
 	size_t i, j;
+	struct os_reltime now, tmp;
+	int dur;
+
+	os_get_reltime(&now);
+	os_reltime_sub(&now, &wpa_s->osu_icon_fetch_start, &tmp);
+	dur = tmp.sec * 1000 + tmp.usec / 1000;
+	wpa_printf(MSG_DEBUG, "HS 2.0: Icon fetch dur=%d ms res=%d",
+		   dur, res);
+
 	for (i = 0; i < wpa_s->osu_prov_count; i++) {
 		struct osu_provider *osu = &wpa_s->osu_prov[i];
 		for (j = 0; j < osu->icon_count; j++) {
@@ -510,6 +519,7 @@ void hs20_next_osu_icon(struct wpa_supplicant *wpa_s)
 			wpa_printf(MSG_DEBUG, "HS 2.0: Try to fetch icon '%s' "
 				   "from " MACSTR, icon->filename,
 				   MAC2STR(osu->bssid));
+			os_get_reltime(&wpa_s->osu_icon_fetch_start);
 			if (hs20_anqp_send_req(wpa_s, osu->bssid,
 					       BIT(HS20_STYPE_ICON_REQUEST),
 					       (u8 *) icon->filename,

wpa_supplicant/wpa_supplicant_i.h

@@ -777,6 +777,7 @@ struct wpa_supplicant {
 	unsigned int osu_icon_id;
 	struct osu_provider *osu_prov;
 	size_t osu_prov_count;
+	struct os_reltime osu_icon_fetch_start;
 #endif /* CONFIG_INTERWORKING */
 	unsigned int drv_capa_known;