Add slow logs for HTTP/2 Connection & Stream

doc/admin-guide/files/records.config.en.rst

@@ -2825,6 +2825,26 @@ Logging Configuration
    completion will cause its timing stats to be written to the :ts:cv:`debugging log file
    <proxy.config.output.logfile>`. This is identifying data about the transaction and all of the :c:type:`transaction milestones <TSMilestonesType>`.
 
+.. ts:cv:: CONFIG proxy.config.http2.connection.slow.log.threshold INT 0
+   :reloadable:
+   :units: milliseconds
+
+   If set to a non-zero value :arg:`N` then any HTTP/2 connection
+   that takes longer than :arg:`N` milliseconds from open to close will cause
+   its timing stats to be written to the :ts:cv:`debugging log file
+   <proxy.config.output.logfile>`. This is identifying data about the
+   transaction and all of the :c:type:`transaction milestones <TSMilestonesType>`.
+
+.. ts:cv:: CONFIG proxy.config.http2.stream.slow.log.threshold INT 0
+   :reloadable:
+   :units: milliseconds
+
+   If set to a non-zero value :arg:`N` then any HTTP/2 stream
+   that takes longer than :arg:`N` milliseconds from open to close will cause
+   its timing stats to be written to the :ts:cv:`debugging log file
+   <proxy.config.output.logfile>`. This is identifying data about the
+   transaction and all of the :c:type:`transaction milestones <TSMilestonesType>`.
+
 .. ts:cv:: CONFIG proxy.config.log.config.filename STRING logging.yaml
    :reloadable:
 

mgmt/RecordsConfig.cc

@@ -641,6 +641,10 @@ static const RecordElement RecordsConfig[] =
   ,
   {RECT_CONFIG, "proxy.config.http.slow.log.threshold", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL}
   ,
+  {RECT_CONFIG, "proxy.config.http2.connection.slow.log.threshold", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL}
+  ,
+  {RECT_CONFIG, "proxy.config.http2.stream.slow.log.threshold", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL}
+  ,
 
   //##############################################################################
   //#

proxy/Milestones.h

@@ -1,6 +1,6 @@
 /** @file
 
-  A brief file description
+  Milestones
 
   @section license License
 
@@ -23,35 +23,45 @@
 
 #pragma once
 
-#include "tscore/ink_platform.h"
-#include "tscore/ink_hrtime.h"
 #include "ts/apidefs.h"
+
+#include "tscore/ink_platform.h"
 #include "tscore/ink_hrtime.h"
 
-/////////////////////////////////////////////////////////////
-//
-// class TransactionMilestones
-//
-/////////////////////////////////////////////////////////////
-class TransactionMilestones
+#include "I_EventSystem.h"
+
+template <class T, size_t entries> class Milestones
 {
 public:
-  TransactionMilestones() { ink_zero(milestones); }
-  ink_hrtime &operator[](TSMilestonesType ms) { return milestones[ms]; }
-  ink_hrtime operator[](TSMilestonesType ms) const { return milestones[ms]; }
+  ink_hrtime &operator[](T ms) { return this->_milestones[static_cast<size_t>(ms)]; }
+  ink_hrtime operator[](T ms) const { return this->_milestones[static_cast<size_t>(ms)]; }
+
+  /**
+   * Mark given milestone with timestamp if it's not marked yet
+   * @param ms The milestone to mark
+   * @return N/A
+   */
+  void
+  mark(T ms)
+  {
+    if (this->_milestones[static_cast<size_t>(ms)] == 0) {
+      this->_milestones[static_cast<size_t>(ms)] = Thread::get_hrtime();
+    }
+  }
+
   /**
    * Takes two milestones and returns the difference.
    * @param start The start time
    * @param end The end time
    * @return The difference time in milliseconds
    */
   int64_t
