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-1775: General hrtime cleanup. This close #515.
Date Wed, 09 Mar 2016 20:28:21 GMT
Repository: trafficserver
Updated Branches:
  refs/heads/master 954deaf3c -> d95d9e84e


TS-1775: General hrtime cleanup.
This close #515.


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

Branch: refs/heads/master
Commit: d95d9e84e82e7752c0348cfa17a851f4bc914061
Parents: 954deaf
Author: Alan M. Carroll <amc@apache.org>
Authored: Sun Mar 6 11:56:12 2016 -0600
Committer: Alan M. Carroll <amc@apache.org>
Committed: Wed Mar 9 13:54:47 2016 -0600

----------------------------------------------------------------------
 iocore/aio/AIO.cc                         |  4 +-
 iocore/cache/CacheDir.cc                  |  8 ++--
 iocore/eventsystem/I_Thread.h             | 28 ++++++++++++++
 iocore/eventsystem/PQ-List.cc             |  2 +-
 iocore/eventsystem/P_UnixEventProcessor.h |  4 +-
 iocore/eventsystem/Thread.cc              |  6 ---
 iocore/eventsystem/UnixEThread.cc         |  8 ++--
 iocore/eventsystem/UnixEventProcessor.cc  |  2 +-
 iocore/net/SSLNetVConnection.cc           |  2 +-
 iocore/net/UnixNetVConnection.cc          |  2 +-
 iocore/net/UnixUDPNet.cc                  | 14 +++----
 lib/ts/ink_hrtime.h                       | 53 +++-----------------------
 proxy/TestDNS.cc                          | 10 ++---
 proxy/http/HttpSM.cc                      | 41 ++++++++++++--------
 14 files changed, 87 insertions(+), 97 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/aio/AIO.cc
----------------------------------------------------------------------
diff --git a/iocore/aio/AIO.cc b/iocore/aio/AIO.cc
index 3bb6885..3f9f2a8 100644
--- a/iocore/aio/AIO.cc
+++ b/iocore/aio/AIO.cc
@@ -116,7 +116,7 @@ static AIOTestData *data;
 int
 AIOTestData::ink_aio_stats(int event, void *d)
 {
-  ink_hrtime now = ink_get_hrtime();
+  ink_hrtime now = Thread::get_hrtime();
   double time_msec = (double)(now - start) / (double)HRTIME_MSECOND;
   int i = (aio_reqs[0] == NULL) ? 1 : 0;
   for (; i < num_filedes; ++i)
@@ -509,7 +509,7 @@ aio_thread_main(void *arg)
         op->thread->schedule_imm_signal(op);
       ink_mutex_acquire(&my_aio_req->aio_mutex);
     } while (1);
-    timespec timedwait_msec = ink_hrtime_to_timespec(Thread::get_hrtime() + HRTIME_MSECONDS(net_config_poll_timeout));
+    timespec timedwait_msec = ink_hrtime_to_timespec(Thread::get_hrtime_updated() + HRTIME_MSECONDS(net_config_poll_timeout));
     ink_cond_timedwait(&my_aio_req->aio_cond, &my_aio_req->aio_mutex, &timedwait_msec);
   }
   return 0;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/cache/CacheDir.cc
