Track TLS overhead: diagnostic for bug 7707

changes/bug7707_diagnostic

@@ -0,0 +1,5 @@
+  o Minor features:
+    - Add another diagnostic to the heartbeat message: track and log
+      overhead that TLS is adding to the data we write.  If this is
+      high, we are sending too little data to SSL_write at a time.
+      Diagnostic for bug 7707.

src/common/tortls.c

@@ -1997,6 +1997,10 @@ tor_tls_free(tor_tls_t *tls)
   if (!tls)
     return;
   tor_assert(tls->ssl);
+  {
+    size_t r,w;
+    tor_tls_get_n_raw_bytes(tls,&r,&w); /* ensure written_by_tls is updated */
+  }
 #ifdef SSL_set_tlsext_host_name
   SSL_set_tlsext_host_name(tls->ssl, NULL);
 #endif
@@ -2048,6 +2052,13 @@ tor_tls_read(tor_tls_t *tls, char *cp, size_t len)
   }
 }
 
+/** Total number of bytes that we've used TLS to send.  Used to track TLS
+ * overhead. */
+static uint64_t total_bytes_written_over_tls = 0;
+/** Total number of bytes that TLS has put on the network for us. Used to
+ * track TLS overhead. */
+static uint64_t total_bytes_written_by_tls = 0;
+
 /** Underlying function for TLS writing.  Write up to <b>n</b>
  * characters from <b>cp</b> onto <b>tls</b>.  On success, returns the
  * number of characters written.  On failure, returns TOR_TLS_ERROR,
@@ -2074,6 +2085,7 @@ tor_tls_write(tor_tls_t *tls, const char *cp, size_t n)
   r = SSL_write(tls->ssl, cp, (int)n);
   err = tor_tls_get_error(tls, r, 0, "writing", LOG_INFO, LD_NET);
   if (err == TOR_TLS_DONE) {
+    total_bytes_written_over_tls += r;
     return r;
   }
   if (err == TOR_TLS_WANTWRITE || err == TOR_TLS_WANTREAD) {
@@ -2563,10 +2575,23 @@ tor_tls_get_n_raw_bytes(tor_tls_t *tls, size_t *n_read, size_t *n_written)
              "r=%lu, last_read=%lu, w=%lu, last_written=%lu",
              r, tls->last_read_count, w, tls->last_write_count);
   }
+  total_bytes_written_by_tls += *n_written;
   tls->last_read_count = r;
   tls->last_write_count = w;
 }
 
+/** Return a ratio of the bytes that TLS has sent to the bytes that we've told
+ * it to send. Used to track whether our TLS records are getting too tiny. */
+double
+tls_get_write_overhead_ratio(void)
+{
+  if (total_bytes_written_over_tls == 0)
+    return 1.0;
+
+  return U64_TO_DBL(total_bytes_written_by_tls) /
+    U64_TO_DBL(total_bytes_written_over_tls);
+}
+
 /** Implement check_no_tls_errors: If there are any pending OpenSSL
  * errors, log an error message. */
 void

src/common/tortls.h

@@ -95,6 +95,8 @@ void tor_tls_get_buffer_sizes(tor_tls_t *tls,
                               size_t *rbuf_capacity, size_t *rbuf_bytes,
                               size_t *wbuf_capacity, size_t *wbuf_bytes);
 
+double tls_get_write_overhead_ratio(void);
+
 int tor_tls_used_v1_handshake(tor_tls_t *tls);
 int tor_tls_received_v3_certificate(tor_tls_t *tls);
 int tor_tls_get_num_server_handshakes(tor_tls_t *tls);

src/or/status.c

@@ -85,6 +85,7 @@ log_heartbeat(time_t now)
   char *bw_rcvd = NULL;
   char *uptime = NULL;
   const routerinfo_t *me;
+  double r = tls_get_write_overhead_ratio();
 
   const or_options_t *options = get_options();
   (void)now;
@@ -112,6 +113,11 @@ log_heartbeat(time_t now)
         100*(U64_TO_DBL(stats_n_data_bytes_packaged) /
              U64_TO_DBL(stats_n_data_cells_packaged*RELAY_PAYLOAD_SIZE)) );
 
+  if (r > 1.0) {
+    double overhead = ( r - 1.0 ) * 100.0;
+    log_notice(LD_HEARTBEAT, "TLS write overhead: %.f%%", overhead);
+  }
+
   tor_free(uptime);
   tor_free(bw_sent);
   tor_free(bw_rcvd);