On May 26, 2014, at 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.
We wanted to get a better picture of the SSL handshake time so we can included it into the total request time and also look at it to see how much time we are saving on average by using session tickets and session caching. Measuring SSL handshake time should ideally be measured by the client, so we are trying to do the best we can with this approach. > > What doesproxy.process.spdy.total_time mean, and how would I use it? This is the total time spent on SPDY requests. I think it is self explanatory. > > Why does proxy.process.ssl.total_success_handshake_count only count > successes? What about failed handshakes? When I was looking through the stats I saw that Ron was keeping track of the error cases. I would have to double check to make sure he is keeping track of the failed handshakes. > > Where is proxy.process.spdy.total_streams decremented? Total stats are normally not decremented and are a total count since the system has been running or since the last time the stats were reset. We don't want to decrement it and there is another stat to see the number of active streams. > > 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? There is a proxy.process.http.total_client_connections already. After the commit I was thinking that proxy.process.https.connection_count name should be changed to be more inline with the http stat. > > 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. Yes, this can be cleaned up. -Bryan > > 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/CHANGES >> ---------------------------------------------------------------------- >> 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 >> >
