From d704c875efd1204a4128d66685fc95b204dc353d Mon Sep 17 00:00:00 2001 From: vmpstr Date: Fri, 3 Apr 2015 13:29:51 -0700 Subject: [PATCH] cc: Add main frame timing info to frame timing tracker. This patch adds main frame timing info to frame timing tracker. The main frame start time is the timestamp of the frame in which we did a SendBeginMainFrame. The "end" of the frame is the timestamp of the beginning of the frame that follows the frame in which we activated. We report start and end_time on each of the frames. If a main frame is aborted, then we don't report the time unless we aborted due to the fact that there were no changes (ie a "successful" frame). R=danakj, brianderson, mpb@chromium.org Review URL: https://codereview.chromium.org/914403003 Cr-Commit-Position: refs/heads/master@{#323806} --- cc/debug/frame_timing_tracker.cc | 47 +++++++- cc/debug/frame_timing_tracker.h | 26 ++++- cc/debug/frame_timing_tracker_unittest.cc | 175 ++++++++++++++++++++++++------ cc/layers/layer_impl.cc | 5 + cc/layers/layer_impl.h | 1 + cc/trees/layer_tree_host_impl.cc | 14 +++ cc/trees/layer_tree_host_impl.h | 13 +++ cc/trees/layer_tree_host_unittest.cc | 39 +++++-- cc/trees/layer_tree_impl.cc | 15 ++- cc/trees/layer_tree_impl.h | 2 + cc/trees/thread_proxy.cc | 21 +++- cc/trees/thread_proxy.h | 4 + 12 files changed, 309 insertions(+), 53 deletions(-) diff --git a/cc/debug/frame_timing_tracker.cc b/cc/debug/frame_timing_tracker.cc index 009d298b3b8f..50aa92be5aab 100644 --- a/cc/debug/frame_timing_tracker.cc +++ b/cc/debug/frame_timing_tracker.cc @@ -21,6 +21,16 @@ FrameTimingTracker::CompositeTimingEvent::CompositeTimingEvent( FrameTimingTracker::CompositeTimingEvent::~CompositeTimingEvent() { } +FrameTimingTracker::MainFrameTimingEvent::MainFrameTimingEvent( + int frame_id, + base::TimeTicks timestamp, + base::TimeTicks end_time) + : frame_id(frame_id), timestamp(timestamp), end_time(end_time) { +} + +FrameTimingTracker::MainFrameTimingEvent::~MainFrameTimingEvent() { +} + // static scoped_ptr FrameTimingTracker::Create() { return make_scoped_ptr(new FrameTimingTracker); @@ -37,23 +47,52 @@ void FrameTimingTracker::SaveTimeStamps( const std::vector& frame_ids) { if (!composite_events_) composite_events_.reset(new CompositeTimingSet); - for (const auto& pair : frame_ids) + for (const auto& pair : frame_ids) { (*composite_events_)[pair.second].push_back( CompositeTimingEvent(pair.first, timestamp)); + } +} + +void FrameTimingTracker::SaveMainFrameTimeStamps( + const std::vector& request_ids, + base::TimeTicks main_frame_time, + base::TimeTicks end_time, + int source_frame_number) { + if (!main_frame_events_) + main_frame_events_.reset(new MainFrameTimingSet); + for (const auto& request : request_ids) { + std::vector& events = (*main_frame_events_)[request]; + events.push_back( + MainFrameTimingEvent(source_frame_number, main_frame_time, end_time)); + } } scoped_ptr -FrameTimingTracker::GroupCountsByRectId() { +FrameTimingTracker::GroupCompositeCountsByRectId() { if (!composite_events_) return make_scoped_ptr(new CompositeTimingSet); - scoped_ptr composite_info(new CompositeTimingSet); - for (auto& infos : *composite_events_) + for (auto& infos : *composite_events_) { std::sort( infos.second.begin(), infos.second.end(), [](const CompositeTimingEvent& lhs, const CompositeTimingEvent& rhs) { return lhs.timestamp < rhs.timestamp; }); + } return composite_events_.Pass(); } +scoped_ptr +FrameTimingTracker::GroupMainFrameCountsByRectId() { + if (!main_frame_events_) + return make_scoped_ptr(new MainFrameTimingSet); + for (auto& infos : *main_frame_events_) { + std::sort( + infos.second.begin(), infos.second.end(), + [](const MainFrameTimingEvent& lhs, const MainFrameTimingEvent& rhs) { + return lhs.timestamp < rhs.timestamp; + }); + } + return main_frame_events_.Pass(); +} + } // namespace cc diff --git a/cc/debug/frame_timing_tracker.h b/cc/debug/frame_timing_tracker.h index 019fe794472a..336499319739 100644 --- a/cc/debug/frame_timing_tracker.h +++ b/cc/debug/frame_timing_tracker.h @@ -32,6 +32,20 @@ class CC_EXPORT FrameTimingTracker { using CompositeTimingSet = base::hash_map>; + struct CC_EXPORT MainFrameTimingEvent { + MainFrameTimingEvent(int frame_id, + base::TimeTicks timestamp, + base::TimeTicks end_time); + ~MainFrameTimingEvent(); + + int frame_id; + base::TimeTicks timestamp; + base::TimeTicks end_time; + }; + + using MainFrameTimingSet = + base::hash_map>; + static scoped_ptr Create(); ~FrameTimingTracker(); @@ -41,7 +55,11 @@ class CC_EXPORT FrameTimingTracker { // [ {f_id1,r_id1,t1}, {f_id2,r_id1,t2}, {f_id3,r_id2,t3} ] // ====> // [ {r_id1,<{f_id1,t1},{f_id2,t2}>}, {r_id2,<{f_id3,t3}>} ] - scoped_ptr GroupCountsByRectId(); + scoped_ptr GroupCompositeCountsByRectId(); + + // This routine takes all of the individual MainFrameEvents stored in the + // tracker and collects them by "rect_id", as in the example below. + scoped_ptr GroupMainFrameCountsByRectId(); // This routine takes a timestamp and an array of frame_id,rect_id pairs // and generates CompositeTimingEvents (frame_id, timestamp) and adds them to @@ -50,10 +68,16 @@ class CC_EXPORT FrameTimingTracker { void SaveTimeStamps(base::TimeTicks timestamp, const std::vector& frame_ids); + void SaveMainFrameTimeStamps(const std::vector& request_ids, + base::TimeTicks main_frame_time, + base::TimeTicks end_time, + int source_frame_number); + private: FrameTimingTracker(); scoped_ptr composite_events_; + scoped_ptr main_frame_events_; DISALLOW_COPY_AND_ASSIGN(FrameTimingTracker); }; diff --git a/cc/debug/frame_timing_tracker_unittest.cc b/cc/debug/frame_timing_tracker_unittest.cc index 85f571611ace..b5574435fbcf 100644 --- a/cc/debug/frame_timing_tracker_unittest.cc +++ b/cc/debug/frame_timing_tracker_unittest.cc @@ -2,6 +2,7 @@ // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. +#include #include #include "base/time/time.h" @@ -13,17 +14,50 @@ namespace cc { namespace { -static std::string ToString( +std::string CompositeToString( scoped_ptr timingset) { scoped_refptr value = new base::trace_event::TracedValue(); value->BeginArray("values"); - for (const auto& it : *timingset) { + std::set rect_ids; + for (const auto& pair : *timingset) + rect_ids.insert(pair.first); + + for (const auto& rect_id : rect_ids) { + auto& events = (*timingset)[rect_id]; + value->BeginDictionary(); + value->SetInteger("rect_id", rect_id); + value->BeginArray("events"); + for (const auto& event : events) { + value->BeginDictionary(); + value->SetInteger("frame_id", event.frame_id); + value->SetInteger("timestamp", event.timestamp.ToInternalValue()); + value->EndDictionary(); + } + value->EndArray(); + value->EndDictionary(); + } + value->EndArray(); + return value->ToString(); +} + +std::string MainFrameToString( + scoped_ptr timingset) { + scoped_refptr value = + new base::trace_event::TracedValue(); + value->BeginArray("values"); + std::set rect_ids; + for (const auto& pair : *timingset) + rect_ids.insert(pair.first); + + for (const auto& rect_id : rect_ids) { + auto& events = (*timingset)[rect_id]; value->BeginDictionary(); - value->SetInteger("rect_id", it.first); + value->SetInteger("rect_id", rect_id); value->BeginArray("events"); - for (const auto& event : it.second) { + for (const auto& event : events) { value->BeginDictionary(); + value->SetInteger("end_time", event.end_time.ToInternalValue()); value->SetInteger("frame_id", event.frame_id); value->SetInteger("timestamp", event.timestamp.ToInternalValue()); value->EndDictionary(); @@ -37,14 +71,27 @@ static std::string ToString( TEST(FrameTimingTrackerTest, DefaultTrackerIsEmpty) { scoped_ptr tracker(FrameTimingTracker::Create()); - EXPECT_EQ("{\"values\":[]}", ToString(tracker->GroupCountsByRectId())); + EXPECT_EQ("{\"values\":[]}", + CompositeToString(tracker->GroupCompositeCountsByRectId())); + EXPECT_EQ("{\"values\":[]}", + MainFrameToString(tracker->GroupMainFrameCountsByRectId())); } TEST(FrameTimingTrackerTest, NoFrameIdsIsEmpty) { scoped_ptr tracker(FrameTimingTracker::Create()); std::vector> ids; tracker->SaveTimeStamps(base::TimeTicks::FromInternalValue(100), ids); - EXPECT_EQ("{\"values\":[]}", ToString(tracker->GroupCountsByRectId())); + EXPECT_EQ("{\"values\":[]}", + CompositeToString(tracker->GroupCompositeCountsByRectId())); +} + +TEST(FrameTimingTrackerTest, NoRectIdsYieldsNoMainFrameEvents) { + scoped_ptr tracker(FrameTimingTracker::Create()); + tracker->SaveMainFrameTimeStamps(std::vector(), + base::TimeTicks::FromInternalValue(100), + base::TimeTicks::FromInternalValue(110), 1); + EXPECT_EQ("{\"values\":[]}", + MainFrameToString(tracker->GroupMainFrameCountsByRectId())); } TEST(FrameTimingTrackerTest, OneFrameId) { @@ -55,7 +102,20 @@ TEST(FrameTimingTrackerTest, OneFrameId) { EXPECT_EQ( "{\"values\":[{\"events\":[" "{\"frame_id\":1,\"timestamp\":100}],\"rect_id\":2}]}", - ToString(tracker->GroupCountsByRectId())); + CompositeToString(tracker->GroupCompositeCountsByRectId())); +} + +TEST(FrameTimingTrackerTest, OneMainFrameRect) { + scoped_ptr tracker(FrameTimingTracker::Create()); + std::vector rect_ids; + rect_ids.push_back(1); + tracker->SaveMainFrameTimeStamps(rect_ids, + base::TimeTicks::FromInternalValue(100), + base::TimeTicks::FromInternalValue(110), 2); + EXPECT_EQ( + "{\"values\":[{\"events\":[" + "{\"end_time\":110,\"frame_id\":2,\"timestamp\":100}],\"rect_id\":1}]}", + MainFrameToString(tracker->GroupMainFrameCountsByRectId())); } TEST(FrameTimingTrackerTest, UnsortedTimestampsIds) { @@ -70,7 +130,28 @@ TEST(FrameTimingTrackerTest, UnsortedTimestampsIds) { "{\"frame_id\":1,\"timestamp\":100}," "{\"frame_id\":1,\"timestamp\":200}," "{\"frame_id\":1,\"timestamp\":400}],\"rect_id\":2}]}", - ToString(tracker->GroupCountsByRectId())); + CompositeToString(tracker->GroupCompositeCountsByRectId())); +} + +TEST(FrameTimingTrackerTest, MainFrameUnsortedTimestamps) { + scoped_ptr tracker(FrameTimingTracker::Create()); + std::vector rect_ids; + rect_ids.push_back(2); + tracker->SaveMainFrameTimeStamps(rect_ids, + base::TimeTicks::FromInternalValue(200), + base::TimeTicks::FromInternalValue(280), 1); + tracker->SaveMainFrameTimeStamps(rect_ids, + base::TimeTicks::FromInternalValue(400), + base::TimeTicks::FromInternalValue(470), 1); + tracker->SaveMainFrameTimeStamps(rect_ids, + base::TimeTicks::FromInternalValue(100), + base::TimeTicks::FromInternalValue(160), 1); + EXPECT_EQ( + "{\"values\":[{\"events\":[" + "{\"end_time\":160,\"frame_id\":1,\"timestamp\":100}," + "{\"end_time\":280,\"frame_id\":1,\"timestamp\":200}," + "{\"end_time\":470,\"frame_id\":1,\"timestamp\":400}],\"rect_id\":2}]}", + MainFrameToString(tracker->GroupMainFrameCountsByRectId())); } TEST(FrameTimingTrackerTest, MultipleFrameIds) { @@ -91,34 +172,56 @@ TEST(FrameTimingTrackerTest, MultipleFrameIds) { ids100.push_back(std::make_pair(3, 4)); tracker->SaveTimeStamps(base::TimeTicks::FromInternalValue(100), ids100); - std::string result = ToString(tracker->GroupCountsByRectId()); - - EXPECT_EQ(strlen( - "{\"values\":[{\"events\":[" - "{\"frame_id\":3,\"timestamp\":100}," - "{\"frame_id\":1,\"timestamp\":200}," - "{\"frame_id\":2,\"timestamp\":400}],\"rect_id\":2}," - "{\"events\":[" - "{\"frame_id\":2,\"timestamp\":100}," - "{\"frame_id\":1,\"timestamp\":200}],\"rect_id\":3}," - "{\"events\":[" - "{\"frame_id\":3,\"timestamp\":100}],\"rect_id\":4}" - "]}"), - result.size()); - EXPECT_NE(std::string::npos, - result.find( - "{\"frame_id\":3,\"timestamp\":100}," - "{\"frame_id\":1,\"timestamp\":200}," - "{\"frame_id\":2,\"timestamp\":400}],\"rect_id\":2}")); - EXPECT_NE(std::string::npos, - result.find( - "{\"events\":[" - "{\"frame_id\":2,\"timestamp\":100}," - "{\"frame_id\":1,\"timestamp\":200}],\"rect_id\":3}")); - EXPECT_NE(std::string::npos, - result.find( - "{\"events\":[" - "{\"frame_id\":3,\"timestamp\":100}],\"rect_id\":4}")); + EXPECT_EQ( + "{\"values\":[{\"events\":[" + "{\"frame_id\":3,\"timestamp\":100}," + "{\"frame_id\":1,\"timestamp\":200}," + "{\"frame_id\":2,\"timestamp\":400}],\"rect_id\":2}," + "{\"events\":[" + "{\"frame_id\":2,\"timestamp\":100}," + "{\"frame_id\":1,\"timestamp\":200}],\"rect_id\":3}," + "{\"events\":[" + "{\"frame_id\":3,\"timestamp\":100}],\"rect_id\":4}" + "]}", + CompositeToString(tracker->GroupCompositeCountsByRectId())); +} + +TEST(FrameTimingTrackerTest, MultipleMainFrameEvents) { + scoped_ptr tracker(FrameTimingTracker::Create()); + + std::vector rect_ids200; + rect_ids200.push_back(2); + rect_ids200.push_back(3); + tracker->SaveMainFrameTimeStamps(rect_ids200, + base::TimeTicks::FromInternalValue(200), + base::TimeTicks::FromInternalValue(220), 1); + + std::vector rect_ids400; + rect_ids400.push_back(2); + tracker->SaveMainFrameTimeStamps(rect_ids400, + base::TimeTicks::FromInternalValue(400), + base::TimeTicks::FromInternalValue(440), 2); + + std::vector rect_ids100; + rect_ids100.push_back(2); + rect_ids100.push_back(3); + rect_ids100.push_back(4); + tracker->SaveMainFrameTimeStamps(rect_ids100, + base::TimeTicks::FromInternalValue(100), + base::TimeTicks::FromInternalValue(110), 3); + + EXPECT_EQ( + "{\"values\":[{\"events\":[" + "{\"end_time\":110,\"frame_id\":3,\"timestamp\":100}," + "{\"end_time\":220,\"frame_id\":1,\"timestamp\":200}," + "{\"end_time\":440,\"frame_id\":2,\"timestamp\":400}],\"rect_id\":2}," + "{\"events\":[" + "{\"end_time\":110,\"frame_id\":3,\"timestamp\":100}," + "{\"end_time\":220,\"frame_id\":1,\"timestamp\":200}],\"rect_id\":3}," + "{\"events\":[" + "{\"end_time\":110,\"frame_id\":3,\"timestamp\":100}],\"rect_id\":4}" + "]}", + MainFrameToString(tracker->GroupMainFrameCountsByRectId())); } } // namespace diff --git a/cc/layers/layer_impl.cc b/cc/layers/layer_impl.cc index b4ba876d0944..3ffeb730bfcb 100644 --- a/cc/layers/layer_impl.cc +++ b/cc/layers/layer_impl.cc @@ -1044,6 +1044,11 @@ void LayerImpl::PassFrameTimingRequests( SetNeedsPushProperties(); } +void LayerImpl::GatherFrameTimingRequestIds(std::vector* request_ids) { + for (const auto& request : frame_timing_requests_) + request_ids->push_back(request.id()); +} + void LayerImpl::SetTransform(const gfx::Transform& transform) { if (transform_ == transform) return; diff --git a/cc/layers/layer_impl.h b/cc/layers/layer_impl.h index e0c42f0bfecf..b13dce911a61 100644 --- a/cc/layers/layer_impl.h +++ b/cc/layers/layer_impl.h @@ -596,6 +596,7 @@ class CC_EXPORT LayerImpl : public LayerAnimationValueObserver, const std::vector& frame_timing_requests() const { return frame_timing_requests_; } + void GatherFrameTimingRequestIds(std::vector* request_ids); SyncedScrollOffset* synced_scroll_offset() { return scroll_offset_.get(); } diff --git a/cc/trees/layer_tree_host_impl.cc b/cc/trees/layer_tree_host_impl.cc index fd685437111b..a54be78ba223 100644 --- a/cc/trees/layer_tree_host_impl.cc +++ b/cc/trees/layer_tree_host_impl.cc @@ -2120,6 +2120,20 @@ void LayerTreeHostImpl::CreateResourceAndTileTaskWorkerPool( settings_.renderer_settings.refresh_rate)); } +void LayerTreeHostImpl::RecordMainFrameTiming( + const BeginFrameArgs& start_of_main_frame_args, + const BeginFrameArgs& expected_next_main_frame_args) { + std::vector request_ids; + active_tree_->GatherFrameTimingRequestIds(&request_ids); + if (request_ids.empty()) + return; + + base::TimeTicks start_time = start_of_main_frame_args.frame_time; + base::TimeTicks end_time = expected_next_main_frame_args.frame_time; + frame_timing_tracker_->SaveMainFrameTimeStamps( + request_ids, start_time, end_time, active_tree_->source_frame_number()); +} + void LayerTreeHostImpl::DestroyTileManager() { tile_manager_ = nullptr; resource_pool_ = nullptr; diff --git a/cc/trees/layer_tree_host_impl.h b/cc/trees/layer_tree_host_impl.h index 778f56200a43..74ca5d8257b7 100644 --- a/cc/trees/layer_tree_host_impl.h +++ b/cc/trees/layer_tree_host_impl.h @@ -536,6 +536,19 @@ class CC_EXPORT LayerTreeHostImpl const gfx::Point& viewport_point, bool is_wheel_scroll); + // Record main frame timing information. + // |start_of_main_frame_args| is the BeginFrameArgs of the beginning of the + // main frame (ie the frame that kicked off the main frame). + // |expected_next_main_frame_args| is the BeginFrameArgs of the frame that + // follows the completion of the main frame (whether it is activation or some + // other completion, such as early out). Note that if there is a main frame + // scheduled in that frame, then this BeginFrameArgs will become the main + // frame args. However, if no such frame is scheduled, then this _would_ be + // the main frame args if it was scheduled. + void RecordMainFrameTiming( + const BeginFrameArgs& start_of_main_frame_args, + const BeginFrameArgs& expected_next_main_frame_args); + protected: LayerTreeHostImpl( const LayerTreeSettings& settings, diff --git a/cc/trees/layer_tree_host_unittest.cc b/cc/trees/layer_tree_host_unittest.cc index 00f4f9aa68dd..80b48d04addc 100644 --- a/cc/trees/layer_tree_host_unittest.cc +++ b/cc/trees/layer_tree_host_unittest.cc @@ -6463,16 +6463,35 @@ class LayerTreeHostTestFrameTimingRequestsSaveTimestamps // TODO(vmpstr): Change this to read things from the main thread when this // information is propagated to the main thread (not yet implemented). FrameTimingTracker* tracker = host_impl->frame_timing_tracker(); - scoped_ptr timing_set = - tracker->GroupCountsByRectId(); - EXPECT_EQ(1u, timing_set->size()); - auto rect_1_it = timing_set->find(1); - EXPECT_TRUE(rect_1_it != timing_set->end()); - const auto& timing_events = rect_1_it->second; - EXPECT_EQ(1u, timing_events.size()); - EXPECT_EQ(host_impl->active_tree()->source_frame_number(), - timing_events[0].frame_id); - EXPECT_GT(timing_events[0].timestamp, base::TimeTicks()); + + // Check composite events. + { + scoped_ptr timing_set = + tracker->GroupCompositeCountsByRectId(); + EXPECT_EQ(1u, timing_set->size()); + auto rect_1_it = timing_set->find(1); + EXPECT_TRUE(rect_1_it != timing_set->end()); + const auto& timing_events = rect_1_it->second; + EXPECT_EQ(1u, timing_events.size()); + EXPECT_EQ(host_impl->active_tree()->source_frame_number(), + timing_events[0].frame_id); + EXPECT_GT(timing_events[0].timestamp, base::TimeTicks()); + } + + // Check main frame events. + { + scoped_ptr timing_set = + tracker->GroupMainFrameCountsByRectId(); + EXPECT_EQ(2u, timing_set->size()); + auto rect_1_it = timing_set->find(1); + EXPECT_TRUE(rect_1_it != timing_set->end()); + const auto& timing_events = rect_1_it->second; + EXPECT_EQ(1u, timing_events.size()); + EXPECT_EQ(host_impl->active_tree()->source_frame_number(), + timing_events[0].frame_id); + EXPECT_GT(timing_events[0].timestamp, base::TimeTicks()); + EXPECT_GT(timing_events[0].end_time, timing_events[0].timestamp); + } EndTest(); } diff --git a/cc/trees/layer_tree_impl.cc b/cc/trees/layer_tree_impl.cc index b5f8aed2307b..c2edaae65d30 100644 --- a/cc/trees/layer_tree_impl.cc +++ b/cc/trees/layer_tree_impl.cc @@ -34,7 +34,6 @@ #include "ui/gfx/geometry/vector2d_conversions.h" namespace cc { - // This class exists to split the LayerScrollOffsetDelegate between the // InnerViewportScrollLayer and the OuterViewportScrollLayer in a manner // that never requires the embedder or LayerImpl to know about. @@ -135,6 +134,20 @@ void LayerTreeImpl::RecreateResources() { } } +void LayerTreeImpl::GatherFrameTimingRequestIds( + std::vector* request_ids) { + if (!root_layer_) + return; + + // TODO(vmpstr): Early out if there are no requests on any of the layers. For + // that, we need to inform LayerTreeImpl whenever there are requests when we + // get them. + LayerTreeHostCommon::CallFunctionForSubtree( + root_layer_.get(), [request_ids](LayerImpl* layer) { + layer->GatherFrameTimingRequestIds(request_ids); + }); +} + void LayerTreeImpl::SetRootLayer(scoped_ptr layer) { if (inner_viewport_scroll_layer_) inner_viewport_scroll_layer_->SetScrollOffsetDelegate(NULL); diff --git a/cc/trees/layer_tree_impl.h b/cc/trees/layer_tree_impl.h index a8c58d1c5206..8ab42634cc83 100644 --- a/cc/trees/layer_tree_impl.h +++ b/cc/trees/layer_tree_impl.h @@ -332,6 +332,8 @@ class CC_EXPORT LayerTreeImpl { scoped_ptr pending_animation); scoped_ptr TakePendingPageScaleAnimation(); + void GatherFrameTimingRequestIds(std::vector* request_ids); + protected: explicit LayerTreeImpl( LayerTreeHostImpl* layer_tree_host_impl, diff --git a/cc/trees/thread_proxy.cc b/cc/trees/thread_proxy.cc index 2253a4f65f6b..beaf92f50b47 100644 --- a/cc/trees/thread_proxy.cc +++ b/cc/trees/thread_proxy.cc @@ -366,6 +366,16 @@ void ThreadProxy::DidSwapBuffersCompleteOnImplThread() { void ThreadProxy::WillBeginImplFrame(const BeginFrameArgs& args) { impl().layer_tree_host_impl->WillBeginImplFrame(args); + if (impl().last_processed_begin_main_frame_args.IsValid()) { + // Last processed begin main frame args records the frame args that we sent + // to the main thread for the last frame that we've processed. If that is + // set, that means the current frame is one past the frame in which we've + // finished the processing. + impl().layer_tree_host_impl->RecordMainFrameTiming( + impl().last_processed_begin_main_frame_args, + impl().layer_tree_host_impl->CurrentBeginFrameArgs()); + impl().last_processed_begin_main_frame_args = BeginFrameArgs(); + } } void ThreadProxy::OnCanDrawStateChanged(bool can_draw) { @@ -691,6 +701,10 @@ void ThreadProxy::ScheduledActionSendBeginMainFrame() { impl().layer_tree_host_impl->memory_allocation_priority_cutoff(); begin_main_frame_state->evicted_ui_resources = impl().layer_tree_host_impl->EvictedUIResourcesExist(); + // TODO(vmpstr): This needs to be fixed if + // main_frame_before_activation_enabled is set, since we might run this code + // twice before recording a duration. crbug.com/469824 + impl().last_begin_main_frame_args = begin_main_frame_state->begin_frame_args; Proxy::MainThreadTaskRunner()->PostTask( FROM_HERE, base::Bind(&ThreadProxy::BeginMainFrame, @@ -935,8 +949,11 @@ void ThreadProxy::BeginMainFrameAbortedOnImplThread( DCHECK(impl().scheduler->CommitPending()); DCHECK(!impl().layer_tree_host_impl->pending_tree()); - if (CommitEarlyOutHandledCommit(reason)) + if (CommitEarlyOutHandledCommit(reason)) { SetInputThrottledUntilCommitOnImplThread(false); + impl().last_processed_begin_main_frame_args = + impl().last_begin_main_frame_args; + } impl().layer_tree_host_impl->BeginMainFrameAborted(reason); impl().scheduler->BeginMainFrameAborted(reason); } @@ -1367,6 +1384,8 @@ void ThreadProxy::DidActivateSyncTree() { } impl().timing_history.DidActivateSyncTree(); + impl().last_processed_begin_main_frame_args = + impl().last_begin_main_frame_args; } void ThreadProxy::DidPrepareTiles() { diff --git a/cc/trees/thread_proxy.h b/cc/trees/thread_proxy.h index 1f0661160001..d8f47480aaa0 100644 --- a/cc/trees/thread_proxy.h +++ b/cc/trees/thread_proxy.h @@ -143,6 +143,10 @@ class CC_EXPORT ThreadProxy : public Proxy, scoped_ptr external_begin_frame_source; + // Values used to keep track of frame durations. Used only in frame timing. + BeginFrameArgs last_begin_main_frame_args; + BeginFrameArgs last_processed_begin_main_frame_args; + scoped_ptr layer_tree_host_impl; base::WeakPtrFactory weak_factory; }; -- 2.11.4.GIT