| Message ID | 1394065200-20377-15-git-send-email-greearb@candelatech.com |
|---|---|
| State | Changes Requested |
| Headers | show |
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().
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
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.
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 };