introduce lws_latency

Signed-off-by: Andy Green <andy.green@linaro.org>

README.build

@@ -98,6 +98,12 @@ There are several other possible configure options
 			the code / data size / speed improvements may be
 			critical.
 
+--with-latency		Builds the latency-tracking code into the library...
+			this slows your library down a bit but is very useful
+			to find the cause of unexpected latencies occurring
+			inside the library.  See README.test-apps for more
+			info
+
 
 Externally configurable important constants
 -------------------------------------------

README.test-apps

@@ -215,6 +215,7 @@ available are (OR together the numbers to select multiple)
  64  HEADER
  128 EXTENSION
  256 CLIENT
+ 512 LATENCY
 
 
 Websocket version supported
@@ -224,3 +225,26 @@ The final IETF standard is supported for both client and server, protocol
 version 13.
 
 
+Latency Tracking
+----------------
+
+Since libwebsockets runs using poll() and a single threaded approach, any
+unexpected latency coming from system calls would be bad news.  There's now
+a latency tracking scheme that can be built in with --with-latency at
+configure-time, logging the time taken for system calls to complete and if
+the whole action did complete that time or was deferred.
+
+You can see the detailed data by enabling logging level 512 (eg, -d 519 on
+the test server to see that and the usual logs), however even without that
+the "worst" latency is kept and reported to the logs with NOTICE severity
+when the context is destroyed.
+
+Some care is needed interpreting them, if the action completed the first figure
+(in us) is the time taken for the whole action, which may have retried through
+the poll loop many times and will depend on network roundtrip times.  High
+figures here don't indicate a problem.  The figure in us reported after "lat"
+in the logging is the time taken by this particular attempt.  High figures
+here may indicate a problem, or if you system is loaded with another app at
+that time, such as the browser, it may simply indicate the OS gave preferential
+treatment to the other app during that call.
+

configure.ac

@@ -94,6 +94,19 @@ CFLAGS="$CFLAGS -DLWS_NO_EXTENSIONS"
 fi
 AM_CONDITIONAL(NO_EXTENSIONS, test x$no_extensions = xyes)
 
+# 
+#
+#
+AC_ARG_WITH(latency,
+ [  --with-latency  Build latency measuring code into the library ],
+ [ latency=yes
+ ])
+
+if test "x$latency" = "xyes" ; then                                             
+CFLAGS="$CFLAGS -DLWS_LATENCY"                                          
+fi
+AM_CONDITIONAL(LATENCY, test x$latency = xyes)
+
 # 
 #
 #

lib/libwebsockets.c

@@ -63,6 +63,7 @@ static const char *log_level_names[] = {
 	"HEADER",
 	"EXTENSION",
 	"CLIENT",
+	"LATENCY",
 };
 
 int
@@ -929,6 +930,11 @@ libwebsocket_context_destroy(struct libwebsocket_context *context)
 	int m;
 	struct libwebsocket_extension *ext;
 
