Repository: trafficserver Updated Branches: refs/heads/master 17b83c839 -> 0ebf6e5ac
TS-3115: add server response time logging fields Add log tags for the time it took to retrieve an object from the origin. This closes #124. Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo Commit: http://git-wip-us.apache.org/repos/asf/trafficserver/commit/0ebf6e5a Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/0ebf6e5a Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/0ebf6e5a Branch: refs/heads/master Commit: 0ebf6e5ac120f1b382700e416c33170a9de7d604 Parents: 17b83c8 Author: Acácio Centeno <[email protected]> Authored: Mon Oct 27 10:23:14 2014 -0700 Committer: James Peach <[email protected]> Committed: Mon Oct 27 10:52:08 2014 -0700 ---------------------------------------------------------------------- CHANGES | 3 +++ doc/admin/event-logging-formats.en.rst | 33 +++++++++++++++++++++++++---- proxy/logging/Log.cc | 28 ++++++++++++++++++++++++ proxy/logging/LogAccess.cc | 15 +++++++++++++ proxy/logging/LogAccess.h | 2 ++ proxy/logging/LogAccessHttp.cc | 30 ++++++++++++++++++++++---- proxy/logging/LogAccessHttp.h | 2 ++ 7 files changed, 105 insertions(+), 8 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/CHANGES ---------------------------------------------------------------------- diff --git a/CHANGES b/CHANGES index 90eaef3..4d733f9 100644 --- a/CHANGES +++ b/CHANGES @@ -1,6 +1,9 @@ -*- coding: utf-8 -*- Changes with Apache Traffic Server 5.2.0 + *) [TS-3115] Add server response time logging fields. + Author: Acácio Centeno <[email protected]> + *) [TS-3154] Add proxy port access log tag as 'php'. Author: Acácio Centeno <[email protected]> http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/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 67f8dc1..3f56c10 100644 --- a/doc/admin/event-logging-formats.en.rst +++ b/doc/admin/event-logging-formats.en.rst @@ -26,7 +26,6 @@ Rather than just reading about those formats, you may also want to try our `online event log builder <http://trafficserver.apache.org/logbuilder/>`_ for an interactive way of building and understanding log formats. - .. toctree:: :maxdepth: 2 @@ -398,6 +397,34 @@ The following list describes Traffic Server custom logging fields. ``sssc`` The HTTP response status code from origin server to Traffic Server. +.. _stms: + +``stms`` + The time spent accessing the origin (in milliseconds); the time is + measured from the time the connection with the origin is established + to the time the connection is closed. + +.. _stmsh: + +``stmsh`` + Same as ``stms`` but in hexadecimal. + +.. _stmsf: + +``stmsf`` + The time Traffic Server spends accessing the origin as a fractional + number of seconds. That is, the time is formated as a floating-point + number, instead of an integer as in ``stms``. + + For example: if the time is 1500 milliseconds, then this field + displays 1.5 while the ``stms`` field displays 1500 and the ``sts`` + field displays 1. + +.. _sts: + +``sts`` + The time Traffic Server spends accessing the origin, in seconds. + .. _ttms: ``ttms`` @@ -432,7 +459,6 @@ The following list describes Traffic Server custom logging fields. the connection with Traffic Server and the time at which Traffic Server sends the last byte of the response back to the client. - .. _logging-format-cross-reference: Logging Format Cross-Reference @@ -529,10 +555,9 @@ Netscape Extended-2 Field Symbols ``h2`` ``pshl`` ``h3`` ``pqhl`` ``h4`` ``sshl`` -``xt`` ``tts`` +``xt`` ``tts`` ``route`` ``phr`` ``pfs`` ``cfsc`` ``ss`` ``pfsc`` ``crc`` ``crc`` =================== ============= - http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/proxy/logging/Log.cc ---------------------------------------------------------------------- diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc index 75d5f0f..c4b8fa6 100644 --- a/proxy/logging/Log.cc +++ b/proxy/logging/Log.cc @@ -776,6 +776,34 @@ Log::init_fields() global_field_list.add(field, false); ink_hash_table_insert(field_symbol_hash, "sshv", field); + field = new LogField("server_resp_time", "stms", + LogField::sINT, + &LogAccess::marshal_server_resp_time_ms, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + ink_hash_table_insert(field_symbol_hash, "stms", field); + + field = new LogField("server_resp_time_hex", "stmsh", + LogField::sINT, + &LogAccess::marshal_server_resp_time_ms, + &LogAccess::unmarshal_int_to_str_hex); + global_field_list.add(field, false); + ink_hash_table_insert(field_symbol_hash, "stmsh", field); + + field = new LogField("server_resp_time_fractional", "stmsf", + LogField::sINT, + &LogAccess::marshal_server_resp_time_ms, + &LogAccess::unmarshal_ttmsf); + global_field_list.add(field, false); + ink_hash_table_insert(field_symbol_hash, "stmsf", field); + + field = new LogField("server_resp_time_sec", "sts", + LogField::sINT, + &LogAccess::marshal_server_resp_time_s, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + ink_hash_table_insert(field_symbol_hash, "sts", field); + field = new LogField("cached_resp_status_code", "csssc", LogField::sINT, &LogAccess::marshal_cache_resp_status_code, http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/proxy/logging/LogAccess.cc ---------------------------------------------------------------------- diff --git a/proxy/logging/LogAccess.cc b/proxy/logging/LogAccess.cc index cef23e1..17cfed8 100644 --- a/proxy/logging/LogAccess.cc +++ b/proxy/logging/LogAccess.cc @@ -448,6 +448,21 @@ LogAccess::marshal_server_resp_http_version(char *buf) } /*------------------------------------------------------------------------- +-------------------------------------------------------------------------*/ +int +LogAccess::marshal_server_resp_time_ms(char *buf) +{ + DEFAULT_INT_FIELD; +} + +int +LogAccess::marshal_server_resp_time_s(char *buf) +{ + DEFAULT_INT_FIELD; +} + + +/*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ int http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/proxy/logging/LogAccess.h ---------------------------------------------------------------------- diff --git a/proxy/logging/LogAccess.h b/proxy/logging/LogAccess.h index b970750..9b1a615 100644 --- a/proxy/logging/LogAccess.h +++ b/proxy/logging/LogAccess.h @@ -218,6 +218,8 @@ public: inkcoreapi virtual int marshal_server_resp_content_len(char *); // INT inkcoreapi virtual int marshal_server_resp_header_len(char *); // INT inkcoreapi virtual int marshal_server_resp_http_version(char *); // INT + inkcoreapi virtual int marshal_server_resp_time_ms(char *); // INT + inkcoreapi virtual int marshal_server_resp_time_s(char *); // INT // // cache -> client fields http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/proxy/logging/LogAccessHttp.cc ---------------------------------------------------------------------- diff --git a/proxy/logging/LogAccessHttp.cc b/proxy/logging/LogAccessHttp.cc index a1a673e..9b41850 100644 --- a/proxy/logging/LogAccessHttp.cc +++ b/proxy/logging/LogAccessHttp.cc @@ -900,6 +900,30 @@ LogAccessHttp::marshal_server_resp_http_version(char *buf) } /*------------------------------------------------------------------------- +-------------------------------------------------------------------------*/ +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; + int64_t val = (int64_t)ink_hrtime_to_msec(elapsed); + marshal_int(buf, val); + } + return INK_MIN_ALIGN; +} + +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; + int64_t val = (int64_t)ink_hrtime_to_sec(elapsed); + marshal_int(buf, val); + } + return INK_MIN_ALIGN; +} + +/*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ int @@ -1044,8 +1068,7 @@ LogAccessHttp::marshal_transfer_time_ms(char *buf) { if (buf) { ink_hrtime elapsed = m_http_sm->milestones.sm_finish - m_http_sm->milestones.sm_start; - elapsed /= HRTIME_MSECOND; - int64_t val = (int64_t) elapsed; + int64_t val = (int64_t)ink_hrtime_to_msec(elapsed); marshal_int(buf, val); } return INK_MIN_ALIGN; @@ -1056,8 +1079,7 @@ LogAccessHttp::marshal_transfer_time_s(char *buf) { if (buf) { ink_hrtime elapsed = m_http_sm->milestones.sm_finish - m_http_sm->milestones.sm_start; - elapsed /= HRTIME_SECOND; - int64_t val = (int64_t) elapsed; + int64_t val = (int64_t)ink_hrtime_to_sec(elapsed); marshal_int(buf, val); } return INK_MIN_ALIGN; http://git-wip-us.apache.org/repos/asf/trafficserver/blob/0ebf6e5a/proxy/logging/LogAccessHttp.h ---------------------------------------------------------------------- diff --git a/proxy/logging/LogAccessHttp.h b/proxy/logging/LogAccessHttp.h index 14e8ce8..dc392f5 100644 --- a/proxy/logging/LogAccessHttp.h +++ b/proxy/logging/LogAccessHttp.h @@ -102,6 +102,8 @@ public: virtual int marshal_server_resp_content_len(char *); // INT virtual int marshal_server_resp_header_len(char *); // INT virtual int marshal_server_resp_http_version(char *); // INT + virtual int marshal_server_resp_time_ms(char *); // INT + virtual int marshal_server_resp_time_s(char *); // INT // // cache -> client fields
