cc: Add main frame timing info to frame timing tracker.

cc/trees/thread_proxy.cc

 // Copyright 2011 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 "cc/trees/thread_proxy.h"
 
 #include <algorithm>
 #include <string>
 
 #include "base/auto_reset.h"
@@ skipping 348 matching lines @@
                "ThreadProxy::DidSwapBuffersCompleteOnImplThread");
   DCHECK(IsImplThread());
   impl().scheduler->DidSwapBuffersComplete();
   Proxy::MainThreadTaskRunner()->PostTask(
       FROM_HERE,
       base::Bind(&ThreadProxy::DidCompleteSwapBuffers, main_thread_weak_ptr_));
 }
 
 void ThreadProxy::WillBeginImplFrame(const BeginFrameArgs& args) {
   impl().layer_tree_host_impl->WillBeginImplFrame(args);
+  impl().last_begin_impl_frame_args =
+      impl().layer_tree_host_impl->CurrentBeginFrameArgs();
 }
 
 void ThreadProxy::OnCanDrawStateChanged(bool can_draw) {
   TRACE_EVENT1(
       "cc", "ThreadProxy::OnCanDrawStateChanged", "can_draw", can_draw);
   DCHECK(IsImplThread());
   impl().scheduler->SetCanDraw(can_draw);
 }
 
 void ThreadProxy::NotifyReadyToActivate() {
@@ skipping 305 matching lines @@
 
   if (!impl().layer_tree_host_impl->settings().impl_side_painting) {
     DCHECK_GT(impl().layer_tree_host_impl->memory_allocation_limit_bytes(), 0u);
   }
   begin_main_frame_state->memory_allocation_limit_bytes =
       impl().layer_tree_host_impl->memory_allocation_limit_bytes();
   begin_main_frame_state->memory_allocation_priority_cutoff =
       impl().layer_tree_host_impl->memory_allocation_priority_cutoff();
   begin_main_frame_state->evicted_ui_resources =
       impl().layer_tree_host_impl->EvictedUIResourcesExist();
+  impl().last_begin_main_frame_args = begin_main_frame_state->begin_frame_args;

[brianderson, 2015/03/20 21:14:05]

If main_frame_before_activation_enabled is true in SchedulerSettings, it's
possible for this line to run twice before DidActivateSyncTree gets called once.

main_frame_before_activation_enabled is experimental, so this isn't important to
fix as part of your patch, but can you add a TODO here so we don't accidentally
break your code in the future?

Alternatively, make impl().last_begin_main_frame_args a queue.

[vmpstr, 2015/03/20 22:31:27]

What's the expected behavior (if say this is made non experimental) from this?
That is, in terms of measuring frame times, this would mean that we have
overlapping frames? If so, would we also end up with two activates?

[brianderson, 2015/03/20 23:01:58]

Yes, we would have overlapping frames and we would end up with two activates,
unless the second commit gets aborted.

That second commit can get aborted before the fist commit activates, which is an
interesting case... Maybe best to make this a TODO =)

[vmpstr, 2015/03/23 20:26:43]

Done.

   Proxy::MainThreadTaskRunner()->PostTask(
       FROM_HERE,
       base::Bind(&ThreadProxy::BeginMainFrame,
                  main_thread_weak_ptr_,
                  base::Passed(&begin_main_frame_state)));
   devtools_instrumentation::DidRequestMainThreadFrame(
       impl().layer_tree_host_id);
   impl().timing_history.DidBeginMainFrame();
 }
 
