diff --git a/doc/admin-guide/files/records.config.en.rst b/doc/admin-guide/files/records.config.en.rst index 6384543b34f..f8e2fa687b3 100644 --- a/doc/admin-guide/files/records.config.en.rst +++ b/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 `. This is identifying data about the transaction and all of the :c:type:`transaction milestones `. +.. 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 + `. This is identifying data about the + transaction and all of the :c:type:`transaction milestones `. + +.. 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 + `. This is identifying data about the + transaction and all of the :c:type:`transaction milestones `. + .. ts:cv:: CONFIG proxy.config.log.config.filename STRING logging.yaml :reloadable: diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc index 9491cddff2a..fd179f0b032 100644 --- a/mgmt/RecordsConfig.cc +++ b/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} + , //############################################################################## //# diff --git a/proxy/Milestones.h b/proxy/Milestones.h index d429e285b81..3170c0f38e0 100644 --- a/proxy/Milestones.h +++ b/proxy/Milestones.h @@ -1,6 +1,6 @@ /** @file - A brief file description + Milestones @section license License @@ -23,22 +23,32 @@ #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 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(ms)]; } + ink_hrtime operator[](T ms) const { return this->_milestones[static_cast(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(ms)] == 0) { + this->_milestones[static_cast(ms)] = Thread::get_hrtime(); + } + } + /** * Takes two milestones and returns the difference. * @param start The start time @@ -46,12 +56,12 @@ class TransactionMilestones * @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(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(ms_end)] - this->_milestones[static_cast(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(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(ms_end)] - this->_milestones[static_cast(ms_start)]; } private: - ink_hrtime milestones[TS_MILESTONE_LAST_ENTRY]; + std::array _milestones = {0}; }; + +// For compatibility with HttpSM.h and HttpTransact.h +using TransactionMilestones = Milestones; diff --git a/proxy/http2/HTTP2.cc b/proxy/http2/HTTP2.cc index a53769b252b..535f3a3de6d 100644 --- a/proxy/http2/HTTP2.cc +++ b/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})); diff --git a/proxy/http2/HTTP2.h b/proxy/http2/HTTP2.h index 63fe9aa3ed6..325ebf35478 100644 --- a/proxy/http2/HTTP2.h +++ b/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(); }; diff --git a/proxy/http2/Http2ClientSession.cc b/proxy/http2/Http2ClientSession.cc index e033ef536df..3e2a8bccd88 100644 --- a/proxy/http2/Http2ClientSession.cc +++ b/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(); diff --git a/proxy/http2/Http2ClientSession.h b/proxy/http2/Http2ClientSession.h index 257f418f5f3..88840224d73 100644 --- a/proxy/http2/Http2ClientSession.h +++ b/proxy/http2/Http2ClientSession.h @@ -30,6 +30,7 @@ #include #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; + Milestones(Http2SsnMilestone::LAST_ENTRY)> _milestones; // For Upgrade: h2c Http2UpgradeContext upgrade_context; diff --git a/proxy/http2/Http2ConnectionState.cc b/proxy/http2/Http2ConnectionState.cc index 9d73d8c551b..7ed5186062c 100644 --- a/proxy/http2/Http2ConnectionState.cc +++ b/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]); } diff --git a/proxy/http2/Http2Stream.cc b/proxy/http2/Http2Stream.cc index 09877f2890c..3bcbfe72328 100644 --- a/proxy/http2/Http2Stream.cc +++ b/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(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(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) { diff --git a/proxy/http2/Http2Stream.h b/proxy/http2/Http2Stream.h index 1e159da5089..8d1c8e73052 100644 --- a/proxy/http2/Http2Stream.h +++ b/proxy/http2/Http2Stream.h @@ -29,12 +29,24 @@ #include "../http/HttpTunnel.h" // To get ChunkedHandler #include "Http2DependencyTree.h" #include "tscore/History.h" +#include "Milestones.h" class Http2Stream; class Http2ConnectionState; typedef Http2DependencyTree::Tree DependencyTree; +enum class Http2StreamMilestone { + OPEN = 0, + START_DECODE_HEADERS, + START_TXN, + START_ENCODE_HEADERS, + START_TX_HEADERS_FRAMES, + START_TX_DATA_FRAMES, + CLOSE, + LAST_ENTRY, +}; + class Http2Stream : public ProxyTransaction { public: @@ -47,10 +59,12 @@ class Http2Stream : public ProxyTransaction void init(Http2StreamId sid, ssize_t initial_rwnd) { - _id = sid; - _start_time = Thread::get_hrtime(); - _thread = this_ethread(); + this->mark_milestone(Http2StreamMilestone::OPEN); + + this->_id = sid; + this->_thread = this_ethread(); this->client_rwnd = initial_rwnd; + sm_reader = request_reader = request_buffer.alloc_reader(); // FIXME: Are you sure? every "stream" needs request_header? _req_header.create(HTTP_TYPE_REQUEST); @@ -223,6 +237,8 @@ class Http2Stream : public ProxyTransaction void increment_client_transactions_stat() override; void decrement_client_transactions_stat() override; + void mark_milestone(Http2StreamMilestone type); + private: void response_initialize_data_handling(bool &is_done); void response_process_data(bool &is_done); @@ -238,16 +254,17 @@ class Http2Stream : public ProxyTransaction bool _switch_thread_if_not_on_right_thread(int event, void *edata); HTTPParser http_parser; - ink_hrtime _start_time = 0; - EThread *_thread = nullptr; + EThread *_thread = nullptr; Http2StreamId _id; Http2StreamState _state = Http2StreamState::HTTP2_STREAM_STATE_IDLE; + int64_t _http_sm_id = -1; HTTPHdr _req_header; VIO read_vio; VIO write_vio; History _history; + Milestones(Http2StreamMilestone::LAST_ENTRY)> _milestones; bool trailing_header = false; bool body_done = false;