Reland of "Add UMA for the delay of CreateStream() and ..."

This is a reland of https://crrev.com/c/6415568, focusing only UMA for
CreateStream() to make a reland CL smaller and isolated.

The original CL causes a crash (https://crbug.com/408060617). The
underlying cause was that `create_stream_end_time_` was not cleared,
even though CreatStream() could be called multiple times. That may cause
a crash in populating LoadTimingInternalInfo later, hitting at:

  CHECK_LE(create_stream_start_time_, create_stream_end_time_);

See also: https://crrev.com/c/6424639.

This CL makes sure to reset `end_time` when setting `start_time` to
prevent an inconsistent state.

Note this is a kind of speculative fix because I couldn't reproduce a
crash locally.

Bug: 393980912,408060617
Change-Id: I8eaf20c866f8239240c40e936bc4594e2979def1
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/6433371
Reviewed-by: Kenichi Ishibashi <bashi@chromium.org>
Reviewed-by: Takashi Toyoshima <toyoshim@chromium.org>
Commit-Queue: Hayato Ito <hayato@chromium.org>
Reviewed-by: Dave Tapuska <dtapuska@chromium.org>
Reviewed-by: Kouhei Ueno <kouhei@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1443851}

components/page_load_metrics/google/browser/gws_page_load_metrics_observer.cc

@@ -55,6 +55,8 @@ const char kHistogramGWSNavigationStartToFirstLoaderCallback[] =
     HISTOGRAM_PREFIX "NavigationTiming.NavigationStartToFirstLoaderCallback";
 const char kHistogramGWSNavigationStartToOnComplete[] =
     HISTOGRAM_PREFIX "NavigationTiming.NavigationStartToOnComplete";
+const char kHistogramGWSCreateStreamDelay[] =
+    HISTOGRAM_PREFIX "NavigationTiming.CreateStreamDelay";
 const char kHistogramGWSInitializeStreamDelay[] =
     HISTOGRAM_PREFIX "NavigationTiming.InitializeStreamDelay";
 
