New histogram to track overhead time spent around beforeunload event + fixes

content/browser/frame_host/render_frame_host_impl.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/browser/frame_host/render_frame_host_impl.h"
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/containers/hash_tables.h"
 #include "base/lazy_instance.h"
@@ skipping 689 matching lines @@
 
   // If we're waiting for a cross-site beforeunload ack from this renderer and
   // we receive a Navigate message from the main frame, then the renderer was
   // navigating already and sent it before hearing the FrameMsg_Stop message.
   // We do not want to cancel the pending navigation in this case, since the
   // old page will soon be stopped.  Instead, treat this as a beforeunload ack
   // to allow the pending navigation to continue.
   if (is_waiting_for_beforeunload_ack_ &&
       unload_ack_is_for_cross_site_transition_ &&
       ui::PageTransitionIsMainFrame(validated_params.transition)) {
-    OnBeforeUnloadACK(true, send_before_unload_start_time_,
-                      base::TimeTicks::Now());
+    base::TimeTicks approx_renderer_start_time = send_before_unload_start_time_;

[carlosk, 2014/10/21 13:07:09]

I'm making this copy because it was unsafe to pass a reference to
send_before_unload_start_time_ as that value could be reset anytime.

[Charlie Reis, 2014/10/21 18:21:48]

"Could be reset anytime" doesn't seem relevant here.  It only seems like this is
needed if OnBeforeUnloadACK resets send_before_unload_start_time_ before
accessing renderer_before_unload_start_time, since they're aliased.

That said, this is safer against future changes, so it's fine.

[carlosk, 2014/10/22 09:08:56]

Yeah I agree with that: it isn't really required. But future-proofing was
exactly what drove me to do it. In fact in a previous version of the code I did
precisely what you described and suddenly renderer_before_unload_start_time was
unexpectedly turning up as 0. :)

+    OnBeforeUnloadACK(true, approx_renderer_start_time, base::TimeTicks::Now());
     return;
   }
 
   // If we're waiting for an unload ack from this renderer and we receive a
   // Navigate message, then the renderer was navigating before it received the
   // unload request.  It will either respond to the unload request soon or our
   // timer will expire.  Either way, we should ignore this message, because we
   // have already committed to closing this renderer.
   if (IsWaitingForUnloadACK())
     return;