----------------------------------------------------------------------
diff --git a/iocore/cache/CacheDir.cc b/iocore/cache/CacheDir.cc
index c9a7068..17f4348 100644
--- a/iocore/cache/CacheDir.cc
+++ b/iocore/cache/CacheDir.cc
@@ -1425,25 +1425,25 @@ EXCLUSIVE_REGRESSION_TEST(Cache_dir)(RegressionTest *t, int /* atype
ATS_UNUSED
   // test insert-delete
   rprintf(t, "insert-delete test\n");
   regress_rand_init(13);
-  ttime = ink_get_hrtime_internal();
+  ttime = Thread::get_hrtime_updated();
   for (i = 0; i < newfree; i++) {
     regress_rand_CacheKey(&key);
     dir_insert(&key, d, &dir);
   }
-  uint64_t us = (ink_get_hrtime_internal() - ttime) / HRTIME_USECOND;
+  uint64_t us = (Thread::get_hrtime_updated() - ttime) / HRTIME_USECOND;
   // On windows us is sometimes 0. I don't know why.
   // printout the insert rate only if its not 0
   if (us)
     rprintf(t, "insert rate = %d / second\n", (int)((newfree * (uint64_t)1000000) / us));
   regress_rand_init(13);
-  ttime = ink_get_hrtime_internal();
+  ttime = Thread::get_hrtime_updated();
   for (i = 0; i < newfree; i++) {
     Dir *last_collision = 0;
     regress_rand_CacheKey(&key);
     if (!dir_probe(&key, d, &dir, &last_collision))
       ret = REGRESSION_TEST_FAILED;
   }
-  us = (ink_get_hrtime_internal() - ttime) / HRTIME_USECOND;
+  us = (Thread::get_hrtime_updated() - ttime) / HRTIME_USECOND;
   // On windows us is sometimes 0. I don't know why.
   // printout the probe rate only if its not 0
   if (us)

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/eventsystem/I_Thread.h
----------------------------------------------------------------------
diff --git a/iocore/eventsystem/I_Thread.h b/iocore/eventsystem/I_Thread.h
index 7d3e74c..abc1726 100644
--- a/iocore/eventsystem/I_Thread.h
+++ b/iocore/eventsystem/I_Thread.h
@@ -157,9 +157,37 @@ public:
   {
   }
 
+  /** Get the current ATS high resolution time.
+      This gets a cached copy of the time so it is very fast and reasonably accurate.
+      The cached time is updated every time the actual operating system time is fetched which
is
+      at least every 10ms and generally more frequently.
+      @note The cached copy shared among threads which means the cached copy is udpated
+      for all threads if any thread updates it.
+  */
   static ink_hrtime get_hrtime();
+
+  /** Get the operating system high resolution time.
+
+      Get the current time at high resolution from the operating system.  This is more expensive
+      than @c get_hrtime and should be used only where very precise timing is required.
+
+      @note This also updates the cached time.
+  */
+  static ink_hrtime get_hrtime_updated();
 };
 
 extern Thread *this_thread();
 
