trafficserver-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From a..@apache.org
Subject trafficserver git commit: TS-3436: Add API milestones.
Date Wed, 13 May 2015 14:11:52 GMT
Repository: trafficserver
Updated Branches:
  refs/heads/master dda6814f0 -> 5260c4a3a


TS-3436: Add API milestones.


Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo
Commit: http://git-wip-us.apache.org/repos/asf/trafficserver/commit/5260c4a3
Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/5260c4a3
Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/5260c4a3

Branch: refs/heads/master
Commit: 5260c4a3acce4226eee111676b999bae0765aeb1
Parents: dda6814
Author: Alan M. Carroll <amc@apache.org>
Authored: Wed Mar 11 09:09:27 2015 -0500
Committer: Alan M. Carroll <solidwallofcode@yahoo-inc.com>
Committed: Wed May 13 08:59:57 2015 -0500

----------------------------------------------------------------------
 CHANGES                               |  2 ++
 lib/ts/apidefs.h.in                   |  2 ++
 plugins/experimental/xdebug/xdebug.cc |  2 ++
 proxy/InkAPI.cc                       |  6 ++++
 proxy/StatSystem.h                    | 14 ++++++--
 proxy/http/HttpSM.cc                  | 56 ++++++++++++++++++++++++++++--
 proxy/http/HttpSM.h                   |  1 +
 7 files changed, 79 insertions(+), 4 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/CHANGES
----------------------------------------------------------------------
diff --git a/CHANGES b/CHANGES
index e136e4c..af2cdda 100644
--- a/CHANGES
+++ b/CHANGES
@@ -1,6 +1,8 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache Traffic Server 6.0.0
 
+  *) [TS-3436] Add API milestones.
+
   *) [TS-3584] Turn off keep alive for HTTP request headers created from SPDY and H2
 
   *) [TS-2609] Header rewrite plugin *URL:HOST condition

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/lib/ts/apidefs.h.in
----------------------------------------------------------------------
diff --git a/lib/ts/apidefs.h.in b/lib/ts/apidefs.h.in
index 7a15785..3d95688 100644
--- a/lib/ts/apidefs.h.in
+++ b/lib/ts/apidefs.h.in
@@ -720,6 +720,8 @@ typedef enum {
   TS_MILESTONE_DNS_LOOKUP_END,
   TS_MILESTONE_SM_START,
   TS_MILESTONE_SM_FINISH,
+  TS_MILESTONE_PLUGIN_ACTIVE,
+  TS_MILESTONE_PLUGIN_TOTAL,
   TS_MILESTONE_LAST_ENTRY
 } TSMilestonesType;
 

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/plugins/experimental/xdebug/xdebug.cc
----------------------------------------------------------------------
diff --git a/plugins/experimental/xdebug/xdebug.cc b/plugins/experimental/xdebug/xdebug.cc
index 6ec7e62..0fc38b6 100644
--- a/plugins/experimental/xdebug/xdebug.cc
+++ b/plugins/experimental/xdebug/xdebug.cc
@@ -165,6 +165,8 @@ InjectMilestonesHeader(TSHttpTxn txn, TSMBuffer buffer, TSMLoc hdr)
     {TS_MILESTONE_CACHE_OPEN_WRITE_END, "CACHE-OPEN-WRITE-END"},
     {TS_MILESTONE_DNS_LOOKUP_BEGIN, "DNS-LOOKUP-BEGIN"},
     {TS_MILESTONE_DNS_LOOKUP_END, "DNS-LOOKUP-END"},
+    {TS_MILESTONE_PLUGIN_ACTIVE, "PLUGIN-ACTIVE"},
+    {TS_MILESTONE_PLUGIN_TOTAL, "PLUGIN-TOTAL"},
   };
 
   TSMLoc dst = TS_NULL_MLOC;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/proxy/InkAPI.cc
