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 <[email protected]> Authored: Tue Jun 16 22:38:27 2015 -0700 Committer: Alan M. Carroll <[email protected]> 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);
