You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by am...@apache.org on 2015/07/08 02:27:22 UTC
trafficserver git commit: TS-2150: Transaction milestone log tag This
closes #229.
Repository: trafficserver
Updated Branches:
refs/heads/master c5dd0f6f4 -> 29c26cd66
TS-2150: Transaction milestone log tag
This closes #229.
Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo
Commit: http://git-wip-us.apache.org/repos/asf/trafficserver/commit/29c26cd6
Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/29c26cd6
Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/29c26cd6
Branch: refs/heads/master
Commit: 29c26cd6642a5b155cf1f65a47cde7f08c2060a1
Parents: c5dd0f6
Author: Francois Pesce <fp...@yahoo-inc.com>
Authored: Tue Jun 16 22:38:27 2015 -0700
Committer: Alan M. Carroll <am...@apache.org>
Committed: Tue Jul 7 19:26:23 2015 -0500
----------------------------------------------------------------------
doc/admin/event-logging-formats.en.rst | 14 +++
proxy/InkAPI.cc | 70 +-----------
proxy/StatSystem.cc | 18 ----
proxy/StatSystem.h | 160 ++++++++++++++++------------
proxy/http/HttpSM.cc | 122 ++++++++++-----------
proxy/http/HttpTransact.cc | 49 +++++----
proxy/logging/Log.cc | 5 +
proxy/logging/LogAccess.cc | 19 ++++
proxy/logging/LogAccess.h | 7 ++
proxy/logging/LogAccessHttp.cc | 35 +++++-
proxy/logging/LogAccessHttp.h | 3 +
proxy/logging/LogField.cc | 135 +++++++++++++++++++++--
proxy/logging/LogField.h | 8 ++
13 files changed, 401 insertions(+), 244 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/doc/admin/event-logging-formats.en.rst
----------------------------------------------------------------------
diff --git a/doc/admin/event-logging-formats.en.rst b/doc/admin/event-logging-formats.en.rst
index 4e1c7cc..2687bc1 100644
--- a/doc/admin/event-logging-formats.en.rst
+++ b/doc/admin/event-logging-formats.en.rst
@@ -299,6 +299,20 @@ The following list describes Traffic Server custom logging fields.
``fsiz``
The size of the file (*n* bytes) as seen by the origin server.
+
+.. _ms:
+
+``{Milestone field name}ms``
+ The timestamp in milliseconds of a specific milestone for this request.
+ see :c:func:`TSHttpTxnMilestoneGet` for milestone names.
+
+.. _msdms
+
+``{Milestone field name1-Milestone field name2}msdms``
+ The difference in milliseconds of between two milestones.
+ see :c:func:`TSHttpTxnMilestoneGet` for milestone names.
+
+
.. _pfsc:
``pfsc``
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/InkAPI.cc
----------------------------------------------------------------------
diff --git a/proxy/InkAPI.cc b/proxy/InkAPI.cc
index a764277..0c0995e 100644
--- a/proxy/InkAPI.cc
+++ b/proxy/InkAPI.cc
@@ -5935,74 +5935,12 @@ TSHttpTxnMilestoneGet(TSHttpTxn txnp, TSMilestonesType milestone, ink_hrtime *ti
HttpSM *sm = (HttpSM *)txnp;
TSReturnCode ret = TS_SUCCESS;
- switch (milestone) {
- case TS_MILESTONE_UA_BEGIN:
- *time = sm->milestones.ua_begin;
- break;
- case TS_MILESTONE_UA_READ_HEADER_DONE:
- *time = sm->milestones.ua_read_header_done;
- break;
- case TS_MILESTONE_UA_BEGIN_WRITE:
- *time = sm->milestones.ua_begin_write;
- break;
- case TS_MILESTONE_UA_CLOSE:
- *time = sm->milestones.ua_close;
- break;
- case TS_MILESTONE_SERVER_FIRST_CONNECT:
- *time = sm->milestones.server_first_connect;
- break;
- case TS_MILESTONE_SERVER_CONNECT:
- *time = sm->milestones.server_connect;
- break;
- case TS_MILESTONE_SERVER_CONNECT_END:
- *time = sm->milestones.server_connect_end;
- break;
- case TS_MILESTONE_SERVER_BEGIN_WRITE:
- *time = sm->milestones.server_begin_write;
- break;
- case TS_MILESTONE_SERVER_FIRST_READ:
- *time = sm->milestones.server_first_read;
- break;
- case TS_MILESTONE_SERVER_READ_HEADER_DONE:
- *time = sm->milestones.server_read_header_done;
- break;
- case TS_MILESTONE_SERVER_CLOSE:
- *time = sm->milestones.server_close;
- break;
- case TS_MILESTONE_CACHE_OPEN_READ_BEGIN:
- *time = sm->milestones.cache_open_read_begin;
- break;
- case TS_MILESTONE_CACHE_OPEN_READ_END:
- *time = sm->milestones.cache_open_read_end;
- break;
- case TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN:
- *time = sm->milestones.cache_open_write_begin;
- break;
- case TS_MILESTONE_CACHE_OPEN_WRITE_END:
- *time = sm->milestones.cache_open_write_end;
- break;
- case TS_MILESTONE_DNS_LOOKUP_BEGIN:
- *time = sm->milestones.dns_lookup_begin;
- break;
- case TS_MILESTONE_DNS_LOOKUP_END:
- *time = sm->milestones.dns_lookup_end;
- break;
- case TS_MILESTONE_SM_START:
- *time = sm->milestones.sm_start;
- break;
- case TS_MILESTONE_SM_FINISH:
- *time = sm->milestones.sm_finish;
- break;
- case TS_MILESTONE_PLUGIN_ACTIVE:
- *time = sm->milestones.plugin_active;
- break;
- case TS_MILESTONE_PLUGIN_TOTAL:
- *time = sm->milestones.plugin_total;
- break;
- default:
+ if ((milestone < (TSMilestonesType)TransactionMilestones::UA_BEGIN) ||
+ (milestone >= (TSMilestonesType)TransactionMilestones::LAST_ENTRY)) {
*time = -1;
ret = TS_ERROR;
- break;
+ } else {
+ *time = sm->milestones[(TransactionMilestones::Milestone)milestone];
}
return ret;
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/StatSystem.cc
----------------------------------------------------------------------
diff --git a/proxy/StatSystem.cc b/proxy/StatSystem.cc
index ed90529..a784429 100644
--- a/proxy/StatSystem.cc
+++ b/proxy/StatSystem.cc
@@ -731,21 +731,3 @@ http_trans_stats_time_useconds_cb(void *data, void *res)
*(float *)res = r;
return res;
}
-
-int64_t
-milestone_difference_msec(const ink_hrtime start, const ink_hrtime end)
-{
- if (end == 0) {
- return -1;
- }
- return (end - start) / 1000000;
-}
-
-double
-milestone_difference(const ink_hrtime start, const ink_hrtime end)
-{
- if (end == 0) {
- return -1;
- }
- return (double)(end - start) / 1000000000;
-}
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/StatSystem.h
----------------------------------------------------------------------
diff --git a/proxy/StatSystem.h b/proxy/StatSystem.h
index 779f384..4a537dc 100644
--- a/proxy/StatSystem.h
+++ b/proxy/StatSystem.h
@@ -49,79 +49,103 @@
class TransactionMilestones
{
public:
- TransactionMilestones()
- : ua_begin(0), ua_first_read(0), ua_read_header_done(0), ua_begin_write(0), ua_close(0), server_first_connect(0),
- server_connect(0), server_connect_end(0), server_begin_write(0), server_first_read(0), server_read_header_done(0),
- server_close(0), cache_open_read_begin(0), cache_open_read_end(0), cache_open_write_begin(0), cache_open_write_end(0),
- dns_lookup_begin(0), dns_lookup_end(0), sm_start(0), sm_finish(0), plugin_active(0), plugin_total(0)
+ // Used for array indexes, insert new value before _LAST one
+ enum Milestone {
+ ////////////////////////////////////////////////////////
+ // user agent: //
+ // user_agent_begin represents the time this //
+ // transaction started. If this is the first //
+ // transaction in a connection, then user_agent_begin //
+ // is set to accept time. otherwise it is set to //
+ // first read time. //
+ ////////////////////////////////////////////////////////
+ UA_BEGIN = 0,
+ UA_FIRST_READ,
+ UA_READ_HEADER_DONE,
+ UA_BEGIN_WRITE,
+ UA_CLOSE,
+
+ ////////////////////////////////////////////////////////
+ // server (origin_server , parent, blind tunnnel //
+ ////////////////////////////////////////////////////////
+ SERVER_FIRST_CONNECT,
+ SERVER_CONNECT,
+ SERVER_CONNECT_END,
+ SERVER_BEGIN_WRITE, // http only
+ SERVER_FIRST_READ, // http only
+ SERVER_READ_HEADER_DONE, // http only
+ SERVER_CLOSE,
+
+ CACHE_OPEN_READ_BEGIN,
+ CACHE_OPEN_READ_END,
+ CACHE_OPEN_WRITE_BEGIN,
+ CACHE_OPEN_WRITE_END,
+
+ DNS_LOOKUP_BEGIN,
+ DNS_LOOKUP_END,
+
+ ///////////////////
+ // state machine //
+ ///////////////////
+ SM_START,
+ SM_FINISH,
+
+ //////////////////
+ // API activity //
+ //////////////////
+ // Total amount of time spent in API calls converted to a timestamp.
+ // (subtract @a sm_start to get the actual time)
+ /// Time spent in API callout.
+ PLUGIN_ACTIVE,
+ /// Time spent in API state during the transaction.
+ PLUGIN_TOTAL,
+ LAST_ENTRY
+ // TODO: Should we instrument these at some point?
+ // CACHE_READ_BEGIN;
+ // CACHE_READ_END;
+ // CACHE_WRITE_BEGIN;
+ // CACHE_WRITE_END;
+ };
+
+ TransactionMilestones() { ink_zero(milestones); }
+
+ ink_hrtime &operator[](Milestone ms) { return milestones[ms]; }
+
+ const ink_hrtime &operator[](Milestone ms) const { return milestones[ms]; }
+
+ /**
+ * Takes two milestones and returns the difference.
+ * @param start The start time
+ * @param end The end time
+ * @return A double that is the time in seconds
+ */
+ int64_t
+ difference_msec(Milestone ms_start, Milestone ms_end) const
{
+ if (milestones[ms_end] == 0) {
+ return -1;
+ }
+ return (milestones[ms_end] - milestones[ms_start]) / 1000000;
}
+ double
+ difference(Milestone ms_start, Milestone ms_end) const
+ {
+ if (milestones[ms_end] == 0) {
+ return -1;
+ }
+ return (double)(milestones[ms_end] - milestones[ms_start]) / 1000000000;
+ }
- ////////////////////////////////////////////////////////
- // user agent: //
- // user_agent_begin represents the time this //
- // transaction started. If this is the first //
- // transaction in a connection, then user_agent_begin //
- // is set to accept time. otherwise it is set to //
- // first read time. //
- ////////////////////////////////////////////////////////
- ink_hrtime ua_begin;
- ink_hrtime ua_first_read;
- ink_hrtime ua_read_header_done;
- ink_hrtime ua_begin_write;
- ink_hrtime ua_close;
-
- ////////////////////////////////////////////////////////
- // server (origin_server , parent, blind tunnnel //
- ////////////////////////////////////////////////////////
- ink_hrtime server_first_connect;
- ink_hrtime server_connect;
- ink_hrtime server_connect_end;
- ink_hrtime server_begin_write; // http only
- ink_hrtime server_first_read; // http only
- ink_hrtime server_read_header_done; // http only
- ink_hrtime server_close;
-
- ink_hrtime cache_open_read_begin;
- ink_hrtime cache_open_read_end;
- ink_hrtime cache_open_write_begin;
- ink_hrtime cache_open_write_end;
-
- ink_hrtime dns_lookup_begin;
- ink_hrtime dns_lookup_end;
-
- ///////////////////
- // state machine //
- ///////////////////
- ink_hrtime sm_start;
- ink_hrtime sm_finish;
-
- //////////////////
- // API activity //
- //////////////////
- // Total amount of time spent in API calls converted to a timestamp.
- // (subtract @a sm_start to get the actual time)
- /// Time spent in API callout.
- ink_hrtime plugin_active;
- /// Time spent in API state during the transaction.
- ink_hrtime plugin_total;
-
- // TODO: Should we instrument these at some point?
- // ink_hrtime cache_read_begin;
- // ink_hrtime cache_read_end;
- // ink_hrtime cache_write_begin;
- // ink_hrtime cache_write_end;
-};
+ ink_hrtime
+ elapsed(Milestone ms_start, Milestone ms_end) const
+ {
+ return milestones[ms_end] - milestones[ms_start];
+ }
-/**
- * Takes two milestones and returns the difference.
- * @param start The start time
- * @param end The end time
- * @return A double that is the time in seconds
- */
-double milestone_difference(const ink_hrtime start, const ink_hrtime end);
-int64_t milestone_difference_msec(const ink_hrtime start, const ink_hrtime end);
+private:
+ ink_hrtime milestones[LAST_ENTRY];
+};
// Modularization Project: Build w/o thread-local-dyn-stats
// temporarily until we switch over to librecords. Revert to old
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/http/HttpSM.cc
----------------------------------------------------------------------
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index afbdf3a..70520a9 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -103,13 +103,13 @@ milestone_update_api_time(TransactionMilestones &milestones, ink_hrtime &api_tim
if (0 == delta)
++delta;
- if (0 == milestones.plugin_total)
- milestones.plugin_total = milestones.sm_start;
- milestones.plugin_total += delta;
+ if (0 == milestones[TransactionMilestones::PLUGIN_TOTAL])
+ milestones[TransactionMilestones::PLUGIN_TOTAL] = milestones[TransactionMilestones::SM_START];
+ milestones[TransactionMilestones::PLUGIN_TOTAL] = milestones[TransactionMilestones::PLUGIN_TOTAL] + delta;
if (active) {
- if (0 == milestones.plugin_active)
- milestones.plugin_active = milestones.sm_start;
- milestones.plugin_active += delta;
+ if (0 == milestones[TransactionMilestones::PLUGIN_ACTIVE])
+ milestones[TransactionMilestones::PLUGIN_ACTIVE] = milestones[TransactionMilestones::SM_START];
+ milestones[TransactionMilestones::PLUGIN_ACTIVE] = milestones[TransactionMilestones::PLUGIN_ACTIVE] + delta;
}
}
}
@@ -317,7 +317,7 @@ HttpSM::destroy()
void
HttpSM::init()
{
- milestones.sm_start = Thread::get_hrtime();
+ milestones[TransactionMilestones::SM_START] = Thread::get_hrtime();
magic = HTTP_SM_MAGIC_ALIVE;
sm_id = 0;
@@ -468,7 +468,7 @@ HttpSM::start_sub_sm()
void
HttpSM::attach_client_session(HttpClientSession *client_vc, IOBufferReader *buffer_reader)
{
- milestones.ua_begin = Thread::get_hrtime();
+ milestones[TransactionMilestones::UA_BEGIN] = Thread::get_hrtime();
ink_assert(client_vc != NULL);
ua_session = client_vc;
@@ -603,7 +603,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
// the accept timeout by the HttpClientSession
//
if (client_request_hdr_bytes == 0) {
- milestones.ua_first_read = Thread::get_hrtime();
+ milestones[TransactionMilestones::UA_FIRST_READ] = Thread::get_hrtime();
ua_session->get_netvc()->set_inactivity_timeout(HRTIME_SECONDS(t_state.txn_conf->transaction_no_activity_timeout_in));
}
/////////////////////
@@ -666,7 +666,7 @@ HttpSM::state_read_client_request_header(int event, void *data)
}
http_parser_clear(&http_parser);
ua_entry->vc_handler = &HttpSM::state_watch_for_client_abort;
- milestones.ua_read_header_done = Thread::get_hrtime();
+ milestones[TransactionMilestones::UA_READ_HEADER_DONE] = Thread::get_hrtime();
}
switch (state) {
@@ -856,7 +856,7 @@ HttpSM::state_watch_for_client_abort(int event, void *data)
ua_entry->read_vio->nbytes = ua_entry->read_vio->ndone;
}
mark_server_down_on_client_abort();
- milestones.ua_close = Thread::get_hrtime();
+ milestones[TransactionMilestones::UA_CLOSE] = Thread::get_hrtime();
set_ua_abort(HttpTransact::ABORTED, event);
terminate_sm = true;
break;
@@ -997,7 +997,7 @@ HttpSM::state_read_push_response_header(int event, void *data)
// Disable further IO
ua_entry->read_vio->nbytes = ua_entry->read_vio->ndone;
http_parser_clear(&http_parser);
- milestones.server_read_header_done = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_READ_HEADER_DONE] = Thread::get_hrtime();
}
switch (state) {
@@ -1031,7 +1031,7 @@ HttpSM::state_raw_http_server_open(int event, void *data)
{
STATE_ENTER(&HttpSM::state_raw_http_server_open, event);
ink_assert(server_entry == NULL);
- milestones.server_connect_end = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_CONNECT_END] = Thread::get_hrtime();
NetVConnection *netvc = NULL;
pending_action = NULL;
@@ -1601,7 +1601,7 @@ HttpSM::state_http_server_open(int event, void *data)
// TODO decide whether to uncomment after finish testing redirect
// ink_assert(server_entry == NULL);
pending_action = NULL;
- milestones.server_connect_end = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_CONNECT_END] = Thread::get_hrtime();
HttpServerSession *session;
switch (event) {
@@ -1732,7 +1732,7 @@ HttpSM::state_read_server_response_header(int event, void *data)
// the connect timeout when we set up to read the header
//
if (server_response_hdr_bytes == 0) {
- milestones.server_first_read = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_FIRST_READ] = Thread::get_hrtime();
if (t_state.api_txn_no_activity_timeout_value != -1) {
server_session->get_netvc()->set_inactivity_timeout(HRTIME_MSECONDS(t_state.api_txn_no_activity_timeout_value));
@@ -1769,7 +1769,7 @@ HttpSM::state_read_server_response_header(int event, void *data)
// Disable further IO
server_entry->read_vio->nbytes = server_entry->read_vio->ndone;
http_parser_clear(&http_parser);
- milestones.server_read_header_done = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_READ_HEADER_DONE] = Thread::get_hrtime();
}
switch (state) {
@@ -2076,11 +2076,11 @@ HttpSM::process_hostdb_info(HostDBInfo *r)
ink_assert(!t_state.host_db_info.round_robin);
}
- milestones.dns_lookup_end = Thread::get_hrtime();
+ milestones[TransactionMilestones::DNS_LOOKUP_END] = Thread::get_hrtime();
if (is_debug_tag_set("http_timeout")) {
if (t_state.api_txn_dns_timeout_value != -1) {
- int foo = (int)(milestone_difference_msec(milestones.dns_lookup_begin, milestones.dns_lookup_end));
+ int foo = (int)(milestones.difference_msec(TransactionMilestones::DNS_LOOKUP_BEGIN, TransactionMilestones::DNS_LOOKUP_END));
DebugSM("http_timeout", "DNS took: %d msec", foo);
}
}
@@ -2343,7 +2343,7 @@ int
HttpSM::state_cache_open_write(int event, void *data)
{
STATE_ENTER(&HttpSM : state_cache_open_write, event);
- milestones.cache_open_write_end = Thread::get_hrtime();
+ milestones[TransactionMilestones::CACHE_OPEN_WRITE_END] = Thread::get_hrtime();
pending_action = NULL;
switch (event) {
@@ -2444,7 +2444,7 @@ int
HttpSM::state_cache_open_read(int event, void *data)
{
STATE_ENTER(&HttpSM::state_cache_open_read, event);
- milestones.cache_open_read_end = Thread::get_hrtime();
+ milestones[TransactionMilestones::CACHE_OPEN_READ_END] = Thread::get_hrtime();
ink_assert(server_entry == NULL);
ink_assert(t_state.cache_info.object_read == 0);
@@ -2827,7 +2827,7 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p)
{
STATE_ENTER(&HttpSM::tunnel_handler_server, event);
- milestones.server_close = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_CLOSE] = Thread::get_hrtime();
bool close_connection = false;
@@ -3067,7 +3067,7 @@ HttpSM::tunnel_handler_ua(int event, HttpTunnelConsumer *c)
STATE_ENTER(&HttpSM::tunnel_handler_ua, event);
ink_assert(c->vc == ua_session);
- milestones.ua_close = Thread::get_hrtime();
+ milestones[TransactionMilestones::UA_CLOSE] = Thread::get_hrtime();
switch (event) {
case VC_EVENT_EOS:
@@ -3914,7 +3914,7 @@ HttpSM::do_hostdb_lookup()
ink_assert(t_state.dns_info.lookup_name != NULL);
ink_assert(pending_action == NULL);
- milestones.dns_lookup_begin = Thread::get_hrtime();
+ milestones[TransactionMilestones::DNS_LOOKUP_BEGIN] = Thread::get_hrtime();
bool use_srv_records = t_state.srv_lookup;
if (use_srv_records) {
@@ -4344,7 +4344,7 @@ HttpSM::do_cache_lookup_and_read()
HTTP_INCREMENT_TRANS_STAT(http_cache_lookups_stat);
- milestones.cache_open_read_begin = Thread::get_hrtime();
+ milestones[TransactionMilestones::CACHE_OPEN_READ_BEGIN] = Thread::get_hrtime();
t_state.cache_lookup_result = HttpTransact::CACHE_LOOKUP_NONE;
t_state.cache_info.lookup_count++;
// YTS Team, yamsat Plugin
@@ -4411,7 +4411,7 @@ HttpSM::do_cache_prepare_write()
{
// statistically no need to retry when we are trying to lock
// LOCK_URL_SECOND url because the server's behavior is unlikely to change
- milestones.cache_open_write_begin = Thread::get_hrtime();
+ milestones[TransactionMilestones::CACHE_OPEN_WRITE_BEGIN] = Thread::get_hrtime();
bool retry = (t_state.api_lock_url == HttpTransact::LOCK_URL_FIRST);
do_cache_prepare_action(&cache_sm, t_state.cache_info.object_read, retry);
}
@@ -4544,19 +4544,20 @@ HttpSM::do_http_server_open(bool raw)
DebugSM("http_seq", "[HttpSM::do_http_server_open] Sending request to server");
- milestones.server_connect = Thread::get_hrtime();
- if (milestones.server_first_connect == 0) {
- milestones.server_first_connect = milestones.server_connect;
+ milestones[TransactionMilestones::SERVER_CONNECT] = Thread::get_hrtime();
+ if (milestones[TransactionMilestones::SERVER_FIRST_CONNECT] == 0) {
+ milestones[TransactionMilestones::SERVER_FIRST_CONNECT] = milestones[TransactionMilestones::SERVER_CONNECT];
}
if (t_state.pCongestionEntry != NULL) {
- if (t_state.pCongestionEntry->F_congested() && (!t_state.pCongestionEntry->proxy_retry(milestones.server_connect))) {
+ if (t_state.pCongestionEntry->F_congested() &&
+ (!t_state.pCongestionEntry->proxy_retry(milestones[TransactionMilestones::SERVER_CONNECT]))) {
t_state.congestion_congested_or_failed = 1;
t_state.pCongestionEntry->stat_inc_F();
CONGEST_INCREMENT_DYN_STAT(congested_on_F_stat);
handleEvent(CONGESTION_EVENT_CONGESTED_ON_F, NULL);
return;
- } else if (t_state.pCongestionEntry->M_congested(ink_hrtime_to_sec(milestones.server_connect))) {
+ } else if (t_state.pCongestionEntry->M_congested(ink_hrtime_to_sec(milestones[TransactionMilestones::SERVER_CONNECT]))) {
t_state.pCongestionEntry->stat_inc_M();
t_state.congestion_congested_or_failed = 1;
CONGEST_INCREMENT_DYN_STAT(congested_on_M_stat);
@@ -4850,7 +4851,7 @@ HttpSM::do_api_callout_internal()
break;
case HttpTransact::SM_ACTION_API_SEND_RESPONSE_HDR:
cur_hook_id = TS_HTTP_SEND_RESPONSE_HDR_HOOK;
- milestones.ua_begin_write = Thread::get_hrtime();
+ milestones[TransactionMilestones::UA_BEGIN_WRITE] = Thread::get_hrtime();
break;
case HttpTransact::SM_ACTION_API_SM_SHUTDOWN:
if (callout_state == HTTP_API_IN_CALLOUT || callout_state == HTTP_API_DEFERED_SERVER_ERROR) {
@@ -4989,10 +4990,10 @@ HttpSM::mark_server_down_on_client_abort()
// the actual origin server is one that is hung //
/////////////////////////////////////////////////////
if (t_state.current.request_to == HttpTransact::ORIGIN_SERVER && t_state.hdr_info.request_content_length == 0) {
- if (milestones.server_first_connect != 0 && milestones.server_first_read == 0) {
+ if (milestones[TransactionMilestones::SERVER_FIRST_CONNECT] != 0 && milestones[TransactionMilestones::SERVER_FIRST_READ] == 0) {
// Check to see if client waited for the threshold
// to declare the origin server as down
- ink_hrtime wait = Thread::get_hrtime() - milestones.server_first_connect;
+ ink_hrtime wait = Thread::get_hrtime() - milestones[TransactionMilestones::SERVER_FIRST_CONNECT];
if (wait < 0) {
wait = 0;
}
@@ -5680,7 +5681,7 @@ HttpSM::setup_server_send_request()
server_request_body_bytes = msg_len;
}
- milestones.server_begin_write = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_BEGIN_WRITE] = Thread::get_hrtime();
server_entry->write_vio = server_entry->vc->do_io_write(this, hdr_length, buf_start);
}
@@ -5710,7 +5711,7 @@ HttpSM::setup_server_read_response_header()
t_state.hdr_info.server_response.create(HTTP_TYPE_RESPONSE);
http_parser_clear(&http_parser);
server_response_hdr_bytes = 0;
- milestones.server_read_header_done = 0;
+ milestones[TransactionMilestones::SERVER_READ_HEADER_DONE] = 0;
// We already done the READ when we setup the connection to
// read the request header
@@ -6344,7 +6345,7 @@ HttpSM::setup_blind_tunnel(bool send_response_hdr)
IOBufferReader *r_from = from_ua_buf->alloc_reader();
IOBufferReader *r_to = to_ua_buf->alloc_reader();
- milestones.server_begin_write = Thread::get_hrtime();
+ milestones[TransactionMilestones::SERVER_BEGIN_WRITE] = Thread::get_hrtime();
if (send_response_hdr) {
client_response_hdr_bytes = write_response_header_into_buffer(&t_state.hdr_info.client_response, to_ua_buf);
} else {
@@ -6586,7 +6587,7 @@ HttpSM::kill_this()
void
HttpSM::update_stats()
{
- milestones.sm_finish = Thread::get_hrtime();
+ milestones[TransactionMilestones::SM_FINISH] = Thread::get_hrtime();
if (t_state.cop_test_page && !t_state.http_config_param->record_cop_page) {
DebugSM("http_seq", "Skipping cop heartbeat logging & stats due to config");
@@ -6615,28 +6616,29 @@ HttpSM::update_stats()
}
}
- ink_hrtime total_time = milestones.sm_finish - milestones.sm_start;
+ ink_hrtime total_time = milestones.elapsed(TransactionMilestones::SM_START, TransactionMilestones::SM_FINISH);
// ua_close will not be assigned properly in some exceptional situation.
// TODO: Assign ua_close with suitable value when HttpTunnel terminates abnormally.
- if (milestones.ua_close == 0 && milestones.ua_read_header_done > 0)
- milestones.ua_close = Thread::get_hrtime();
+ if (milestones[TransactionMilestones::UA_CLOSE] == 0 && milestones[TransactionMilestones::UA_READ_HEADER_DONE] > 0)
+ milestones[TransactionMilestones::UA_CLOSE] = Thread::get_hrtime();
// request_process_time = The time after the header is parsed to the completion of the transaction
- ink_hrtime request_process_time = milestones.ua_close - milestones.ua_read_header_done;
+ ink_hrtime request_process_time =
+ milestones[TransactionMilestones::UA_CLOSE] - milestones[TransactionMilestones::UA_READ_HEADER_DONE];
HttpTransact::client_result_stat(&t_state, total_time, request_process_time);
ink_hrtime ua_write_time;
- if (milestones.ua_begin_write != 0 && milestones.ua_close != 0) {
- ua_write_time = milestones.ua_close - milestones.ua_begin_write;
+ if (milestones[TransactionMilestones::UA_BEGIN_WRITE] != 0 && milestones[TransactionMilestones::UA_CLOSE] != 0) {
+ ua_write_time = milestones.elapsed(TransactionMilestones::UA_BEGIN_WRITE, TransactionMilestones::UA_CLOSE);
} else {
ua_write_time = -1;
}
ink_hrtime os_read_time;
- if (milestones.server_read_header_done != 0 && milestones.server_close != 0) {
- os_read_time = milestones.server_close - milestones.server_read_header_done;
+ if (milestones[TransactionMilestones::SERVER_READ_HEADER_DONE] != 0 && milestones[TransactionMilestones::SERVER_CLOSE] != 0) {
+ os_read_time = milestones.elapsed(TransactionMilestones::SERVER_READ_HEADER_DONE, TransactionMilestones::SERVER_CLOSE);
} else {
os_read_time = -1;
}
@@ -6717,21 +6719,21 @@ HttpSM::update_stats()
"plugin_total: %.3f",
sm_id, client_ip, ats_ip_port_host_order(&t_state.client_info.addr), url_string, status, unique_id_string,
redirection_tries, client_response_body_bytes, fd, t_state.client_info.state, t_state.server_info.state,
- milestone_difference(milestones.sm_start, milestones.ua_begin),
- milestone_difference(milestones.sm_start, milestones.ua_first_read),
- milestone_difference(milestones.sm_start, milestones.ua_read_header_done),
- milestone_difference(milestones.sm_start, milestones.cache_open_read_begin),
- milestone_difference(milestones.sm_start, milestones.cache_open_read_end),
- milestone_difference(milestones.sm_start, milestones.dns_lookup_begin),
- milestone_difference(milestones.sm_start, milestones.dns_lookup_end),
- milestone_difference(milestones.sm_start, milestones.server_connect),
- milestone_difference(milestones.sm_start, milestones.server_first_read),
- milestone_difference(milestones.sm_start, milestones.server_read_header_done),
- milestone_difference(milestones.sm_start, milestones.server_close),
- milestone_difference(milestones.sm_start, milestones.ua_close),
- milestone_difference(milestones.sm_start, milestones.sm_finish),
- milestone_difference(milestones.sm_start, milestones.plugin_active),
- milestone_difference(milestones.sm_start, milestones.plugin_total));
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::UA_BEGIN),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::UA_FIRST_READ),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::UA_READ_HEADER_DONE),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::CACHE_OPEN_READ_BEGIN),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::CACHE_OPEN_READ_END),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::DNS_LOOKUP_BEGIN),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::DNS_LOOKUP_END),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::SERVER_CONNECT),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::SERVER_FIRST_READ),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::SERVER_READ_HEADER_DONE),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::SERVER_CLOSE),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::UA_CLOSE),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::SM_FINISH),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::PLUGIN_ACTIVE),
+ milestones.difference(TransactionMilestones::SM_START, TransactionMilestones::PLUGIN_TOTAL));
}
}
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/http/HttpTransact.cc
----------------------------------------------------------------------
diff --git a/proxy/http/HttpTransact.cc b/proxy/http/HttpTransact.cc
index 3974b86..304a4eb 100644
--- a/proxy/http/HttpTransact.cc
+++ b/proxy/http/HttpTransact.cc
@@ -8865,75 +8865,84 @@ HttpTransact::update_size_and_time_stats(State *s, ink_hrtime total_time, ink_hr
// update milestones stats
if (http_ua_begin_time_stat) {
- HTTP_SUM_TRANS_STAT(http_ua_begin_time_stat, milestone_difference_msec(milestones.sm_start, milestones.ua_begin))
+ HTTP_SUM_TRANS_STAT(http_ua_begin_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::UA_BEGIN))
}
if (http_ua_first_read_time_stat) {
- HTTP_SUM_TRANS_STAT(http_ua_first_read_time_stat, milestone_difference_msec(milestones.sm_start, milestones.ua_first_read))
+ HTTP_SUM_TRANS_STAT(http_ua_first_read_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::UA_FIRST_READ))
}
if (http_ua_read_header_done_time_stat) {
HTTP_SUM_TRANS_STAT(http_ua_read_header_done_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.ua_read_header_done))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::UA_READ_HEADER_DONE))
}
if (http_ua_begin_write_time_stat) {
- HTTP_SUM_TRANS_STAT(http_ua_begin_write_time_stat, milestone_difference_msec(milestones.sm_start, milestones.ua_begin_write))
+ HTTP_SUM_TRANS_STAT(http_ua_begin_write_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::UA_BEGIN_WRITE))
}
if (http_ua_close_time_stat) {
- HTTP_SUM_TRANS_STAT(http_ua_close_time_stat, milestone_difference_msec(milestones.sm_start, milestones.ua_close))
+ HTTP_SUM_TRANS_STAT(http_ua_close_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::UA_CLOSE))
}
if (http_server_first_connect_time_stat) {
HTTP_SUM_TRANS_STAT(http_server_first_connect_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.server_first_connect))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_FIRST_CONNECT))
}
if (http_server_connect_time_stat) {
- HTTP_SUM_TRANS_STAT(http_server_connect_time_stat, milestone_difference_msec(milestones.sm_start, milestones.server_connect))
+ HTTP_SUM_TRANS_STAT(http_server_connect_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_CONNECT))
}
if (http_server_connect_end_time_stat) {
HTTP_SUM_TRANS_STAT(http_server_connect_end_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.server_connect_end))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_CONNECT_END))
}
if (http_server_begin_write_time_stat) {
HTTP_SUM_TRANS_STAT(http_server_begin_write_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.server_begin_write))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_BEGIN_WRITE))
}
if (http_server_first_read_time_stat) {
HTTP_SUM_TRANS_STAT(http_server_first_read_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.server_first_read))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_FIRST_READ))
}
if (http_server_read_header_done_time_stat) {
HTTP_SUM_TRANS_STAT(http_server_read_header_done_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.server_read_header_done))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_READ_HEADER_DONE))
}
if (http_server_close_time_stat) {
- HTTP_SUM_TRANS_STAT(http_server_close_time_stat, milestone_difference_msec(milestones.sm_start, milestones.server_close))
+ HTTP_SUM_TRANS_STAT(http_server_close_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SERVER_CLOSE))
}
if (http_cache_open_read_begin_time_stat) {
HTTP_SUM_TRANS_STAT(http_cache_open_read_begin_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.cache_open_read_begin))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::CACHE_OPEN_READ_BEGIN))
}
if (http_cache_open_read_end_time_stat) {
HTTP_SUM_TRANS_STAT(http_cache_open_read_end_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.cache_open_read_end))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::CACHE_OPEN_READ_END))
}
if (http_cache_open_write_begin_time_stat) {
HTTP_SUM_TRANS_STAT(http_cache_open_write_begin_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.cache_open_write_begin))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::CACHE_OPEN_WRITE_BEGIN))
}
if (http_cache_open_write_end_time_stat) {
HTTP_SUM_TRANS_STAT(http_cache_open_write_end_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.cache_open_write_end))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::CACHE_OPEN_WRITE_END))
}
if (http_dns_lookup_begin_time_stat) {
HTTP_SUM_TRANS_STAT(http_dns_lookup_begin_time_stat,
- milestone_difference_msec(milestones.sm_start, milestones.dns_lookup_begin))
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::DNS_LOOKUP_BEGIN))
}
if (http_dns_lookup_end_time_stat) {
- HTTP_SUM_TRANS_STAT(http_dns_lookup_end_time_stat, milestone_difference_msec(milestones.sm_start, milestones.dns_lookup_end))
+ HTTP_SUM_TRANS_STAT(http_dns_lookup_end_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::DNS_LOOKUP_END))
}
if (http_sm_start_time_stat) {
- HTTP_SUM_TRANS_STAT(http_sm_start_time_stat, milestone_difference_msec(milestones.sm_start, milestones.sm_start))
+ HTTP_SUM_TRANS_STAT(http_sm_start_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SM_START))
}
if (http_sm_finish_time_stat) {
- HTTP_SUM_TRANS_STAT(http_sm_finish_time_stat, milestone_difference_msec(milestones.sm_start, milestones.sm_finish))
+ HTTP_SUM_TRANS_STAT(http_sm_finish_time_stat,
+ milestones.difference_msec(TransactionMilestones::SM_START, TransactionMilestones::SM_FINISH))
}
}
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/Log.cc
----------------------------------------------------------------------
diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc
index 2559f61..eee7892 100644
--- a/proxy/logging/Log.cc
+++ b/proxy/logging/Log.cc
@@ -318,6 +318,11 @@ Log::init_fields()
LogField *field;
//
+ // Initializes material to find a milestone name from their
+ // name in a rapid manner.
+ field->init_milestone_container();
+
+ //
// Create a hash table that will be used to find the global field
// objects from their symbol names in a rapid manner.
//
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/LogAccess.cc
----------------------------------------------------------------------
diff --git a/proxy/logging/LogAccess.cc b/proxy/logging/LogAccess.cc
index bd2aacb..f43e71c 100644
--- a/proxy/logging/LogAccess.cc
+++ b/proxy/logging/LogAccess.cc
@@ -643,6 +643,25 @@ LogAccess::marshal_config_str_var(char *config_var, char *buf)
return len;
}
+/*-------------------------------------------------------------------------
+ -------------------------------------------------------------------------*/
+
+int
+LogAccess::marshal_milestone(TransactionMilestones::Milestone ms, char *buf)
+{
+ DEFAULT_INT_FIELD;
+}
+
+/*-------------------------------------------------------------------------
+ -------------------------------------------------------------------------*/
+
+int
+LogAccess::marshal_milestone_diff(TransactionMilestones::Milestone ms1, TransactionMilestones::Milestone ms2, char *buf)
+{
+ DEFAULT_INT_FIELD;
+}
+
+
// To allow for a generic marshal_record function, rather than
// multiple functions (one per data type) we always marshal a record
// as a string of a fixed length. We use a fixed length because the
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/LogAccess.h
----------------------------------------------------------------------
diff --git a/proxy/logging/LogAccess.h b/proxy/logging/LogAccess.h
index b8fdd2d..83121fd 100644
--- a/proxy/logging/LogAccess.h
+++ b/proxy/logging/LogAccess.h
@@ -282,6 +282,13 @@ public:
int marshal_record(char *record, char *buf);
//
+ // milestones access
+ //
+ inkcoreapi virtual int marshal_milestone(TransactionMilestones::Milestone ms, char *buf);
+ inkcoreapi virtual int marshal_milestone_diff(TransactionMilestones::Milestone ms1, TransactionMilestones::Milestone ms2,
+ char *buf);
+
+ //
// unmarshalling routines
//
// They used to return a string; now they unmarshal directly into the
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/LogAccessHttp.cc
----------------------------------------------------------------------
diff --git a/proxy/logging/LogAccessHttp.cc b/proxy/logging/LogAccessHttp.cc
index a0a5689..f5fc802 100644
--- a/proxy/logging/LogAccessHttp.cc
+++ b/proxy/logging/LogAccessHttp.cc
@@ -957,7 +957,8 @@ int
LogAccessHttp::marshal_server_resp_time_ms(char *buf)
{
if (buf) {
- ink_hrtime elapsed = m_http_sm->milestones.server_close - m_http_sm->milestones.server_connect;
+ ink_hrtime elapsed =
+ m_http_sm->milestones[TransactionMilestones::SERVER_CLOSE] - m_http_sm->milestones[TransactionMilestones::SERVER_CONNECT];
int64_t val = (int64_t)ink_hrtime_to_msec(elapsed);
marshal_int(buf, val);
}
@@ -968,7 +969,8 @@ int
LogAccessHttp::marshal_server_resp_time_s(char *buf)
{
if (buf) {
- ink_hrtime elapsed = m_http_sm->milestones.server_close - m_http_sm->milestones.server_connect;
+ ink_hrtime elapsed =
+ m_http_sm->milestones[TransactionMilestones::SERVER_CLOSE] - m_http_sm->milestones[TransactionMilestones::SERVER_CONNECT];
int64_t val = (int64_t)ink_hrtime_to_sec(elapsed);
marshal_int(buf, val);
}
@@ -1116,7 +1118,8 @@ int
LogAccessHttp::marshal_transfer_time_ms(char *buf)
{
if (buf) {
- ink_hrtime elapsed = m_http_sm->milestones.sm_finish - m_http_sm->milestones.sm_start;
+ ink_hrtime elapsed =
+ m_http_sm->milestones[TransactionMilestones::SM_FINISH] - m_http_sm->milestones[TransactionMilestones::SM_START];
int64_t val = (int64_t)ink_hrtime_to_msec(elapsed);
marshal_int(buf, val);
}
@@ -1127,7 +1130,8 @@ int
LogAccessHttp::marshal_transfer_time_s(char *buf)
{
if (buf) {
- ink_hrtime elapsed = m_http_sm->milestones.sm_finish - m_http_sm->milestones.sm_start;
+ ink_hrtime elapsed =
+ m_http_sm->milestones[TransactionMilestones::SM_FINISH] - m_http_sm->milestones[TransactionMilestones::SM_START];
int64_t val = (int64_t)ink_hrtime_to_sec(elapsed);
marshal_int(buf, val);
}
@@ -1372,3 +1376,26 @@ LogAccessHttp::marshal_http_header_field_escapify(LogField::Container container,
return (padded_len);
}
+
+
+int
+LogAccessHttp::marshal_milestone(TransactionMilestones::Milestone ms, char *buf)
+{
+ if (buf) {
+ int64_t val = ink_hrtime_to_msec(m_http_sm->milestones[ms]);
+ marshal_int(buf, val);
+ }
+ return INK_MIN_ALIGN;
+}
+
+
+int
+LogAccessHttp::marshal_milestone_diff(TransactionMilestones::Milestone ms1, TransactionMilestones::Milestone ms2, char *buf)
+{
+ if (buf) {
+ ink_hrtime elapsed = m_http_sm->milestones.elapsed(ms2, ms1);
+ int64_t val = (int64_t)ink_hrtime_to_msec(elapsed);
+ marshal_int(buf, val);
+ }
+ return INK_MIN_ALIGN;
+}
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/LogAccessHttp.h
----------------------------------------------------------------------
diff --git a/proxy/logging/LogAccessHttp.h b/proxy/logging/LogAccessHttp.h
index 93731b8..587a248 100644
--- a/proxy/logging/LogAccessHttp.h
+++ b/proxy/logging/LogAccessHttp.h
@@ -141,6 +141,9 @@ public:
virtual int marshal_http_header_field(LogField::Container container, char *field, char *buf);
virtual int marshal_http_header_field_escapify(LogField::Container container, char *field, char *buf);
+ virtual int marshal_milestone(TransactionMilestones::Milestone ms, char *buf);
+ virtual int marshal_milestone_diff(TransactionMilestones::Milestone ms1, TransactionMilestones::Milestone ms2, char *buf);
+
virtual void set_client_req_url(char *, int); // STR
virtual void set_client_req_url_canon(char *, int); // STR
virtual void set_client_req_unmapped_url_canon(char *, int); // STR
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/LogField.cc
----------------------------------------------------------------------
diff --git a/proxy/logging/LogField.cc b/proxy/logging/LogField.cc
index 64d01b0..d99ab54 100644
--- a/proxy/logging/LogField.cc
+++ b/proxy/logging/LogField.cc
@@ -37,7 +37,7 @@
#include "Log.h"
const char *container_names[] = {"not-a-container", "cqh", "psh", "pqh", "ssh", "cssh", "ecqh", "epsh", "epqh", "essh", "ecssh",
- "icfg", "scfg", "record", ""};
+ "icfg", "scfg", "record", "ms", "msdms", ""};
const char *aggregate_names[] = {"not-an-agg-op", "COUNT", "SUM", "AVG", "FIRST", "LAST", ""};
@@ -119,11 +119,60 @@ LogSlice::toStrOffset(int strlen, int *offset)
LogField::LogField
-------------------------------------------------------------------------*/
+struct cmp_str {
+ bool operator()(ts::ConstBuffer a, ts::ConstBuffer b) { return memcmp(a._ptr, b._ptr, MAX(a._size, b._size)) < 0; }
+};
+
+typedef std::map<ts::ConstBuffer, TransactionMilestones::Milestone, cmp_str> milestone_map;
+static milestone_map m_milestone_map;
+
+struct milestone {
+ const char *msname;
+ TransactionMilestones::Milestone mstype;
+};
+
+static const milestone milestones[] = {
+ {"TS_MILESTONE_UA_BEGIN", TransactionMilestones::UA_BEGIN},
+ {"TS_MILESTONE_UA_FIRST_READ", TransactionMilestones::UA_FIRST_READ},
+ {"TS_MILESTONE_UA_READ_HEADER_DONE", TransactionMilestones::UA_READ_HEADER_DONE},
+ {"TS_MILESTONE_UA_BEGIN_WRITE", TransactionMilestones::UA_BEGIN_WRITE},
+ {"TS_MILESTONE_UA_CLOSE", TransactionMilestones::UA_CLOSE},
+ {"TS_MILESTONE_SERVER_FIRST_CONNECT", TransactionMilestones::SERVER_FIRST_CONNECT},
+ {"TS_MILESTONE_SERVER_CONNECT", TransactionMilestones::SERVER_CONNECT},
+ {"TS_MILESTONE_SERVER_CONNECT_END", TransactionMilestones::SERVER_CONNECT_END},
+ {"TS_MILESTONE_SERVER_BEGIN_WRITE", TransactionMilestones::SERVER_BEGIN_WRITE},
+ {"TS_MILESTONE_SERVER_FIRST_READ", TransactionMilestones::SERVER_FIRST_READ},
+ {"TS_MILESTONE_SERVER_READ_HEADER_DONE", TransactionMilestones::SERVER_READ_HEADER_DONE},
+ {"TS_MILESTONE_SERVER_CLOSE", TransactionMilestones::SERVER_CLOSE},
+ {"TS_MILESTONE_CACHE_OPEN_READ_BEGIN", TransactionMilestones::CACHE_OPEN_READ_BEGIN},
+ {"TS_MILESTONE_CACHE_OPEN_READ_END", TransactionMilestones::CACHE_OPEN_READ_END},
+ {"TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN", TransactionMilestones::CACHE_OPEN_WRITE_BEGIN},
+ {"TS_MILESTONE_CACHE_OPEN_WRITE_END", TransactionMilestones::CACHE_OPEN_WRITE_END},
+ {"TS_MILESTONE_DNS_LOOKUP_BEGIN", TransactionMilestones::DNS_LOOKUP_BEGIN},
+ {"TS_MILESTONE_DNS_LOOKUP_END", TransactionMilestones::DNS_LOOKUP_END},
+ {"TS_MILESTONE_SM_START", TransactionMilestones::SM_START},
+ {"TS_MILESTONE_SM_FINISH", TransactionMilestones::SM_FINISH},
+ {"TS_MILESTONE_PLUGIN_ACTIVE", TransactionMilestones::PLUGIN_ACTIVE},
+ {"TS_MILESTONE_PLUGIN_TOTAL", TransactionMilestones::PLUGIN_TOTAL},
+};
+
+void
+LogField::init_milestone_container(void)
+{
+ if (m_milestone_map.empty()) {
+ for (unsigned i = 0; i < countof(milestones); ++i) {
+ m_milestone_map.insert(
+ std::make_pair(ts::ConstBuffer(milestones[i].msname, strlen(milestones[i].msname)), milestones[i].mstype));
+ }
+ }
+}
+
// Generic field ctor
LogField::LogField(const char *name, const char *symbol, Type type, MarshalFunc marshal, UnmarshalFunc unmarshal, SetFunc _setfunc)
: m_name(ats_strdup(name)), m_symbol(ats_strdup(symbol)), m_type(type), m_container(NO_CONTAINER), m_marshal_func(marshal),
m_unmarshal_func(unmarshal), m_unmarshal_func_map(NULL), m_agg_op(NO_AGGREGATE), m_agg_cnt(0), m_agg_val(0),
- m_time_field(false), m_alias_map(0), m_set_func(_setfunc)
+ m_milestone1(TransactionMilestones::LAST_ENTRY), m_milestone2(TransactionMilestones::LAST_ENTRY), m_time_field(false),
+ m_alias_map(0), m_set_func(_setfunc)
{
ink_assert(m_name != NULL);
ink_assert(m_symbol != NULL);
@@ -138,7 +187,8 @@ LogField::LogField(const char *name, const char *symbol, Type type, MarshalFunc
Ptr<LogFieldAliasMap> map, SetFunc _setfunc)
: m_name(ats_strdup(name)), m_symbol(ats_strdup(symbol)), m_type(type), m_container(NO_CONTAINER), m_marshal_func(marshal),
m_unmarshal_func(NULL), m_unmarshal_func_map(unmarshal), m_agg_op(NO_AGGREGATE), m_agg_cnt(0), m_agg_val(0),
- m_time_field(false), m_alias_map(map), m_set_func(_setfunc)
+ m_milestone1(TransactionMilestones::LAST_ENTRY), m_milestone2(TransactionMilestones::LAST_ENTRY), m_time_field(false),
+ m_alias_map(map), m_set_func(_setfunc)
{
ink_assert(m_name != NULL);
ink_assert(m_symbol != NULL);
@@ -150,11 +200,50 @@ LogField::LogField(const char *name, const char *symbol, Type type, MarshalFunc
strcmp(m_symbol, "cqtn") == 0 || strcmp(m_symbol, "cqtd") == 0 || strcmp(m_symbol, "cqtt") == 0);
}
+TransactionMilestones::Milestone
+LogField::milestone_from_m_name()
+{
+ milestone_map::iterator it;
+ TransactionMilestones::Milestone result = TransactionMilestones::LAST_ENTRY;
+
+ it = m_milestone_map.find(ts::ConstBuffer(m_name, strlen(m_name)));
+ if (it != m_milestone_map.end())
+ result = it->second;
+
+ return result;
+}
+
+int
+LogField::milestones_from_m_name(TransactionMilestones::Milestone *ms1, TransactionMilestones::Milestone *ms2)
+{
+ milestone_map::iterator it;
+ ts::ConstBuffer ms1_name, ms2_name(m_name, strlen(m_name));
+
+ ms1_name = ms2_name.splitOn('-');
+
+ it = m_milestone_map.find(ms1_name);
+ if (it != m_milestone_map.end()) {
+ *ms1 = it->second;
+ } else {
+ return -1;
+ }
+
+ it = m_milestone_map.find(ms2_name);
+ if (it != m_milestone_map.end()) {
+ *ms2 = it->second;
+ } else {
+ return -1;
+ }
+
+ return 0;
+}
+
// Container field ctor
LogField::LogField(const char *field, Container container, SetFunc _setfunc)
: m_name(ats_strdup(field)), m_symbol(ats_strdup(container_names[container])), m_type(LogField::STRING), m_container(container),
m_marshal_func(NULL), m_unmarshal_func(NULL), m_unmarshal_func_map(NULL), m_agg_op(NO_AGGREGATE), m_agg_cnt(0), m_agg_val(0),
- m_time_field(false), m_alias_map(0), m_set_func(_setfunc)
+ m_milestone1(TransactionMilestones::LAST_ENTRY), m_milestone2(TransactionMilestones::LAST_ENTRY), m_time_field(false),
+ m_alias_map(0), m_set_func(_setfunc)
{
ink_assert(m_name != NULL);
ink_assert(m_symbol != NULL);
@@ -186,6 +275,21 @@ LogField::LogField(const char *field, Container container, SetFunc _setfunc)
m_unmarshal_func = &(LogAccess::unmarshal_record);
break;
+ case MS:
+ m_milestone1 = milestone_from_m_name();
+ if (TransactionMilestones::LAST_ENTRY == m_milestone1)
+ Note("Invalid milestone name in LogField ctor: %s", m_name);
+ m_unmarshal_func = &(LogAccess::unmarshal_int_to_str);
+ break;
+
+ case MSDMS: {
+ int rv = milestones_from_m_name(&m_milestone1, &m_milestone2);
+ if (0 != rv)
+ Note("Invalid milestone range in LogField ctor: %s", m_name);
+ m_unmarshal_func = &(LogAccess::unmarshal_int_to_str);
+ break;
+ }
+
default:
Note("Invalid container type in LogField ctor: %d", container);
}
@@ -195,7 +299,8 @@ LogField::LogField(const char *field, Container container, SetFunc _setfunc)
LogField::LogField(const LogField &rhs)
: m_name(ats_strdup(rhs.m_name)), m_symbol(ats_strdup(rhs.m_symbol)), m_type(rhs.m_type), m_container(rhs.m_container),
m_marshal_func(rhs.m_marshal_func), m_unmarshal_func(rhs.m_unmarshal_func), m_unmarshal_func_map(rhs.m_unmarshal_func_map),
- m_agg_op(rhs.m_agg_op), m_agg_cnt(0), m_agg_val(0), m_time_field(rhs.m_time_field), m_alias_map(rhs.m_alias_map),
+ m_agg_op(rhs.m_agg_op), m_agg_cnt(0), m_agg_val(0), m_milestone1(TransactionMilestones::LAST_ENTRY),
+ m_milestone2(TransactionMilestones::LAST_ENTRY), m_time_field(rhs.m_time_field), m_alias_map(rhs.m_alias_map),
m_set_func(rhs.m_set_func)
{
ink_assert(m_name != NULL);
@@ -250,6 +355,12 @@ LogField::marshal_len(LogAccess *lad)
case RECORD:
return lad->marshal_record(m_name, NULL);
+ case MS:
+ return lad->marshal_milestone(m_milestone1, NULL);
+
+ case MSDMS:
+ return lad->marshal_milestone_diff(m_milestone1, m_milestone2, NULL);
+
default:
return 0;
}
@@ -300,6 +411,12 @@ LogField::marshal(LogAccess *lad, char *buf)
case RECORD:
return lad->marshal_record(m_name, buf);
+ case MS:
+ return lad->marshal_milestone(m_milestone1, buf);
+
+ case MSDMS:
+ return lad->marshal_milestone_diff(m_milestone1, m_milestone2, buf);
+
default:
return 0;
}
@@ -439,7 +556,6 @@ LogField::update_aggregate(int64_t val)
m_symbol, val, m_agg_val, m_agg_cnt);
}
-
LogField::Container
LogField::valid_container_name(char *name)
{
@@ -467,10 +583,13 @@ LogField::valid_aggregate_name(char *name)
bool
LogField::fieldlist_contains_aggregates(char *fieldlist)
{
+ char *match;
bool contains_aggregates = false;
for (int i = 1; i < LogField::N_AGGREGATES; i++) {
- if (strstr(fieldlist, aggregate_names[i]) != NULL) {
- contains_aggregates = true;
+ if ((match = strstr(fieldlist, aggregate_names[i])) != NULL) {
+ // verify that the aggregate string is not part of a container field name.
+ if ((strchr(fieldlist, '{') == NULL) && (strchr(match, '}') == NULL))
+ contains_aggregates = true;
}
}
return contains_aggregates;
http://git-wip-us.apache.org/repos/asf/trafficserver/blob/29c26cd6/proxy/logging/LogField.h
----------------------------------------------------------------------
diff --git a/proxy/logging/LogField.h b/proxy/logging/LogField.h
index 09562da..eea38d8 100644
--- a/proxy/logging/LogField.h
+++ b/proxy/logging/LogField.h
@@ -27,6 +27,7 @@
#include "libts.h"
#include "LogFieldAliasMap.h"
+#include "StatSystem.h"
class LogAccess;
@@ -103,6 +104,8 @@ public:
ICFG,
SCFG,
RECORD,
+ MS,
+ MSDMS,
N_CONTAINERS,
};
@@ -167,6 +170,7 @@ public:
void set_aggregate_op(Aggregate agg_op);
void update_aggregate(int64_t val);
+ static void init_milestone_container(void);
static Container valid_container_name(char *name);
static Aggregate valid_aggregate_name(char *name);
static bool fieldlist_contains_aggregates(char *fieldlist);
@@ -182,9 +186,13 @@ private:
Aggregate m_agg_op;
int64_t m_agg_cnt;
int64_t m_agg_val;
+ TransactionMilestones::Milestone m_milestone1; ///< Used for MS and MSDMS as the first (or only) milestone.
+ TransactionMilestones::Milestone m_milestone2; ///< Second milestone for MSDMS
bool m_time_field;
Ptr<LogFieldAliasMap> m_alias_map; // map sINT <--> string
SetFunc m_set_func;
+ TransactionMilestones::Milestone milestone_from_m_name();
+ int milestones_from_m_name(TransactionMilestones::Milestone *m1, TransactionMilestones::Milestone *m2);
public:
LINK(LogField, link);