-  difference_msec(TSMilestonesType ms_start, TSMilestonesType ms_end) const
+  difference_msec(T ms_start, T ms_end) const
   {
-    if (milestones[ms_end] == 0) {
+    if (this->_milestones[static_cast<size_t>(ms_end)] == 0) {
       return -1;
     }
-    return ink_hrtime_to_msec(milestones[ms_end] - milestones[ms_start]);
+    return ink_hrtime_to_msec(this->_milestones[static_cast<size_t>(ms_end)] - this->_milestones[static_cast<size_t>(ms_start)]);
   }
 
   /**
@@ -61,17 +71,26 @@ class TransactionMilestones
    * @return A double that is the difference time in seconds
    */
   double
-  difference_sec(TSMilestonesType ms_start, TSMilestonesType ms_end) const
+  difference_sec(T ms_start, T ms_end) const
   {
-    return (double)difference_msec(ms_start, ms_end) / 1000.0;
+    return static_cast<double>(difference_msec(ms_start, ms_end) / 1000.0);
   }
 
+  /**
+   * Takes two milestones and returns the difference.
+   * @param start The start time
+   * @param end The end time
+   * @return The difference time in high-resolution time
+   */
   ink_hrtime
-  elapsed(TSMilestonesType ms_start, TSMilestonesType ms_end) const
+  elapsed(T ms_start, T ms_end) const
   {
-    return milestones[ms_end] - milestones[ms_start];
+    return this->_milestones[static_cast<size_t>(ms_end)] - this->_milestones[static_cast<size_t>(ms_start)];
   }
 
 private:
-  ink_hrtime milestones[TS_MILESTONE_LAST_ENTRY];
+  std::array<ink_hrtime, entries> _milestones = {0};
 };
+
+// For compatibility with HttpSM.h and HttpTransact.h
+using TransactionMilestones = Milestones<TSMilestonesType, TS_MILESTONE_LAST_ENTRY>;

proxy/http2/HTTP2.cc

@@ -745,6 +745,8 @@ uint32_t Http2::zombie_timeout_in          = 0;
 float Http2::stream_error_rate_threshold   = 0.1;
 uint32_t Http2::max_settings_per_frame     = 7;
 uint32_t Http2::max_settings_per_minute    = 14;
+uint32_t Http2::con_slow_log_threshold     = 0;
+uint32_t Http2::stream_slow_log_threshold  = 0;
 
 void
 Http2::init()
@@ -765,6 +767,8 @@ Http2::init()
   REC_EstablishStaticConfigFloat(stream_error_rate_threshold, "proxy.config.http2.stream_error_rate_threshold");
   REC_EstablishStaticConfigInt32U(max_settings_per_frame, "proxy.config.http2.max_settings_per_frame");
   REC_EstablishStaticConfigInt32U(max_settings_per_minute, "proxy.config.http2.max_settings_per_minute");
+  REC_EstablishStaticConfigInt32U(con_slow_log_threshold, "proxy.config.http2.connection.slow.log.threshold");
+  REC_EstablishStaticConfigInt32U(stream_slow_log_threshold, "proxy.config.http2.stream.slow.log.threshold");
 
   // If any settings is broken, ATS should not start
   ink_release_assert(http2_settings_parameter_is_valid({HTTP2_SETTINGS_MAX_CONCURRENT_STREAMS, max_concurrent_streams_in}));

proxy/http2/HTTP2.h

@@ -378,6 +378,8 @@ class Http2
   static float stream_error_rate_threshold;
   static uint32_t max_settings_per_frame;
   static uint32_t max_settings_per_minute;
+  static uint32_t con_slow_log_threshold;
+  static uint32_t stream_slow_log_threshold;
 
   static void init();
 };

proxy/http2/Http2ClientSession.cc

@@ -98,6 +98,16 @@ Http2ClientSession::free()
   REMEMBER(NO_EVENT, this->recursion)
   Http2SsnDebug("session free");
 
+  this->_milestones.mark(Http2SsnMilestone::CLOSE);
+  ink_hrtime total_time = this->_milestones.elapsed(Http2SsnMilestone::OPEN, Http2SsnMilestone::CLOSE);
+
+  // Slow Log
+  if (Http2::con_slow_log_threshold != 0 && ink_hrtime_from_msec(Http2::con_slow_log_threshold) < total_time) {
+    Error("[%" PRIu64 "] Slow H2 Connection: open: %" PRIu64 " close: %.3f", this->con_id,
+          ink_hrtime_to_msec(this->_milestones[Http2SsnMilestone::OPEN]),
+          this->_milestones.difference_sec(Http2SsnMilestone::OPEN, Http2SsnMilestone::CLOSE));
+  }
+
   HTTP2_DECREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_SESSION_COUNT, this->mutex->thread_holding);
 
   // Update stats on how we died.  May want to eliminate this.  Was useful for
