[PATCH 15/15] supplicant: Add state transition timestamps.
greearb at candelatech.com
greearb
Wed Mar 5 16:20:00 PST 2014
From: Ben Greear <greearb at candelatech.com>
Helps with understanding how long it takes to do various
tasks.
Signed-off-by: Ben Greear <greearb at 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(-)
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
};
--
1.7.3.4
More information about the Hostap
mailing list