This is an automated email from the ASF dual-hosted git repository. cmcfarlen pushed a commit to branch 10.1.x in repository https://gitbox.apache.org/repos/asf/trafficserver.git
commit 248c8f09a248b0181ad9b566d386a35b65b9d94f Author: Brian Neradt <[email protected]> AuthorDate: Wed Jun 24 20:39:52 2026 -0500 HttpSM.cc: fix cache read end milestone order (#13325) The log-milestone-fields AuTest intermittently logged a valid TCP_MEM_HIT with hit_proc rendered as unset. That field is computed from TS_MILESTONE_UA_BEGIN_WRITE minus TS_MILESTONE_CACHE_OPEN_READ_END, so the failing logs showed the client write-begin milestone could be observed before the cache open-read end milestone on a fast cache-hit path. The cache had already delivered the open-read result in state_cache_open_read(), so that ordering pointed at milestone stamping rather than an actual cache sequencing problem. TS_MILESTONE_CACHE_OPEN_READ_END was marked after cache-open-read state handling, and that handling can advance into cache serving and stamp TS_MILESTONE_UA_BEGIN_WRITE first. This records TS_MILESTONE_CACHE_OPEN_READ_END in the terminal cache-open-read handling paths before they can advance to later transaction milestones. The compatibility-key retry path is left unstamped so the retried lookup owns a coherent cache-read begin/end pair. (cherry picked from commit 8f33dbf76b81e82ff541af58457619ed95e26f89) --- src/proxy/http/HttpSM.cc | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index 57530b2884..0a5dc7ce3e 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -2617,6 +2617,11 @@ HttpSM::state_cache_open_read(int event, void *data) Metrics::Counter::increment(http_rsb.cache_compat_key_reads); } + // Record the cache open-read completion before state handling can advance + // into cache serving and stamp later transaction milestones. + ATS_PROBE1(milestone_cache_open_read_end, sm_id); + milestones[TS_MILESTONE_CACHE_OPEN_READ_END] = ink_get_hrtime(); + ink_assert(t_state.cache_info.object_read != nullptr); call_transact_and_set_next_state(HttpTransact::HandleCacheOpenRead); break; @@ -2643,6 +2648,11 @@ HttpSM::state_cache_open_read(int event, void *data) t_state.cache_lookup_result = HttpTransact::CACHE_LOOKUP_MISS; } + // Record the final cache open-read completion after any compatibility-key + // retry has been ruled out. + ATS_PROBE1(milestone_cache_open_read_end, sm_id); + milestones[TS_MILESTONE_CACHE_OPEN_READ_END] = ink_get_hrtime(); + ink_assert(t_state.transact_return_point == nullptr); t_state.transact_return_point = HttpTransact::HandleCacheOpenRead; setup_cache_lookup_complete_api(); @@ -2653,9 +2663,6 @@ HttpSM::state_cache_open_read(int event, void *data) break; } - ATS_PROBE1(milestone_cache_open_read_end, sm_id); - milestones[TS_MILESTONE_CACHE_OPEN_READ_END] = ink_get_hrtime(); - return 0; }
