diff --git a/README.build b/README.build index d0c22e9c..4825245d 100644 --- a/README.build +++ b/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 ------------------------------------------- diff --git a/README.test-apps b/README.test-apps index 081c0c6d..9950f19d 100644 --- a/README.test-apps +++ b/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. + diff --git a/configure.ac b/configure.ac index d6868ec1..a8030efd 100644 --- a/configure.ac +++ b/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) + # # # diff --git a/lib/libwebsockets.c b/lib/libwebsockets.c index e6c87fd1..38fc098a 100644 --- a/lib/libwebsockets.c +++ b/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) diff --git a/lib/libwebsockets.h b/lib/libwebsockets.h index 0b08fcb2..113e9d54 100644 --- a/lib/libwebsockets.h +++ b/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 { diff --git a/lib/private-libwebsockets.h b/lib/private-libwebsockets.h index 0e013b3c..7c62e074 100644 --- a/lib/private-libwebsockets.h +++ b/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);