@@ skipping 101 matching lines @@
   if (!GetParent())
     delegate_->SwappedOut(this);
 }
 
 void RenderFrameHostImpl::OnBeforeUnloadACK(
     bool proceed,
     const base::TimeTicks& renderer_before_unload_start_time,
     const base::TimeTicks& renderer_before_unload_end_time) {
   TRACE_EVENT_ASYNC_END0(
       "navigation", "RenderFrameHostImpl::BeforeUnload", this);
-  // TODO(creis): Support beforeunload on subframes.  For now just pretend that
-  // the handler ran and allowed the navigation to proceed.
-  if (GetParent()) {
-    is_waiting_for_beforeunload_ack_ = false;
-    frame_tree_node_->render_manager()->OnBeforeUnloadACK(
-        unload_ack_is_for_cross_site_transition_, proceed,
-        renderer_before_unload_end_time);
-    return;
-  }
-
+  DCHECK(!GetParent());
   render_view_host_->decrement_in_flight_event_count();
   render_view_host_->StopHangMonitorTimeout();
   // If this renderer navigated while the beforeunload request was in flight, we
   // may have cleared this state in OnDidCommitProvisionalLoad, in which case we
   // can ignore this message.
   // However renderer might also be swapped out but we still want to proceed
   // with navigation, otherwise it would block future navigations. This can
   // happen when pending cross-site navigation is canceled by a second one just
   // before OnDidCommitProvisionalLoad while current RVH is waiting for commit
   // but second navigation is started from the beginning.
   if (!is_waiting_for_beforeunload_ack_) {
     return;
   }
+  DCHECK(!send_before_unload_start_time_.is_null());
 
-  is_waiting_for_beforeunload_ack_ = false;
-
-  base::TimeTicks before_unload_end_time;
-  if (!send_before_unload_start_time_.is_null() &&
-      !renderer_before_unload_start_time.is_null() &&
+  // Sets a default value for before_unload_end_time so that the browser
+  // survives a hacked renderer.
+  base::TimeTicks before_unload_end_time = renderer_before_unload_end_time;

[carlosk, 2014/10/21 13:07:09]

So finally, this initialization was not the correct solution for the problem I
found out before (the previous comment is the fix) but it is required if we want
the browser not to die from a hacked renderer.

+  if (!renderer_before_unload_start_time.is_null() &&
       !renderer_before_unload_end_time.is_null()) {
     // When passing TimeTicks across process boundaries, we need to compensate
     // for any skew between the processes. Here we are converting the
     // renderer's notion of before_unload_end_time to TimeTicks in the browser
     // process. See comments in inter_process_time_ticks_converter.h for more.
+    base::TimeTicks receive_before_unload_ack_time = base::TimeTicks::Now();
     InterProcessTimeTicksConverter converter(
         LocalTimeTicks::FromTimeTicks(send_before_unload_start_time_),
-        LocalTimeTicks::FromTimeTicks(base::TimeTicks::Now()),
+        LocalTimeTicks::FromTimeTicks(receive_before_unload_ack_time),
         RemoteTimeTicks::FromTimeTicks(renderer_before_unload_start_time),
         RemoteTimeTicks::FromTimeTicks(renderer_before_unload_end_time));
     LocalTimeTicks browser_before_unload_end_time =
         converter.ToLocalTimeTicks(
             RemoteTimeTicks::FromTimeTicks(renderer_before_unload_end_time));
     before_unload_end_time = browser_before_unload_end_time.ToTimeTicks();
 
     // Collect UMA on the inter-process skew.
     bool is_skew_additive = false;
     if (converter.IsSkewAdditiveForMetrics()) {
       is_skew_additive = true;
       base::TimeDelta skew = converter.GetSkewForMetrics();
       if (skew >= base::TimeDelta()) {
         UMA_HISTOGRAM_TIMES(
             "InterProcessTimeTicks.BrowserBehind_RendererToBrowser", skew);
       } else {
         UMA_HISTOGRAM_TIMES(
             "InterProcessTimeTicks.BrowserAhead_RendererToBrowser", -skew);
       }
     }
     UMA_HISTOGRAM_BOOLEAN(
         "InterProcessTimeTicks.IsSkewAdditive_RendererToBrowser",
         is_skew_additive);
 
+    base::TimeDelta on_before_unload_overhead_time =
+        (receive_before_unload_ack_time - send_before_unload_start_time_) -
+        (renderer_before_unload_end_time - renderer_before_unload_start_time);
+    UMA_HISTOGRAM_TIMES("Navigation.OnBeforeUnloadOverheadTime",
+                        on_before_unload_overhead_time);
+
     frame_tree_node_->navigator()->LogBeforeUnloadTime(
         renderer_before_unload_start_time, renderer_before_unload_end_time);
   }
+  // Resets beforeunload waiting state.

[Charlie Reis, 2014/10/21 18:21:48]

nit: There should have been a blank line before this because it's separate from
the block above.  (Not worth its own CL, but for future reference.)

[carlosk, 2014/10/22 09:08:56]

Acknowledged.

+  is_waiting_for_beforeunload_ack_ = false;
+  send_before_unload_start_time_ = base::TimeTicks();

[carlosk, 2014/10/21 13:07:09]

I moved the state reset down here so that both variables could be changed at the
same time. Otherwise I'd have to whether split these two statements apart or
make a copy of send_before_unload_start_time_.

[Charlie Reis, 2014/10/21 18:21:48]

Acknowledged.

+
   frame_tree_node_->render_manager()->OnBeforeUnloadACK(
       unload_ack_is_for_cross_site_transition_, proceed,
       before_unload_end_time);
 
   // If canceled, notify the delegate to cancel its pending navigation entry.
   if (!proceed)
     render_view_host_->GetDelegate()->DidCancelLoading();
 }
 
 bool RenderFrameHostImpl::IsWaitingForUnloadACK() const {
@@ skipping 310 matching lines @@
   // Whenever we change the RFH state to and from active or swapped out state,
   // we should not be waiting for beforeunload or close acks.  We clear them
   // here to be safe, since they can cause navigations to be ignored in
   // OnDidCommitProvisionalLoad.
   // TODO(creis): Move is_waiting_for_beforeunload_ack_ into the state machine.
   if (rfh_state == STATE_DEFAULT ||
       rfh_state == STATE_SWAPPED_OUT ||
       rfh_state_ == STATE_DEFAULT ||
       rfh_state_ == STATE_SWAPPED_OUT) {
     is_waiting_for_beforeunload_ack_ = false;
+    send_before_unload_start_time_ = base::TimeTicks();
     render_view_host_->is_waiting_for_close_ack_ = false;
   }
   rfh_state_ = rfh_state;
 }
 
 bool RenderFrameHostImpl::CanCommitURL(const GURL& url) {
   // TODO(creis): We should also check for WebUI pages here.  Also, when the
   // out-of-process iframes implementation is ready, we should check for
   // cross-site URLs that are not allowed to commit in this process.
 
@@ skipping 64 matching lines @@
 
 void RenderFrameHostImpl::OpenURL(const FrameHostMsg_OpenURL_Params& params) {
   OnOpenURL(params);
 }
 
 void RenderFrameHostImpl::Stop() {
   Send(new FrameMsg_Stop(routing_id_));
 }
 
 void RenderFrameHostImpl::DispatchBeforeUnload(bool for_cross_site_transition) {
+  // TODO(creis): Support beforeunload on subframes.  For now just pretend that
+  // the handler ran and allowed the navigation to proceed.
+  if (GetParent() || !IsRenderFrameLive()) {
+    // We don't have a live renderer, so just skip running beforeunload.
+    frame_tree_node_->render_manager()->OnBeforeUnloadACK(
+        for_cross_site_transition, true, base::TimeTicks::Now());
+    return;
+  }
   TRACE_EVENT_ASYNC_BEGIN0(
       "navigation", "RenderFrameHostImpl::BeforeUnload", this);
-  // TODO(creis): Support subframes.
-  if (GetParent() || !IsRenderFrameLive()) {
-    // We don't have a live renderer, so just skip running beforeunload.
-    is_waiting_for_beforeunload_ack_ = true;
-    unload_ack_is_for_cross_site_transition_ = for_cross_site_transition;
-    base::TimeTicks now = base::TimeTicks::Now();
-    OnBeforeUnloadACK(true, now, now);
-    return;
-  }
 
   // This may be called more than once (if the user clicks the tab close button
   // several times, or if she clicks the tab close button then the browser close
   // button), and we only send the message once.
   if (is_waiting_for_beforeunload_ack_) {
     // Some of our close messages could be for the tab, others for cross-site
     // transitions. We always want to think it's for closing the tab if any
     // of the messages were, since otherwise it might be impossible to close
     // (if there was a cross-site "close" request pending when the user clicked
     // the close button). We want to keep the "for cross site" flag only if
@@ skipping 230 matching lines @@
   // Clear any state if a pending navigation is canceled or preempted.
   if (suspended_nav_params_)
     suspended_nav_params_.reset();
 
   TRACE_EVENT_ASYNC_END0("navigation",
                          "RenderFrameHostImpl navigation suspended", this);
   navigations_suspended_ = false;
 }
 
 }  // namespace content