Patchwork [15/15] supplicant: Add state transition timestamps.

login
register
mail settings
Submitter Ben Greear
Date March 6, 2014, 12:20 a.m.
Message ID <1394065200-20377-15-git-send-email-greearb@candelatech.com>
Download mbox | patch
Permalink /patch/327251/
State New
Headers show

Comments

Ben Greear - March 6, 2014, 12:20 a.m.
From: Ben Greear <greearb@candelatech.com>

Helps with understanding how long it takes to do various
tasks.

Signed-off-by: Ben Greear <greearb@candelatech.com>
---
 wpa_supplicant/Makefile           |    5 +++
 wpa_supplicant/ctrl_iface.c       |   27 ++++++++++++++++
 wpa_supplicant/defconfig          |    5 +++
 wpa_supplicant/interworking.c     |   13 ++++++++
 wpa_supplicant/wpa_supplicant.c   |   60 +++++++++++++++++++++++++++++++++++++
 wpa_supplicant/wpa_supplicant_i.h |   19 +++++++++++
 6 files changed, 129 insertions(+), 0 deletions(-)

Patch

diff --git a/wpa_supplicant/Makefile b/wpa_supplicant/Makefile
index 2b8cb93..355712a 100644
--- a/wpa_supplicant/Makefile
+++ b/wpa_supplicant/Makefile
@@ -1484,6 +1484,11 @@  OBJS += offchannel.o
 CFLAGS += -DCONFIG_OFFCHANNEL
 endif
 
+ifdef CONFIG_REPORT_TIMERS
+CFLAGS += -DCONFIG_REPORT_TIMERS
+endif
+
+
 OBJS += ../src/drivers/driver_common.o
 OBJS_priv += ../src/drivers/driver_common.o
 
diff --git a/wpa_supplicant/ctrl_iface.c b/wpa_supplicant/ctrl_iface.c
index 2935ce7..efbbe68 100644
--- a/wpa_supplicant/ctrl_iface.c
+++ b/wpa_supplicant/ctrl_iface.c
@@ -1819,6 +1819,33 @@  static int wpa_supplicant_ctrl_iface_status(struct wpa_supplicant *wpa_s,
 	}
 #endif /* ANDROID */
 
+#ifdef CONFIG_REPORT_TIMERS
+#define PRINT_TIME_STAMP(a) do {					\
+		double tval = (double)(wpa_s->a.sec) +			\
+			(double)(wpa_s->a.usec) / (double)(1000000);	\
+		ret = os_snprintf(pos, end - pos, #a "=%f\n",		\
+				  tval);				\
+		if (ret < 0 || ret >= end - pos)			\
+			return pos - buf;				\
+		pos += ret;						\
+	} while (0)
+
+	PRINT_TIME_STAMP(state_disconnected_orig_at);
+	PRINT_TIME_STAMP(state_disconnected_at);
+	PRINT_TIME_STAMP(state_disabled_at);
+	PRINT_TIME_STAMP(state_inactive_at);
+	PRINT_TIME_STAMP(state_scanning_at);
+	PRINT_TIME_STAMP(started_anqp_query_at);
+	PRINT_TIME_STAMP(finished_anqp_query_at);
+	PRINT_TIME_STAMP(state_authenticating_at);
+	PRINT_TIME_STAMP(state_associating_at);
+	PRINT_TIME_STAMP(state_associated_at);
+	PRINT_TIME_STAMP(state_4way_at);
+	PRINT_TIME_STAMP(state_group_handshake_at);
+	PRINT_TIME_STAMP(state_wpa_completed_4way_at);
+	PRINT_TIME_STAMP(state_wpa_completed_conn_at);
+#endif
+
 	return pos - buf;
 }
 
diff --git a/wpa_supplicant/defconfig b/wpa_supplicant/defconfig
index 7b21d60..e736e0e 100644
--- a/wpa_supplicant/defconfig
+++ b/wpa_supplicant/defconfig
@@ -497,3 +497,8 @@  CONFIG_PEERKEY=y
 #
 # External password backend for testing purposes (developer use)
 #CONFIG_EXT_PASSWORD_TEST=y
+
+# Keep some timestamps for various events, report them with 'wpa_cli status'
+# Aids in testing APs if nothing else.   Should be low impact on CPU and
+# memory usage, but increases both slightly.
+#CONFIG_REPORT_TIMERS=y
diff --git a/wpa_supplicant/interworking.c b/wpa_supplicant/interworking.c
index 732724d..36a302f 100644
--- a/wpa_supplicant/interworking.c
+++ b/wpa_supplicant/interworking.c
@@ -2538,6 +2538,11 @@  static void interworking_next_anqp_fetch(struct wpa_supplicant *wpa_s)
 			hs20_osu_icon_fetch(wpa_s);
 			return;
 		}
+
+#ifdef CONFIG_REPORT_TIMERS
+		os_get_time(&wpa_s->finished_anqp_query_at);
+#endif
+
 		wpa_msg(wpa_s, MSG_INFO, "ANQP fetch completed");
 		wpa_s->fetch_anqp_in_progress = 0;
 		if (wpa_s->network_select)
