0

[v8 code cache] Fix timestamp mismatch issue

When we get a HTTP 304 ("Not Modified") response, we update the
response_time in the HTTP cache. But we don't update the code cache
response time. Later on, we check that the code cache associated with a
response has the same response time, but they won't match. This results
in discarding valid code caches.

Design doc: https://docs.google.com/document/d/1ndVOb-GUCCHiVT4uO-NyOQ3N3R4f8iDKtMU8zurnc-U/edit?usp=sharing

Bug: 373703283
Change-Id: I2d1ada339535736fc09a5df151cb01282b9a0972
Fixed: 373703283
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/5937821
Reviewed-by: Nidhi Jaju <nidhijaju@chromium.org>
Commit-Queue: Marja Hölttä <marja@chromium.org>
Reviewed-by: Adam Rice <ricea@chromium.org>
Reviewed-by: Takashi Toyoshima <toyoshim@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1379562}
This commit is contained in:
Marja Hölttä
2024-11-07 10:07:09 +00:00
committed by Chromium LUCI CQ
parent bc3bab8307
commit f5a004e60f
17 changed files with 74 additions and 29 deletions

@ -2082,6 +2082,9 @@ int HttpCache::Transaction::DoUpdateCachedResponse() {
response_.headers->Update(*new_response_->headers.get());
response_.stale_revalidate_timeout = base::Time();
response_.response_time = new_response_->response_time;
if (new_response_->headers->response_code() != net::HTTP_NOT_MODIFIED) {
response_.original_response_time = new_response_->response_time;
}
response_.request_time = new_response_->request_time;
response_.network_accessed = new_response_->network_accessed;
response_.unused_since_prefetch = new_response_->unused_since_prefetch;

@ -11194,6 +11194,12 @@ TEST_F(HttpCacheTest, UpdatesRequestResponseTimeOn304) {
kNetResponse1.AssignTo(&mock_network_response);
base::Time request_time1 = base::Time() + base::Hours(1232);
base::Time response_time1 = base::Time() + base::Hours(1233);
mock_network_response.request_time = request_time1;
mock_network_response.response_time = response_time1;
RunTransactionTest(cache.http_cache(), request);
// Request |kUrl| again, this time validating the cache and getting
@ -11206,20 +11212,21 @@ TEST_F(HttpCacheTest, UpdatesRequestResponseTimeOn304) {
kNetResponse2.AssignTo(&mock_network_response);
base::Time request_time = base::Time() + base::Hours(1234);
base::Time response_time = base::Time() + base::Hours(1235);
base::Time request_time2 = base::Time() + base::Hours(1234);
base::Time response_time2 = base::Time() + base::Hours(1235);
mock_network_response.request_time = request_time;
mock_network_response.response_time = response_time;
mock_network_response.request_time = request_time2;
mock_network_response.response_time = response_time2;
HttpResponseInfo response;
RunTransactionTestWithResponseInfo(cache.http_cache(), request, &response);
// The request and response times should have been updated.
EXPECT_EQ(request_time.ToInternalValue(),
response.request_time.ToInternalValue());
EXPECT_EQ(response_time.ToInternalValue(),
response.response_time.ToInternalValue());
EXPECT_EQ(request_time2, response.request_time);
EXPECT_EQ(response_time2, response.response_time);
// The original response time should still be the same.
EXPECT_EQ(response.original_response_time, response_time1);
EXPECT_EQ(
"HTTP/1.1 200 OK\n"

@ -144,6 +144,9 @@ enum {
// This bit is set if the response has valid `proxy_chain`.
RESPONSE_EXTRA_INFO_HAS_PROXY_CHAIN = 1 << 1,
// This bit is set if the response has original_response_time.
RESPONSE_EXTRA_INFO_HAS_ORIGINAL_RESPONSE_TIME = 1 << 2
};
HttpResponseInfo::HttpResponseInfo() = default;
@ -188,6 +191,14 @@ bool HttpResponseInfo::InitFromPickle(const base::Pickle& pickle,
return false;
response_time = Time::FromInternalValue(time_val);
// Read original-response-time
if ((extra_flags & RESPONSE_EXTRA_INFO_HAS_ORIGINAL_RESPONSE_TIME) != 0) {
if (!iter.ReadInt64(&time_val)) {
return false;
}
original_response_time = Time::FromInternalValue(time_val);
}
// Read response-headers
headers = base::MakeRefCounted<HttpResponseHeaders>(&iter);
if (headers->response_code() == -1)
@ -420,16 +431,14 @@ void HttpResponseInfo::Persist(base::Pickle* pickle,
extra_flags |= RESPONSE_EXTRA_INFO_HAS_PROXY_CHAIN;
}
if (extra_flags) {
flags |= RESPONSE_INFO_HAS_EXTRA_FLAGS;
}
extra_flags |= RESPONSE_EXTRA_INFO_HAS_ORIGINAL_RESPONSE_TIME;
flags |= RESPONSE_INFO_HAS_EXTRA_FLAGS;
pickle->WriteInt(flags);
if (extra_flags) {
pickle->WriteInt(extra_flags);
}
pickle->WriteInt(extra_flags);
pickle->WriteInt64(request_time.ToInternalValue());
pickle->WriteInt64(response_time.ToInternalValue());
pickle->WriteInt64(original_response_time.ToInternalValue());
HttpResponseHeaders::PersistOptions persist_options =
HttpResponseHeaders::PERSIST_RAW;

@ -165,6 +165,9 @@ class NET_EXPORT HttpResponseInfo {
// this is the last time the cache entry was validated.
base::Time response_time;
// Like response_time, but ignoring revalidations.
base::Time original_response_time;
// Host resolution error info.
ResolveErrorInfo resolve_error_info;

@ -898,7 +898,8 @@ int HttpStreamParser::HandleReadHeaderResult(int result) {
// Record our best estimate of the 'response time' as the time when we read
// the first bytes of the response headers.
if (read_buf_->offset() == 0) {
response_->response_time = base::Time::Now();
response_->response_time = response_->original_response_time =
base::Time::Now();
// Also keep the time as base::TimeTicks for `first_response_start_time_`
// and `non_informational_response_start_time_`.
current_response_start_time_ = base::TimeTicks::Now();

@ -639,8 +639,10 @@ int MockNetworkTransaction::DoSendRequest() {
}
response_.response_time = transaction_factory_->Now();
if (!t->response_time.is_null())
if (!t->response_time.is_null()) {
response_.response_time = t->response_time;
response_.original_response_time = t->response_time;
}
response_.headers = base::MakeRefCounted<HttpResponseHeaders>(header_data);
response_.ssl_info.cert = t->cert;

@ -626,7 +626,8 @@ int QuicHttpStream::ProcessResponseHeaders(
response_info_->was_alpn_negotiated = true;
response_info_->alpn_negotiated_protocol =
HttpConnectionInfoToString(response_info_->connection_info);
response_info_->response_time = base::Time::Now();
response_info_->response_time = response_info_->original_response_time =
base::Time::Now();
response_info_->request_time = request_time_;
response_headers_received_ = true;

@ -306,7 +306,8 @@ void SpdyHttpStream::OnHeadersReceived(
return;
}
response_info_->response_time = stream_->response_time();
response_info_->response_time = response_info_->original_response_time =
stream_->response_time();
// Don't store the SSLInfo in the response here, HttpNetworkTransaction
// will take care of that part.
CHECK_EQ(stream_->GetNegotiatedProtocol(), kProtoHTTP2);

@ -518,6 +518,11 @@ class NET_EXPORT URLRequest : public base::SupportsUserData {
return response_info_.response_time;
}
// Like response_time, but ignoring revalidations.
const base::Time& original_response_time() const {
return response_info_.original_response_time;
}
// Indicate if this response was fetched from disk cache.
bool was_cached() const { return response_info_.was_cached; }

@ -410,7 +410,8 @@ void URLRequestJob::NotifyHeadersComplete() {
// Initialize to the current time, and let the subclass optionally override
// the time stamps if it has that information. The default request_time is
// set by URLRequest before it calls our Start method.
request_->response_info_.response_time = base::Time::Now();
request_->response_info_.response_time =
request_->response_info_.original_response_time = base::Time::Now();
GetResponseInfo(&request_->response_info_);
request_->OnHeadersComplete();

@ -50,6 +50,7 @@ void URLRequestRedirectJob::GetResponseInfo(HttpResponseInfo* info) {
info->headers = fake_headers_;
info->request_time = response_time_;
info->response_time = response_time_;
info->original_response_time = response_time_;
}
void URLRequestRedirectJob::GetLoadTimingInfo(

@ -285,7 +285,8 @@ void WebSocketHttp2HandshakeStream::OnHeadersReceived(
SpdyHeadersToHttpResponse(response_headers, http_response_info_);
DCHECK_NE(rv, ERR_INCOMPLETE_HTTP2_HEADERS);
http_response_info_->response_time = stream_->response_time();
http_response_info_->response_time =
http_response_info_->original_response_time = stream_->response_time();
// Do not store SSLInfo in the response here, HttpNetworkTransaction will take
// care of that part.
http_response_info_->was_alpn_negotiated = true;

@ -288,7 +288,8 @@ void WebSocketHttp3HandshakeStream::OnHeadersReceived(
// Do not store SSLInfo in the response here, HttpNetworkTransaction will take
// care of that part.
http_response_info_->was_alpn_negotiated = true;
http_response_info_->response_time = base::Time::Now();
http_response_info_->response_time =
http_response_info_->original_response_time = base::Time::Now();
http_response_info_->request_time = request_time_;
http_response_info_->connection_info = HttpConnectionInfo::kHTTP2;
http_response_info_->alpn_negotiated_protocol =

@ -41,6 +41,11 @@ struct URLResponseHead {
// responses, this time could be "far" in the past.
mojo_base.mojom.Time response_time;
// The response_time for when the response was first received. For cached
// and revalidated responses, this is the time when the resource was first
// received, and is not updated after revalidation.
mojo_base.mojom.Time original_response_time;
// The response headers or NULL if the URL type does not support headers.
HttpResponseHeaders headers;

@ -1459,6 +1459,7 @@ mojom::URLResponseHeadPtr URLLoader::BuildResponseHead() const {
response->request_time = url_request_->request_time();
response->response_time = url_request_->response_time();
response->original_response_time = url_request_->original_response_time();
response->headers = url_request_->response_headers();
response->parsed_headers =
PopulateParsedHeaders(response->headers.get(), url_request_->url());

@ -61,9 +61,17 @@ bool ShouldUseIsolatedCodeCache(
} else if (!response_head.should_use_source_hash_for_js_code_cache) {
// If the timestamps don't match or are null, the code cache data may be
// for a different response. See https://crbug.com/1099587.
if (code_cache_response_time.is_null() ||
response_head.response_time.is_null() ||
code_cache_response_time != response_head.response_time) {
// When the cached resource is revalidated and an HTTP 304 ("Not Modified")
// response is received, the response time changes. However, the code cache
// is still valid. We use original_response_time (which doesn't change when
// a HTTP 304 is received) instead of response_time for validating the code
// cache.
base::Time response_time = response_head.original_response_time.is_null()
? response_head.response_time
: response_head.original_response_time;
if (code_cache_response_time.is_null() || response_time.is_null() ||
code_cache_response_time != response_time) {
return false;
}
}

@ -1,5 +0,0 @@
This is a testharness.js-based test.
[FAIL] code-cache-after-304
assert_true: Did use the code cache after the third compilation expected true got false
Harness: the test ran to completion.