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 <[email protected]> Authored: Sun Mar 6 11:56:12 2016 -0600 Committer: Alan M. Carroll <[email protected]> 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) {