@@ -177,6 +187,7 @@ Http2ClientSession::new_connection(NetVConnection *new_vc, MIOBuffer *iobuf, IOB
   ink_assert(new_vc->mutex->thread_holding == this_ethread());
   HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_SESSION_COUNT, new_vc->mutex->thread_holding);
   HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_CLIENT_CONNECTION_COUNT, new_vc->mutex->thread_holding);
+  this->_milestones.mark(Http2SsnMilestone::OPEN);
 
   // Unique client session identifier.
   this->con_id    = ProxySession::next_connection_id();

proxy/http2/Http2ClientSession.h

@@ -30,6 +30,7 @@
 #include <string_view>
 #include "tscore/ink_inet.h"
 #include "tscore/History.h"
+#include "Milestones.h"
 
 // Name                       Edata                 Description
 // HTTP2_SESSION_EVENT_INIT   Http2ClientSession *  HTTP/2 session is born
@@ -49,6 +50,12 @@ enum class Http2SessionCod : int {
   HIGH_ERROR_RATE,
 };
 
+enum class Http2SsnMilestone {
+  OPEN = 0,
+  CLOSE,
+  LAST_ENTRY,
+};
+
 size_t const HTTP2_HEADER_BUFFER_SIZE_INDEX = CLIENT_CONNECTION_FIRST_READ_BUFFER_SIZE_INDEX;
 
 // To support Upgrade: h2c
@@ -334,6 +341,7 @@ class Http2ClientSession : public ProxySession
   IpEndpoint cached_local_addr;
 
   History<HISTORY_DEFAULT_SIZE> _history;
+  Milestones<Http2SsnMilestone, static_cast<size_t>(Http2SsnMilestone::LAST_ENTRY)> _milestones;
 
   // For Upgrade: h2c
   Http2UpgradeContext upgrade_context;

proxy/http2/Http2ConnectionState.cc

@@ -336,6 +336,7 @@ rcv_headers_frame(Http2ConnectionState &cstate, const Http2Frame &frame)
       empty_request = true;
     }
 
+    stream->mark_milestone(Http2StreamMilestone::START_DECODE_HEADERS);
     Http2ErrorCode result =
       stream->decode_header_blocks(*cstate.local_hpack_handle, cstate.server_settings.get(HTTP2_SETTINGS_HEADER_TABLE_SIZE));
 
@@ -355,6 +356,7 @@ rcv_headers_frame(Http2ConnectionState &cstate, const Http2Frame &frame)
     // Set up the State Machine
     if (!empty_request) {
       SCOPED_MUTEX_LOCK(stream_lock, stream->mutex, this_ethread());
+      stream->mark_milestone(Http2StreamMilestone::START_TXN);
       stream->new_transaction();
       // Send request header to SM
       stream->send_request(cstate);
@@ -864,6 +866,7 @@ rcv_continuation_frame(Http2ConnectionState &cstate, const Http2Frame &frame)
 
     // Set up the State Machine
     SCOPED_MUTEX_LOCK(stream_lock, stream->mutex, this_ethread());
+    stream->mark_milestone(Http2StreamMilestone::START_TXN);
     stream->new_transaction();
     // Send request header to SM
     stream->send_request(cstate);
@@ -1520,6 +1523,8 @@ Http2ConnectionState::send_headers_frame(Http2Stream *stream)
     h2_hdr.destroy();
     return;
   }
+
+  stream->mark_milestone(Http2StreamMilestone::START_ENCODE_HEADERS);
   Http2ErrorCode result = http2_encode_header_blocks(&h2_hdr, buf, buf_len, &header_blocks_size, *(this->remote_hpack_handle),
                                                      client_settings.get(HTTP2_SETTINGS_HEADER_TABLE_SIZE));
   if (result != Http2ErrorCode::HTTP2_ERROR_NO_ERROR) {
@@ -1536,6 +1541,7 @@ Http2ConnectionState::send_headers_frame(Http2Stream *stream)
       flags |= HTTP2_FLAGS_HEADERS_END_STREAM;
       stream->send_end_stream = true;
     }