@@ skipping 224 matching lines @@
 
 void ThreadProxy::BeginMainFrameAbortedOnImplThread(
     CommitEarlyOutReason reason) {
   TRACE_EVENT1("cc", "ThreadProxy::BeginMainFrameAbortedOnImplThread", "reason",
                CommitEarlyOutReasonToString(reason));
   DCHECK(IsImplThread());
   DCHECK(impl().scheduler);
   DCHECK(impl().scheduler->CommitPending());
   DCHECK(!impl().layer_tree_host_impl->pending_tree());
 
-  if (CommitEarlyOutHandledCommit(reason))
+  if (CommitEarlyOutHandledCommit(reason)) {
     SetInputThrottledUntilCommitOnImplThread(false);
+    RecordMainFrameTiming();
+  }
   impl().layer_tree_host_impl->BeginMainFrameAborted(reason);
   impl().scheduler->BeginMainFrameAborted(reason);
 }
 
 void ThreadProxy::ScheduledActionAnimate() {
   TRACE_EVENT0("cc", "ThreadProxy::ScheduledActionAnimate");
   DCHECK(IsImplThread());
 
   // Don't animate if there is no root layer.
   // TODO(mithro): Both Animate and UpdateAnimationState already have a
@@ skipping 399 matching lines @@
 
   if (impl().completion_event_for_commit_held_on_tree_activation) {
     TRACE_EVENT_INSTANT0(
         "cc", "ReleaseCommitbyActivation", TRACE_EVENT_SCOPE_THREAD);
     DCHECK(impl().layer_tree_host_impl->settings().impl_side_painting);
     impl().completion_event_for_commit_held_on_tree_activation->Signal();
     impl().completion_event_for_commit_held_on_tree_activation = NULL;
   }
 
   impl().timing_history.DidActivateSyncTree();
+  RecordMainFrameTiming();

[brianderson, 2015/03/20 21:14:06]

Regarding the interval / prediction issue, we should be able to wait for the
next BeginImpFrame's frame_time instead of predicting it.

We always request one more BeginFrame than we need before going idle to avoid
excess toggling of SetNeedsBeginFrames. The logic that does that is here:
https://code.google.com/p/chromium/codesearch#chromium/src/cc/scheduler/sched...

Can you do something like:
1) Add a last_begin_main_frame_activated_args and assign it to
last_begin_main_frame_args here.
2) If last_begin_main_frame_activated_args.IsValid() in WillBeginImplFrame, call
RecordMainFrameTiming there.

[vmpstr, 2015/03/20 22:31:27]

I think that's an excellent idea. I'm guessing the whole kick-off one more frame
before becoming idle idea is sticking around, right? :)

Also, is this going to happen in the case of CommitEarlyOutHandledCommit?

[brianderson, 2015/03/20 23:01:58]

There are no plans to get rid of it. It's especially important for requesting
BeginFrames from the Browser where we want to hide the latency of the thread
hops. We are moving all platforms to that model.
No. Good catch. 

You'd need to modify SchedulerStateMachine::UpdateStateOnCommit(true) to somehow
make ProactiveBeginFrameWanted true, which is something we should probably do
anyway.

[mithro-old, 2015/03/23 00:15:08]

I agree with Brian here.

[vmpstr, 2015/03/23 20:26:43]

Done.

 }
 
 void ThreadProxy::DidPrepareTiles() {
   DCHECK(IsImplThread());
   impl().scheduler->DidPrepareTiles();
 }
 
 void ThreadProxy::DidCompletePageScaleAnimationOnImplThread() {
   DCHECK(IsImplThread());
   Proxy::MainThreadTaskRunner()->PostTask(
       FROM_HERE, base::Bind(&ThreadProxy::DidCompletePageScaleAnimation,
                             main_thread_weak_ptr_));
 }
 
+void ThreadProxy::RecordMainFrameTiming() {
+  // Last begin main frame args records the frame args that we last sent to the
+  // main thread. Last begin impl frame args, on the other hand, records the
+  // last time we started an impl frame which should be the frame during which
+  // this call is being run.
+  impl().layer_tree_host_impl->RecordMainFrameTiming(
+      impl().last_begin_main_frame_args, impl().last_begin_impl_frame_args);

[brianderson, 2015/03/20 21:14:06]

Although this is slightly wrong right now because begin_main_frame_args uses
Now() for it's frame time, while begin_impl_frame_args uses the original frame
time, I think it's good enough to land.

Tim's patch should make this 100% correct once it lands and I don't see a reason
to introduce workarounds in this patch, especially since getting this 100%
correct isn't urgent.

[vmpstr, 2015/03/20 22:31:27]

Acknowledged.

+}
+
 }  // namespace cc