+TS_INLINE ink_hrtime
+Thread::get_hrtime()
+{
+  return cur_time;
+}
+
+TS_INLINE ink_hrtime
+Thread::get_hrtime_updated()
+{
+  return cur_time = ink_get_hrtime_internal();
+}
+
 #endif /*_I_Thread_h*/

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/eventsystem/PQ-List.cc
----------------------------------------------------------------------
diff --git a/iocore/eventsystem/PQ-List.cc b/iocore/eventsystem/PQ-List.cc
index 8d7944d..c3686bf 100644
--- a/iocore/eventsystem/PQ-List.cc
+++ b/iocore/eventsystem/PQ-List.cc
@@ -25,7 +25,7 @@
 
 PriorityEventQueue::PriorityEventQueue()
 {
-  last_check_time = ink_get_based_hrtime_internal();
+  last_check_time = Thread::get_hrtime_updated();
   last_check_buckets = last_check_time / PQ_BUCKET_TIME(0);
 }
 

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/eventsystem/P_UnixEventProcessor.h
----------------------------------------------------------------------
diff --git a/iocore/eventsystem/P_UnixEventProcessor.h b/iocore/eventsystem/P_UnixEventProcessor.h
index 55bf4a8..21be1bc 100644
--- a/iocore/eventsystem/P_UnixEventProcessor.h
+++ b/iocore/eventsystem/P_UnixEventProcessor.h
@@ -90,7 +90,7 @@ EventProcessor::schedule_imm_signal(Continuation *cont, EventType et, int
callba
 
   ink_assert(et < MAX_EVENT_TYPES);
 #ifdef ENABLE_TIME_TRACE
-  e->start_time = ink_get_hrtime();
+  e->start_time = Thread::get_hrtime();
 #endif
   e->callback_event = callback_event;
   e->cookie = cookie;
@@ -104,7 +104,7 @@ EventProcessor::schedule_imm(Continuation *cont, EventType et, int callback_even
 
   ink_assert(et < MAX_EVENT_TYPES);
 #ifdef ENABLE_TIME_TRACE
-  e->start_time = ink_get_hrtime();
+  e->start_time = Thread::get_hrtime();
 #endif
   e->callback_event = callback_event;
   e->cookie = cookie;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/eventsystem/Thread.cc
----------------------------------------------------------------------
diff --git a/iocore/eventsystem/Thread.cc b/iocore/eventsystem/Thread.cc
index 41b17ca..03af6db 100644
--- a/iocore/eventsystem/Thread.cc
+++ b/iocore/eventsystem/Thread.cc
@@ -102,9 +102,3 @@ Thread::start(const char *name, size_t stacksize, ThreadFunction f, void
*a)
 
   return tid;
 }
-
-ink_hrtime
-Thread::get_hrtime()
-{
-  return Thread::cur_time;
-}

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/eventsystem/UnixEThread.cc
----------------------------------------------------------------------
diff --git a/iocore/eventsystem/UnixEThread.cc b/iocore/eventsystem/UnixEThread.cc
index e178930..8af5c98 100644
--- a/iocore/eventsystem/UnixEThread.cc
+++ b/iocore/eventsystem/UnixEThread.cc
@@ -42,14 +42,14 @@ struct AIOCallback;
 bool shutdown_event_system = false;
 
 EThread::EThread()
-  : generator((uint64_t)ink_get_hrtime_internal() ^ (uint64_t)(uintptr_t) this), ethreads_to_be_signalled(NULL),
+  : generator((uint64_t)Thread::get_hrtime_updated() ^ (uint64_t)(uintptr_t) this), ethreads_to_be_signalled(NULL),
     n_ethreads_to_be_signalled(0), main_accept_index(-1), id(NO_ETHREAD_ID), event_types(0),
signal_hook(0), tt(REGULAR)
 {
   memset(thread_private, 0, PER_THREAD_DATA);
 }
 
 EThread::EThread(ThreadType att, int anid)
-  : generator((uint64_t)ink_get_hrtime_internal() ^ (uint64_t)(uintptr_t) this), ethreads_to_be_signalled(NULL),
+  : generator((uint64_t)Thread::get_hrtime_updated() ^ (uint64_t)(uintptr_t) this), ethreads_to_be_signalled(NULL),
     n_ethreads_to_be_signalled(0), main_accept_index(-1), id(anid), event_types(0), signal_hook(0),
tt(att),
     server_session_pool(NULL)
 {
@@ -136,7 +136,7 @@ EThread::process_event(Event *e, int calling_code)
         if (e->period < 0)
           e->timeout_at = e->period;
         else {
-          cur_time = get_hrtime();
+          this->get_hrtime_updated();
           e->timeout_at = cur_time + e->period;
           if (e->timeout_at < cur_time)
             e->timeout_at = cur_time;
@@ -175,7 +175,7 @@ EThread::execute()
       }
       // execute all the available external events that have
       // already been dequeued
-      cur_time = ink_get_based_hrtime_internal();
+      cur_time = Thread::get_hrtime_updated();
       while ((e = EventQueueExternal.dequeue_local())) {
         if (e->cancelled)
           free_event(e);

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/eventsystem/UnixEventProcessor.cc
----------------------------------------------------------------------
diff --git a/iocore/eventsystem/UnixEventProcessor.cc b/iocore/eventsystem/UnixEventProcessor.cc
index a7d5395..7711965 100644
--- a/iocore/eventsystem/UnixEventProcessor.cc
+++ b/iocore/eventsystem/UnixEventProcessor.cc
@@ -85,7 +85,7 @@ EventProcessor::start(int n_event_threads, size_t stacksize)
     if (i == 0) {
       ink_thread_setspecific(Thread::thread_data_key, t);
       global_mutex = t->mutex;
-      t->cur_time = ink_get_based_hrtime_internal();
+      Thread::get_hrtime_updated();
     }
     all_ethreads[i] = t;
 

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/net/SSLNetVConnection.cc
----------------------------------------------------------------------
diff --git a/iocore/net/SSLNetVConnection.cc b/iocore/net/SSLNetVConnection.cc
index bb81687..9373405 100644
--- a/iocore/net/SSLNetVConnection.cc
+++ b/iocore/net/SSLNetVConnection.cc
@@ -698,7 +698,7 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, int64_t &wattempted,
i
   // Dynamic TLS record sizing
   ink_hrtime now = 0;
   if (SSLConfigParams::ssl_maxrecord == -1) {
-    now = ink_get_hrtime_internal();
+    now = Thread::get_hrtime_updated();
     int msec_since_last_write = ink_hrtime_diff_msec(now, sslLastWriteTime);
 
     if (msec_since_last_write > SSL_DEF_TLS_RECORD_MSEC_THRESHOLD) {

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/net/UnixNetVConnection.cc
----------------------------------------------------------------------
diff --git a/iocore/net/UnixNetVConnection.cc b/iocore/net/UnixNetVConnection.cc
index e235bc7..3da42ab 100644
--- a/iocore/net/UnixNetVConnection.cc
+++ b/iocore/net/UnixNetVConnection.cc
@@ -1163,7 +1163,7 @@ UnixNetVConnection::mainEvent(int event, Event *e)
   if (event == EVENT_IMMEDIATE) {
     /* BZ 49408 */
     // ink_assert(inactivity_timeout_in);
-    // ink_assert(next_inactivity_timeout_at < ink_get_hrtime());
+    // ink_assert(next_inactivity_timeout_at < Thread::get_hrtime());
     if (!inactivity_timeout_in || next_inactivity_timeout_at > Thread::get_hrtime())
       return EVENT_CONT;
     signal_event = VC_EVENT_INACTIVITY_TIMEOUT;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/iocore/net/UnixUDPNet.cc
----------------------------------------------------------------------
diff --git a/iocore/net/UnixUDPNet.cc b/iocore/net/UnixUDPNet.cc
index b4dd8c1..3c460b2 100644
--- a/iocore/net/UnixUDPNet.cc
+++ b/iocore/net/UnixUDPNet.cc
@@ -630,7 +630,7 @@ void
 UDPQueue::service(UDPNetHandler *nh)
 {
   (void)nh;
-  ink_hrtime now = ink_get_hrtime_internal();
+  ink_hrtime now = Thread::get_hrtime_updated();
   uint64_t timeSpent = 0;
   uint64_t pktSendStartTime;
   UDPPacketInternal *p;
@@ -684,8 +684,8 @@ void
 UDPQueue::SendPackets()
 {
   UDPPacketInternal *p;
-  static ink_hrtime lastCleanupTime = ink_get_hrtime_internal();
-  ink_hrtime now = ink_get_hrtime_internal();
+  static ink_hrtime lastCleanupTime = Thread::get_hrtime_updated();
+  ink_hrtime now = Thread::get_hrtime_updated();
   ink_hrtime send_threshold_time = now + SLOT_TIME;
   int32_t bytesThisSlot = INT_MAX, bytesUsed = 0;
   int32_t bytesThisPipe, sentOne;
@@ -721,7 +721,7 @@ sendPackets:
 
   if ((bytesThisSlot > 0) && sentOne) {
     // redistribute the slack...
-    now = ink_get_hrtime_internal();
+    now = Thread::get_hrtime_updated();
     if (pipeInfo.firstPacket(now) == NULL) {
       pipeInfo.advanceNow(now);
     }
@@ -797,7 +797,7 @@ UDPNetHandler::UDPNetHandler()
   mutex = new_ProxyMutex();
   ink_atomiclist_init(&udpOutQueue.atomicQueue, "Outgoing UDP Packet queue", offsetof(UDPPacketInternal,
alink.next));
   ink_atomiclist_init(&udpNewConnections, "UDP Connection queue", offsetof(UnixUDPConnection,
newconn_alink.next));
-  nextCheck = ink_get_hrtime_internal() + HRTIME_MSECONDS(1000);
+  nextCheck = Thread::get_hrtime_updated() + HRTIME_MSECONDS(1000);
   lastCheck = 0;
   SET_HANDLER((UDPNetContHandler)&UDPNetHandler::startNetEvent);
 }
@@ -847,7 +847,7 @@ UDPNetHandler::mainNetEvent(int event, Event *e)
   }   // end for
 
   // remove dead UDP connections
-  ink_hrtime now = ink_get_hrtime_internal();
+  ink_hrtime now = Thread::get_hrtime_updated();
   if (now >= nextCheck) {
     for (uc = udp_polling.head; uc; uc = next) {
       ink_assert(uc->mutex && uc->continuation);
@@ -859,7 +859,7 @@ UDPNetHandler::mainNetEvent(int event, Event *e)
         uc->Release();
       }
     }
-    nextCheck = ink_get_hrtime_internal() + HRTIME_MSECONDS(1000);
+    nextCheck = Thread::get_hrtime_updated() + HRTIME_MSECONDS(1000);
   }
   // service UDPConnections with data ready for callback.
   Que(UnixUDPConnection, callback_link) q = udp_callbacks;

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/lib/ts/ink_hrtime.h
----------------------------------------------------------------------
diff --git a/lib/ts/ink_hrtime.h b/lib/ts/ink_hrtime.h
index f084948..9e76deb 100644
--- a/lib/ts/ink_hrtime.h
+++ b/lib/ts/ink_hrtime.h
@@ -44,30 +44,6 @@ char *int64_to_str(char *buf, unsigned int buf_size, int64_t val, unsigned
int *
 
 //////////////////////////////////////////////////////////////////////////////
 //
-// Time Stamp Counter
-//
-//////////////////////////////////////////////////////////////////////////////
-#ifdef USE_TIME_STAMP_COUNTER_HRTIME
-extern ink_hrtime init_hrtime_TSC();
-extern uint32_t hrtime_freq;
-extern double hrtime_freq_float;
-static inline ink_hrtime
-hrtime_rdtsc()
-{
-  ink_hrtime rv;
-  asm volatile(".byte 0x0f, 0x31" : "=A"(rv));
-  return (rv);
-}
-static inline uint64_t
-get_hrtime_rdtsc()
-{
-  // do it fixed point if you have better hardware support
-  return (uint64_t)(hrtime_freq_float * hrtime_rdtsc());
-}
-#endif
-
-//////////////////////////////////////////////////////////////////////////////
-//
 //      Factors to multiply units by to obtain coresponding ink_hrtime values.
 //
 //////////////////////////////////////////////////////////////////////////////
@@ -82,7 +58,7 @@ get_hrtime_rdtsc()
 #define HRTIME_SECOND (1000 * HRTIME_MSECOND)
 #define HRTIME_MSECOND (1000 * HRTIME_USECOND)
 #define HRTIME_USECOND (1000 * HRTIME_NSECOND)
-#define HRTIME_NSECOND (1LL)
+#define HRTIME_NSECOND (static_cast<ink_hrtime>(1))
 
 #define HRTIME_APPROX_SECONDS(_x) ((_x) >> 30) // off by 7.3%
 #define HRTIME_APPROX_FACTOR (((float)(1 << 30)) / (((float)HRTIME_SECOND)))
@@ -248,9 +224,7 @@ ink_hrtime_to_timeval2(ink_hrtime t, struct timeval *tv)
 static inline ink_hrtime
 ink_get_hrtime_internal()
 {
-#if defined(USE_TIME_STAMP_COUNTER_HRTIME)
-  return get_hrtime_rdtsc();
-#elif defined(freebsd)
+#if defined(freebsd) || HAVE_CLOCK_GETTIME
   timespec ts;
   clock_gettime(CLOCK_REALTIME, &ts);
   return ink_hrtime_from_timespec(&ts);
@@ -261,39 +235,22 @@ ink_get_hrtime_internal()
 #endif
 }
 
-static inline ink_hrtime
-ink_get_based_hrtime_internal()
-{
-#if defined(USE_TIME_STAMP_COUNTER_HRTIME)
-  return hrtime_offset + ink_get_hrtime_internal();
-#elif !HAVE_CLOCK_GETTIME
-  timeval tv;
-  gettimeofday(&tv, NULL);
-  return ink_hrtime_from_timeval(&tv);
-#else
-  timespec ts;
-  clock_gettime(CLOCK_REALTIME, &ts);
-  return ink_hrtime_from_timespec(&ts);
-#endif
-}
-
-
 static inline struct timeval
 ink_gettimeofday()
 {
-  return ink_hrtime_to_timeval(ink_get_based_hrtime_internal());
+  return ink_hrtime_to_timeval(ink_get_hrtime_internal());
 }
 
 static inline int
 ink_gethrtimeofday(struct timeval *tp, void *)
 {
-  return ink_hrtime_to_timeval2(ink_get_based_hrtime_internal(), tp);
+  return ink_hrtime_to_timeval2(ink_get_hrtime_internal(), tp);
 }
 
 static inline int
 ink_time()
 {
-  return (int)ink_hrtime_to_sec(ink_get_based_hrtime_internal());
+  return (int)ink_hrtime_to_sec(ink_get_hrtime_internal());
 }
 
 static inline int

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/proxy/TestDNS.cc
----------------------------------------------------------------------
diff --git a/proxy/TestDNS.cc b/proxy/TestDNS.cc
index 21cc8b2..e2efce7 100644
--- a/proxy/TestDNS.cc
+++ b/proxy/TestDNS.cc
@@ -181,7 +181,7 @@ complete()
   ink_hrtime now;
   state_machines_finished++;
   if (!(state_machines_finished % measurement_interval)) {
-    now = ink_get_hrtime();
+    now = Thread::get_hrtime();
     cumul_throughput = state_machines_finished * 1.0 * HRTIME_SECOND / (now - start_time);
     throughput = measurement_interval * 1.0 * HRTIME_SECOND / (now - last_measurement_time);
     last_measurement_time = now;
@@ -199,7 +199,7 @@ complete()
     fout_rate.flush();
   }
   if (state_machines_finished == state_machines_created) {
-    now = ink_get_hrtime();
+    now = Thread::get_hrtime();
     fout_rate_misc << (now - start_time) * 1.0 / HRTIME_SECOND << "\n";
     fout_rate_misc.flush();
     fout.close();
@@ -240,14 +240,14 @@ test()
   state_machines_created = N_STATE_MACHINES;
   state_machines_finished = 0;
   measurement_interval = MEASUREMENT_INTERVAL;
-  start_time = ink_get_hrtime();
-  last_measurement_time = ink_get_hrtime();
+  start_time = Thread::get_hrtime();
+  last_measurement_time = Thread::get_hrtime();
   while ((fscanf(fin, "%s", host) != EOF) && (i < state_machines_created)) {
     test_dns_state_machine = new TestDnsStateMachine(host, sizeof(host));
     test_dns_state_machine->handleEvent();
     i++;
   }
-  now = ink_get_hrtime();
+  now = Thread::get_hrtime();
   cout << "Finished creating all Continuations at " << (now - start_time) / HRTIME_SECOND
<< " sec and "
        << (now - start_time) % HRTIME_SECOND << "nanosec\n";
   fout_rate_misc << (now - start_time) * 1.0 / HRTIME_SECOND << "\n";

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/d95d9e84/proxy/http/HttpSM.cc
----------------------------------------------------------------------
diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc
index 6ac4531..28ef1aa 100644
--- a/proxy/http/HttpSM.cc
+++ b/proxy/http/HttpSM.cc
@@ -95,22 +95,21 @@ milestone_update_api_time(TransactionMilestones &milestones, ink_hrtime
&api_tim
     bool active = api_timer >= 0;
     if (!active)
       api_timer = -api_timer;
-    delta = Thread::get_hrtime() - api_timer;
+    delta = Thread::get_hrtime_updated() - 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;
+    // Zero or negative time is a problem because we want to signal *something* happened
+    // vs. no API activity at all. This can happen due to graininess or real time
+    // clock adjustment.
+    if (delta <= 0)
+      delta = 1;
 
     if (0 == milestones[TS_MILESTONE_PLUGIN_TOTAL])
       milestones[TS_MILESTONE_PLUGIN_TOTAL] = milestones[TS_MILESTONE_SM_START];
-    milestones[TS_MILESTONE_PLUGIN_TOTAL] = milestones[TS_MILESTONE_PLUGIN_TOTAL] + delta;
+    milestones[TS_MILESTONE_PLUGIN_TOTAL] += delta;
     if (active) {
       if (0 == milestones[TS_MILESTONE_PLUGIN_ACTIVE])
         milestones[TS_MILESTONE_PLUGIN_ACTIVE] = milestones[TS_MILESTONE_SM_START];
-      milestones[TS_MILESTONE_PLUGIN_ACTIVE] = milestones[TS_MILESTONE_PLUGIN_ACTIVE] + delta;
+      milestones[TS_MILESTONE_PLUGIN_ACTIVE] += delta;
     }
   }
 }
@@ -1309,11 +1308,18 @@ HttpSM::state_api_callout(int event, void *data)
     STATE_ENTER(&HttpSM::state_api_callout, event);
   }
 
+  if (api_timer < 0) {
+    // This happens when either the plugin lock was missed and the hook rescheduled or
+    // the transaction got an event without the plugin calling TsHttpTxnReenable().
+    // The call chain does not recurse here if @a api_timer < 0 which means this call
+    // is the first from an event dispatch in this case.
+    milestone_update_api_time(milestones, api_timer);
+  }
+
   switch (event) {
   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:
@@ -1360,10 +1366,14 @@ 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 = -Thread::get_hrtime();
+            api_timer = -Thread::get_hrtime_updated();
             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));
+            // Should @a callout_state be reset back to HTTP_API_NO_CALLOUT here? Because
the default
+            // handler has been changed the value isn't important to the rest of the state
machine
+            // but not resetting means there is no way to reliably detect re-entrance to
this state with an
+            // outstanding callout.
             return 0;
           }
         } else {
@@ -1376,14 +1386,15 @@ HttpSM::state_api_callout(int event, void *data)
         APIHook *hook = cur_hook;
         cur_hook = cur_hook->next();
 
-        api_timer = Thread::get_hrtime();
+        if (!api_timer)
+          api_timer = Thread::get_hrtime_updated();
         hook->invoke(TS_EVENT_HTTP_READ_REQUEST_HDR + cur_hook_id, this);
-        if (api_timer > 0) {
+        if (api_timer > 0) { // true if the hook did not call TxnReenable()
           milestone_update_api_time(milestones, api_timer);
-          api_timer = -Thread::get_hrtime(); // set in order to track non-active callout
duration
+          api_timer = -Thread::get_hrtime_updated(); // 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.
+          // up in state_api_callback when the plugin re-enables this transaction.
         }
 
         if (plugin_lock) {


Mime
View raw message