@@ -410,6 +412,8 @@ void GWSPageLoadMetricsObserver::RecordNavigationTimingHistograms() {
   PAGE_LOAD_SHORT_HISTOGRAM(
       internal::kHistogramGWSConnectTimingFinalRequestSslDelay,
       timing.final_request_ssl_delay);
+  PAGE_LOAD_SHORT_HISTOGRAM(internal::kHistogramGWSCreateStreamDelay,
+                            timing.create_stream_delay);
   PAGE_LOAD_SHORT_HISTOGRAM(internal::kHistogramGWSInitializeStreamDelay,
                             timing.initialize_stream_delay);
 

content/browser/renderer_host/navigation_request.cc

@@ -6938,6 +6938,8 @@ void NavigationRequest::UpdateNavigationHandleTimingsOnResponseReceived(
   navigation_handle_timing_.final_request_ssl_delay = ssl_delay;
 
   if (response_head_->load_timing_internal_info) {
+    navigation_handle_timing_.create_stream_delay =
+        response_head_->load_timing_internal_info->create_stream_delay;
     navigation_handle_timing_.initialize_stream_delay =
         response_head_->load_timing_internal_info->initialize_stream_delay;
     // Reset `load_timing_internal_info` to make sure that isn't exposed.

content/public/browser/navigation_handle_timing.h

@@ -142,6 +142,9 @@ struct CONTENT_EXPORT NavigationHandleTiming {
   base::TimeDelta final_request_connect_delay;
   base::TimeDelta final_request_ssl_delay;
 
+  // CreateStream related delay information.
+  base::TimeDelta create_stream_delay;
+
   // InitializeStream related delay information.
   base::TimeDelta initialize_stream_delay;
 };

net/base/load_timing_internal_info.h

@@ -21,6 +21,9 @@ struct NET_EXPORT LoadTimingInternalInfo {
   bool operator==(const LoadTimingInternalInfo& other) const;
   ~LoadTimingInternalInfo();
 
+  // The time taken for HTTP stream creating to finish.
+  base::TimeDelta create_stream_delay;
+
   // The time taken for HTTP stream initialization to finish if the
   // initialization was blocked.
   base::TimeDelta initialize_stream_delay;

net/http/http_network_transaction.cc

@@ -578,6 +578,12 @@ bool HttpNetworkTransaction::GetLoadTimingInfo(
 
 void HttpNetworkTransaction::PopulateLoadTimingInternalInfo(
     LoadTimingInternalInfo* load_timing_internal_info) const {
+  if (!create_stream_start_time_.is_null() &&
+      !create_stream_end_time_.is_null()) {
+    CHECK_LE(create_stream_start_time_, create_stream_end_time_);
+    load_timing_internal_info->create_stream_delay =
+        create_stream_end_time_ - create_stream_start_time_;
+  }
   if (!initialize_stream_start_time_.is_null() &&
       !initialize_stream_end_time_.is_null()) {
     CHECK_LE(initialize_stream_start_time_, initialize_stream_end_time_);
@@ -982,6 +988,10 @@ int HttpNetworkTransaction::DoCreateStream() {
   }
 
   create_stream_start_time_ = base::TimeTicks::Now();
+  // Reset `create_stream_end_time__` to prevent an inconsistent state in
+  // case that `DoCreateStream` is called multiple times.
+  create_stream_end_time_ = base::TimeTicks();
+
   if (ForWebSocketHandshake()) {
     stream_request_ =
         session_->http_stream_factory()->RequestWebSocketHandshakeStream(
@@ -1003,9 +1013,11 @@ int HttpNetworkTransaction::DoCreateStreamComplete(int result) {
   RecordStreamRequestResult(result);
   CopyConnectionAttemptsFromStreamRequest();
   if (result == OK) {
+    create_stream_end_time_ = base::TimeTicks::Now();
     next_state_ = STATE_CONNECTED_CALLBACK;
     DCHECK(stream_.get());
     CHECK(!create_stream_start_time_.is_null());
+    CHECK_LE(create_stream_start_time_, create_stream_end_time_);
     base::UmaHistogramTimes(
         base::StrCat(
             {"Net.NetworkTransaction.Create",
@@ -1013,7 +1025,7 @@ int HttpNetworkTransaction::DoCreateStreamComplete(int result) {
                                       : "HttpStreamTime."),
              (IsGoogleHostWithAlpnH3(url_.host()) ? "GoogleHost." : ""),
              NegotiatedProtocolToHistogramSuffix(negotiated_protocol_)}),
-        base::TimeTicks::Now() - create_stream_start_time_);
+        create_stream_end_time_ - create_stream_start_time_);
     if (!reset_connection_and_request_for_resend_start_time_.is_null()) {
       base::UmaHistogramTimes(
           "Net.NetworkTransaction.ResetConnectionAndResendRequestTime",

net/http/http_network_transaction.h

@@ -451,8 +451,9 @@ class NET_EXPORT_PRIVATE HttpNetworkTransaction
   // transaction.
   int64_t total_sent_bytes_ = 0;
 
-  // When the transaction started creating a stream.
+  // When the transaction started / finished creating a stream.
   base::TimeTicks create_stream_start_time_;
+  base::TimeTicks create_stream_end_time_;
 
   // When the transaction started / finished sending the request, including
   // the body, if present. |send_start_time_| is set to |base::TimeTicks()|

services/network/public/cpp/load_timing_internal_info_mojom_traits.cc

@@ -8,6 +8,14 @@
 
 namespace mojo {
 
+// static
+const base::TimeDelta&
+StructTraits<network::mojom::LoadTimingInternalInfoDataView,
+             net::LoadTimingInternalInfo>::
+    create_stream_delay(const net::LoadTimingInternalInfo& info) {
+  return info.create_stream_delay;
+}
+
 // static
 const base::TimeDelta&
 StructTraits<network::mojom::LoadTimingInternalInfoDataView,

services/network/public/cpp/load_timing_internal_info_mojom_traits.h

@@ -16,6 +16,8 @@ template <>
 struct COMPONENT_EXPORT(NETWORK_CPP_BASE)
     StructTraits<network::mojom::LoadTimingInternalInfoDataView,
                  net::LoadTimingInternalInfo> {
+  static const base::TimeDelta& create_stream_delay(
+      const net::LoadTimingInternalInfo& info);
   static const base::TimeDelta& initialize_stream_delay(
       const net::LoadTimingInternalInfo& info);
   static bool Read(network::mojom::LoadTimingInternalInfoDataView data,

services/network/public/mojom/load_timing_internal_info.mojom

@@ -8,5 +8,6 @@ import "mojo/public/mojom/base/time.mojom";
 
 // Mirror of net::LoadTimingInternalInfo.
 struct LoadTimingInternalInfo {
+  mojo_base.mojom.TimeDelta create_stream_delay;
   mojo_base.mojom.TimeDelta initialize_stream_delay;
 };

tools/metrics/histograms/metadata/page/histograms.xml

@@ -1314,6 +1314,19 @@ chromium-metrics-reviews@google.com.
   </token>
 </histogram>
 
+<histogram
+    name="PageLoad.Clients.GoogleSearch.NavigationTiming.CreateStreamDelay"
+    units="ms" expires_after="2025-10-01">
+  <owner>hayato@chromium.org</owner>
+  <owner>chrome-loading@google.com</owner>
+  <summary>
+    The time taken for HTTP stream creation to finish, for Google Search page
+    loads. Recorded every time HttpStream::CreateStream() is called, for Google
+    Search page loads. Emitted when the navigation is completed or the app is
+    backgrounded on Android.
+  </summary>
+</histogram>
+
 <histogram
     name="PageLoad.Clients.GoogleSearch.NavigationTiming.InitializeStreamDelay"
     units="ms" expires_after="2025-09-01">