@@ -2554,6 +2559,11 @@  void interworking_start_fetch_anqp(struct wpa_supplicant *wpa_s)
 		bss->flags &= ~WPA_BSS_ANQP_FETCH_TRIED;
 
 	wpa_s->fetch_anqp_in_progress = 1;
+
+#ifdef CONFIG_REPORT_TIMERS
+	os_get_time(&wpa_s->started_anqp_query_at);
+#endif
+
 	interworking_next_anqp_fetch(wpa_s);
 }
 
@@ -2578,6 +2588,9 @@  void interworking_stop_fetch_anqp(struct wpa_supplicant *wpa_s)
 	if (!wpa_s->fetch_anqp_in_progress)
 		return;
 
+#ifdef CONFIG_REPORT_TIMERS
+	os_get_time(&wpa_s->finished_anqp_query_at);
+#endif
 	wpa_s->fetch_anqp_in_progress = 0;
 }
 
diff --git a/wpa_supplicant/wpa_supplicant.c b/wpa_supplicant/wpa_supplicant.c
index 4bd3d2d..b81b8ed 100644
--- a/wpa_supplicant/wpa_supplicant.c
+++ b/wpa_supplicant/wpa_supplicant.c
@@ -668,6 +668,66 @@  void wpa_supplicant_set_state(struct wpa_supplicant *wpa_s,
 	if (state == WPA_COMPLETED)
 		wpas_connect_work_done(wpa_s);
 
+#ifdef CONFIG_REPORT_TIMERS
+	if ((old_state != state) ||
+	    (state == WPA_DISCONNECTED && wpa_s->state_disconnected_at.sec == 0)) {
+		switch (state) {
+		case WPA_DISCONNECTED:
+			os_get_time(&wpa_s->state_disconnected_at);
+			if (! wpa_s->disconnect_since_complete) {
+				/* First disconnect state since we were last fully connected
+				 */
+				wpa_s->state_disconnected_orig_at = wpa_s->state_disconnected_at;
+				wpa_s->disconnect_since_complete = 1;
+			}
+			break;
+		case WPA_INTERFACE_DISABLED:
+			os_get_time(&wpa_s->state_disabled_at);
+			break;
+		case WPA_INACTIVE:
+			os_get_time(&wpa_s->state_inactive_at);
+			break;
+		case WPA_SCANNING:
+			os_get_time(&wpa_s->state_scanning_at);
+			break;
+		case WPA_AUTHENTICATING:
+			/* On roam, we go from completed -> associating, never hitting
+			 * disconnected.  Treat this as disconnected with regard to timers.
+			 */
+			if (!wpa_s->disconnect_since_complete) {
+				os_get_time(&wpa_s->state_disconnected_at);
+				wpa_s->state_disconnected_orig_at = wpa_s->state_disconnected_at;
+				wpa_s->disconnect_since_complete = 1;
+			}
+			os_get_time(&wpa_s->state_authenticating_at);
+			break;
+		case WPA_ASSOCIATING:
+			os_get_time(&wpa_s->state_associating_at);
+			break;
+		case WPA_ASSOCIATED:
+			os_get_time(&wpa_s->state_associated_at);
+			break;
+		case WPA_4WAY_HANDSHAKE:
+			wpa_s->had_4way_since_complete = 1;
+			os_get_time(&wpa_s->state_4way_at);
+			break;
+		case WPA_GROUP_HANDSHAKE:
+			os_get_time(&wpa_s->state_group_handshake_at);
+			break;
+		case WPA_COMPLETED:
+			if (wpa_s->had_4way_since_complete) {
+				os_get_time(&wpa_s->state_wpa_completed_4way_at);
+				wpa_s->had_4way_since_complete = 0;
+			}
+			if (wpa_s->disconnect_since_complete) {
+				os_get_time(&wpa_s->state_wpa_completed_conn_at);
+				wpa_s->disconnect_since_complete = 0;
+			}
+			break;
+		}
+	}/* if state actually changed */
+#endif
+
 	if (state != WPA_SCANNING)
 		wpa_supplicant_notify_scanning(wpa_s, 0);
 
diff --git a/wpa_supplicant/wpa_supplicant_i.h b/wpa_supplicant/wpa_supplicant_i.h
index a430756..d53e3fe 100644
--- a/wpa_supplicant/wpa_supplicant_i.h
+++ b/wpa_supplicant/wpa_supplicant_i.h
@@ -824,6 +824,25 @@  struct wpa_supplicant {
 	struct wpa_radio_work *connect_work;
 
 	unsigned int ext_work_id;
+
+#ifdef CONFIG_REPORT_TIMERS
+	u8 disconnect_since_complete;
+	u8 had_4way_since_complete;
+	struct os_time state_disconnected_orig_at;
+	struct os_time state_disconnected_at;
+	struct os_time state_disabled_at;
+	struct os_time state_inactive_at;
+	struct os_time state_scanning_at;
+	struct os_time state_authenticating_at;
+	struct os_time state_associating_at;
+	struct os_time state_associated_at;
+	struct os_time state_4way_at;
+	struct os_time state_group_handshake_at;
+	struct os_time state_wpa_completed_4way_at;
+	struct os_time state_wpa_completed_conn_at;
+	struct os_time started_anqp_query_at;
+	struct os_time finished_anqp_query_at;
+#endif
 };