+#ifdef LWS_LATENCY
+	if (context->worst_latency_info[0])
+		lwsl_notice("Worst latency: %s\n", context->worst_latency_info);
+#endif
+
 	for (n = 0; n < context->fds_count; n++) {
 		struct libwebsocket *wsi = context->lws_lookup[context->fds[n].fd];
 		libwebsocket_close_and_free_session(context,
@@ -1207,6 +1213,40 @@ libwebsocket_get_socket_fd(struct libwebsocket *wsi)
 	return wsi->sock;
 }
 
+#ifdef LWS_LATENCY
+void
+lws_latency(struct libwebsocket_context *context, struct libwebsocket *wsi, const char *action, int ret, int completed)
+{
+	struct timeval tv;
+	unsigned long u;
+	char buf[256];
+
+	gettimeofday(&tv, NULL);
+
+	u = (tv.tv_sec * 1000000) + tv.tv_usec;
+
+	if (action) {
+		if (completed) {
+			if (wsi->action_start == wsi->latency_start)
+				sprintf(buf, "Completion first try lat %luus: %p: ret %d: %s\n", u - wsi->latency_start, (void *)wsi, ret, action);
+			else
+				sprintf(buf, "Completion %luus: lat %luus: %p: ret %d: %s\n", u - wsi->action_start, u - wsi->latency_start, (void *)wsi, ret, action);
+			wsi->action_start = 0;
+		} else
+			sprintf(buf, "lat %luus: %p: ret %d: %s\n", u - wsi->latency_start, (void *)wsi, ret, action);
+		if (u - wsi->latency_start > context->worst_latency) {
+			context->worst_latency = u - wsi->latency_start;
+			strcpy(context->worst_latency_info, buf);
+		}
+		lwsl_latency("%s", buf);
+	} else {
+		wsi->latency_start = u;
+		if (!wsi->action_start)
+			wsi->action_start = u;
+	}
+}
+#endif
+
 #ifdef LWS_NO_SERVER
 int
 _libwebsocket_rx_flow_control(struct libwebsocket *wsi)

lib/libwebsockets.h

@@ -76,38 +76,44 @@ enum lws_log_levels {
 	LLL_HEADER = 1 << 6,
 	LLL_EXT = 1 << 7,
 	LLL_CLIENT = 1 << 8,
+	LLL_LATENCY = 1 << 9,
 
-	LLL_COUNT = 9 /* set to count of valid flags */
+	LLL_COUNT = 10 /* set to count of valid flags */
 };
 
 extern void _lws_log(int filter, const char *format, ...);
 
-/* warn and log are always compiled in */
+/* notice, warn and log are always compiled in */
 #define lwsl_notice(...) _lws_log(LLL_NOTICE, __VA_ARGS__)
 #define lwsl_warn(...) _lws_log(LLL_WARN, __VA_ARGS__)
 #define lwsl_err(...) _lws_log(LLL_ERR, __VA_ARGS__)
-
 /*
- *  weaker logging can be deselected at configure time using disable_debug
+ *  weaker logging can be deselected at configure time using --disable-debug
  *  that gets rid of the overhead of checking while keeping _warn and _err
  *  active
  */
 #ifdef _DEBUG
+
 #define lwsl_info(...) _lws_log(LLL_INFO, __VA_ARGS__)
 #define lwsl_debug(...) _lws_log(LLL_DEBUG, __VA_ARGS__)
 #define lwsl_parser(...) _lws_log(LLL_PARSER, __VA_ARGS__)
 #define lwsl_header(...)  _lws_log(LLL_HEADER, __VA_ARGS__)
-#define lwsl_ext(...)  _lws_log(LLL_HEADER, __VA_ARGS__)
+#define lwsl_ext(...)  _lws_log(LLL_EXT, __VA_ARGS__)
 #define lwsl_client(...) _lws_log(LLL_CLIENT, __VA_ARGS__)
+#define lwsl_latency(...) _lws_log(LLL_LATENCY, __VA_ARGS__)
 extern void lwsl_hexdump(void *buf, size_t len);
+
 #else /* no debug */
+
 #define lwsl_info(...)
 #define lwsl_debug(...)
 #define lwsl_parser(...)
 #define lwsl_header(...)
 #define lwsl_ext(...)
 #define lwsl_client(...)
+#define lwsl_latency(...)
 #define lwsl_hexdump(a, b)
+
 #endif
 
 enum libwebsocket_context_options {

lib/private-libwebsockets.h

@@ -239,6 +239,11 @@ struct libwebsocket_context {
 	int listen_service_fd;
 	int listen_service_extraseen;
 
+#ifdef LWS_LATENCY
+	unsigned long worst_latency;
+	char worst_latency_info[256];
+#endif
+
 #ifdef LWS_OPENSSL_SUPPORT
 	int use_ssl;
 	SSL_CTX *ssl_ctx;
@@ -337,6 +342,10 @@ struct libwebsocket {
 
 	int sock;
 	int position_in_fds_table;
+#ifdef LWS_LATENCY
+	unsigned long action_start;
+	unsigned long latency_start;
+#endif
 
 	void *user_space;
 
@@ -370,6 +379,15 @@ struct libwebsocket {
 #endif	
 };
 
+#ifndef LWS_LATENCY
+static inline void lws_latency(struct libwebsocket_context *context, struct libwebsocket *wsi, const char *action, int ret, int completion) { while (0); }
+static inline void lws_latency_pre(struct libwebsocket_context *context, struct libwebsocket *wsi) { while (0); }
+#else
+#define lws_latency_pre(_context, _wsi) lws_latency(_context, _wsi, NULL, 0, 0)
+extern void
+lws_latency(struct libwebsocket_context *context, struct libwebsocket *wsi, const char *action, int ret, int completion);
+#endif
+
 extern int
 libwebsocket_client_rx_sm(struct libwebsocket *wsi, unsigned char c);