LWS_WITH_STATS

CMakeLists.txt

@@ -117,6 +117,7 @@ option(LWS_WITH_RANGES "Support http ranges (RFC7233)" ON)
 option(LWS_FALLBACK_GETHOSTBYNAME "Also try to do dns resolution using gethostbyname if getaddrinfo fails" OFF)
 option(LWS_WITH_ZIP_FOPS "Support serving pre-zipped files" ON)
 option(LWS_AVOID_SIGPIPE_IGN "Android 7+ seems to need this" OFF)
+option(LWS_WITH_STATS "Keep statistics of lws internal operations" OFF)
 
 if (LWS_WITH_LWSWS)
  message(STATUS "LWS_WITH_LWSWS --> Enabling LWS_WITH_PLUGINS and LWS_WITH_LIBUV")
@@ -1767,6 +1768,7 @@ message(" LWS_PLAT_OPTEE = ${LWS_PLAT_OPTEE}")
 message(" LWS_WITH_ESP32 = ${LWS_WITH_ESP32}")
 message(" LWS_WITH_ZIP_FOPS = ${LWS_WITH_ZIP_FOPS}")
 message(" LWS_AVOID_SIGPIPE_IGN = ${LWS_AVOID_SIGPIPE_IGN}")
+message(" LWS_WITH_STATS = ${LWS_WITH_STATS}")
 
 message("---------------------------------------------------------------------")
 

component.mk

@@ -25,6 +25,7 @@ build:
 		-DCMAKE_BUILD_TYPE=RELEASE \
 		-DOPENSSL_INCLUDE_DIR=${IDF_PATH}/components/openssl/include \
 		-DOPENSSL_LIBRARIES=x \
+		-DLWS_WITH_STATS=1 \
 		-DZLIB_LIBRARY=$(BUILD_DIR_BASE)/zlib/libzlib.a \
 		-DZLIB_INCLUDE_DIR=$(COMPONENT_PATH)/../zlib \
 		-DLWS_WITH_ESP32=1 ;\

lib/context.c

@@ -616,6 +616,9 @@ lws_create_context(struct lws_context_creation_info *info)
 	lwsl_info(" LWS_MAX_SMP           : %u\n", LWS_MAX_SMP);
 	lwsl_info(" SPEC_LATEST_SUPPORTED : %u\n", SPEC_LATEST_SUPPORTED);
 	lwsl_info(" sizeof (*info)        : %ld\n", (long)sizeof(*info));
+#if defined(LWS_WITH_STATS)
+	lwsl_notice(" LWS_WITH_STATS        : on\n");
+#endif
 #if LWS_POSIX
 	lwsl_info(" SYSTEM_RANDOM_FILEPATH: '%s'\n", SYSTEM_RANDOM_FILEPATH);
 #endif
@@ -1109,12 +1112,13 @@ lws_context_destroy2(struct lws_context *context)
 		vh = vh1;
 	}
 
+	lws_stats_log_dump(context);
+
 	lws_ssl_context_destroy(context);
 	lws_plat_context_late_destroy(context);
 
 	if (context->external_baggage_free_on_destroy)
 		free(context->external_baggage_free_on_destroy);
 
-
 	lws_free(context);
 }

lib/libwebsockets.c

