On 5/29/14, 1:36 AM, "Bryan Call" <bc...@yahoo-inc.com> wrote:
> >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. Looks like submit_time is created before ::accept() in do_blocking_accept(), might not be accurate to measure the starting time. > >-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/CHANG >>>ES >>> ---------------------------------------------------------------------- >>> 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/iocor >>>e/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/iocor >>>e/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/iocor >>>e/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/iocor >>>e/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/iocor >>>e/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 >>> >> >