+    stream->mark_milestone(Http2StreamMilestone::START_TX_HEADERS_FRAMES);
   } else {
     payload_length = BUFFER_SIZE_FOR_INDEX(buffer_size_index[HTTP2_FRAME_TYPE_HEADERS]);
   }

proxy/http2/Http2Stream.cc

@@ -172,6 +172,7 @@ Http2Stream::send_request(Http2ConnectionState &cstate)
 
   // Is there a read_vio request waiting?
   this->update_read_request(INT64_MAX, true);
+  this->_http_sm_id = this->current_reader->sm_id;
 }
 
 bool
@@ -627,7 +628,7 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len,
         if (is_done) {
           this->mark_body_done();
         }
-
+        this->_milestones.mark(Http2StreamMilestone::START_TX_DATA_FRAMES);
         this->send_response_body(call_update);
       }
       break;
@@ -642,7 +643,7 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len,
     if (write_vio.ntodo() == bytes_avail || is_done) {
       this->mark_body_done();
     }
-
+    this->_milestones.mark(Http2StreamMilestone::START_TX_DATA_FRAMES);
     this->send_response_body(call_update);
   }
 
@@ -725,6 +726,8 @@ Http2Stream::destroy()
   ink_release_assert(this->closed);
   ink_release_assert(reentrancy_count == 0);
 
+  uint64_t cid = 0;
+
   // Safe to initiate SSN_CLOSE if this is the last stream
   if (proxy_ssn) {
     Http2ClientSession *h2_proxy_ssn = static_cast<Http2ClientSession *>(proxy_ssn);
@@ -735,13 +738,38 @@ Http2Stream::destroy()
 
     // Update session's stream counts, so it accurately goes into keep-alive state
     h2_proxy_ssn->connection_state.release_stream(this);
+
+    cid = proxy_ssn->connection_id();
   }
 
   // Clean up the write VIO in case of inactivity timeout
   this->do_io_write(nullptr, 0, nullptr);
 
-  ink_hrtime end_time = Thread::get_hrtime();
-  HTTP2_SUM_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_TRANSACTIONS_TIME, _thread, end_time - _start_time);
+  this->_milestones.mark(Http2StreamMilestone::CLOSE);
+
+  ink_hrtime total_time = this->_milestones.elapsed(Http2StreamMilestone::OPEN, Http2StreamMilestone::CLOSE);
+  HTTP2_SUM_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_TRANSACTIONS_TIME, this->_thread, total_time);
+
+  // Slow Log
+  if (Http2::stream_slow_log_threshold != 0 && ink_hrtime_from_msec(Http2::stream_slow_log_threshold) < total_time) {
+    Error("[%" PRIu64 "] [%" PRIu32 "] [%" PRId64 "] Slow H2 Stream: "
+          "open: %" PRIu64 " "
+          "dec_hdrs: %.3f "
+          "txn: %.3f "
+          "enc_hdrs: %.3f "
+          "tx_hdrs: %.3f "
+          "tx_data: %.3f "
+          "close: %.3f",
+          cid, static_cast<uint32_t>(this->_id), this->_http_sm_id,
+          ink_hrtime_to_msec(this->_milestones[Http2StreamMilestone::OPEN]),
+          this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_DECODE_HEADERS),
+          this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_TXN),
+          this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_ENCODE_HEADERS),
+          this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_TX_HEADERS_FRAMES),
+          this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_TX_DATA_FRAMES),
+          this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::CLOSE));
+  }
+
   _req_header.destroy();
   response_header.destroy();
 
@@ -907,6 +935,12 @@ Http2Stream::decrement_client_transactions_stat()
   HTTP2_DECREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_STREAM_COUNT, _thread);
 }
 
+void
+Http2Stream::mark_milestone(Http2StreamMilestone type)
+{
+  this->_milestones.mark(type);
+}
+
 bool
 Http2Stream::_switch_thread_if_not_on_right_thread(int event, void *edata)
 {