@@ -249,6 +249,7 @@ lws_close_free_wsi(struct lws *wsi, enum lws_close_status reason)
 
 	context = wsi->context;
 	pt = &context->pt[(int)wsi->tsi];
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_C_API_CLOSE, 1);
 
 	/* if we have children, close them first */
 	if (wsi->child_list) {
@@ -3110,3 +3111,81 @@ lws_json_dump_context(const struct lws_context *context, char *buf, int len,
 }
 
 #endif
+
+#if defined(LWS_WITH_STATS)
+
+LWS_VISIBLE LWS_EXTERN uint64_t
+lws_stats_get(struct lws_context *context, int index)
+{
+	if (index >= LWSSTATS_SIZE)
+		return 0;
+
+	return context->lws_stats[index];
+}
+
+LWS_VISIBLE LWS_EXTERN void
+lws_stats_log_dump(struct lws_context *context)
+{
+	if (!context->updated)
+		return;
+
+	context->updated = 0;
+
+	lwsl_notice("\n");
+	lwsl_notice("LWS internal statistics dump ----->\n");
+	lwsl_notice("LWSSTATS_C_CONNECTIONS:                     %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_CONNECTIONS));
+	lwsl_notice("LWSSTATS_C_API_CLOSE:                       %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_API_CLOSE));
+	lwsl_notice("LWSSTATS_C_API_READ:                        %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_API_READ));
+	lwsl_notice("LWSSTATS_C_API_LWS_WRITE:                   %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_API_LWS_WRITE));
+	lwsl_notice("LWSSTATS_C_API_WRITE:                       %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_API_WRITE));
+	lwsl_notice("LWSSTATS_C_WRITE_PARTIALS:                  %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_WRITE_PARTIALS));
+	lwsl_notice("LWSSTATS_C_WRITEABLE_CB_REQ:                %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_WRITEABLE_CB_REQ));
+	lwsl_notice("LWSSTATS_C_WRITEABLE_CB_EFF_REQ:            %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_WRITEABLE_CB_EFF_REQ));
+	lwsl_notice("LWSSTATS_C_WRITEABLE_CB:                    %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_WRITEABLE_CB));
+	lwsl_notice("LWSSTATS_C_SSL_CONNECTIONS_FAILED:          %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_SSL_CONNECTIONS_FAILED));
+	lwsl_notice("LWSSTATS_C_SSL_CONNECTIONS_ACCEPTED:        %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_SSL_CONNECTIONS_ACCEPTED));
+	lwsl_notice("LWSSTATS_C_TIMEOUTS:                        %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_TIMEOUTS));
+	lwsl_notice("LWSSTATS_C_SERVICE_ENTRY:                   %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_C_SERVICE_ENTRY));
+	lwsl_notice("LWSSTATS_B_READ:                            %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_B_READ));
+	lwsl_notice("LWSSTATS_B_WRITE:                           %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_B_WRITE));
+	lwsl_notice("LWSSTATS_B_PARTIALS_ACCEPTED_PARTS:         %8llu\n", (unsigned long long)lws_stats_get(context, LWSSTATS_B_PARTIALS_ACCEPTED_PARTS));
+	lwsl_notice("LWSSTATS_MS_SSL_CONNECTIONS_ACCEPTED_DELAY: %8llums\n", (unsigned long long)lws_stats_get(context, LWSSTATS_MS_SSL_CONNECTIONS_ACCEPTED_DELAY) / 1000);
+	if (lws_stats_get(context, LWSSTATS_C_SSL_CONNECTIONS_ACCEPTED))
+		lwsl_notice("  Avg accept delay:                         %8llums\n",
+			(unsigned long long)(lws_stats_get(context, LWSSTATS_MS_SSL_CONNECTIONS_ACCEPTED_DELAY) /
+			lws_stats_get(context, LWSSTATS_C_SSL_CONNECTIONS_ACCEPTED)) / 1000);
+	lwsl_notice("LWSSTATS_MS_WRITABLE_DELAY:                 %8lluus\n",
+			(unsigned long long)lws_stats_get(context, LWSSTATS_MS_WRITABLE_DELAY));
+	lwsl_notice("LWSSTATS_MS_WORST_WRITABLE_DELAY:           %8lluus\n",
+				(unsigned long long)lws_stats_get(context, LWSSTATS_MS_WORST_WRITABLE_DELAY));
+	if (lws_stats_get(context, LWSSTATS_C_WRITEABLE_CB))
+		lwsl_notice("  Avg writable delay:                       %8lluus\n",
+			(unsigned long long)(lws_stats_get(context, LWSSTATS_MS_WRITABLE_DELAY) /
+			lws_stats_get(context, LWSSTATS_C_WRITEABLE_CB)));
+	lwsl_notice("\n");
+}
+
+void
+lws_stats_atomic_bump(struct lws_context * context,
+		struct lws_context_per_thread *pt, int index, uint64_t bump)
+{
+	lws_pt_lock(pt);
+	context->lws_stats[index] += bump;
+	if (index != LWSSTATS_C_SERVICE_ENTRY)
+		context->updated = 1;
+	lws_pt_unlock(pt);
+}
+
+void
+lws_stats_atomic_max(struct lws_context * context,
+		struct lws_context_per_thread *pt, int index, uint64_t val)
+{
+	lws_pt_lock(pt);
+	if (val > context->lws_stats[index]) {
+		context->lws_stats[index] = val;
+		context->updated = 1;
+	}
+	lws_pt_unlock(pt);
+}
+
+#endif

lib/libwebsockets.h

@@ -4784,6 +4784,54 @@ lws_email_destroy(struct lws_email *email);
 #endif
 //@}
 
+/*
+ * Stats are all uint64_t numbers that start at 0.
+ * Index names here have the convention
+ *
+ *  _C_ counter
+ *  _B_ byte count
+ *  _MS_ millisecond count
+ */
+
+enum {
+	LWSSTATS_C_CONNECTIONS, /**< count incoming connections */
+	LWSSTATS_C_API_CLOSE, /**< count calls to close api */
+	LWSSTATS_C_API_READ, /**< count calls to read from socket api */
+	LWSSTATS_C_API_LWS_WRITE, /**< count calls to lws_write API */
+	LWSSTATS_C_API_WRITE, /**< count calls to write API */
+	LWSSTATS_C_WRITE_PARTIALS, /**< count of partial writes */
+	LWSSTATS_C_WRITEABLE_CB_REQ, /**< count of writable callback requests */
+	LWSSTATS_C_WRITEABLE_CB_EFF_REQ, /**< count of effective writable callback requests */
+	LWSSTATS_C_WRITEABLE_CB, /**< count of writable callbacks */
+	LWSSTATS_C_SSL_CONNECTIONS_FAILED, /**< count of failed SSL connections */
+	LWSSTATS_C_SSL_CONNECTIONS_ACCEPTED, /**< count of accepted SSL connections */
+	LWSSTATS_C_TIMEOUTS, /**< count of timed-out connections */
+	LWSSTATS_C_SERVICE_ENTRY, /**< count of entries to lws service loop */
+	LWSSTATS_B_READ, /**< aggregate bytes read */
+	LWSSTATS_B_WRITE, /**< aggregate bytes written */
+	LWSSTATS_B_PARTIALS_ACCEPTED_PARTS, /**< aggreate of size of accepted write data from new partials */
+	LWSSTATS_MS_SSL_CONNECTIONS_ACCEPTED_DELAY, /**< aggregate delay in accepting connection */
+	LWSSTATS_MS_WRITABLE_DELAY, /**< aggregate delay between asking for writable and getting cb */
+	LWSSTATS_MS_WORST_WRITABLE_DELAY, /**< single worst delay between asking for writable and getting cb */
+
+	/* Add new things just above here ---^
+	 * This is part of the ABI, don't needlessly break compatibility */
+	LWSSTATS_SIZE
+};
+
+#if defined(LWS_WITH_STATS)
+
+LWS_VISIBLE LWS_EXTERN uint64_t
+lws_stats_get(struct lws_context *context, int index);
+LWS_VISIBLE LWS_EXTERN void
+lws_stats_log_dump(struct lws_context *context);
+#else
+static inline uint64_t
+lws_stats_get(struct lws_context *context, int index) { return 0; }
+static inline void
+lws_stats_log_dump(struct lws_context *context) { }
+#endif
+
 #ifdef __cplusplus
 }
 #endif

lib/lws-plat-esp32.c

@@ -115,6 +115,7 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi)
 		return 1;
 
 	pt = &context->pt[tsi];
+	lws_stats_atomic_bump(context, pt, LWSSTATS_C_SERVICE_ENTRY, 1);
 
 	if (timeout_ms < 0)
 		goto faked_service;

lib/lws-plat-unix.c

@@ -114,6 +114,8 @@ _lws_plat_service_tsi(struct lws_context *context, int timeout_ms, int tsi)
 
 	pt = &context->pt[tsi];
 
+	lws_stats_atomic_bump(context, pt, LWSSTATS_C_SERVICE_ENTRY, 1);
+
 	if (timeout_ms < 0)
 		goto faked_service;
 

lib/output.c

@@ -95,10 +95,13 @@ LWS_VISIBLE void lwsl_hexdump(void *vbuf, 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];
 	size_t real_len = len;
 	unsigned int n;
 	int m;
 
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_C_API_WRITE, 1);
+
 	if (!len)
 		return 0;
 	/* just ignore sends after we cleared the truncation buffer */
@@ -207,6 +210,9 @@ int lws_issue_raw(struct lws *wsi, unsigned char *buf, size_t len)
 	lwsl_debug("%p new partial sent %d from %lu total\n", wsi, n,
 		    (unsigned long)real_len);
 
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_C_WRITE_PARTIALS, 1);
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_B_PARTIALS_ACCEPTED_PARTS, n);
+
 	/*
 	 *  - if we still have a suitable malloc lying around, use it
 	 *  - or, if too small, reallocate it
@@ -244,12 +250,16 @@ LWS_VISIBLE int lws_write(struct lws *wsi, unsigned char *buf, size_t len,
 	int pre = 0, n;
 	size_t orig_len = len;
 
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_C_API_LWS_WRITE, 1);
+
 	if ((int)len < 0) {
 		lwsl_err("%s: suspicious len int %d, ulong %lu\n", __func__,
 				(int)len, (unsigned long)len);
 		return -1;
 	}
 
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_B_WRITE, len);
+
 #ifdef LWS_WITH_ACCESS_LOG
 	wsi->access_log.sent += len;
 #endif
@@ -766,12 +776,17 @@ LWS_VISIBLE int lws_serve_http_file_fragment(struct lws *wsi)
 LWS_VISIBLE int
 lws_ssl_capable_read_no_ssl(struct lws *wsi, unsigned char *buf, int len)
 {
+	struct lws_context *context = wsi->context;
+	struct lws_context_per_thread *pt = &context->pt[(int)wsi->tsi];
 	int n;
 
+	lws_stats_atomic_bump(context, pt, LWSSTATS_C_API_READ, 1);
+
 	n = recv(wsi->desc.sockfd, (char *)buf, len, 0);
 	if (n >= 0) {
 		if (wsi->vhost)
 			wsi->vhost->conn_stats.rx += n;
+		lws_stats_atomic_bump(context, pt, LWSSTATS_B_READ, n);
 		lws_restart_ws_ping_pong_timer(wsi);
 		return n;
 	}

lib/pollfd.c

@@ -336,6 +336,7 @@ lws_change_pollfd(struct lws *wsi, int _and, int _or)
 LWS_VISIBLE int
 lws_callback_on_writable(struct lws *wsi)
 {
+	struct lws_context_per_thread *pt;
 #ifdef LWS_USE_HTTP2
 	struct lws *network_wsi, *wsi2;
 	int already;
@@ -347,6 +348,15 @@ lws_callback_on_writable(struct lws *wsi)
 	if (wsi->socket_is_permanently_unusable)
 		return 0;
 
+	pt = &wsi->context->pt[(int)wsi->tsi];
+	lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_C_WRITEABLE_CB_REQ, 1);
+#if defined(LWS_WITH_STATS)
+	if (!wsi->active_writable_req_us) {
+		wsi->active_writable_req_us = time_in_microseconds();
+		lws_stats_atomic_bump(wsi->context, pt, LWSSTATS_C_WRITEABLE_CB_EFF_REQ, 1);
+	}
+#endif
+
 #ifdef LWS_USE_HTTP2
 	lwsl_info("%s: %p\n", __func__, wsi);
 

lib/private-libwebsockets.h

@@ -879,6 +879,12 @@ struct lws_context {
 	char worst_latency_info[256];
 #endif
 
+#if defined(LWS_WITH_STATS)
+	uint64_t lws_stats[LWSSTATS_SIZE];
+	uint64_t last_dump;
+	int updated;
+#endif
+
 	int max_fds;
 #if defined(LWS_USE_LIBEV) || defined(LWS_USE_LIBUV) || defined(LWS_USE_LIBEVENT)
 	int use_ev_sigint;
@@ -1465,6 +1471,9 @@ struct lws {
 	SSL *ssl;
 	BIO *client_bio;
 	struct lws *pending_read_list_prev, *pending_read_list_next;
+#if defined(LWS_WITH_STATS)
+	uint64_t accept_start_us;
+#endif
 #endif
 #ifdef LWS_WITH_HTTP_PROXY
 	struct lws_rewrite *rw;
@@ -1474,7 +1483,9 @@ struct lws {
 	unsigned long latency_start;
 #endif
 	lws_sock_file_fd_type desc; /* .filefd / .sockfd */
-
+#if defined(LWS_WITH_STATS)
+	uint64_t active_writable_req_us;
+#endif
 	/* ints */
 	int position_in_fds_table;
 	int rxflow_len;
@@ -2072,6 +2083,22 @@ lws_same_vh_protocol_remove(struct lws *wsi);
 LWS_EXTERN void
 lws_same_vh_protocol_insert(struct lws *wsi, int n);
 
+#if defined(LWS_WITH_STATS)
+void
+lws_stats_atomic_bump(struct lws_context * context,
+		struct lws_context_per_thread *pt, int index, uint64_t bump);
+void
+lws_stats_atomic_max(struct lws_context * context,
+		struct lws_context_per_thread *pt, int index, uint64_t val);
+#else
+static inline uint64_t lws_stats_atomic_bump(struct lws_context * context,
+		struct lws_context_per_thread *pt, int index, uint64_t bump) {
+	(void)context; (void)pt; (void)index; (void)bump; return 0; }
+static inline uint64_t lws_stats_atomic_max(struct lws_context * context,
+		struct lws_context_per_thread *pt, int index, uint64_t val) {
+	(void)context; (void)pt; (void)index; (void)val; return 0; }
+#endif
+
 #ifdef __cplusplus
 };
 #endif