On May 29, 2014, at 12:19 AM, Wei Sun <sun...@yahoo-inc.com> wrote: > > > 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.
I wonder if that's a bug. NetAccept::acceptFastEvent() and net_accept() both set it after the accept. > >> >> -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