----------------------------------------------------------------------
diff --git a/proxy/InkAPI.cc b/proxy/InkAPI.cc
index cfc1411..53bfb38 100644
--- a/proxy/InkAPI.cc
+++ b/proxy/InkAPI.cc
@@ -5984,6 +5984,12 @@ TSHttpTxnMilestoneGet(TSHttpTxn txnp, TSMilestonesType milestone, ink_hrtime
*ti
   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:
     *time = -1;
     ret = TS_ERROR;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/proxy/StatSystem.h
----------------------------------------------------------------------
diff --git a/proxy/StatSystem.h b/proxy/StatSystem.h
index 401acec..779f384 100644
--- a/proxy/StatSystem.h
+++ b/proxy/StatSystem.h
@@ -50,10 +50,10 @@ class TransactionMilestones
 {
 public:
   TransactionMilestones()
-    : ua_begin(0), ua_first_read(), ua_read_header_done(0), ua_begin_write(0), ua_close(0),
server_first_connect(0),
+    : 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)
+      dns_lookup_begin(0), dns_lookup_end(0), sm_start(0), sm_finish(0), plugin_active(0),
plugin_total(0)
   {
   }
 
@@ -97,6 +97,16 @@ public:
   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;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/proxy/http/HttpSM.cc
----------------------------------------------------------------------
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index 516a8a5..afe9733 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -98,6 +98,41 @@ static const int len_100_continue_response = strlen(str_100_continue_response);
 static const char *str_408_request_timeout_response = "HTTP/1.1 408 Request Timeout\r\nConnection:
close\r\n\r\n";
 static const int len_408_request_timeout_response = strlen(str_408_request_timeout_response);
 
+namespace
+{
+/// Update the milestone state given the milestones and timer.
+inline void
+milestone_update_api_time(TransactionMilestones &milestones, ink_hrtime &api_timer)
+{
+  // Bit of funkiness - we set @a api_timer to be the negative value when we're tracking
+  // non-active API time. In that case we need to make a note of it and flip the value back
+  // to positive.
+  if (api_timer) {
+    ink_hrtime delta;
+    bool active = api_timer >= 0;
+    if (!active)
+      api_timer = -api_timer;
+    delta = ink_get_hrtime() - api_timer;
+    api_timer = 0;
+    // Exactly zero is a problem because we want to signal *something* happened
+    // vs. no API activity at all. This can happen when the API time is less than
+    // the HR timer resolution, so in fact we're understating the time even with
+    // this tweak.
+    if (0 == delta)
+      ++delta;
+
+    if (0 == milestones.plugin_total)
+      milestones.plugin_total = milestones.sm_start;
+    milestones.plugin_total += delta;
+    if (active) {
+      if (0 == milestones.plugin_active)
+        milestones.plugin_active = milestones.sm_start;
+      milestones.plugin_active += delta;
+    }
+  }
+}
+}
+
 void
 HttpSM::_make_scatter_list(HttpSM *prototype)
 {
@@ -1247,6 +1282,8 @@ HttpSM::state_api_callback(int event, void *data)
   ink_assert(reentrancy_count >= 0);
   reentrancy_count++;
 
+  milestone_update_api_time(milestones, api_timer);
+
   STATE_ENTER(&HttpSM::state_api_callback, event);
 
   state_api_callout(event, data);
@@ -1294,6 +1331,7 @@ HttpSM::state_api_callout(int event, void *data)
   case EVENT_INTERVAL:
     ink_assert(pending_action == data);
     pending_action = NULL;
+    milestone_update_api_time(milestones, api_timer);
   // FALLTHROUGH
   case EVENT_NONE:
   case HTTP_API_CONTINUE:
@@ -1340,6 +1378,7 @@ HttpSM::state_api_callout(int event, void *data)
           plugin_lock = MUTEX_TAKE_TRY_LOCK(cur_hook->m_cont->mutex, mutex->thread_holding);
 
           if (!plugin_lock) {
+            api_timer = -ink_get_hrtime();
             HTTP_SM_SET_DEFAULT_HANDLER(&HttpSM::state_api_callout);
             ink_assert(pending_action == NULL);
             pending_action = mutex->thread_holding->schedule_in(this, HRTIME_MSECONDS(10));
@@ -1355,7 +1394,15 @@ HttpSM::state_api_callout(int event, void *data)
         APIHook *hook = cur_hook;
         cur_hook = cur_hook->next();
 
+        api_timer = ink_get_hrtime();
         hook->invoke(TS_EVENT_HTTP_READ_REQUEST_HDR + cur_hook_id, this);
+        if (api_timer > 0) {
+          milestone_update_api_time(milestones, api_timer);
+          api_timer = -ink_get_hrtime(); // set in order to track non-active callout duration
+          // which means that if we get back from the invoke with api_timer < 0 we're
already
+          // tracking a non-complete callout from a chain so just let it ride. It will get
cleaned
+          // up in state_api_callback.
+        }
 
         if (plugin_lock) {
           Mutex_unlock(plugin_mutex, mutex->thread_holding);
@@ -1424,6 +1471,7 @@ HttpSM::state_api_callout(int event, void *data)
   // Now that we're completed with the api state and figured out what
   //   to do next, do it
   callout_state = HTTP_API_NO_CALLOUT;
+  api_timer = 0;
   switch (api_next) {
   case API_RETURN_CONTINUE:
     if (t_state.api_next_action == HttpTransact::SM_ACTION_API_SEND_RESPONSE_HDR) {
@@ -6726,7 +6774,9 @@ HttpSM::update_stats()
           "server_read_header_done: %.3f "
           "server_close: %.3f "
           "ua_close: %.3f "
-          "sm_finish: %.3f",
+          "sm_finish: %.3f "
+          "plugin_active: %.3f "
+          "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),
@@ -6741,7 +6791,9 @@ HttpSM::update_stats()
           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.sm_finish),
+          milestone_difference(milestones.sm_start, milestones.plugin_active),
+          milestone_difference(milestones.sm_start, milestones.plugin_total));
   }
 }
 

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5260c4a3/proxy/http/HttpSM.h
----------------------------------------------------------------------
diff --git a/proxy/http/HttpSM.h b/proxy/http/HttpSM.h
index 852f847..89a7e74 100644
--- a/proxy/http/HttpSM.h
+++ b/proxy/http/HttpSM.h
@@ -496,6 +496,7 @@ public:
   int pushed_response_hdr_bytes;
   int64_t pushed_response_body_bytes;
   TransactionMilestones milestones;
+  ink_hrtime api_timer;
   // The next two enable plugins to tag the state machine for
   // the purposes of logging so the instances can be correlated
   // with the source plugin.


Mime
View raw message