This is an automated email from the ASF dual-hosted git repository.
masaori pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push:
new 0d2ad23 Add slow logs for HTTP/2 Connection & Stream
0d2ad23 is described below
commit 0d2ad23921061c4117104b64d15bc17cae79c9fe
Author: Masaori Koshiba <[email protected]>
AuthorDate: Wed Jul 24 14:48:09 2019 +0900
Add slow logs for HTTP/2 Connection & Stream
---
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 | 42 ++++++++++++++++++--
proxy/http2/Http2Stream.h | 27 ++++++++++---
10 files changed, 154 insertions(+), 29 deletions(-)
diff --git a/doc/admin-guide/files/records.config.en.rst
b/doc/admin-guide/files/records.config.en.rst
index 243d03a..65f27f0 100644
--- a/doc/admin-guide/files/records.config.en.rst
+++ b/doc/admin-guide/files/records.config.en.rst
@@ -2852,6 +2852,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 3058a2a..a0891df 100644
--- a/mgmt/RecordsConfig.cc
+++ b/mgmt/RecordsConfig.cc
@@ -645,6 +645,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 a53769b..535f3a3 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 63fe9aa..325ebf3 100644
--- a/proxy/http2/HTTP2.h
+++ b/proxy/http2/HTTP2.h
@@ -378,6 +378,8 @@ public:
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 e033ef5..3e2a8bc 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 257f418..8884022 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
@@ -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 @@ 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 9d73d8c..7ed5186 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 09877f2..3bcbfe7 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<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)
{
diff --git a/proxy/http2/Http2Stream.h b/proxy/http2/Http2Stream.h
index 1e159da..8d1c8e7 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 ProxyTransaction
{
public:
@@ -47,10 +59,12 @@ public:
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 @@ public:
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 @@ 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 body_done = false;
