Optional <TimeDelta> since they may be non existent.

components/page_load_metrics/browser/metrics_web_contents_observer.cc

 // Copyright 2015 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 "components/page_load_metrics/browser/metrics_web_contents_observer.h"
 
 #include <algorithm>
 #include <string>
 #include <utility>
 
@@ skipping 241 matching lines @@
       embedder_interface_(embedder_interface) {
   DCHECK(!navigation_handle->HasCommitted());
   embedder_interface_->RegisterObservers(this);
   for (const auto& observer : observers_) {
     observer->OnStart(navigation_handle, currently_committed_url,
                       started_in_foreground_);
   }
 }
 
 PageLoadTracker::~PageLoadTracker() {
-  const PageLoadExtraInfo info = GetPageLoadMetricsInfo();
-  if (!info.time_to_commit.is_zero() && renderer_tracked() &&
-      timing_.IsEmpty()) {
+  const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
+
+  if (info.time_to_commit && renderer_tracked() && timing_.IsEmpty()) {
     RecordInternalError(ERR_NO_IPCS_RECEIVED);
   }
   // Recall that trackers that are given ABORT_UNKNOWN_NAVIGATION have their
   // chain length added to the next navigation. Take care not to double count
   // them. Also do not double count committed loads, which call this already.
   if (commit_time_.is_null() && abort_type_ != ABORT_UNKNOWN_NAVIGATION)
     LogAbortChainHistograms(nullptr);
 
   for (const auto& observer : observers_) {
     observer->OnComplete(timing_, info);
@@ skipping 40 matching lines @@
     default:
       NOTREACHED()
           << "LogAbortChainHistograms received unexpected ui::PageTransition: "
           << committed_transition;
       return;
   }
 }
 
 void PageLoadTracker::WebContentsHidden() {
   // Only log the first time we background in a given page load.
-  if (background_time_.is_null()) {
-    // Make sure we either started in the foreground and haven't been
-    // foregrounded yet, or started in the background and have already been
-    // foregrounded.
-    DCHECK_EQ(started_in_foreground_, foreground_time_.is_null());
-    background_time_ = base::TimeTicks::Now();
+  if (!background_time_.is_null()) {
+    return;
   }
+  // Make sure we either started in the foreground and haven't been
+  // foregrounded yet, or started in the background and have already been
+  // foregrounded.
+  DCHECK_EQ(started_in_foreground_, foreground_time_.is_null());
+  background_time_ = base::TimeTicks::Now();
+  ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_);
 
   for (const auto& observer : observers_)
     observer->OnHidden();
 }
 
 void PageLoadTracker::WebContentsShown() {
   // Only log the first time we foreground in a given page load.
-  if (foreground_time_.is_null()) {
-    // Make sure we either started in the background and haven't been
-    // backgrounded yet, or started in the foreground and have already been
-    // backgrounded.
-    DCHECK_NE(started_in_foreground_, background_time_.is_null());
-    foreground_time_ = base::TimeTicks::Now();
+  if (!foreground_time_.is_null()) {
+    return;
   }
+  // Make sure we either started in the background and haven't been
+  // backgrounded yet, or started in the foreground and have already been
+  // backgrounded.
+  DCHECK_NE(started_in_foreground_, background_time_.is_null());
+  foreground_time_ = base::TimeTicks::Now();
+  ClampBrowserTimestampIfInterProcessTimeTickSkew(&foreground_time_);
 
   for (const auto& observer : observers_)
     observer->OnShown();
 }
 
 void PageLoadTracker::Commit(content::NavigationHandle* navigation_handle) {
   // TODO(bmcquade): To improve accuracy, consider adding commit time to
   // NavigationHandle. Taking a timestamp here should be close enough for now.
   commit_time_ = base::TimeTicks::Now();
+  ClampBrowserTimestampIfInterProcessTimeTickSkew(&commit_time_);
   url_ = navigation_handle->GetURL();
   for (const auto& observer : observers_) {
     observer->OnCommit(navigation_handle);
   }
   LogAbortChainHistograms(navigation_handle);
 }
 
 void PageLoadTracker::FailedProvisionalLoad(
     content::NavigationHandle* navigation_handle) {
   for (const auto& observer : observers_) {
@@ skipping 24 matching lines @@
       valid_behavior_descendent) {
     // There are some subtle ordering constraints here. GetPageLoadMetricsInfo()
     // must be called before DispatchObserverTimingCallbacks, but its
     // implementation depends on the state of metadata_, so we need to update
     // metadata_ before calling GetPageLoadMetricsInfo. Thus, we make a copy of
     // timing here, update timing_ and metadata_, and then proceed to dispatch
     // the observer timing callbacks.
     const PageLoadTiming last_timing = timing_;
     timing_ = new_timing;
     metadata_ = new_metadata;
-    const PageLoadExtraInfo info = GetPageLoadMetricsInfo();
+    const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
     for (const auto& observer : observers_) {
       DispatchObserverTimingCallbacks(observer.get(), last_timing, new_timing,
                                       info);
     }
     return true;
   }
   return false;
 }
 
 void PageLoadTracker::set_renderer_tracked(bool renderer_tracked) {
   renderer_tracked_ = renderer_tracked;
 }
 
 void PageLoadTracker::AddObserver(
     std::unique_ptr<PageLoadMetricsObserver> observer) {
   observers_.push_back(std::move(observer));
 }
 
-PageLoadExtraInfo PageLoadTracker::GetPageLoadMetricsInfo() {
-  base::TimeDelta first_background_time;
-  base::TimeDelta first_foreground_time;
-  base::TimeDelta time_to_abort;
-  base::TimeDelta time_to_commit;
-  if (!background_time_.is_null())
+void PageLoadTracker::ClampBrowserTimestampIfInterProcessTimeTickSkew(
+    base::TimeTicks* event_time) {
+  // Windows 10 GCE bot non-deterministically failed because TimeTicks::Now()
+  // called in the browser process e.g. commit_time was less than
+  // navigation_start_ that was populated in the renderer process because the
+  // clock was not system-wide monotonic.
+
+  // TODO (shivanisha) Currently IsHighResolution is the best way to check
+  // if the clock is system-wide monotonic. However IsHighResolution
+  // does a broader check to see if the clock in use is high resolution
+  // which also implies it is system-wide monotonic (on Windows).
+  if (base::TimeTicks::IsHighResolution()) {
+    return;
+  }
+
+  if (!event_time->is_null() && *event_time < navigation_start_) {
+    UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents,

[Charlie Harrison, 2016/05/24 19:32:01]

Use RecordInternalError to avoid inlining a bunch of histogram code.

[shivanisha, 2016/05/24 20:09:56]

done

+                              ERR_INTER_PROCESS_TIME_TICK_SKEW, ERR_LAST_ENTRY);
+    *event_time = navigation_start_;
+  }
+}
+
+PageLoadExtraInfo PageLoadTracker::ComputePageLoadExtraInfo() {
+  base::Optional<base::TimeDelta> first_background_time;
+  base::Optional<base::TimeDelta> first_foreground_time;
+  base::Optional<base::TimeDelta> time_to_abort;
+  base::Optional<base::TimeDelta> time_to_commit;
+
+  if (!background_time_.is_null()) {
+    DCHECK_GE(background_time_, navigation_start_);
     first_background_time = background_time_ - navigation_start_;
-  if (!foreground_time_.is_null())
+  }
+
+  if (!foreground_time_.is_null()) {
+    DCHECK_GE(foreground_time_, navigation_start_);
     first_foreground_time = foreground_time_ - navigation_start_;
+  }
+
   if (abort_type_ != ABORT_NONE) {
-    DCHECK_GT(abort_time_, navigation_start_);
+    DCHECK_GE(abort_time_, navigation_start_);
     time_to_abort = abort_time_ - navigation_start_;
   } else {
     DCHECK(abort_time_.is_null());
   }
 
   if (!commit_time_.is_null()) {
-    DCHECK_GT(commit_time_, navigation_start_);
+    DCHECK_GE(commit_time_, navigation_start_);
     time_to_commit = commit_time_ - navigation_start_;
-  } else {
-    DCHECK(commit_time_.is_null());
   }
+
   return PageLoadExtraInfo(
       first_background_time, first_foreground_time, started_in_foreground_,
       commit_time_.is_null() ? GURL() : url_, time_to_commit, abort_type_,
       time_to_abort, metadata_);
 }
 
 void PageLoadTracker::NotifyAbort(UserAbortType abort_type,
-                                  base::TimeTicks timestamp) {
+                                  base::TimeTicks timestamp,
+                                  bool is_browser_timestamp) {
   DCHECK_NE(abort_type, ABORT_NONE);
   // Use UpdateAbort to update an already notified PageLoadTracker.
   if (abort_type_ != ABORT_NONE)
     return;
 
-  UpdateAbortInternal(abort_type, timestamp);
+  UpdateAbortInternal(abort_type, timestamp, is_browser_timestamp);
 }
 
 void PageLoadTracker::UpdateAbort(UserAbortType abort_type,
-                                  base::TimeTicks timestamp) {
+                                  base::TimeTicks timestamp,
+                                  bool is_browser_timestamp) {
   DCHECK_NE(abort_type, ABORT_NONE);
   DCHECK_NE(abort_type, ABORT_OTHER);
   DCHECK_EQ(abort_type_, ABORT_OTHER);
 
   // For some aborts (e.g. navigations), the initiated timestamp can be earlier
   // than the timestamp that aborted the load. Taking the minimum gives the
   // closest user initiated time known.
-  UpdateAbortInternal(abort_type, std::min(abort_time_, timestamp));
+  UpdateAbortInternal(abort_type, std::min(abort_time_, timestamp),
+                      is_browser_timestamp);
 }
 
 bool PageLoadTracker::IsLikelyProvisionalAbort(
     base::TimeTicks abort_cause_time) {
   // Note that |abort_cause_time - abort_time| can be negative.
   return abort_type_ == ABORT_OTHER &&
          (abort_cause_time - abort_time_).InMilliseconds() < 100;
 }
 
 bool PageLoadTracker::MatchesOriginalNavigation(
     content::NavigationHandle* navigation_handle) {
   // Neither navigation should have committed.
   DCHECK(!navigation_handle->HasCommitted());
   DCHECK(commit_time_.is_null());
   return navigation_handle->GetURL() == url_;
 }
 
 void PageLoadTracker::UpdateAbortInternal(UserAbortType abort_type,
-                                          base::TimeTicks timestamp) {
+                                          base::TimeTicks timestamp,
+                                          bool is_browser_timestamp) {
   // When a provisional navigation commits, that navigation's start time is
   // interpreted as the abort time for other provisional loads in the tab.
   // However, this only makes sense if the committed load started after the
   // aborted provisional loads started. Thus we ignore cases where the committed
   // load started before the aborted provisional load, as this would result in
   // recording a negative time-to-abort. The real issue here is that we have to
   // infer the cause of aborts. It would be better if the navigation code could
   // instead report the actual cause of an aborted navigation. See crbug/571647
   // for details.
-  if (timestamp <= navigation_start_) {
+  if (timestamp < navigation_start_) {
     RecordInternalError(ERR_ABORT_BEFORE_NAVIGATION_START);
     abort_type_ = ABORT_NONE;
     abort_time_ = base::TimeTicks();
     return;
   }
   abort_type_ = abort_type;
   abort_time_ = timestamp;
+
+  if (is_browser_timestamp) {
+    ClampBrowserTimestampIfInterProcessTimeTickSkew(&abort_time_);
+  }
 }
 
 // static
 MetricsWebContentsObserver::MetricsWebContentsObserver(
     content::WebContents* web_contents,
     std::unique_ptr<PageLoadMetricsEmbedderInterface> embedder_interface)
     : content::WebContentsObserver(web_contents),
       in_foreground_(false),
       embedder_interface_(std::move(embedder_interface)),
       has_navigated_(false) {}
@@ skipping 75 matching lines @@
   // the MetricsWebContentsObserver owns them both list and they are torn down
   // after the PageLoadTracker. The PageLoadTracker does not hold on to
   // committed_load_ or navigation_handle beyond the scope of the constructor.
   provisional_loads_.insert(std::make_pair(
       navigation_handle,
       base::WrapUnique(new PageLoadTracker(
           in_foreground_, embedder_interface_.get(), currently_committed_url,
           navigation_handle, chain_size, chain_size_same_url))));
 }
 
+const PageLoadExtraInfo
+MetricsWebContentsObserver::GetPageLoadExtraInfoForCommittedLoad() {
+  DCHECK(committed_load_);
+  return committed_load_->ComputePageLoadExtraInfo();
+}
+
 void MetricsWebContentsObserver::DidFinishNavigation(
     content::NavigationHandle* navigation_handle) {
   if (!navigation_handle->IsInMainFrame())
     return;
 
   std::unique_ptr<PageLoadTracker> finished_nav(
       std::move(provisional_loads_[navigation_handle]));
   provisional_loads_.erase(navigation_handle);
 
   // There's a chance a navigation could have started before we were added to a
@@ skipping 12 matching lines @@
     net::Error error = navigation_handle->GetNetErrorCode();
 
     // net::OK: This case occurs when the NavigationHandle finishes and reports
     // !HasCommitted(), but reports no net::Error. This should not occur
     // pre-PlzNavigate, but afterwards it should represent the navigation
     // stopped by the user before it was ready to commit.
     // net::ERR_ABORTED: An aborted provisional load has error net::ERR_ABORTED.
     // Note that this can come from some non user-initiated errors, such as
     // downloads, or 204 responses. See crbug.com/542369.
     if ((error == net::OK) || (error == net::ERR_ABORTED)) {
-      finished_nav->NotifyAbort(ABORT_OTHER, base::TimeTicks::Now());
+      finished_nav->NotifyAbort(ABORT_OTHER, base::TimeTicks::Now(), true);
       aborted_provisional_loads_.push_back(std::move(finished_nav));
     }
 
     return;
   }
 
   // Don't treat a same-page nav as a new page load.
   if (navigation_handle->IsSamePage())
     return;
 
   // Notify other loads that they may have been aborted by this committed load.
   // Note that by using the committed navigation start as the abort cause, we
   // lose data on provisional loads that were aborted by other provisional
   // loads. Those will either be listed as ABORT_OTHER or as being aborted by
   // this load.
   NotifyAbortAllLoadsWithTimestamp(
       AbortTypeForPageTransition(navigation_handle->GetPageTransition()),
-      navigation_handle->NavigationStart());
+      navigation_handle->NavigationStart(), false);
 
   committed_load_ = std::move(finished_nav);
   aborted_provisional_loads_.clear();
 
   const GURL& browser_url = web_contents()->GetLastCommittedURL();
   const std::string& mime_type = web_contents()->GetContentsMimeType();
   DCHECK(!browser_url.is_empty());
   DCHECK(!mime_type.empty());
   committed_load_->set_renderer_tracked(
       IsRelevantNavigation(navigation_handle, browser_url, mime_type));
@@ skipping 52 matching lines @@
   }
 
   // If this is a crash, eagerly log the aborted provisional loads and the
   // committed load. |provisional_loads_| don't need to be destroyed here
   // because their lifetime is tied to the NavigationHandle.
   committed_load_.reset();
   aborted_provisional_loads_.clear();
 }
 
 void MetricsWebContentsObserver::NotifyAbortAllLoads(UserAbortType abort_type) {
-  NotifyAbortAllLoadsWithTimestamp(abort_type, base::TimeTicks::Now());
+  NotifyAbortAllLoadsWithTimestamp(abort_type, base::TimeTicks::Now(), true);
 }
 
 void MetricsWebContentsObserver::NotifyAbortAllLoadsWithTimestamp(
     UserAbortType abort_type,
-    base::TimeTicks timestamp) {
+    base::TimeTicks timestamp,
+    bool is_browser_timestamp) {
   if (committed_load_)
-    committed_load_->NotifyAbort(abort_type, timestamp);
+    committed_load_->NotifyAbort(abort_type, timestamp, is_browser_timestamp);
   for (const auto& kv : provisional_loads_) {
-    kv.second->NotifyAbort(abort_type, timestamp);
+    kv.second->NotifyAbort(abort_type, timestamp, is_browser_timestamp);
   }
   for (const auto& tracker : aborted_provisional_loads_) {
     if (tracker->IsLikelyProvisionalAbort(timestamp))
-      tracker->UpdateAbort(abort_type, timestamp);
+      tracker->UpdateAbort(abort_type, timestamp, is_browser_timestamp);
   }
   aborted_provisional_loads_.clear();
 }
 
 std::unique_ptr<PageLoadTracker>
 MetricsWebContentsObserver::NotifyAbortedProvisionalLoadsNewNavigation(
     content::NavigationHandle* new_navigation) {
   // If there are multiple aborted loads that can be attributed to this one,
   // just count the latest one for simplicity. Other loads will fall into the
   // OTHER bucket, though there shouldn't be very many.
   if (aborted_provisional_loads_.size() == 0)
     return nullptr;
   if (aborted_provisional_loads_.size() > 1)
     RecordInternalError(ERR_NAVIGATION_SIGNALS_MULIPLE_ABORTED_LOADS);
 
   std::unique_ptr<PageLoadTracker> last_aborted_load =
       std::move(aborted_provisional_loads_.back());
   aborted_provisional_loads_.pop_back();
 
   base::TimeTicks timestamp = new_navigation->NavigationStart();
   if (last_aborted_load->IsLikelyProvisionalAbort(timestamp))
-    last_aborted_load->UpdateAbort(ABORT_UNKNOWN_NAVIGATION, timestamp);
+    last_aborted_load->UpdateAbort(ABORT_UNKNOWN_NAVIGATION, timestamp, false);
 
   aborted_provisional_loads_.clear();
   return last_aborted_load;
 }
 
 void MetricsWebContentsObserver::OnTimingUpdated(
     content::RenderFrameHost* render_frame_host,
     const PageLoadTiming& timing,
     const PageLoadMetadata& metadata) {
   bool error = false;
@@ skipping 22 matching lines @@
 
   if (!committed_load_->UpdateTiming(timing, metadata)) {
     // If the page load tracker cannot update its timing, something is wrong
     // with the IPC (it's from another load, or it's invalid in some other way).
     // We expect this to be a rare occurrence.
     RecordInternalError(ERR_BAD_TIMING_IPC);
   }
 }
 
 }  // namespace page_load_metrics