ITS#9599 Add latency tracking

configure.ac

@@ -2206,6 +2206,12 @@ fi
 dnl ----------------------------------------------------------------
 dnl Libevent
 if test $ol_enable_balancer != no ; then
+	AC_MSG_CHECKING(compiler support for atomics)
+	AC_COMPILE_IFELSE([AC_LANG_PROGRAM([],
+		[[__atomic_thread_fence( __ATOMIC_ACQUIRE );]])],
+		[AC_MSG_RESULT(yes)],
+		[AC_MSG_ERROR(["Balancer requires support for atomic operations"])])
+
 	AC_CHECK_LIB(event_extra, evdns_base_new,
 		[have_libevent=yes
 		LEVENT_LIBS="$LEVENT_LIBS -levent_core -levent_extra"],

servers/lloadd/client.c

@@ -147,7 +147,7 @@ request_process( LloadConnection *client, LloadOperation *op )
                 client->c_restricted_inflight == 0 &&
                 client->c_restricted_at >= 0 &&
                 client->c_restricted_at + lload_write_coherence <
-                    op->o_start ) {
+                    op->o_start.tv_sec ) {
             Debug( LDAP_DEBUG_TRACE, "request_process: "
                     "connid=%lu write coherence to backend '%s' expired\n",
                     client->c_connid, client->c_backend->b_name.bv_val );

servers/lloadd/lload.h

@@ -474,6 +474,9 @@ struct LloadConnection {
 
     TAvlnode *c_ops; /* Operations pending on the connection */
 
+    uintptr_t c_operation_count;
+    uintptr_t c_operation_time;
+
 #ifdef HAVE_TLS
     enum lload_tls_type c_is_tls; /* true if this LDAP over raw TLS */
 #endif
@@ -532,13 +535,13 @@ struct LloadOperation {
     LloadConnection *o_upstream;
     unsigned long o_upstream_connid;
     ber_int_t o_upstream_msgid;
-    time_t o_last_response;
+    struct timeval o_last_response;
 
     /* Protects o_client, o_upstream links */
     ldap_pvt_thread_mutex_t o_link_mutex;
 
     ber_tag_t o_tag;
-    time_t o_start;
+    struct timeval o_start;
     unsigned long o_pin_id;
 
     enum op_result o_res;

servers/lloadd/operation.c

@@ -146,7 +146,7 @@ operation_init( LloadConnection *c, BerElement *ber )
     op->o_client = c;
     op->o_client_connid = c->c_connid;
     op->o_ber = ber;
-    op->o_start = slap_get_time();
+    gettimeofday( &op->o_start, NULL );
 
     ldap_pvt_thread_mutex_init( &op->o_link_mutex );
 
@@ -288,15 +288,16 @@ operation_unlink_client( LloadOperation *op, LloadConnection *client )
         client->c_n_ops_executing--;
 
         if ( op->o_restricted == LLOAD_OP_RESTRICTED_WRITE ) {
-            if ( !--client->c_restricted_inflight && client->c_restricted_at >= 0 ) {
+            if ( !--client->c_restricted_inflight &&
+                    client->c_restricted_at >= 0 ) {
                 if ( lload_write_coherence < 0 ) {
                     client->c_restricted_at = -1;
-                } else if ( op->o_last_response ) {
-                    client->c_restricted_at = op->o_last_response;
+                } else if ( timerisset( &op->o_last_response ) ) {
+                    client->c_restricted_at = op->o_last_response.tv_sec;
                 } else {
                     /* We have to default to o_start just in case we abandoned an
                      * operation that the backend actually processed */
-                    client->c_restricted_at = op->o_start;
+                    client->c_restricted_at = op->o_start.tv_sec;
                 }
             }
         }
@@ -547,13 +548,13 @@ connection_timeout( LloadConnection *upstream, void *arg )
     LloadOperation *op;
     TAvlnode *ops = NULL, *node, *next;
     LloadBackend *b = upstream->c_backend;
-    time_t threshold = *(time_t *)arg;
+    struct timeval *threshold = arg;
     int rc, nops = 0;
 
     CONNECTION_LOCK(upstream);
-    for ( node = ldap_tavl_end( upstream->c_ops, TAVL_DIR_LEFT ); node &&
-            ((LloadOperation *)node->avl_data)->o_start <
-                    threshold; /* shortcut */
+    for ( node = ldap_tavl_end( upstream->c_ops, TAVL_DIR_LEFT );
+            node && timercmp( &((LloadOperation *)node->avl_data)->o_start,
+                    threshold, < ); /* shortcut */
             node = next ) {
         LloadOperation *found_op;
 
@@ -561,7 +562,8 @@ connection_timeout( LloadConnection *upstream, void *arg )
         op = node->avl_data;
 
         /* Have we received another response since? */
-        if ( op->o_last_response && op->o_last_response >= threshold ) {
+        if ( timerisset( &op->o_last_response ) &&
+                !timercmp( &op->o_last_response, threshold, < ) ) {
             continue;
         }
 

servers/lloadd/upstream.c

@@ -249,7 +249,19 @@ handle_one_response( LloadConnection *c )
         }
     }
     if ( op ) {
-        op->o_last_response = slap_get_time();
+        struct timeval tv, tvdiff;
+        uintptr_t diff;
+
+        gettimeofday( &tv, NULL );
+        if ( !timerisset( &op->o_last_response ) ) {
+            timersub( &tv, &op->o_start, &tvdiff );
+            diff = 1000000 * tvdiff.tv_sec + tvdiff.tv_usec;
+
+            __atomic_add_fetch( &c->c_operation_count, 1, __ATOMIC_RELAXED );
+            __atomic_add_fetch( &c->c_operation_time, diff, __ATOMIC_RELAXED );
+        }
+        op->o_last_response = tv;
+
         Debug( LDAP_DEBUG_STATS2, "handle_one_response: "
                 "upstream connid=%lu, processing response for "
                 "client connid=%lu, msgid=%d\n",