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 Changes Requested
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(-)
Jouni Malinen - Jan. 31, 2015, 11:15 p.m.
On Wed, Mar 05, 2014 at 04:20:00PM -0800, greearb@candelatech.com wrote:
> Helps with understanding how long it takes to do various
> tasks.

This feels too complex.. I don't really want to add N new #ifdef/#endif
blocks for something like this, i.e., that should be cleaned up with
conditionally defined inline functions (etc.) that keeps the source code
readable.

Timing can be figured out from debug log timestamps. If something is
needed at runtime through control interface, I'd like to understand the
use case better before adding this. In addition, this should most likely
be using os_get_reltime() rather than os_get_time().
Ben Greear - Jan. 31, 2015, 11:59 p.m.
On 01/31/2015 03:15 PM, Jouni Malinen wrote:
> On Wed, Mar 05, 2014 at 04:20:00PM -0800, greearb@candelatech.com wrote:
>> Helps with understanding how long it takes to do various
>> tasks.
>
> This feels too complex.. I don't really want to add N new #ifdef/#endif
> blocks for something like this, i.e., that should be cleaned up with
> conditionally defined inline functions (etc.) that keeps the source code
> readable.
>
> Timing can be figured out from debug log timestamps. If something is
> needed at runtime through control interface, I'd like to understand the
> use case better before adding this. In addition, this should most likely
> be using os_get_reltime() rather than os_get_time().

I wanted to get the info through the wpa_cli API.  The idea is to be able to
report the time it took to establish connection, do 4-way auth, anqp, etc.

Parsing logs is too complex, fragile, and in-efficient, especially with lots of virtual
stations.

I will be happy to re-write it with inline methods.  I think I do want os_get_time()
so I can compare time-stamps with other logs and other events if needed.

My use case is generating better reports for testing, and aside from that, this
feature is probably not that useful.  So, if you think some code cleanup would
be good enough to get this in, then I will work on re-spinning the patches.
But, if it is unlikely to ever be wanted upstream anyway, then please let me
know up front and I'll try to remember not to submit it again :)

Thanks,
Ben
Jouni Malinen - Feb. 8, 2015, 7:35 p.m.
On Sat, Jan 31, 2015 at 03:59:03PM -0800, Ben Greear wrote:
> I wanted to get the info through the wpa_cli API.  The idea is to be able to
> report the time it took to establish connection, do 4-way auth, anqp, etc.
> 
> Parsing logs is too complex, fragile, and in-efficient, especially with lots of virtual
> stations.
> 
> I will be happy to re-write it with inline methods.  I think I do want os_get_time()
> so I can compare time-stamps with other logs and other events if needed.

If you are reporting the time it took do something, that should use
os_get_reltime(). If you are reporting a timestamp for some specific
instance, that would be os_get_time(). The patch seemed to show mainly
timestamps, but that's something I'm not sure is really the best thing
to report if this is supposed to make it convenient for interface. I'd
again point at the log with timestamps as the source for raw timestamps,
if that is what you need here. I understand that it may be somewhat
inconvenient for large number of virtual stations.

Number of the values used just a snapshot of the last time something
happened. This may provide quite confusing results, e.g., when ANQP
query was used for some earlier connection and the latest association
did not use ANQP at all. Same would apply for number of other timestamps
here.

As far as PRINT_TIME_STAMP() is concerned, it seems to be used floating
points unnecessarily. All existing cases of printing a timestamp use
integer values here ("%ld.%06y", (long) sec, (unsigned int) usec).

> My use case is generating better reports for testing, and aside from that, this
> feature is probably not that useful.  So, if you think some code cleanup would
> be good enough to get this in, then I will work on re-spinning the patches.
> But, if it is unlikely to ever be wanted upstream anyway, then please let me
> know up front and I'll try to remember not to submit it again :)

I'm not sure a simple cleanup would be sufficient to convince me that
this exact set of timestamps is a useful addition in upstream. Getting
rid of #ifdef/#endif with inline functions hiding that and moving the
results from STATUS to somewhere else (say, "STATUS-TIMESTAMPS") would
likely get quite a bit closer to getting at least some of this included,
though.

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