ssl_stream增加延迟的统计

platform/src/ssl_stream.cpp

@@ -47,7 +47,7 @@ int SSL_PEER_CERT_VERIFY_PASSED=1;
 int SSL_PEER_CERT_VERIFY_FAILED=0;
 
 #define MAX_NET_RETRIES        50
-
+#define	LATENCY_WARNING_THRESHOLD_MS		1000
 /*
  * Default cipher suite spec.
  * Use 'openssl ciphers -v spec' to see what ciphers are effectively enabled
@@ -195,6 +195,7 @@ struct ssl_connect_server_ctx
 	evutil_socket_t fd_downstream;
 	struct event_base * evbase;
 	struct future * f_peek_chello;
+	struct timespec start,end;
 };
 
 struct ssl_connect_client_ctx
@@ -210,6 +211,7 @@ struct ssl_connect_client_ctx
 	struct future * f_ask_keyring;
 	struct bufferevent * bev_down;
 	struct ssl_stream * downstream;
+	struct timespec start,end;
 };
 
 /*
@@ -940,7 +942,8 @@ static void ssl_server_connected_eventcb(struct bufferevent * bev, short events,
 	SSL_SESSION * ssl_sess = NULL;
 	char error_str[TFE_STRING_MAX];
 	const char* sni=s_stream->client_hello->sni?s_stream->client_hello->sni:"null";
-
+	long jiffies_ms;
+	char* addr_string=NULL;
 	if (events & BEV_EVENT_ERROR)
 	{
 		ATOMIC_INC(&(ctx->mgr->stat_val[SSL_UP_ERR]));
@@ -964,6 +967,15 @@ static void ssl_server_connected_eventcb(struct bufferevent * bev, short events,
 	{		
 		bufferevent_disable(ctx->bev, EV_READ | EV_WRITE);
 		bufferevent_setcb(ctx->bev, NULL, NULL, NULL, NULL); //leave a clean bev for on_success
+		clock_gettime(CLOCK_MONOTONIC, &(ctx->end));
+		jiffies_ms=(ctx->end.tv_sec-ctx->start.tv_sec)*1000+(ctx->end.tv_nsec-ctx->start.tv_nsec)/1000000;
+		if(jiffies_ms>LATENCY_WARNING_THRESHOLD_MS)
+		{
+			addr_string=tfe_string_addr_create_by_fd(ctx->fd_upstream, CONN_DIR_UPSTREAM);
+			TFE_LOG_ERROR(mgr->logger, "Warning: ssl connect server lantency %ld ms: addr=%s, sni=%s", jiffies_ms, addr_string, sni);
+			free(addr_string);
+			addr_string=NULL;
+		}
 
 		if(!SSL_session_reused(s_stream->ssl))
 		{
@@ -1028,6 +1040,7 @@ static void peek_chello_on_succ(future_result_t * result, void * user)
 	{
 		ATOMIC_INC(&(ctx->mgr->stat_val[SSL_NO_SNI]));
 	}
+	clock_gettime(CLOCK_MONOTONIC, &(ctx->start));
 	ctx->s_stream = ssl_stream_new(ctx->mgr, ctx->fd_upstream, CONN_DIR_UPSTREAM, chello, NULL, NULL);
 	ctx->bev = bufferevent_openssl_socket_new(ctx->evbase, ctx->fd_upstream,
 		ctx->s_stream->ssl, BUFFEREVENT_SSL_CONNECTING, BEV_OPT_DEFER_CALLBACKS);
@@ -1429,9 +1442,11 @@ static void ssl_client_connected_eventcb(struct bufferevent * bev, short events,
 	struct ssl_connect_client_ctx * ctx = (struct ssl_connect_client_ctx *) promise_dettach_ctx(p);
 
 	struct ssl_stream * s_stream = ctx->downstream;
-	struct ssl_mgr* mgr=s_stream->mgr;
+	struct ssl_mgr* mgr=s_stream->mgr;	
+	char* addr_string=NULL;
 	const char* sni=ctx->origin_ssl->client_hello->sni?ctx->origin_ssl->client_hello->sni:"null";
 	char error_str[TFE_STRING_MAX]={0};
+	long jiffies_ms=0;
 	if (events & BEV_EVENT_ERROR)
 	{
 		ATOMIC_INC(&(mgr->stat_val[SSL_DOWN_ERR]));
@@ -1452,7 +1467,17 @@ static void ssl_client_connected_eventcb(struct bufferevent * bev, short events,
 		promise_failed(p, FUTURE_ERROR_TIMEOUT, error_str);
 	}
 	else if(events & BEV_EVENT_CONNECTED)
-	{		
+	{
+		
+		clock_gettime(CLOCK_MONOTONIC, &(ctx->end));
+		jiffies_ms=(ctx->end.tv_sec-ctx->start.tv_sec)*1000+(ctx->end.tv_nsec-ctx->start.tv_nsec)/1000000;
+		if(jiffies_ms>LATENCY_WARNING_THRESHOLD_MS)
+		{
+			addr_string=tfe_string_addr_create_by_fd(ctx->fd_downstream, CONN_DIR_DOWNSTREAM);
+			TFE_LOG_ERROR(mgr->logger, "Warning: ssl connect client lantency %ld ms: addr=%s, sni=%s", jiffies_ms, addr_string, sni);
+			free(addr_string);
+			addr_string=NULL;
+		}
 		bufferevent_disable(ctx->bev_down, EV_READ | EV_WRITE);
 		bufferevent_setcb(ctx->bev_down, NULL, NULL, NULL, NULL); //leave a clean bev for on_success
 
@@ -1478,7 +1503,8 @@ void ask_keyring_on_succ(void * result, void * user)
 
 	kyr = key_keeper_release_keyring(result);	//kyr will be freed at ssl downstream closing.
 
-
+	
+	clock_gettime(CLOCK_MONOTONIC, &(ctx->start));
 	ctx->downstream = ssl_stream_new(mgr, ctx->fd_downstream, CONN_DIR_DOWNSTREAM, NULL, kyr,
 										ctx->origin_ssl?ctx->origin_ssl->alpn_selected:NULL);
 	ctx->bev_down = bufferevent_openssl_socket_new(ctx->evbase, ctx->fd_downstream, ctx->downstream->ssl,
@@ -1516,7 +1542,6 @@ void ssl_async_downstream_create(struct future * f, struct ssl_mgr * mgr, struct
 	ctx->ssl_mgr = mgr;
 	ctx->fd_downstream = fd_downstream;
 	ctx->evbase = evbase;
-	
 	if (upstream != NULL)
 	{
 		ctx->origin_ssl = upstream;