Add a bunch of vlogs to RAF related calls in chrome.

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 659 matching lines @@
 }
 
 void ThreadProxy::FinishAllRenderingOnImplThread(CompletionEvent* completion) {
   TRACE_EVENT0("cc", "ThreadProxy::FinishAllRenderingOnImplThread");
   DCHECK(IsImplThread());
   impl().layer_tree_host_impl->FinishAllRendering();
   completion->Signal();
 }
 
 void ThreadProxy::ScheduledActionSendBeginMainFrame() {
+  VLOG(2) << "ThreadProxy::ScheduledActionSendBeginMainFrame";
   unsigned int begin_frame_id = nextBeginFrameId++;
   benchmark_instrumentation::ScopedBeginFrameTask begin_frame_task(
       benchmark_instrumentation::kSendBeginFrame, begin_frame_id);
   scoped_ptr<BeginMainFrameAndCommitState> begin_main_frame_state(
       new BeginMainFrameAndCommitState);
   begin_main_frame_state->begin_frame_id = begin_frame_id;
   begin_main_frame_state->begin_frame_args =
       impl().layer_tree_host_impl->CurrentBeginFrameArgs();
   begin_main_frame_state->scroll_info =
       impl().layer_tree_host_impl->ProcessScrollDeltas();
@@ skipping 18 matching lines @@
 }
 
 void ThreadProxy::BeginMainFrame(
     scoped_ptr<BeginMainFrameAndCommitState> begin_main_frame_state) {
   benchmark_instrumentation::ScopedBeginFrameTask begin_frame_task(
       benchmark_instrumentation::kDoBeginFrame,
       begin_main_frame_state->begin_frame_id);
   TRACE_EVENT_SYNTHETIC_DELAY_BEGIN("cc.BeginMainFrame");
   DCHECK(IsMainThread());
 
+  VLOG(2) << "ThreadProxy::BeginMainFrame - BEGIN";
+
   if (main().defer_commits) {
     main().pending_deferred_commit = begin_main_frame_state.Pass();
     layer_tree_host()->DidDeferCommit();
     TRACE_EVENT_INSTANT0(
         "cc", "EarlyOut_DeferCommits", TRACE_EVENT_SCOPE_THREAD);
+    VLOG(2) << "ThreadProxy::BeginMainFrame: EarlyOut_DeferCommits";
     return;
   }
 
   // If the commit finishes, LayerTreeHost will transfer its swap promises to
   // LayerTreeImpl. The destructor of ScopedSwapPromiseChecker aborts the
   // remaining swap promises.
   ScopedAbortRemainingSwapPromises swap_promise_checker(layer_tree_host());
 
   main().commit_requested = false;
   main().commit_request_sent_to_impl_thread = false;
   main().animate_requested = false;
 
   if (!layer_tree_host()->visible()) {
     TRACE_EVENT_INSTANT0("cc", "EarlyOut_NotVisible", TRACE_EVENT_SCOPE_THREAD);
+    VLOG(2) << "ThreadProxy::BeginMainFrame: EarlyOut_NotVisible";
     bool did_handle = false;
     Proxy::ImplThreadTaskRunner()->PostTask(
         FROM_HERE,
         base::Bind(&ThreadProxy::BeginMainFrameAbortedOnImplThread,
                    impl_thread_weak_ptr_,
                    did_handle));
     return;
   }
 
   if (layer_tree_host()->output_surface_lost()) {
     TRACE_EVENT_INSTANT0(
         "cc", "EarlyOut_OutputSurfaceLost", TRACE_EVENT_SCOPE_THREAD);
+    VLOG(2) << "ThreadProxy::BeginMainFrame: EarlyOut_OutputSurfaceLost";
     bool did_handle = false;
     Proxy::ImplThreadTaskRunner()->PostTask(
         FROM_HERE,
         base::Bind(&ThreadProxy::BeginMainFrameAbortedOnImplThread,
                    impl_thread_weak_ptr_,
                    did_handle));
     return;
   }
 
   // Do not notify the impl thread of commit requests that occur during
@@ skipping 51 matching lines @@
 
   bool updated = layer_tree_host()->UpdateLayers(queue.get());
 
   layer_tree_host()->WillCommit();
 
   // Before calling animate, we set main().animate_requested to false. If it is
   // true now, it means SetNeedAnimate was called again, but during a state when
   // main().commit_request_sent_to_impl_thread = true. We need to force that
   // call to happen again now so that the commit request is sent to the impl
   // thread.
   if (main().animate_requested) {

[Ken Russell (switch to Gerrit), 2014/08/29 22:25:43]

Should this branch be instrumented too? As well as stuff in SetNeedsAnimate?

[Zhenyao Mo, 2014/08/29 23:11:11]

The logging I added are on the direct call stack to serve RAF.  I think they are
enough to confirm is the root cause of the problem comes from scheduler.  Once
it is confirmed, we can add more logs to digger further.

     // Forces SetNeedsAnimate to consider posting a commit task.
     main().animate_requested = false;
     SetNeedsAnimate();
   }
 
   if (!updated && can_cancel_this_commit) {
     TRACE_EVENT_INSTANT0("cc", "EarlyOut_NoUpdates", TRACE_EVENT_SCOPE_THREAD);
+    VLOG(2) << "ThreadProxy::BeginMainFrame: EarlyOut_NoUpdates";
     bool did_handle = true;
     Proxy::ImplThreadTaskRunner()->PostTask(
         FROM_HERE,
         base::Bind(&ThreadProxy::BeginMainFrameAbortedOnImplThread,
                    impl_thread_weak_ptr_,
                    did_handle));
 
     // Although the commit is internally aborted, this is because it has been
     // detected to be a no-op.  From the perspective of an embedder, this commit
     // went through, and input should no longer be throttled, etc.
@@ skipping 552 matching lines @@
 
   impl().timing_history.DidActivateSyncTree();
 }
 
 void ThreadProxy::DidManageTiles() {
   DCHECK(IsImplThread());
   impl().scheduler->DidManageTiles();
 }
 
 }  // namespace cc