This is an automated email from the ASF dual-hosted git repository. zwoop pushed a commit to branch 8.1.x in repository https://gitbox.apache.org/repos/asf/trafficserver.git
commit cd5a364ccdc7af408f4a61764583ed92418317f6 Author: Masaori Koshiba <[email protected]> AuthorDate: Wed Jul 24 14:48:09 2019 +0900 Add slow logs for HTTP/2 Connection & Stream (cherry picked from commit 0d2ad23921061c4117104b64d15bc17cae79c9fe) Conflicts: proxy/http2/HTTP2.cc proxy/http2/HTTP2.h proxy/http2/Http2Stream.cc proxy/http2/Http2Stream.h --- doc/admin-guide/files/records.config.en.rst | 20 ++++++++++ mgmt/RecordsConfig.cc | 4 ++ proxy/Milestones.h | 59 +++++++++++++++++++---------- proxy/http2/HTTP2.cc | 4 ++ proxy/http2/HTTP2.h | 2 + proxy/http2/Http2ClientSession.cc | 11 ++++++ proxy/http2/Http2ClientSession.h | 8 ++++ proxy/http2/Http2ConnectionState.cc | 6 +++ proxy/http2/Http2Stream.cc | 40 ++++++++++++++++++- proxy/http2/Http2Stream.h | 24 ++++++++++-- 10 files changed, 153 insertions(+), 25 deletions(-) diff --git a/doc/admin-guide/files/records.config.en.rst b/doc/admin-guide/files/records.config.en.rst index 109122e..f0d80c5 100644 --- a/doc/admin-guide/files/records.config.en.rst +++ b/doc/admin-guide/files/records.config.en.rst @@ -2882,6 +2882,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: diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc index 72a501f..dbcb07f 100644 --- a/mgmt/RecordsConfig.cc +++ b/mgmt/RecordsConfig.cc @@ -658,6 +658,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 d429e28..3170c0f 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 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 @@ -46,12 +56,12 @@ public: * @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 @@ public: * @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>; diff --git a/proxy/http2/HTTP2.cc b/proxy/http2/HTTP2.cc index 2844c87..ddd7450 100644 --- a/proxy/http2/HTTP2.cc +++ b/proxy/http2/HTTP2.cc @@ -740,6 +740,8 @@ uint32_t Http2::max_settings_frames_per_minute = 14; uint32_t Http2::max_ping_frames_per_minute = 60; uint32_t Http2::max_priority_frames_per_minute = 120; float Http2::min_avg_window_update = 2560.0; +uint32_t Http2::con_slow_log_threshold = 0; +uint32_t Http2::stream_slow_log_threshold = 0; void Http2::init() @@ -764,6 +766,8 @@ Http2::init() REC_EstablishStaticConfigInt32U(max_ping_frames_per_minute, "proxy.config.http2.max_ping_frames_per_minute"); REC_EstablishStaticConfigInt32U(max_priority_frames_per_minute, "proxy.config.http2.max_priority_frames_per_minute"); REC_EstablishStaticConfigFloat(min_avg_window_update, "proxy.config.http2.min_avg_window_update"); + 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 22b132d..515aabd 100644 --- a/proxy/http2/HTTP2.h +++ b/proxy/http2/HTTP2.h @@ -385,6 +385,8 @@ public: static uint32_t max_ping_frames_per_minute; static uint32_t max_priority_frames_per_minute; static float min_avg_window_update; + 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 cab22ee..e2e6ddc 100644 --- a/proxy/http2/Http2ClientSession.cc +++ b/proxy/http2/Http2ClientSession.cc @@ -107,6 +107,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 @@ -186,6 +196,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); // HTTP/2 for the backdoor connections? Let's not deal woth that yet. ink_release_assert(backdoor == false); diff --git a/proxy/http2/Http2ClientSession.h b/proxy/http2/Http2ClientSession.h index ca8977b..9027016 100644 --- a/proxy/http2/Http2ClientSession.h +++ b/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 @@ -50,6 +51,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 @@ -352,6 +359,7 @@ private: 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; diff --git a/proxy/http2/Http2ConnectionState.cc b/proxy/http2/Http2ConnectionState.cc index 93280a8..e57e4bf 100644 --- a/proxy/http2/Http2ConnectionState.cc +++ b/proxy/http2/Http2ConnectionState.cc @@ -337,6 +337,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)); @@ -356,6 +357,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); @@ -905,6 +907,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); @@ -1564,6 +1567,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) { @@ -1580,6 +1585,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 5fa978b..122dcff 100644 --- a/proxy/http2/Http2Stream.cc +++ b/proxy/http2/Http2Stream.cc @@ -175,6 +175,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,6 +628,7 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len, // make sure to send the end of stream is_done |= (write_vio.ntodo() + this->response_header.length_get()) == bytes_avail; if (this->response_is_data_available() || is_done) { + this->_milestones.mark(Http2StreamMilestone::START_TX_DATA_FRAMES); this->send_response_body(call_update); } break; @@ -638,6 +640,7 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len, break; } } else { + this->_milestones.mark(Http2StreamMilestone::START_TX_DATA_FRAMES); this->send_response_body(call_update); } @@ -720,6 +723,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 (parent) { Http2ClientSession *h2_parent = static_cast<Http2ClientSession *>(parent); @@ -730,14 +735,39 @@ Http2Stream::destroy() // Update session's stream counts, so it accurately goes into keep-alive state h2_parent->connection_state.release_stream(this); + cid = parent->connection_id(); } // Clean up the write VIO in case of inactivity timeout this->do_io_write(nullptr, 0, nullptr); HTTP2_DECREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_STREAM_COUNT, _thread); - 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(); @@ -946,6 +976,12 @@ Http2Stream::decrement_server_rwnd(size_t amount) } } +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 6f65f6c..edb0116 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<Http2Stream *> 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 ProxyClientTransaction { public: @@ -47,12 +59,15 @@ public: void init(Http2StreamId sid, ssize_t initial_rwnd) { + this->mark_milestone(Http2StreamMilestone::OPEN); + _id = sid; - _start_time = Thread::get_hrtime(); _thread = this_ethread(); this->_client_rwnd = initial_rwnd; + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_STREAM_COUNT, _thread); HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_CLIENT_STREAM_COUNT, _thread); + sm_reader = request_reader = request_buffer.alloc_reader(); http_parser_init(&http_parser); // FIXME: Are you sure? every "stream" needs request_header? @@ -223,6 +238,8 @@ public: return is_first_transaction_flag; } + void mark_milestone(Http2StreamMilestone type); + private: void response_initialize_data_handling(bool &is_done); void response_process_data(bool &is_done); @@ -238,16 +255,17 @@ private: 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_DEFAULT_SIZE> _history; + Milestones<Http2StreamMilestone, static_cast<size_t>(Http2StreamMilestone::LAST_ENTRY)> _milestones; bool trailing_header = false; bool chunked = false;
