On May 27, 2014, at 7:33 AM, Sudheer Vinukonda <sudhe...@yahoo-inc.com> wrote:
> > > On 5/26/14, 6:00 PM, "James Peach" <jpe...@apache.org> wrote: > >> Bryan, >> >> How are you expecting proxy.process.ssl.total_handshake_time to be used? >> What units is it in? Unless I'm missing something, the aggregate >> handshake time does not seem very interesting. > > > From what I can see in the patch, proxy.process.ssl.total_handshake_time = > proxy.process.ssl.total_*successful*_handshake_time and this is likely > meant to be used with proxy.process.ssl.total_success_handshake_count, to > determine the average *successful* handshake duration. This should be > useful in measuring the ssl handshake latency and perhaps how much > improvement is seen with features such as ssl session reuse or spdy. This is a very shaky rationale for this metric and a very limited use case. If you want to measure SSL handshake time, then you should measure it directly. If you try to measure it with this metric, you will need to use the connection_count metrics, which are also of dubious general utility since they are counters, not gauges. Even when you do that, all you can do is measure the average, which is not very interesting. You really want to measure the average and the variance, or even generate a heat map. To do this, you need per-request values. I think that you should nuke this metric and write a plugin to gather the data you actually need. Use or extend the transaction milestone API to get the session accept timestamp. You can use the kernel TCP info socket option to measure round trips, estimated latency, etc. >> What does proxy.process.spdy.total_time mean, and how would I use it? >> >> Why does proxy.process.ssl.total_success_handshake_count only count >> successes? What about failed handshakes? >> >> Where is proxy.process.spdy.total_streams decremented? >> >> Where is proxy.process.https.connection_count decremented? Why is it >> persistent? If it's measuring the total number of https connections >> accepted, where is proxy.process.http.connection_count? >> >> SSL_INCREMENT_DYN_STAT_EX is not a great name, and it's only used once. >> Does it really need a global macro? >> >> I'm not sure that sslHandshakeBeginTime is needed; >> UnixNetVConnection::submit_time seems to be there to mark the birth time >> of a netvc. >> >> On May 23, 2014, at 1:14 PM, bc...@apache.org wrote: >> >>> Repository: trafficserver >>> Updated Branches: >>> refs/heads/master 33a477145 -> 12bde5b9c >>> >>> >>> TS-2753: Add more SPDY and HTTPS statistics >>> Reviewed: Bryan Call >>> >>> >>> Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo >>> Commit: >>> http://git-wip-us.apache.org/repos/asf/trafficserver/commit/12bde5b9 >>> Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/12bde5b9 >>> Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/12bde5b9 >>> >>> Branch: refs/heads/master >>> Commit: 12bde5b9cfbc99a6bc9227166b0107cee35d8f9f >>> Parents: 33a4771 >>> Author: Wei Sun <sun...@yahoo-inc.com> >>> Authored: Fri May 23 13:14:31 2014 -0700 >>> Committer: Bryan Call <bc...@apache.org> >>> Committed: Fri May 23 13:14:31 2014 -0700 >>> >>> ---------------------------------------------------------------------- >>> CHANGES | 2 ++ >>> iocore/net/P_SSLNetVConnection.h | 1 + >>> iocore/net/P_SSLUtils.h | 3 +++ >>> iocore/net/SSLNetVConnection.cc | 9 +++++++++ >>> iocore/net/SSLNextProtocolAccept.cc | 1 + >>> iocore/net/SSLUtils.cc | 8 ++++++++ >>> proxy/http/HttpClientSession.cc | 4 ++++ >>> proxy/http/HttpConfig.cc | 6 ++++++ >>> proxy/http/HttpConfig.h | 3 +++ >>> proxy/http/HttpTransact.cc | 4 ++++ >>> proxy/spdy/SpdyClientSession.cc | 2 ++ >>> proxy/spdy/SpdyCommon.cc | 4 ++++ >>> proxy/spdy/SpdyCommon.h | 8 ++++++++ >>> 13 files changed, 55 insertions(+) >>> ---------------------------------------------------------------------- >>> >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/CHANGE >>> S >>> ---------------------------------------------------------------------- >>> diff --git a/CHANGES b/CHANGES >>> index c589668..8793946 100644 >>> --- a/CHANGES >>> +++ b/CHANGES >>> @@ -1,6 +1,8 @@ >>> -*- coding: >>> utf-8 -*- >>> Changes with Apache Traffic Server 5.0.0 >>> >>> + *) [TS-2753] Add more SPDY and HTTPS statistics >>> + >>> *) [TS-2677] Don't apply path / scheme URL changes in remap when >>> method is >>> CONNECT. >>> >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/iocore >>> /net/P_SSLNetVConnection.h >>> ---------------------------------------------------------------------- >>> diff --git a/iocore/net/P_SSLNetVConnection.h >>> b/iocore/net/P_SSLNetVConnection.h >>> index 47861e4..c464e60 100644 >>> --- a/iocore/net/P_SSLNetVConnection.h >>> +++ b/iocore/net/P_SSLNetVConnection.h >>> @@ -101,6 +101,7 @@ public: >>> virtual ~SSLNetVConnection() { } >>> >>> SSL *ssl; >>> + ink_hrtime sslHandshakeBeginTime; >>> >>> static int advertise_next_protocol(SSL * ssl, const unsigned char ** >>> out, unsigned * outlen, void *); >>> static int select_next_protocol(SSL * ssl, const unsigned char ** >>> out, unsigned char * outlen, const unsigned char * in, unsigned inlen, >>> void *); >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/iocore >>> /net/P_SSLUtils.h >>> ---------------------------------------------------------------------- >>> diff --git a/iocore/net/P_SSLUtils.h b/iocore/net/P_SSLUtils.h >>> index 7297eac..5145cb7 100644 >>> --- a/iocore/net/P_SSLUtils.h >>> +++ b/iocore/net/P_SSLUtils.h >>> @@ -62,6 +62,8 @@ enum SSL_Stats >>> ssl_user_agent_session_hit_stat, >>> ssl_user_agent_session_miss_stat, >>> ssl_user_agent_session_timeout_stat, >>> + ssl_total_handshake_time_stat, >>> + ssl_total_success_handshake_count_stat, >>> >>> ssl_cipher_stats_start = 100, >>> ssl_cipher_stats_end = 300, >>> @@ -75,6 +77,7 @@ extern RecRawStatBlock *ssl_rsb; >>> #define SSL_INCREMENT_DYN_STAT(x) RecIncrRawStat(ssl_rsb, NULL, (int) >>> x, 1) >>> #define SSL_DECREMENT_DYN_STAT(x) RecIncrRawStat(ssl_rsb, NULL, (int) >>> x, -1) >>> #define SSL_SET_COUNT_DYN_STAT(x,count) RecSetRawStatCount(ssl_rsb, x, >>> count) >>> +#define SSL_INCREMENT_DYN_STAT_EX(x, y) RecIncrRawStat(ssl_rsb, NULL, >>> (int) x, y) >>> #define SSL_CLEAR_DYN_STAT(x) \ >>> do { \ >>> RecSetRawStatSum(ssl_rsb, (x), 0); \ >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/iocore >>> /net/SSLNetVConnection.cc >>> ---------------------------------------------------------------------- >>> diff --git a/iocore/net/SSLNetVConnection.cc >>> b/iocore/net/SSLNetVConnection.cc >>> index 57c022c..11e9d1e 100644 >>> --- a/iocore/net/SSLNetVConnection.cc >>> +++ b/iocore/net/SSLNetVConnection.cc >>> @@ -468,6 +468,7 @@ SSLNetVConnection::SSLNetVConnection(): >>> npnEndpoint(NULL) >>> { >>> ssl = NULL; >>> + sslHandshakeBeginTime = 0; >>> } >>> >>> void >>> @@ -572,6 +573,14 @@ SSLNetVConnection::sslServerHandShakeEvent(int >>> &err) >>> >>> sslHandShakeComplete = true; >>> >>> + if (sslHandshakeBeginTime) { >>> + const ink_hrtime ssl_handshake_time = ink_get_hrtime() - >>> sslHandshakeBeginTime; >>> + Debug("ssl", "ssl handshake time:%" PRId64, ssl_handshake_time); >>> + sslHandshakeBeginTime = 0; >>> + SSL_INCREMENT_DYN_STAT_EX(ssl_total_handshake_time_stat, >>> ssl_handshake_time); >>> + SSL_INCREMENT_DYN_STAT(ssl_total_success_handshake_count_stat); >>> + } >>> + >>> { >>> const unsigned char * proto = NULL; >>> unsigned len = 0; >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/iocore >>> /net/SSLNextProtocolAccept.cc >>> ---------------------------------------------------------------------- >>> diff --git a/iocore/net/SSLNextProtocolAccept.cc >>> b/iocore/net/SSLNextProtocolAccept.cc >>> index 92524d0..558a1b1 100644 >>> --- a/iocore/net/SSLNextProtocolAccept.cc >>> +++ b/iocore/net/SSLNextProtocolAccept.cc >>> @@ -119,6 +119,7 @@ SSLNextProtocolAccept::mainEvent(int event, void * >>> edata) >>> { >>> SSLNetVConnection * netvc = ssl_netvc_cast(event, edata); >>> >>> + netvc->sslHandshakeBeginTime = ink_get_hrtime(); >>> Debug("ssl", "[SSLNextProtocolAccept:mainEvent] event %d netvc %p", >>> event, netvc); >>> >>> switch (event) { >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/iocore >>> /net/SSLUtils.cc >>> ---------------------------------------------------------------------- >>> diff --git a/iocore/net/SSLUtils.cc b/iocore/net/SSLUtils.cc >>> index f5083b9..8d80c90 100644 >>> --- a/iocore/net/SSLUtils.cc >>> +++ b/iocore/net/SSLUtils.cc >>> @@ -634,6 +634,14 @@ SSLInitializeStatistics() >>> RECD_INT, RECP_PERSISTENT, (int) >>> ssl_origin_server_unknown_ca_stat, >>> RecRawStatSyncSum); >>> >>> + // SSL handshake time >>> + RecRegisterRawStat(ssl_rsb, RECT_PROCESS, >>> "proxy.process.ssl.total_handshake_time", >>> + RECD_INT, RECP_PERSISTENT, (int) >>> ssl_total_handshake_time_stat, >>> + RecRawStatSyncSum); >>> + RecRegisterRawStat(ssl_rsb, RECT_PROCESS, >>> "proxy.process.ssl.total_success_handshake_count", >>> + RECD_INT, RECP_PERSISTENT, (int) >>> ssl_total_success_handshake_count_stat, >>> + RecRawStatSyncCount); >>> + >>> // Get and register the SSL cipher stats. Note that we are using the >>> default SSL context to obtain >>> // the cipher list. This means that the set of ciphers is fixed by >>> the build configuration and not >>> // filtered by proxy.config.ssl.server.cipher_suite. This keeps the >>> set of cipher suites stable across >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> http/HttpClientSession.cc >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/http/HttpClientSession.cc >>> b/proxy/http/HttpClientSession.cc >>> index 0620b3b..3f00cd4 100644 >>> --- a/proxy/http/HttpClientSession.cc >>> +++ b/proxy/http/HttpClientSession.cc >>> @@ -191,6 +191,10 @@ HttpClientSession::new_connection(NetVConnection * >>> new_vc, bool backdoor, MIOBuf >>> HTTP_INCREMENT_DYN_STAT(http_current_client_connections_stat); >>> conn_decrease = true; >>> HTTP_INCREMENT_DYN_STAT(http_total_client_connections_stat); >>> + if (static_cast<HttpProxyPort::TransportType>(new_vc->attributes) == >>> HttpProxyPort::TRANSPORT_SSL) { >>> + HTTP_INCREMENT_DYN_STAT(https_connection_count_stat); >>> + } >>> + >>> /* inbound requests stat should be incremented here, not after the >>> * header has been read */ >>> HTTP_INCREMENT_DYN_STAT(http_total_incoming_connections_stat); >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> http/HttpConfig.cc >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/http/HttpConfig.cc b/proxy/http/HttpConfig.cc >>> index 0d9c9e3..62d6304 100644 >>> --- a/proxy/http/HttpConfig.cc >>> +++ b/proxy/http/HttpConfig.cc >>> @@ -1198,6 +1198,12 @@ register_stat_callbacks() >>> RECD_COUNTER, RECP_PERSISTENT, >>> (int) http_total_x_redirect_stat, >>> RecRawStatSyncCount); >>> >>> + RecRegisterRawStat(http_rsb, RECT_PROCESS, >>> + "proxy.process.https.incoming_requests", >>> + RECD_COUNTER, RECP_PERSISTENT, (int) >>> https_incoming_requests_stat, RecRawStatSyncCount); >>> + RecRegisterRawStat(http_rsb, RECT_PROCESS, >>> + "proxy.process.https.connection_count", >>> + RECD_COUNTER, RECP_PERSISTENT, (int) >>> https_connection_count_stat, RecRawStatSyncCount); >>> } >>> >>> >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> http/HttpConfig.h >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/http/HttpConfig.h b/proxy/http/HttpConfig.h >>> index 15f4b79..4805097 100644 >>> --- a/proxy/http/HttpConfig.h >>> +++ b/proxy/http/HttpConfig.h >>> @@ -337,6 +337,9 @@ enum >>> http_response_status_505_count_stat, >>> http_response_status_5xx_count_stat, >>> >>> + https_incoming_requests_stat, >>> + https_connection_count_stat, >>> + >>> http_stat_count >>> }; >>> >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> http/HttpTransact.cc >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/http/HttpTransact.cc b/proxy/http/HttpTransact.cc >>> index 0167136..1d94dec 100644 >>> --- a/proxy/http/HttpTransact.cc >>> +++ b/proxy/http/HttpTransact.cc >>> @@ -1293,6 +1293,10 @@ HttpTransact::HandleRequest(State* s) >>> >>> HTTP_INCREMENT_TRANS_STAT(http_incoming_requests_stat); >>> >>> + if (s->client_info.port_attribute == HttpProxyPort::TRANSPORT_SSL) { >>> + HTTP_INCREMENT_TRANS_STAT(https_incoming_requests_stat); >>> + } >>> + >>> if (s->api_release_server_session == true) { >>> s->api_release_server_session = false; >>> } >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> spdy/SpdyClientSession.cc >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/spdy/SpdyClientSession.cc >>> b/proxy/spdy/SpdyClientSession.cc >>> index fcb79fb..47f57c3 100644 >>> --- a/proxy/spdy/SpdyClientSession.cc >>> +++ b/proxy/spdy/SpdyClientSession.cc >>> @@ -101,6 +101,7 @@ SpdyClientSession::init(NetVConnection * netvc, >>> spdy::SessionVersion vers) >>> // with no increment. It seems a lesser thing to have the thread >>> counts >>> // a little off but globally consistent. >>> SpdyStatIncrCount(Config::STAT_ACTIVE_SESSION_COUNT, netvc); >>> + SpdyStatIncrCount(Config::STAT_TOTAL_CONNECTION_COUNT, netvc); >>> >>> ink_release_assert(r == 0); >>> sm_id = atomic_inc(g_sm_id); >>> @@ -398,6 +399,7 @@ spdy_read_fetch_body_callback(spdylay_session * >>> /*session*/, int32_t stream_id, >>> if (already < (int64_t)length) { >>> if (req->event == TS_FETCH_EVENT_EXT_BODY_DONE) { >>> TSHRTime end_time = TShrtime(); >>> + SpdyStatIncr(Config::STAT_TOTAL_STREAM_TIME, sm, end_time - >>> req->start_time); >>> Debug("spdy", "----Request[%" PRIu64 ":%d] %s %lld %d", >>> sm->sm_id, req->stream_id, >>> req->url.c_str(), (end_time - >>> req->start_time)/TS_HRTIME_MSECOND, >>> req->fetch_data_len); >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> spdy/SpdyCommon.cc >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/spdy/SpdyCommon.cc b/proxy/spdy/SpdyCommon.cc >>> index 0b89bf8..d5687f4 100644 >>> --- a/proxy/spdy/SpdyCommon.cc >>> +++ b/proxy/spdy/SpdyCommon.cc >>> @@ -30,6 +30,8 @@ Config SPDY_CFG; >>> static char const * const SPDY_STAT_ACTIVE_SESSION_NAME = >>> "proxy.process.spdy.active_sessions"; >>> static char const * const SPDY_STAT_ACTIVE_STREAM_NAME = >>> "proxy.process.spdy.active_streams"; >>> static char const * const SPDY_STAT_TOTAL_STREAM_NAME = >>> "proxy.process.spdy.total_streams"; >>> +static char const * const SPDY_STAT_TOTAL_TIME_NAME = >>> "proxy.process.spdy.total_time"; >>> +static char const * const SPDY_STAT_TOTAL_CONNECTION_NAME = >>> "proxy.process.spdy.connection_count"; >>> >>> string >>> http_date(time_t t) >>> @@ -56,6 +58,8 @@ spdy_config_load() >>> RecRegisterRawStat(SPDY_CFG.rsb, RECT_PROCESS, >>> SPDY_STAT_ACTIVE_SESSION_NAME, RECD_INT, RECP_NON_PERSISTENT, >>> static_cast<int>(Config::STAT_ACTIVE_SESSION_COUNT), >>> RecRawStatSyncCount); >>> RecRegisterRawStat(SPDY_CFG.rsb, RECT_PROCESS, >>> SPDY_STAT_ACTIVE_STREAM_NAME, RECD_INT, RECP_NON_PERSISTENT, >>> static_cast<int>(Config::STAT_ACTIVE_STREAM_COUNT), RecRawStatSyncCount); >>> RecRegisterRawStat(SPDY_CFG.rsb, RECT_PROCESS, >>> SPDY_STAT_TOTAL_STREAM_NAME, RECD_INT, RECP_NON_PERSISTENT, >>> static_cast<int>(Config::STAT_TOTAL_STREAM_COUNT), RecRawStatSyncCount); >>> + RecRegisterRawStat(SPDY_CFG.rsb, RECT_PROCESS, >>> SPDY_STAT_TOTAL_TIME_NAME, RECD_INT, RECP_NON_PERSISTENT, >>> static_cast<int>(Config::STAT_TOTAL_STREAM_TIME), RecRawStatSyncSum); >>> + RecRegisterRawStat(SPDY_CFG.rsb, RECT_PROCESS, >>> SPDY_STAT_TOTAL_CONNECTION_NAME, RECD_INT, RECP_NON_PERSISTENT, >>> static_cast<int>(Config::STAT_TOTAL_CONNECTION_COUNT), >>> RecRawStatSyncCount); >>> >>> return 0; >>> } >>> >>> >>> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/12bde5b9/proxy/ >>> spdy/SpdyCommon.h >>> ---------------------------------------------------------------------- >>> diff --git a/proxy/spdy/SpdyCommon.h b/proxy/spdy/SpdyCommon.h >>> index 92ab047..330a979 100644 >>> --- a/proxy/spdy/SpdyCommon.h >>> +++ b/proxy/spdy/SpdyCommon.h >>> @@ -73,6 +73,9 @@ struct Config { >>> STAT_ACTIVE_SESSION_COUNT, ///< Current # of active SPDY sessions. >>> STAT_ACTIVE_STREAM_COUNT, ///< Current # of active SPDY streams. >>> STAT_TOTAL_STREAM_COUNT, ///< Total number of streams created. >>> + STAT_TOTAL_STREAM_TIME, //< Total stream time >>> + STAT_TOTAL_CONNECTION_COUNT, //< Total connections running spdy >>> + >>> N_STATS ///< Terminal counter, NOT A STAT INDEX. >>> }; >>> RecRawStatBlock* rsb; ///< Container for statistics. >>> @@ -112,4 +115,9 @@ SpdyStatDecrCount(Config::StatIndex idx, >>> Continuation* contp) { >>> RecIncrRawStatCount(SPDY_CFG.rsb, contp->mutex->thread_holding, idx, >>> -1); >>> } >>> >>> +inline void >>> +SpdyStatIncr(Config::StatIndex idx, Continuation* contp, const int64_t >>> incr) { >>> + RecIncrRawStat(SPDY_CFG.rsb, contp->mutex->thread_holding, idx, >>> incr); >>> +} >>> + >>> #endif >>> >> >
