diff --git a/CMakeLists.txt b/CMakeLists.txt index 3779924ca..54a1b3739 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -99,7 +99,6 @@ option(LWS_WITHOUT_EXTENSIONS "Don't compile with extensions" ON) option(LWS_WITHOUT_BUILTIN_GETIFADDRS "Don't use the BSD getifaddrs implementation from libwebsockets if it is missing (this will result in a compilation error) ... The default is to assume that your libc provides it. On some systems such as uclibc it doesn't exist." OFF) option(LWS_FALLBACK_GETHOSTBYNAME "Also try to do dns resolution using gethostbyname if getaddrinfo fails" OFF) option(LWS_WITHOUT_BUILTIN_SHA1 "Don't build the lws sha-1 (eg, because openssl will provide it" OFF) -option(LWS_WITH_LATENCY "Build latency measuring code into the library" OFF) option(LWS_WITHOUT_DAEMONIZE "Don't build the daemonization api" ON) option(LWS_SSL_SERVER_WITH_ECDH_CERT "Include SSL server use ECDH certificate" OFF) option(LWS_WITH_LEJP "With the Lightweight JSON Parser" ON) @@ -139,6 +138,7 @@ option(LWS_WITH_EXTERNAL_POLL "Support external POLL integration using callback option(LWS_WITH_LWS_DSH "Support lws_dsh_t Disordered Shared Heap" OFF) option(LWS_CLIENT_HTTP_PROXYING "Support external http proxies for client connections" ON) option(LWS_WITH_FILE_OPS "Support file operations vfs" ON) +option(LWS_WITH_DETAILED_LATENCY "Record detailed latency stats for each read and write" OFF) # # to use miniz, enable both LWS_WITH_ZLIB and LWS_WITH_MINIZ # @@ -677,10 +677,6 @@ if (LWS_SSL_CLIENT_USE_OS_CA_CERTS) set(LWS_SSL_CLIENT_USE_OS_CA_CERTS 1) endif() -if (LWS_WITH_LATENCY) - set(LWS_LATENCY 1) -endif() - if (LWS_WITHOUT_DAEMONIZE OR WIN32) set(LWS_NO_DAEMONIZE 1) endif() @@ -1030,6 +1026,11 @@ if (LWS_WITH_NETWORK) lib/system/async-dns/async-dns-parse.c) endif() + if (LWS_WITH_DETAILED_LATENCY) + list(APPEND SOURCES + lib/core-net/detailed-latency.c) + endif() + if (LWS_WITH_LWS_DSH) list(APPEND SOURCES lib/core-net/lws-dsh.c) @@ -2739,7 +2740,6 @@ message(" LWS_WITHOUT_TEST_SERVER_EXTPOLL = ${LWS_WITHOUT_TEST_SERVER_EXTPOLL}") message(" LWS_WITHOUT_TEST_PING = ${LWS_WITHOUT_TEST_PING}") message(" LWS_WITHOUT_TEST_CLIENT = ${LWS_WITHOUT_TEST_CLIENT}") message(" LWS_WITHOUT_EXTENSIONS = ${LWS_WITHOUT_EXTENSIONS}") -message(" LWS_WITH_LATENCY = ${LWS_WITH_LATENCY}") message(" LWS_WITHOUT_DAEMONIZE = ${LWS_WITHOUT_DAEMONIZE}") message(" LWS_WITH_LIBEV = ${LWS_WITH_LIBEV}") message(" LWS_WITH_LIBUV = ${LWS_WITH_LIBUV}") diff --git a/READMEs/README.detailed-latency.md b/READMEs/README.detailed-latency.md new file mode 100644 index 000000000..29e29d03a --- /dev/null +++ b/READMEs/README.detailed-latency.md @@ -0,0 +1,117 @@ +# lws detailed latency + +![lws detailed latency example plot](../doc-assets/lws-detailed-latency-example.png) + +## Introduction + +lws has the capability to make detailed latency measurements and +report them in realtime to a specified callback. + +A default callback is provided that renders the data as text in +space-separated format suitable for gnuplot, to a specified file. + +## Configuring + +Enable `LWS_WITH_DETAILED_LATENCY` at cmake. + +Create your context with something similar to this + +``` +#if defined(LWS_WITH_DETAILED_LATENCY) + info.detailed_latency_cb = lws_det_lat_plot_cb; + info.detailed_latency_filepath = "/tmp/lws-latency-results"; +#endif +``` + +`lws_det_lat_plot_cb` is provided by lws as a convenience to convert +the stuct data provided at the callback interface to space-separated +text data that is easy to process with shell commands and gnuplot. + +## `lws_det_lat_plot_cb` format + +``` +728239173547 N 23062 0 0 23062 0 0 0 +728239192554 C 18879 0 0 18879 0 0 0 +728239217894 T 25309 0 0 25309 0 0 0 +728239234998 r 0 0 0 0 271 172 256 +728239250611 r 0 0 0 0 69 934 4096 +728239255679 w 19 122 18 159 20 80 80 +728239275718 w 20 117 15 152 18 80 80 +728239295578 w 10 73 7 90 7 80 80 +728239315567 w 9 67 5 81 7 80 80 +728239335745 w 23 133 9 165 14 80 80 +... +``` + +Each event is shown in 9 columns + + - unix time in us + - event type + - N = Name resolution + - C = TCP Connection + - T = TLS negotiation server + - t = TLS negotiation client + - r = Read + - w = Write + - us duration, for w time client spent waiting to write + - us duration, for w time data spent in transit to proxy + - us duration, for w time proxy waited to send data + - as a convenience, sum of last 3 columns above + - us duration, time spent in callback + - last 2 are actual / requested size in bytes + +## Processing captured data with ministat + +Eg, to summarize overall latencies on all captured writes + +``` + $ cat /tmp/lws-latency-results | grep " w " | cut -d' ' -f6 | ministat +... + N Min Max Median Avg Stddev +x 1000 43 273 141 132.672 32.471693 +``` + +## Processing captured data with gnuplot + +### Gnuplot plotting script + +Create a gnuplot script, eg myscript.gp + +``` +reset +set term pngcairo enhanced nocrop font "OpenSans, 12" size 800,600#output terminal and file +set output "lws-latency.png" +#set yrange [0:10000] +#to put an empty boundary around the +#data inside an autoscaled graph. +set offset graph 0.05,0.05,0.05,0.0 +set style fill transparent solid 0.5 #fillstyle +set tics out nomirror +set xlabel "event" +set ylabel "latency (us)" +set format x "" +set title "Write latency" +set key invert reverse Right inside nobox +set key autotitle columnheader +set style data histogram +set style histogram rowstacked +set style fill solid border -1 +set boxwidth 0.75 +set style fill solid 1.00 noborder +set tic scale 0 +set grid ytics lc rgb "#505050" +unset border +unset xtics + +plot '/tmp/1' \ + using ($3 + $4 + $5):xtic(1) w boxes lt rgbcolor "blue" title 'prox wr wait', \ + '' using ($3 + $4):xtic(1) w boxes lt rgbcolor "green" title 'txfr to prox', \ + '' using 3:xtic(1) w boxes lt rgbcolor "red" title 'cli wri wait' +``` + +### gnuplot invocation + +``` + $ cat /tmp/lws-latency-results | grep " w " \>/tmp/1 ; gnuplot myscript.gp && eog lws-latency.png +``` + diff --git a/cmake/lws_config.h.in b/cmake/lws_config.h.in index ef120343b..9adf8f4ce 100644 --- a/cmake/lws_config.h.in +++ b/cmake/lws_config.h.in @@ -72,7 +72,6 @@ #cmakedefine LWS_HAVE_UV_VERSION_H #cmakedefine LWS_HAVE_X509_get_key_usage #cmakedefine LWS_HAVE_X509_VERIFY_PARAM_set1_host -#cmakedefine LWS_LATENCY #cmakedefine LWS_LIBRARY_VERSION "${LWS_LIBRARY_VERSION}" #cmakedefine LWS_MINGW_SUPPORT #cmakedefine LWS_NO_CLIENT @@ -100,6 +99,7 @@ #cmakedefine LWS_WITH_CGI #cmakedefine LWS_WITH_CUSTOM_HEADERS #cmakedefine LWS_WITH_DEPRECATED_LWS_DLL +#cmakedefine LWS_WITH_DETAILED_LATENCY #cmakedefine LWS_WITH_DIR #cmakedefine LWS_WITH_ESP32 #cmakedefine LWS_WITH_EXTERNAL_POLL diff --git a/doc-assets/lws-detailed-latency-example.png b/doc-assets/lws-detailed-latency-example.png new file mode 100644 index 000000000..e23132b87 Binary files /dev/null and b/doc-assets/lws-detailed-latency-example.png differ diff --git a/include/libwebsockets.h b/include/libwebsockets.h index 8c582a718..ccadd2c94 100644 --- a/include/libwebsockets.h +++ b/include/libwebsockets.h @@ -530,6 +530,7 @@ struct lws_vhost; struct lws; #include +#include #include #include #include diff --git a/include/libwebsockets/lws-context-vhost.h b/include/libwebsockets/lws-context-vhost.h index dd9120057..2f1e9ec8d 100644 --- a/include/libwebsockets/lws-context-vhost.h +++ b/include/libwebsockets/lws-context-vhost.h @@ -677,6 +677,11 @@ struct lws_context_creation_info { const lws_system_ops_t *system_ops; /**< CONTEXT: hook up lws_system_ apis to system-specific * implementations */ + det_lat_buf_cb_t detailed_latency_cb; + /**< CONTEXT: NULL, or callback to receive detailed latency information + * collected for each read and write */ + const char *detailed_latency_filepath; + /**< CONTEXT: NULL, or filepath to put latency data into */ /* Add new things just above here ---^ * This is part of the ABI, don't needlessly break compatibility diff --git a/include/libwebsockets/lws-detailed-latency.h b/include/libwebsockets/lws-detailed-latency.h new file mode 100644 index 000000000..1b352c7a6 --- /dev/null +++ b/include/libwebsockets/lws-detailed-latency.h @@ -0,0 +1,140 @@ +/* + * libwebsockets - small server side websockets and web server implementation + * + * Copyright (C) 2010 - 2019 Andy Green + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to + * deal in the Software without restriction, including without limitation the + * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or + * sell copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + * + * included from libwebsockets.h + */ + +enum { + + /* types of latency, all nonblocking except name resolution */ + + LDLT_READ, /* time taken to read LAT_DUR_PROXY_RX_TO_CLIENT_WRITE */ + LDLT_WRITE, + LDLT_NAME_RESOLUTION, /* BLOCKING: LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE */ + LDLT_CONNECTION, /* conn duration: LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE */ + LDLT_TLS_NEG_CLIENT, /* tls conn duration: LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE */ + LDLT_TLS_NEG_SERVER, /* tls conn duration: LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE */ + + LDLT_USER, + + /* interval / duration elements in latencies array */ + + LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE = 0, + /* us the client spent waiting to write to proxy */ + LAT_DUR_PROXY_CLIENT_WRITE_TO_PROXY_RX, + /* us the packet took to be received by proxy */ + LAT_DUR_PROXY_PROXY_REQ_TO_WRITE, + /* us the proxy has to wait before it could write */ + LAT_DUR_PROXY_RX_TO_ONWARD_TX, + /* us the proxy spent waiting to write to destination, or + * if nonproxied, then time between write request and write */ + + LAT_DUR_USERCB, /* us duration of user callback */ + + LAT_DUR_STEPS /* last */ +}; + +typedef struct lws_detlat { + lws_usec_t earliest_write_req; + lws_usec_t earliest_write_req_pre_write; + /**< use this for interval comparison */ + const char *aux; /* name for name resolution timing */ + int type; + uint32_t latencies[LAT_DUR_STEPS]; + size_t req_size; + size_t acc_size; +} lws_detlat_t; + +typedef int (*det_lat_buf_cb_t)(struct lws_context *context, + const lws_detlat_t *d); + +/** + * lws_det_lat_cb() - inject your own latency records + * + * \param context: the lws_context + * \param d: the lws_detlat_t you have prepared + * + * For proxying or similar cases where latency information is available from + * user code rather than lws itself, you can generate your own latency callback + * events with your own lws_detlat_t. + */ + +LWS_VISIBLE LWS_EXTERN int +lws_det_lat_cb(struct lws_context *context, lws_detlat_t *d); + +/* + * detailed_latency_plot_cb() - canned save to file in plottable format cb + * + * \p context: the lws_context + * \p d: the detailed latency event information + * + * This canned callback makes it easy to export the detailed latency information + * to a file. Just set the context creation members like this + * + * #if defined(LWS_WITH_DETAILED_LATENCY) + * info.detailed_latency_cb = lws_det_lat_plot_cb; + * info.detailed_latency_filepath = "/tmp/lws-latency-results"; + * #endif + * + * and you will get a file containing information like this + * + * 718823864615 N 10589 0 0 10589 0 0 0 + * 718823880837 C 16173 0 0 16173 0 0 0 + * 718823913063 T 32212 0 0 32212 0 0 0 + * 718823931835 r 0 0 0 0 232 30 256 + * 718823948757 r 0 0 0 0 40 30 256 + * 718823948799 r 0 0 0 0 83 30 256 + * 718823965602 r 0 0 0 0 27 30 256 + * 718823965617 r 0 0 0 0 43 30 256 + * 718823965998 r 0 0 0 0 12 28 256 + * 718823983887 r 0 0 0 0 74 3 4096 + * 718823986411 w 16 87 7 110 9 80 80 + * 718824006358 w 8 68 6 82 6 80 80 + * + * which is easy to grep and pass to gnuplot. + * + * The columns are + * + * - unix time in us + * - N = Name resolution, C = TCP Connection, T = TLS negotiation server, + * t = TLS negotiation client, r = Read, w = Write + * - us duration, for w time client spent waiting to write + * - us duration, for w time data spent in transit to proxy + * - us duration, for w time proxy waited to send data + * - as a convenience, sum of last 3 columns above + * - us duration, time spent in callback + * - last 2 are actual / requested size in bytes + */ +LWS_VISIBLE LWS_EXTERN int +lws_det_lat_plot_cb(struct lws_context *context, const lws_detlat_t *d); + +/** + * lws_det_lat_active() - indicates if latencies are being measured + * + * \context: lws_context + * + * Returns 0 if latency measurement has not been set up (the callback is NULL). + * Otherwise returns 1 + */ +LWS_VISIBLE LWS_EXTERN int +lws_det_lat_active(struct lws_context *context); diff --git a/lib/core-net/connect.c b/lib/core-net/connect.c index fd435c848..2bbcfaafe 100644 --- a/lib/core-net/connect.c +++ b/lib/core-net/connect.c @@ -61,6 +61,11 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) wsi->desc.sockfd = LWS_SOCK_INVALID; wsi->seq = i->seq; +#if defined(LWS_WITH_DETAILED_LATENCY) + if (i->context->detailed_latency_cb) + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif + wsi->vhost = NULL; if (!i->vhost) lws_vhost_bind_wsi(i->context->vhost_list, wsi); @@ -91,6 +96,9 @@ lws_client_connect_via_info(const struct lws_client_connect_info *i) lwsl_info("%s: client binds to caller tsi %d\n", __func__, n); wsi->tsi = n; +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.tsi = n; +#endif break; } diff --git a/lib/core-net/detailed-latency.c b/lib/core-net/detailed-latency.c new file mode 100644 index 000000000..e176b4beb --- /dev/null +++ b/lib/core-net/detailed-latency.c @@ -0,0 +1,79 @@ +/* + * libwebsockets - small server side websockets and web server implementation + * + * Copyright (C) 2010 - 2019 Andy Green + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to + * deal in the Software without restriction, including without limitation the + * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or + * sell copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + */ + +#include "private-lib-core.h" + +int +lws_det_lat_active(struct lws_context *context) +{ + return !!context->detailed_latency_cb; +} + +int +lws_det_lat_cb(struct lws_context *context, lws_detlat_t *d) +{ + int n; + + if (!context->detailed_latency_cb) + return 0; + + n = context->detailed_latency_cb(context, d); + + memset(&d->latencies, 0, sizeof(d->latencies)); + + return n; +} + +static const char types[] = "rwNCTt????"; +int +lws_det_lat_plot_cb(struct lws_context *context, const lws_detlat_t *d) +{ + char buf[80], *p = buf, *end = &p[sizeof(buf) - 1]; + + if (!context->detailed_latency_filepath) + return 1; + + if (context->latencies_fd == -1) { + context->latencies_fd = open(context->detailed_latency_filepath, + LWS_O_CREAT | LWS_O_TRUNC | LWS_O_WRONLY, 0600); + if (context->latencies_fd == -1) + return 1; + } + + p += lws_snprintf(p, lws_ptr_diff(end, p), + "%llu %c %u %u %u %u %u %zu %zu\n", + (unsigned long long)lws_now_usecs(), types[d->type], + d->latencies[LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE], + d->latencies[LAT_DUR_PROXY_CLIENT_WRITE_TO_PROXY_RX], + d->latencies[LAT_DUR_PROXY_PROXY_REQ_TO_WRITE], + d->latencies[LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE] + + d->latencies[LAT_DUR_PROXY_CLIENT_WRITE_TO_PROXY_RX] + + d->latencies[LAT_DUR_PROXY_PROXY_REQ_TO_WRITE], + d->latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX], + d->acc_size, d->req_size); + + write(context->latencies_fd, buf, lws_ptr_diff(p, buf)); + + return 0; +} diff --git a/lib/core-net/network.c b/lib/core-net/network.c index 7c4250f04..7aa13587e 100644 --- a/lib/core-net/network.c +++ b/lib/core-net/network.c @@ -159,15 +159,11 @@ lws_get_peer_addresses(struct lws *wsi, lws_sockfd_type fd, char *name, struct sockaddr_in6 sin6; #endif struct sockaddr_in sin4; - struct lws_context *context = wsi->context; - int ret = -1; void *p; rip[0] = '\0'; name[0] = '\0'; - lws_latency_pre(context, wsi); - #ifdef LWS_WITH_IPV6 if (LWS_IPV6_ENABLED(wsi->vhost)) { len = sizeof(sin6); @@ -184,10 +180,9 @@ lws_get_peer_addresses(struct lws *wsi, lws_sockfd_type fd, char *name, goto bail; } - ret = lws_get_addresses(wsi->vhost, p, name, name_len, rip, rip_len); + lws_get_addresses(wsi->vhost, p, name, name_len, rip, rip_len); bail: - lws_latency(context, wsi, "lws_get_peer_addresses", ret, 1); #endif (void)wsi; (void)fd; diff --git a/lib/core-net/output.c b/lib/core-net/output.c index 1dac56eca..2838b7009 100644 --- a/lib/core-net/output.c +++ b/lib/core-net/output.c @@ -27,7 +27,8 @@ /* * notice this returns number of bytes consumed, or -1 */ -int lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) +int +lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) { struct lws_context *context = lws_get_context(wsi); struct lws_context_per_thread *pt = &wsi->context->pt[(int)wsi->tsi]; @@ -108,10 +109,8 @@ int lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) n = (int)len; /* nope, send it on the socket directly */ - lws_latency_pre(context, wsi); - m = lws_ssl_capable_write(wsi, buf, n); - lws_latency(context, wsi, "send lws_issue_raw", n, n == m); + m = lws_ssl_capable_write(wsi, buf, n); lwsl_info("%s: ssl_capable_write (%d) says %d\n", __func__, n, m); /* something got written, it can have been truncated now */ @@ -220,10 +219,15 @@ int lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len) return (int)real_len; } -LWS_VISIBLE int lws_write(struct lws *wsi, unsigned char *buf, size_t len, - enum lws_write_protocol wp) +int +lws_write(struct lws *wsi, unsigned char *buf, size_t len, + enum lws_write_protocol wp) { struct lws_context_per_thread *pt = &wsi->context->pt[(int)wsi->tsi]; +#if defined(LWS_WITH_DETAILED_LATENCY) + lws_usec_t us; +#endif + int m; lws_stats_bump(pt, LWSSTATS_C_API_LWS_WRITE, 1); @@ -242,15 +246,38 @@ LWS_VISIBLE int lws_write(struct lws *wsi, unsigned char *buf, size_t len, if (wsi->vhost) wsi->vhost->conn_stats.tx += len; #endif +#if defined(LWS_WITH_DETAILED_LATENCY) + us = lws_now_usecs(); +#endif assert(wsi->role_ops); if (!wsi->role_ops->write_role_protocol) return lws_issue_raw(wsi, buf, len); - return wsi->role_ops->write_role_protocol(wsi, buf, len, &wp); + m = wsi->role_ops->write_role_protocol(wsi, buf, len, &wp); + if (m < 0) + return m; + +#if defined(LWS_WITH_DETAILED_LATENCY) + if (wsi->context->detailed_latency_cb) { + wsi->detlat.req_size = len; + wsi->detlat.acc_size = m; + wsi->detlat.type = LDLT_WRITE; + if (wsi->detlat.earliest_write_req_pre_write) + wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = + us - wsi->detlat.earliest_write_req_pre_write; + else + wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = 0; + wsi->detlat.latencies[LAT_DUR_USERCB] = lws_now_usecs() - us; + lws_det_lat_cb(wsi->context, &wsi->detlat); + + } +#endif + + return m; } -LWS_VISIBLE int +int lws_ssl_capable_read_no_ssl(struct lws *wsi, unsigned char *buf, int len) { struct lws_context *context = wsi->context; @@ -299,7 +326,7 @@ lws_ssl_capable_read_no_ssl(struct lws *wsi, unsigned char *buf, int len) return LWS_SSL_CAPABLE_ERROR; } -LWS_VISIBLE int +int lws_ssl_capable_write_no_ssl(struct lws *wsi, unsigned char *buf, int len) { int n = 0; @@ -339,7 +366,7 @@ lws_ssl_capable_write_no_ssl(struct lws *wsi, unsigned char *buf, int len) return LWS_SSL_CAPABLE_ERROR; } -LWS_VISIBLE int +int lws_ssl_pending_no_ssl(struct lws *wsi) { (void)wsi; diff --git a/lib/core-net/pollfd.c b/lib/core-net/pollfd.c index abdbff311..69ea94152 100644 --- a/lib/core-net/pollfd.c +++ b/lib/core-net/pollfd.c @@ -511,6 +511,11 @@ lws_callback_on_writable(struct lws *wsi) pt = &wsi->context->pt[(int)wsi->tsi]; +#if defined(LWS_WITH_DETAILED_LATENCY) + if (!wsi->detlat.earliest_write_req) + wsi->detlat.earliest_write_req = lws_now_usecs(); +#endif + lws_stats_bump(pt, LWSSTATS_C_WRITEABLE_CB_REQ, 1); #if defined(LWS_WITH_STATS) if (!wsi->active_writable_req_us) { @@ -519,7 +524,6 @@ lws_callback_on_writable(struct lws *wsi) } #endif - if (wsi->role_ops->callback_on_writable) { if (wsi->role_ops->callback_on_writable(wsi)) return 1; diff --git a/lib/core-net/service.c b/lib/core-net/service.c index c2c02cd92..5f3f73d32 100644 --- a/lib/core-net/service.c +++ b/lib/core-net/service.c @@ -41,7 +41,17 @@ lws_callback_as_writeable(struct lws *wsi) wsi->active_writable_req_us = 0; } #endif +#if defined(LWS_WITH_DETAILED_LATENCY) + if (wsi->context->detailed_latency_cb) { + lws_usec_t us = lws_now_usecs(); + wsi->detlat.earliest_write_req_pre_write = + wsi->detlat.earliest_write_req; + wsi->detlat.earliest_write_req = 0; + wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = + ((uint32_t)us - wsi->detlat.earliest_write_req_pre_write); + } +#endif n = wsi->role_ops->writeable_cb[lwsi_role_server(wsi)]; m = user_callback_handle_rxflow(wsi->protocol->callback, @@ -356,8 +366,7 @@ lws_buflist_aware_read(struct lws_context_per_thread *pt, struct lws *wsi, /* stash what we read */ - n = lws_buflist_append_segment(&wsi->buflist, ebuf->token, - ebuf->len); + n = lws_buflist_append_segment(&wsi->buflist, ebuf->token, ebuf->len); if (n < 0) return -1; if (n) { diff --git a/lib/core-net/vhost.c b/lib/core-net/vhost.c index 096299fcf..1b7e18e9b 100644 --- a/lib/core-net/vhost.c +++ b/lib/core-net/vhost.c @@ -289,7 +289,7 @@ lws_protocol_init(struct lws_context *context) { struct lws_vhost *vh = context->vhost_list; const struct lws_protocol_vhost_options *pvo, *pvo1; - struct lws wsi; + struct lws *wsi = context->pt[0].fake_wsi; int n, any = 0; if (context->doing_protocol_init) @@ -297,13 +297,12 @@ lws_protocol_init(struct lws_context *context) context->doing_protocol_init = 1; - memset(&wsi, 0, sizeof(wsi)); - wsi.context = context; + wsi->context = context; lwsl_info("%s\n", __func__); while (vh) { - wsi.vhost = vh; + wsi->vhost = vh; /* only do the protocol init once for a given vhost */ if (vh->created_vhost_protocols || @@ -313,7 +312,7 @@ lws_protocol_init(struct lws_context *context) /* initialize supported protocols on this vhost */ for (n = 0; n < vh->count_protocols; n++) { - wsi.protocol = &vh->protocols[n]; + wsi->protocol = &vh->protocols[n]; if (!vh->protocols[n].name) continue; pvo = lws_vhost_protocol_options(vh, @@ -366,7 +365,7 @@ lws_protocol_init(struct lws_context *context) * NOTE the wsi is all zeros except for the context, vh * + protocol ptrs so lws_get_context(wsi) etc can work */ - if (vh->protocols[n].callback(&wsi, + if (vh->protocols[n].callback(wsi, LWS_CALLBACK_PROTOCOL_INIT, NULL, (void *)pvo, 0)) { if (vh->protocol_vh_privs[n]) { diff --git a/lib/core-net/wsi.c b/lib/core-net/wsi.c index 018ef126f..66dda34c5 100644 --- a/lib/core-net/wsi.c +++ b/lib/core-net/wsi.c @@ -751,47 +751,6 @@ lws_get_context(const struct lws *wsi) return wsi->context; } -#ifdef LWS_LATENCY -void -lws_latency(struct lws_context *context, struct lws *wsi, const char *action, - int ret, int completed) -{ - unsigned long long u; - char buf[256]; - - u = lws_now_usecs(); - - if (!action) { - wsi->latency_start = u; - if (!wsi->action_start) - wsi->action_start = u; - return; - } - if (completed) { - if (wsi->action_start == wsi->latency_start) - sprintf(buf, - "Completion first try lat %lluus: %p: ret %d: %s\n", - u - wsi->latency_start, - (void *)wsi, ret, action); - else - sprintf(buf, - "Completion %lluus: lat %lluus: %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 %lluus: %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); -} -#endif - LWS_VISIBLE int LWS_WARN_UNUSED_RESULT lws_raw_transaction_completed(struct lws *wsi) { diff --git a/lib/core/context.c b/lib/core/context.c index ec9ba4435..ca32249d1 100644 --- a/lib/core/context.c +++ b/lib/core/context.c @@ -144,6 +144,11 @@ lws_create_context(const struct lws_context_creation_info *info) context->pt_serv_buf_size = s1; #if defined(LWS_WITH_NETWORK) context->count_threads = count_threads; +#if defined(LWS_WITH_DETAILED_LATENCY) + context->detailed_latency_cb = info->detailed_latency_cb; + context->detailed_latency_filepath = info->detailed_latency_filepath; + context->latencies_fd = -1; +#endif #endif /* if he gave us names, set the uid / gid */ @@ -648,6 +653,11 @@ lws_context_destroy3(struct lws_context *context) #endif lws_context_deinit_ssl_library(context); +#if defined(LWS_WITH_DETAILED_LATENCIES) + if (context->latencies_fd != -1) + compatible_close(context->latencies_fd); +#endif + lws_free(context); lwsl_info("%s: ctx %p freed\n", __func__, context); @@ -764,7 +774,6 @@ lws_context_destroy(struct lws_context *context) volatile struct lws_foreign_thread_pollfd *ftp, *next; volatile struct lws_context_per_thread *vpt; struct lws_vhost *vh = NULL; - struct lws wsi; int n, m; #endif @@ -800,18 +809,11 @@ lws_context_destroy(struct lws_context *context) #if defined(LWS_WITH_NETWORK) m = context->count_threads; - memset(&wsi, 0, sizeof(wsi)); - wsi.context = context; - -#ifdef LWS_LATENCY - if (context->worst_latency_info[0]) - lwsl_notice("Worst latency: %s\n", context->worst_latency_info); -#endif while (m--) { struct lws_context_per_thread *pt = &context->pt[m]; - vpt = (volatile struct lws_context_per_thread *)pt; + vpt = (volatile struct lws_context_per_thread *)pt; ftp = vpt->foreign_pfd_list; while (ftp) { next = ftp->next; diff --git a/lib/core/private-lib-core.h b/lib/core/private-lib-core.h index 7c318c449..cf72f27eb 100644 --- a/lib/core/private-lib-core.h +++ b/lib/core/private-lib-core.h @@ -286,6 +286,7 @@ struct lws_context { struct lws_mutex_refcount mr; #endif +#if defined(LWS_WITH_NETWORK) #if defined(LWS_WITH_LIBEV) struct lws_context_eventlibs_libev ev; #endif @@ -309,22 +310,21 @@ struct lws_context { struct lws_vhost *vhost_list; struct lws_vhost *no_listener_vhost_list; struct lws_vhost *vhost_pending_destruction_list; - struct lws_context **pcontext_finalize; - const char *username, *groupname; #if defined(LWS_WITH_SERVER) const char *server_string; #endif struct lws_event_loop_ops *event_loop_ops; - -#if defined(LWS_WITH_FILE_OPS) - const struct lws_plat_file_ops *fops; #endif #if defined(LWS_WITH_TLS) const struct lws_tls_ops *tls_ops; #endif + +#if defined(LWS_WITH_DETAILED_LATENCY) + det_lat_buf_cb_t detailed_latency_cb; +#endif #if defined(LWS_WITH_PLUGINS) struct lws_plugin *plugin_list; #endif @@ -337,6 +337,16 @@ struct lws_context { #endif #endif /* NETWORK */ +#if defined(LWS_WITH_FILE_OPS) + const struct lws_plat_file_ops *fops; +#endif + + struct lws_context **pcontext_finalize; + const char *username, *groupname; +#if defined(LWS_WITH_DETAILED_LATENCY) + const char *detailed_latency_filepath; +#endif + #if defined(LWS_AMAZON_RTOS) mbedtls_entropy_context mec; mbedtls_ctr_drbg_context mcdc; @@ -364,14 +374,15 @@ struct lws_context { #endif void (*eventlib_signal_cb)(void *event_lib_handle, int signum); - time_t last_ws_ping_pong_check_s; - lws_usec_t time_up; /* monotonic */ - #if defined(LWS_HAVE_SYS_CAPABILITY_H) && defined(LWS_HAVE_LIBCAP) cap_value_t caps[4]; char count_caps; #endif + lws_usec_t time_up; /* monotonic */ + + time_t last_ws_ping_pong_check_s; + #if defined(LWS_PLAT_FREERTOS) unsigned long time_last_state_dump; uint32_t last_free_heap; @@ -385,7 +396,9 @@ struct lws_context { int uid, gid; int fd_random; - +#if defined(LWS_WITH_DETAILED_LATENCY) + int latencies_fd; +#endif int count_wsi_allocated; int count_cgi_spawned; unsigned int options; @@ -464,36 +477,10 @@ lws_strdup(const char *s); LWS_EXTERN int log_level; - - -#ifndef LWS_LATENCY -static LWS_INLINE void -lws_latency(struct lws_context *context, struct lws *wsi, const char *action, - int ret, int completion) { - do { - (void)context; (void)wsi; (void)action; (void)ret; - (void)completion; - } while (0); -} -static LWS_INLINE void -lws_latency_pre(struct lws_context *context, struct lws *wsi) { - do { (void)context; (void)wsi; } while (0); -} -#else -#define lws_latency_pre(_context, _wsi) lws_latency(_context, _wsi, NULL, 0, 0) -extern void -lws_latency(struct lws_context *context, struct lws *wsi, const char *action, - int ret, int completion); -#endif - - LWS_EXTERN int lws_b64_selftest(void); - - - #ifndef LWS_NO_DAEMONIZE LWS_EXTERN int get_daemonize_pid(); #else diff --git a/lib/plat/freertos/freertos-service.c b/lib/plat/freertos/freertos-service.c index 5fdd25669..5f8f7c622 100644 --- a/lib/plat/freertos/freertos-service.c +++ b/lib/plat/freertos/freertos-service.c @@ -145,6 +145,16 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi) n = select(max_fd + 1, &readfds, &writefds, &errfds, ptv); n = 0; + +#if defined(LWS_WITH_DETAILED_LATENCY) + /* + * so we can track how long it took before we actually read a POLLIN + * that was signalled when we last exited poll() + */ + if (context->detailed_latency_cb) + pt->ust_left_poll = lws_now_usecs(); +#endif + for (m = 0; m < (int)pt->fds_count; m++) { c = 0; if (FD_ISSET(pt->fds[m].fd, &readfds)) { diff --git a/lib/plat/unix/unix-service.c b/lib/plat/unix/unix-service.c index 6db663721..c158c664e 100644 --- a/lib/plat/unix/unix-service.c +++ b/lib/plat/unix/unix-service.c @@ -102,6 +102,15 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi) vpt->inside_poll = 0; lws_memory_barrier(); +#if defined(LWS_WITH_DETAILED_LATENCY) + /* + * so we can track how long it took before we actually read a POLLIN + * that was signalled when we last exited poll() + */ + if (context->detailed_latency_cb) + pt->ust_left_poll = lws_now_usecs(); +#endif + /* Collision will be rare and brief. Just spin until it completes */ while (vpt->foreign_spinlock) ; diff --git a/lib/roles/h2/http2.c b/lib/roles/h2/http2.c index 4923483b9..1c07c6c61 100644 --- a/lib/roles/h2/http2.c +++ b/lib/roles/h2/http2.c @@ -1912,14 +1912,15 @@ lws_h2_parser(struct lws *wsi, unsigned char *in, lws_filepos_t inlen, } #if defined(LWS_WITH_CLIENT) if (h2n->swsi->client_h2_substream) { - + if (h2n->swsi->protocol) { m = user_callback_handle_rxflow( h2n->swsi->protocol->callback, h2n->swsi, LWS_CALLBACK_RECEIVE_CLIENT_HTTP_READ, h2n->swsi->user_space, in - 1, n); - + } else + m = 1; in += n - 1; h2n->inside += n; h2n->count += n - 1; @@ -2241,8 +2242,10 @@ lws_h2_client_handshake(struct lws *wsi) if (lws_finalize_http_header(wsi, &p, end)) goto fail_length; - n = lws_write(wsi, start, p - start, - LWS_WRITE_HTTP_HEADERS); +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif + n = lws_write(wsi, start, p - start, LWS_WRITE_HTTP_HEADERS); if (n != (p - start)) { lwsl_err("_write returned %d from %ld\n", n, (long)(p - start)); diff --git a/lib/roles/http/client/client-handshake.c b/lib/roles/http/client/client-handshake.c index eb4d6dca0..326621596 100644 --- a/lib/roles/http/client/client-handshake.c +++ b/lib/roles/http/client/client-handshake.c @@ -154,6 +154,10 @@ send_hs: * wait in the queue until it's possible to send them. */ lws_callback_on_writable(wsi_piggyback); +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req = + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif lwsl_info("%s: wsi %p: waiting to send hdrs (par state 0x%x)\n", __func__, wsi, lwsi_state(wsi_piggyback)); } else { @@ -311,7 +315,7 @@ lws_client_connect_3_connect(struct lws *wsi, const char *ads, } #if defined(LWS_WITH_UNIX_SOCK) - if (*ads == '+') { + if (ads && *ads == '+') { ads++; memset(&sau, 0, sizeof(sau)); sau.sun_family = AF_UNIX; @@ -552,10 +556,13 @@ ads_known: * The actual connection attempt */ +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req = + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif + m = connect(wsi->desc.sockfd, (const struct sockaddr *)psa, n); if (m == -1) { - - lwsl_debug("%s: connect says errno: %d\n", __func__, LWS_ERRNO); if (LWS_ERRNO != LWS_EALREADY && @@ -591,6 +598,22 @@ conn_good: lwsl_debug("%s: Connection started\n", __func__); + /* the tcp connection has happend */ + +#if defined(LWS_WITH_DETAILED_LATENCY) + if (wsi->context->detailed_latency_cb) { + wsi->detlat.type = LDLT_CONNECTION; + wsi->detlat.latencies[LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE] = + lws_now_usecs() - + wsi->detlat.earliest_write_req_pre_write; + wsi->detlat.latencies[LAT_DUR_USERCB] = 0; + lws_det_lat_cb(wsi->context, &wsi->detlat); + wsi->detlat.earliest_write_req = + wsi->detlat.earliest_write_req_pre_write = + lws_now_usecs(); + } +#endif + lws_addrinfo_clean(wsi); if (wsi->protocol) @@ -664,6 +687,12 @@ lws_client_connect_2_dnsreq(struct lws *wsi) #endif int n, port = 0; + if (lwsi_state(wsi) == LRS_WAITING_DNS) { + lwsl_notice("%s: LRS_WAITING_DNS\n", __func__); + + return wsi; + } + #if defined(LWS_ROLE_H1) || defined(LWS_ROLE_H2) if (!wsi->http.ah && !wsi->stash) { cce = "ah was NULL at cc2"; @@ -836,6 +865,19 @@ create_new_conn: } #endif +#if defined(LWS_WITH_DETAILED_LATENCY) + if (lwsi_state(wsi) == LRS_WAITING_DNS && + wsi->context->detailed_latency_cb) { + wsi->detlat.type = LDLT_NAME_RESOLUTION; + wsi->detlat.latencies[LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE] = + lws_now_usecs() - + wsi->detlat.earliest_write_req_pre_write; + wsi->detlat.latencies[LAT_DUR_USERCB] = 0; + lws_det_lat_cb(wsi->context, &wsi->detlat); + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); + } +#endif + #if defined(LWS_CLIENT_HTTP_PROXYING) && \ (defined(LWS_ROLE_H1) || defined(LWS_ROLE_H2)) @@ -876,9 +918,13 @@ create_new_conn: lwsl_warn("%s: %p: lookup %s:%u\n", __func__, wsi, ads, port); (void)port; +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif #if !defined(LWS_WITH_SYS_ASYNC_DNS) n = lws_getaddrinfo46(wsi, ads, &result); #else + lwsi_set_state(wsi, LRS_WAITING_DNS); /* this is either FAILED, CONTINUING, or already called connect_4 */ n = lws_async_dns_query(wsi->context, wsi->tsi, ads, LWS_ADNS_RECORD_A, diff --git a/lib/roles/http/client/client-http.c b/lib/roles/http/client/client-http.c index 1a4b66b5a..000c9a593 100644 --- a/lib/roles/http/client/client-http.c +++ b/lib/roles/http/client/client-http.c @@ -112,6 +112,9 @@ lws_client_socket_service(struct lws *wsi, struct lws_pollfd *pollfd, } lws_end_foreach_dll_safe(d, d1); if (wfound) { +#if defined(LWS_WITH_DETAILED_LATENCY) + wfound->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif /* * pollfd has the master sockfd in it... we * need to use that in HANDSHAKE2 to understand @@ -152,6 +155,7 @@ lws_client_socket_service(struct lws *wsi, struct lws_pollfd *pollfd, /* either still pending connection, or changed mode */ return 0; + case LRS_WAITING_CONNECT: /* @@ -367,6 +371,16 @@ start_ws_handshake: } else wsi->tls.ssl = NULL; #endif +#if defined(LWS_WITH_DETAILED_LATENCY) + if (context->detailed_latency_cb) { + wsi->detlat.type = LDLT_TLS_NEG_CLIENT; + wsi->detlat.latencies[LAT_DUR_PROXY_CLIENT_REQ_TO_WRITE] = + lws_now_usecs() - + wsi->detlat.earliest_write_req_pre_write; + wsi->detlat.latencies[LAT_DUR_USERCB] = 0; + lws_det_lat_cb(wsi->context, &wsi->detlat); + } +#endif #if defined (LWS_WITH_HTTP2) if (wsi->client_h2_alpn) { /* @@ -409,7 +423,6 @@ start_ws_handshake: } /* send our request to the server */ - lws_latency_pre(context, wsi); w = _lws_client_wsi_master(wsi); lwsl_info("%s: HANDSHAKE2: %p: sending headers on %p " @@ -417,10 +430,10 @@ start_ws_handshake: __func__, wsi, w, (unsigned long)wsi->wsistate, (unsigned long)w->wsistate, w->desc.sockfd, wsi->desc.sockfd); - +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif n = lws_ssl_capable_write(w, (unsigned char *)sb, (int)(p - sb)); - lws_latency(context, wsi, "send lws_issue_raw", n, - n == p - sb); switch (n) { case LWS_SSL_CAPABLE_ERROR: lwsl_debug("ERROR writing to client socket\n"); @@ -538,8 +551,6 @@ client_http_body_sent: int plen = 1; n = lws_ssl_capable_read(wsi, &c, 1); - lws_latency(context, wsi, "send lws_issue_raw", n, - n == 1); switch (n) { case 0: case LWS_SSL_CAPABLE_ERROR: diff --git a/lib/roles/http/header.c b/lib/roles/http/header.c index 2ea695317..007bb00ef 100644 --- a/lib/roles/http/header.c +++ b/lib/roles/http/header.c @@ -95,6 +95,9 @@ lws_finalize_write_http_header(struct lws *wsi, unsigned char *start, p = *pp; len = lws_ptr_diff(p, start); +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif if (lws_write(wsi, start, len, LWS_WRITE_HTTP_HEADERS) != len) return 1; @@ -446,6 +449,9 @@ lws_return_http_status(struct lws *wsi, unsigned int code, * * Solve it by writing the headers now... */ +#if defined(LWS_WITH_DETAILED_LATENCY) + wsi->detlat.earliest_write_req_pre_write = lws_now_usecs(); +#endif m = lws_write(wsi, start, lws_ptr_diff(p, start), LWS_WRITE_HTTP_HEADERS); if (m != lws_ptr_diff(p, start)) diff --git a/lib/roles/listen/ops-listen.c b/lib/roles/listen/ops-listen.c index be5783313..670fdaa40 100644 --- a/lib/roles/listen/ops-listen.c +++ b/lib/roles/listen/ops-listen.c @@ -73,7 +73,6 @@ rops_handle_POLLIN_listen(struct lws_context_per_thread *pt, struct lws *wsi, /* listen socket got an unencrypted connection... */ clilen = sizeof(cli_addr); - lws_latency_pre(context, wsi); /* * We cannot identify the peer who is in the listen @@ -84,8 +83,6 @@ rops_handle_POLLIN_listen(struct lws_context_per_thread *pt, struct lws *wsi, accept_fd = accept((int)pollfd->fd, (struct sockaddr *)&cli_addr, &clilen); - lws_latency(context, wsi, "listener accept", - (int)accept_fd, accept_fd != LWS_SOCK_INVALID); if (accept_fd == LWS_SOCK_INVALID) { if (LWS_ERRNO == LWS_EAGAIN || LWS_ERRNO == LWS_EWOULDBLOCK) { diff --git a/lib/tls/mbedtls/mbedtls-client.c b/lib/tls/mbedtls/mbedtls-client.c index 88d7aa260..d50ee4d97 100644 --- a/lib/tls/mbedtls/mbedtls-client.c +++ b/lib/tls/mbedtls/mbedtls-client.c @@ -152,9 +152,6 @@ lws_tls_client_confirm_peer_cert(struct lws *wsi, char *ebuf, int ebuf_len) lwsl_info("peer provided cert\n"); n = SSL_get_verify_result(wsi->tls.ssl); - lws_latency(wsi->context, wsi, - "SSL_get_verify_result LWS_CONNMODE..HANDSHAKE", n, n > 0); - lwsl_debug("get_verify says %d\n", n); if (n == X509_V_OK) diff --git a/lib/tls/mbedtls/mbedtls-ssl.c b/lib/tls/mbedtls/mbedtls-ssl.c index 65a47534e..d2e410a6f 100644 --- a/lib/tls/mbedtls/mbedtls-ssl.c +++ b/lib/tls/mbedtls/mbedtls-ssl.c @@ -113,7 +113,17 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) if (wsi->vhost) wsi->vhost->conn_stats.rx += n; #endif - +#if defined(LWS_WITH_DETAILED_LATENCY) + if (context->detailed_latency_cb) { + wsi->detlat.req_size = len; + wsi->detlat.acc_size = n; + wsi->detlat.type = LDLT_READ; + wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = + lws_now_usecs() - pt->ust_left_poll; + wsi->detlat.latencies[LAT_DUR_USERCB] = 0; + lws_det_lat_cb(wsi->context, &wsi->detlat); + } +#endif /* * if it was our buffer that limited what we read, * check if SSL has additional data pending inside SSL buffers. diff --git a/lib/tls/openssl/openssl-client.c b/lib/tls/openssl/openssl-client.c index 180c00e6c..9628eb568 100644 --- a/lib/tls/openssl/openssl-client.c +++ b/lib/tls/openssl/openssl-client.c @@ -329,12 +329,9 @@ lws_tls_client_confirm_peer_cert(struct lws *wsi, char *ebuf, int ebuf_len) char *sb = p; int n; - lws_latency_pre(wsi->context, wsi); errno = 0; ERR_clear_error(); n = SSL_get_verify_result(wsi->tls.ssl); - lws_latency(wsi->context, wsi, - "SSL_get_verify_result LWS_CONNMODE..HANDSHAKE", n, n > 0); lwsl_debug("get_verify says %d\n", n); diff --git a/lib/tls/openssl/openssl-ssl.c b/lib/tls/openssl/openssl-ssl.c index ee0bff852..cc5e93993 100644 --- a/lib/tls/openssl/openssl-ssl.c +++ b/lib/tls/openssl/openssl-ssl.c @@ -271,6 +271,18 @@ lws_ssl_capable_read(struct lws *wsi, unsigned char *buf, int len) // lwsl_hexdump_err(buf, n); +#if defined(LWS_WITH_DETAILED_LATENCY) + if (context->detailed_latency_cb) { + wsi->detlat.req_size = len; + wsi->detlat.acc_size = n; + wsi->detlat.type = LDLT_READ; + wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = + lws_now_usecs() - pt->ust_left_poll; + wsi->detlat.latencies[LAT_DUR_USERCB] = 0; + lws_det_lat_cb(wsi->context, &wsi->detlat); + } +#endif + /* * if it was our buffer that limited what we read, * check if SSL has additional data pending inside SSL buffers. diff --git a/lib/tls/tls-client.c b/lib/tls/tls-client.c index 7bafffbb7..0a65e1197 100644 --- a/lib/tls/tls-client.c +++ b/lib/tls/tls-client.c @@ -27,13 +27,9 @@ int lws_ssl_client_connect1(struct lws *wsi) { - struct lws_context *context = wsi->context; - int n = 0; + int n; - lws_latency_pre(context, wsi); n = lws_tls_client_connect(wsi); - lws_latency(context, wsi, "SSL_connect hs", n, n > 0); - switch (n) { case LWS_SSL_CAPABLE_ERROR: return -1; @@ -58,12 +54,8 @@ lws_ssl_client_connect2(struct lws *wsi, char *errbuf, int len) int n = 0; if (lwsi_state(wsi) == LRS_WAITING_SSL) { - lws_latency_pre(wsi->context, wsi); - n = lws_tls_client_connect(wsi); lwsl_debug("%s: SSL_connect says %d\n", __func__, n); - lws_latency(wsi->context, wsi, - "SSL_connect LRS_WAITING_SSL", n, n > 0); switch (n) { case LWS_SSL_CAPABLE_ERROR: @@ -96,7 +88,7 @@ int lws_context_init_client_ssl(const struct lws_context_creation_info *info, const char *cert_filepath = info->ssl_cert_filepath; const char *ca_filepath = info->ssl_ca_filepath; const char *cipher_list = info->ssl_cipher_list; - struct lws wsi; + struct lws *wsi = vhost->context->pt[0].fake_wsi; if (vhost->options & LWS_SERVER_OPTION_ADOPT_APPLY_LISTEN_ACCEPT_CONFIG) return 0; @@ -152,11 +144,12 @@ int lws_context_init_client_ssl(const struct lws_context_creation_info *info, * give him a fake wsi with context set, so he can use * lws_get_context() in the callback */ - memset(&wsi, 0, sizeof(wsi)); - wsi.vhost = vhost; /* not a real bound wsi */ - wsi.context = vhost->context; - vhost->protocols[0].callback(&wsi, + wsi->vhost = vhost; /* not a real bound wsi */ + wsi->context = vhost->context; + wsi->protocol = NULL; + + vhost->protocols[0].callback(wsi, LWS_CALLBACK_OPENSSL_LOAD_EXTRA_CLIENT_VERIFY_CERTS, vhost->tls.ssl_client_ctx, NULL, 0); diff --git a/lib/tls/tls-server.c b/lib/tls/tls-server.c index 43f4c6d89..9a2291726 100644 --- a/lib/tls/tls-server.c +++ b/lib/tls/tls-server.c @@ -120,7 +120,7 @@ lws_context_init_server_ssl(const struct lws_context_creation_info *info, struct lws_vhost *vhost) { struct lws_context *context = vhost->context; - struct lws wsi; + struct lws *wsi = context->pt[0].fake_wsi; if (!lws_check_opt(info->options, LWS_SERVER_OPTION_DO_SSL_GLOBAL_INIT)) { @@ -159,9 +159,9 @@ lws_context_init_server_ssl(const struct lws_context_creation_info *info, * give him a fake wsi with context + vhost set, so he can use * lws_get_context() in the callback */ - memset(&wsi, 0, sizeof(wsi)); - wsi.vhost = vhost; /* not a real bound wsi */ - wsi.context = context; + wsi->vhost = vhost; /* not a real bound wsi */ + wsi->context = context; + wsi->protocol = NULL; /* * as a server, if we are requiring clients to identify themselves @@ -177,12 +177,12 @@ lws_context_init_server_ssl(const struct lws_context_creation_info *info, * allowing it to verify incoming client certs */ if (vhost->tls.use_ssl) { - if (lws_tls_server_vhost_backend_init(info, vhost, &wsi)) + if (lws_tls_server_vhost_backend_init(info, vhost, wsi)) return -1; lws_tls_server_client_cert_verify_config(vhost); - if (vhost->protocols[0].callback(&wsi, + if (vhost->protocols[0].callback(wsi, LWS_CALLBACK_OPENSSL_LOAD_EXTRA_SERVER_VERIFY_CERTS, vhost->tls.ssl_ctx, vhost, 0)) return -1; @@ -272,8 +272,6 @@ lws_server_socket_service_ssl(struct lws *wsi, lws_sockfd_type accept_fd) goto fail; } - lws_latency_pre(context, wsi); - if (wsi->vhost->tls.allow_non_ssl_on_ssl_port) { n = recv(wsi->desc.sockfd, (char *)pt->serv_buf, @@ -390,8 +388,6 @@ lws_server_socket_service_ssl(struct lws *wsi, lws_sockfd_type accept_fd) errno = 0; lws_stats_bump(pt, LWSSTATS_C_SSL_ACCEPT_SPIN, 1); n = lws_tls_server_accept(wsi); - lws_latency(context, wsi, - "SSL_accept LRS_SSL_ACK_PENDING\n", n, n == 1); lwsl_info("SSL_accept says %d\n", n); switch (n) { case LWS_SSL_CAPABLE_DONE: @@ -416,6 +412,16 @@ lws_server_socket_service_ssl(struct lws *wsi, lws_sockfd_type accept_fd) wsi->accept_start_us); wsi->accept_start_us = lws_now_usecs(); #endif +#if defined(LWS_WITH_DETAILED_LATENCY) + if (context->detailed_latency_cb) { + wsi->detlat.type = LDLT_TLS_NEG_SERVER; + wsi->detlat.latencies[LAT_DUR_PROXY_RX_TO_ONWARD_TX] = + lws_now_usecs() - + wsi->detlat.earliest_write_req_pre_write; + wsi->detlat.latencies[LAT_DUR_USERCB] = 0; + lws_det_lat_cb(wsi->context, &wsi->detlat); + } +#endif /* adapt our vhost to match the SNI SSL_CTX that was chosen */ vh = context->vhost_list; diff --git a/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c b/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c index ffd1070fb..fdd4abdc5 100644 --- a/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c +++ b/minimal-examples/http-client/minimal-http-client-multi/minimal-http-client-multi.c @@ -278,6 +278,11 @@ int main(int argc, const char **argv) info.client_ssl_ca_filepath = "./warmcat.com.cer"; #endif +#if defined(LWS_WITH_DETAILED_LATENCY) + info.detailed_latency_cb = lws_det_lat_plot_cb; + info.detailed_latency_filepath = "/tmp/lws-latency-results"; +#endif + context = lws_create_context(&info); if (!context) { lwsl_err("lws init failed\n"); @@ -313,6 +318,9 @@ int main(int argc, const char **argv) if ((p = lws_cmdline_option(argc, argv, "--port"))) i.port = atoi(p); + if ((p = lws_cmdline_option(argc, argv, "--server"))) + i.address = p; + i.host = i.address; i.origin = i.address; i.method = "GET";