Issue metadata
Sign in to add a comment
|
DCHECK: (last_begin_frame_args_.source_id != last_args.source_id) || (last_begin_frame_args_.sequence_number > last_args.sequence_number) |
||||||||||||||||||||||
Issue descriptionWhile debugging 735196, I hit this DCHECK. I don't think it's related to the bug I'm investigating, and I can't reliably repro, but hopefully the dcheck contains enough information. I navigated to http://www.20minutes.fr/elections/resultats/ on linux debug build and scrolled around for a bit before hitting: [1669:1669:0626/110455.744552:FATAL:begin_frame_source.cc(345)] Check failed: (last_begin_frame_args_.source_id != last_args.source_id) || (last_begin_frame_args_.sequence_number > last_args.sequence_number). current {"created_from":"CreateBeginFrameArgs@../../cc/scheduler/begin_frame_source.cc:180","deadline_us":8372272014078.0,"frame_time_us":8372272012929.0,"interval_us":16666.0,"on_critical_path":true,"sequence_number":1654,"source_id":2,"subtype":"NORMAL","type":"BeginFrameArgs"}, last {"created_from":"CreateBeginFrameArgs@../../cc/scheduler/begin_frame_source.cc:180","deadline_us":8372272014078.0,"frame_time_us":8372271997412.0,"interval_us":16666.0,"on_critical_path":true,"sequence_number":1655,"source_id":2,"subtype":"MISSED","type":"BeginFrameArgs"} #0 0x7f974671f3bb base::debug::StackTrace::StackTrace() #1 0x7f974671e0bc base::debug::StackTrace::StackTrace() #2 0x7f9746792573 logging::LogMessage::~LogMessage() #3 0x7f973d915809 cc::ExternalBeginFrameSource::GetMissedBeginFrameArgs() #4 0x7f973d914c83 cc::ExternalBeginFrameSource::AddObserver() #5 0x7f973d925a28 cc::Scheduler::SetupNextBeginFrameIfNeeded() #6 0x7f973d92413c cc::Scheduler::ProcessScheduledActions() #7 0x7f973d92477e cc::Scheduler::SetNeedsBeginMainFrame() #8 0x7f973daf5b06 cc::SingleThreadProxy::SetNeedsCommit() #9 0x7f973d9fa166 cc::LayerTreeHost::SetNeedsCommit() #10 0x7f973b8953fd ui::Compositor::ScheduleDraw() #11 0x7f973b8c0a0d ui::Layer::ScheduleDraw() #12 0x7f973b8c0980 ui::Layer::SchedulePaint() #13 0x7f973a609ce0 views::View::SchedulePaintInRect() #14 0x7f973a605ced views::View::SchedulePaint() #15 0x7f974b4067a7 Tab::RefreshThrobber() #16 0x7f974b406619 Tab::StepLoadingAnimation() #17 0x7f974b4015fe BrowserTabStripController::UpdateLoadingAnimations() #18 0x7f974b414120 TabStrip::UpdateLoadingAnimations() #19 0x7f974b3b755a BrowserView::LoadingAnimationCallback() ... Assigning to stanisc@ as the person who added the dcheck, but feel free to reassign.
,
Jun 26 2017
-> sunnyps@ could you triage/reassign?
,
Jun 29 2017
This breaks webgl_conformance_tests on Linux GPU.FYI bots. https://build.chromium.org/p/chromium.gpu.fyi/builders/Linux%20Debug%20%28Intel%20HD%20530%29/builds/2524 - WebglConformance_conformance_context_constants_and_properties https://build.chromium.org/p/chromium.gpu.fyi/builders/Linux%20Debug%20%28Intel%20HD%20530%29/builds/2523 - WebglConformance_conformance_buffers_index_validation_large_buffer https://build.chromium.org/p/chromium.gpu.fyi/builders/Linux%20Debug%20%28Intel%20HD%20530%29/builds/2522 - WebglConformance_conformance_glsl_implicit_multiply_int_vec3_vert https://build.chromium.org/p/chromium.gpu.fyi/builders/Linux%20Debug%20%28Intel%20HD%20530%29/builds/2521 - WebglConformance_conformance_textures_canvas_tex_2d_rgba_rgba_unsigned_short_4_4_4_4 [16578:16578:0628/111604.928845:FATAL:begin_frame_source.cc(345)] Check failed: (last_begin_frame_args_.source_id != last_args.source_id) || (last_begin_frame_args_.sequence_number > last_args.sequence_number). current {"created_from":"CreateBeginFrameArgs@../../cc/scheduler/begin_frame_source.cc:180","deadline_us":4919952499.0,"frame_time_us":4919939175.0,"interval_us":13328.0,"on_critical_path":true,"sequence_number":9822,"source_id":2,"subtype":"NORMAL","type":"BeginFrameArgs"}, last {"created_from":"CreateBeginFrameArgs@../../cc/scheduler/begin_frame_source.cc:180","deadline_us":4919952499.0,"frame_time_us":4919939171.0,"interval_us":13328.0,"on_critical_path":true,"sequence_number":9823,"source_id":2,"subtype":"MISSED","type":"BeginFrameArgs"} #0 0x7faa6cf203fb base::debug::StackTrace::StackTrace() #1 0x7faa6cf1f0fc base::debug::StackTrace::StackTrace() #2 0x7faa6cf935c3 logging::LogMessage::~LogMessage() #3 0x7faa640615c9 cc::ExternalBeginFrameSource::GetMissedBeginFrameArgs() #4 0x7faa64060a43 cc::ExternalBeginFrameSource::AddObserver() #5 0x7faa640717e8 cc::Scheduler::SetupNextBeginFrameIfNeeded() #6 0x7faa6406fefc cc::Scheduler::ProcessScheduledActions() #7 0x7faa6407053e cc::Scheduler::SetNeedsBeginMainFrame() #8 0x7faa64241dc6 cc::SingleThreadProxy::SetNeedsCommit() #9 0x7faa64145f66 cc::LayerTreeHost::SetNeedsCommit() #10 0x7faa61f454fd ui::Compositor::ScheduleDraw() #11 0x7faa61f70b0d ui::Layer::ScheduleDraw() #12 0x7faa61f70a80 ui::Layer::SchedulePaint() #13 0x7faa60c516d0 views::View::SchedulePaintInRect() #14 0x7faa60c4d6dd views::View::SchedulePaint() #15 0x7faa60c4ed74 views::View::SetVisible() #16 0x561d4f2b33c4 Tab::AdvanceLoadingAnimation() #17 0x561d4f2b31a4 Tab::UpdateLoadingAnimation() #18 0x561d4f2ae5aa BrowserTabStripController::UpdateLoadingAnimations() #19 0x561d4f2bf160 TabStrip::UpdateLoadingAnimations() #20 0x561d4f2644da BrowserView::LoadingAnimationCallback() #21 0x561d4f264479 BrowserView::UpdateLoadingAnimations() #22 0x561d4f0d2041 Browser::LoadingStateChanged() #23 0x7faa66ba42c4 content::WebContentsImpl::LoadingStateChanged() #24 0x7faa66babf40 content::WebContentsImpl::DidStopLoading() #25 0x7faa661ca0f2 content::FrameTreeNode::DidStopLoading() #26 0x7faa66240fcc content::RenderFrameHostImpl::OnDidStopLoading() #27 0x7faa6511e681 _ZN4base20DispatchToMethodImplIPN7content11PpapiThreadEMS2_FvvERKSt5tupleIJEEJEEEvRKT_T0_OT1_NS_13IndexSequenceIJXspT2_EEEE #28 0x7faa6511e5f0 _ZN4base16DispatchToMethodIPN7content11PpapiThreadEMS2_FvvERKSt5tupleIJEEEEvRKT_T0_OT1_ #29 0x7faa6626e3ff _ZN3IPC16DispatchToMethodIN7content19RenderFrameHostImplEMS2_FvvEvSt5tupleIJEEEEvPT_T0_PT1_RKT2_ #30 0x7faa662581b3 _ZN3IPC8MessageTI32FrameHostMsg_DidStopLoading_MetaSt5tupleIJEEvE8DispatchIN7content19RenderFrameHostImplES7_vMS7_FvvEEEbPKNS_7MessageEPT_PT0_PT1_T2_ #31 0x7faa66239c74 content::RenderFrameHostImpl::OnMessageReceived() #32 0x7faa668117b7 content::RenderProcessHostImpl::OnMessageReceived() #33 0x7faa69d01be8 IPC::ChannelProxy::Context::OnDispatchMessage() #34 0x7faa69d079d7 _ZN4base8internal13FunctorTraitsIMN3IPC12ChannelProxy7ContextEFvRKNS2_7MessageEEvE6InvokeIRK13scoped_refptrIS4_EJS7_EEEvS9_OT_DpOT0_ #35 0x7faa69d078c6 _ZN4base8internal12InvokeHelperILb0EvE8MakeItSoIRKMN3IPC12ChannelProxy7ContextEFvRKNS4_7MessageEEJRK13scoped_refptrIS6_ES9_EEEvOT_DpOT0_ #36 0x7faa69d07853 _ZN4base8internal7InvokerINS0_9BindStateIMN3IPC12ChannelProxy7ContextEFvRKNS3_7MessageEEJ13scoped_refptrIS5_ES6_EEEFvvEE7RunImplIRKSA_RKSt5tupleIJSC_S6_EEJLm0ELm1EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEE #37 0x7faa69d0776c _ZN4base8internal7InvokerINS0_9BindStateIMN3IPC12ChannelProxy7ContextEFvRKNS3_7MessageEEJ13scoped_refptrIS5_ES6_EEEFvvEE3RunEPNS0_13BindStateBaseE #38 0x7faa6cedb78e _ZNO4base8CallbackIFvvELNS_8internal8CopyModeE0ELNS2_10RepeatModeE0EE3RunEv #39 0x7faa6cf2605e base::debug::TaskAnnotator::RunTask() #40 0x7faa6cfbcf9d base::MessageLoop::RunTask() #41 0x7faa6cfbd227 base::MessageLoop::DeferOrRunPendingTask() #42 0x7faa6cfbd53f base::MessageLoop::DoWork() #43 0x7faa6cfd056c base::MessagePumpGlib::HandleDispatch() #44 0x7faa6cfd0d11 base::(anonymous namespace)::WorkSourceDispatch() #45 0x7faa5560a7d7 g_main_context_dispatch #46 0x7faa5560aa40 <unknown> #47 0x7faa5560aaec g_main_context_iteration #48 0x7faa6cfd066f base::MessagePumpGlib::Run() #49 0x7faa6cfbc968 base::MessageLoop::Run() #50 0x7faa6d0668ad base::RunLoop::Run() #51 0x561d4cedb02e ChromeBrowserMainParts::MainMessageLoopRun() #52 0x7faa65e31c88 content::BrowserMainLoop::RunMainMessageLoopParts() #53 0x7faa65e3da66 content::BrowserMainRunnerImpl::Run() #54 0x7faa65e2b468 content::BrowserMain() #55 0x7faa6790e2c6 content::RunNamedProcessTypeMain() #56 0x7faa679107ad content::ContentMainRunnerImpl::Run() #57 0x7faa6790cd2a content::ContentServiceManagerMainDelegate::RunEmbedderProcess() #58 0x7faa6d665f71 service_manager::Main() #59 0x7faa6790dd1f content::ContentMain() #60 0x561d4b5245ae ChromeMain #61 0x561d4b5244c2 main
,
Jun 29 2017
Please revert the change which caused this DCHECK to start firing. We can debug it in more detail once the bots are back to a green state.
,
Jun 29 2017
sunny@, I wonder if this has anything to do with not emptying last_begin_frame_args_ when all observers are removed - see line 309 here: https://codereview.chromium.org/2897263003/diff/120001/cc/scheduler/begin_frame_source.cc You recommended me to remove that line during the code review. I think emptying last_begin_frame_args_ probably prevented this assert when the last observer was deleted and then re-added again. It looks like this code would now generate a MISSED BeginFrame in that case but it didn't before due to the emptied last_begin_frame_args_. But the frame_time_us is different between last_begin_frame_args_ and the observer's last_args so the problem probably lies deeper.
,
Jun 29 2017
Is there a way to see more than 200 results for this bot? https://build.chromium.org/p/chromium.gpu.fyi/builders/Linux%20Debug%20%28Intel%20HD%20530%29?numbuilds=200 The change in question landed 4 weeks ago (https://codereview.chromium.org/2897263003). There were just a few flaky runs early on, and I can't tell for sure whether the flakiness started with that change because I can't see the earlier history.
,
Jun 29 2017
,
Jun 29 2017
So one possibility is that the BFS on the other end of the ExternalBFS misbehaves. ExternalBFS::OnBeginFrame always sets last_begin_frame_args_ without checking, so if the parent BFS or plumbing in between sends frames out of order this DCHECK could be triggered.
,
Jun 29 2017
Re comment #6: You can with https://luci-milo.appspot.com/buildbot/chromium.gpu.fyi/Linux%20Debug%20%28Intel%20HD%20530%29/?limit=500 First failure is https://luci-milo.appspot.com/buildbot/chromium.gpu.fyi/Linux%20Debug%20%28Intel%20HD%20530%29/2250, but looks like stdout was already discarded, so no way to confirm it is the same reason. But, https://luci-milo.appspot.com/buildbot/chromium.gpu.fyi/Linux%20Debug%20%28Intel%20HD%20530%29/2275 hit this DCHECK: [16921:16921:0604/202005.866167:FATAL:begin_frame_source.cc(345)] Check failed: (last_begin_frame_args_.source_id != last_args.source_id) || (last_begin_frame_args_.sequence_number > last_args.sequence_number). current {"created_from":"CreateBeginFrameArgs@../../cc/scheduler/begin_frame_source.cc:180","deadline_us":5494299264.0,"frame_time_us":5494285930.0,"interval_us":13328.0,"on_critical_path":true,"sequence_number":81,"source_id":2,"subtype":"NORMAL","type":"BeginFrameArgs"}, last {"created_from":"CreateBeginFrameArgs@../../cc/scheduler/begin_frame_source.cc:180","deadline_us":5494299264.0,"frame_time_us":5494285936.0,"interval_us":13328.0,"on_critical_path":true,"sequence_number":82,"source_id":2,"subtype":"MISSED","type":"BeginFrameArgs"}
,
Jun 29 2017
@8: yes, that is likely the case, especially considering that this happens only on Linux which has a different type of VSyncProvider. Anyway, I'll go ahead and revert my change and we'll see if these DCHECK failures continue. As I mentioned in #6 there might have been a subtle change in logic caused by removal of the line that empties last_begin_frame_args_ on removal of all observers. I plan to re-land that change later again. It is needed to avoid another regression with GPU V-sync.
,
Jun 29 2017
Also seeing this on Win10 Intel HD 530: https://build.chromium.org/p/chromium.gpu.fyi/builders/Win10%20Debug%20%28Intel%20HD%20530%29/builds/1088 https://build.chromium.org/p/chromium.gpu.fyi/builders/Win10%20Debug%20%28Intel%20HD%20530%29/builds/1090
,
Jun 29 2017
Re comment #9. That case was different because the first frame_time_us is earlier than than the second one. I've fixed that one 3 weeks ago with this change: https://chromium.googlesource.com/chromium/src/+/25d005fb3364df055d7773cffe7039cfd3d33eca The cases that we are seeing now with the first timestamp being later would have been hit with the original code as I explained in #1
,
Jun 29 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/d76957c122db1f7cf7d60f5663b6926a6dc34285 commit d76957c122db1f7cf7d60f5663b6926a6dc34285 Author: stanisc <stanisc@chromium.org> Date: Thu Jun 29 23:20:23 2017 Revert "Fix Omnibox.CharTypedToRepaintLatency regression with D3DVsync experiment" This reverts commit https://chromium.googlesource.com/chromium/src/+/25d005fb3364df055d7773cffe7039cfd3d33eca This reverts commit https://chromium.googlesource.com/chromium/src/+/c9365f582c63efd4f812d4dd56fdfed84af29837 BUG= 736826 CQ_INCLUDE_TRYBOTS=master.tryserver.blink:linux_trusty_blink_rel TBR=sunnyps@chromium.org, jbauman@chromium.org Review-Url: https://codereview.chromium.org/2967553002 Cr-Commit-Position: refs/heads/master@{#483540} [modify] https://crrev.com/d76957c122db1f7cf7d60f5663b6926a6dc34285/cc/scheduler/begin_frame_source.cc [modify] https://crrev.com/d76957c122db1f7cf7d60f5663b6926a6dc34285/cc/scheduler/begin_frame_source.h [modify] https://crrev.com/d76957c122db1f7cf7d60f5663b6926a6dc34285/cc/scheduler/begin_frame_source_unittest.cc [modify] https://crrev.com/d76957c122db1f7cf7d60f5663b6926a6dc34285/content/browser/compositor/gpu_vsync_begin_frame_source.cc [modify] https://crrev.com/d76957c122db1f7cf7d60f5663b6926a6dc34285/content/browser/compositor/gpu_vsync_begin_frame_source.h [delete] https://crrev.com/dda3acb809c43e2d633c335778ff4a1522927e59/content/browser/compositor/gpu_vsync_begin_frame_source_unittest.cc [modify] https://crrev.com/d76957c122db1f7cf7d60f5663b6926a6dc34285/content/test/BUILD.gn
,
Jul 11 2017
I haven't been able to repro this so far. I think there are two issues here:
1. DelayBasedBFS sometimes produces frames out of order.
2.
For 1, I strongly suspect this has to do with the following code in DelayBasedBFS::AddObserver:
base::TimeTicks last_or_missed_tick_time =
time_source_->NextTickTime() - time_source_->Interval();
if (current_begin_frame_args_.IsValid() &&
current_begin_frame_args_.frame_time == last_or_missed_tick_time &&
current_begin_frame_args_.interval == time_source_->Interval()) {
// Ensure that the args have the right type.
current_begin_frame_args_.type = BeginFrameArgs::MISSED;
} else {
// The args are not up to date and we need to create new ones with the
// missed tick's time and a new sequence number.
current_begin_frame_args_ =
CreateBeginFrameArgs(last_or_missed_tick_time, BeginFrameArgs::MISSED);
}
last_or_missed_tick_time can be before current_begin_frame_args_.frame_time if the timebase/interval change. Since we're using == instead of >= when comparing frame_time with last_or_missed_tick_time, we can issue a missed frame with a smaller timestamp than the previous frame. The errors logged in comments #0 and #3 exhibit this issue.
I haven't been able to figure out what causes 2 yet.
,
Jul 11 2017
Issue 2 is: DirectLayerTreeFrameSink's ExternalBFS gets delivered frames out of order. Note that this is sequence numbers being out of order and is different from frame times being out of order as in 1. This is exhibited in the error in comment #9 where only the sequence numbers are out of order.
,
Jul 11 2017
Issue mentioned in #9 is from June 4th. It was caused by Issue 730218 , so should ignore it. See my comment #10.
,
Jul 11 2017
Ok, but in both cases out of order begin frames (sequence number and/or frame time) are being delivered from DelayBasedBFS to the ExternalBFS across CompositorFrameSinkSupport (observer of DelayBasedBFS) and DirectLayerTreeFrameSink/LayerTreeFrameSinkLocal (owner and client of ExternalBFS).
We know that this DCHECK in DelayBasedBFS::AddObserver is not failing:
DCHECK(current_begin_frame_args_.sequence_number >
last_args.sequence_number ||
current_begin_frame_args_.source_id != last_args.source_id)
<< "current " << current_begin_frame_args_.AsValue()->ToString()
<< ", last " << last_args.AsValue()->ToString();
(source_id does not change in #0 and #3)
Here's a possibility:
1. cc::Scheduler receives a NORMAL BeginFrame via the ExternalBFS of the LayerTreeFrameSink attached to LayerTreeHostImpl.
2. The compositor decides to ReleaseLayerTreeFrameSink for whatever reason (context loss, going invisible on android, etc.)
3. Compositor creates new LayerTreeFrameSink (and therefore ExternalBFS and CFSSSupport). cc::Scheduler is still the same so it's LastUsedBeginFrameArgs is whatever was sent in 1. DelayBasedBFS is also same. What changes is the LayerTreeFrameSink/CFSSupport/ExternalBFS. CFSSupport is the observer of the DelayBasedBFS and will return invalid BeginFrameArgs for its LastUsedBeginFrameArgs so DelayBasedBFS can give it a newer sequence number with an older frame time.
Some details are off even with the above explanation but I suspect something like this is happening.
I think the big issue we have today is that using LastUsedBeginFrameArgs is error prone because it doesn't reflect the true state of the observer on the other side (the cc::Scheduler). Since CFSSupport/Client is meant to be an IPC boundary this makes sense. I think we should get rid of LastUsedBeginFrameArgs and instead do minimal checking (double ticking prevention for DelayBasedBFS) based on the last_begin_frame_args_ of the BFS only. We should also make BeginFrameObserverBase resilient to frames arriving out of order (especially from different sources).
,
Jul 12 2017
From a local run of content_browsertests SecurityExploitBrowserTest.InvalidRequestId:
[FATAL:begin_frame_source.cc(328)] Check failed: !last_begin_frame_args_.IsValid() || (args.frame_time > last_begin_frame_args_.frame_time && (args.source_id != last_begin_frame_args_.source_id || args.sequence_number > last_begin_frame_args_.sequence_number)).
C 119.146s Main args: {"deadline_us":1212418494227.0,"frame_time_us":1212418441683.0,"interval_us":16666.0,"on_critical_path":true,"sequence_number":30,"source_id":0,"subtype":"MISSED","type":"BeginFrameArgs"}
C 119.146s Main last_begin_frame_args_: {"deadline_us":1212418458349.0,"frame_time_us":1212418441683.0,"interval_us":16666.0,"on_critical_path":true,"sequence_number":30,"source_id":0,"subtype":"NORMAL","type":"BeginFrameArgs"}
Stack Trace:
RELADDR FUNCTION FILE:LINE
000a1b9f ~LogMessage /usr/local/google/home/sunnyps/src/chromium/src/base/logging.cc:553
000e0ae3 cc::ExternalBeginFrameSource::OnBeginFrame(cc::BeginFrameArgs const&) /usr/local/google/home/sunnyps/src/chromium/src/cc/scheduler/begin_frame_source.cc:325
000101c5 ui::WindowAndroid::WindowBeginFrameSource::AddObserver(cc::BeginFrameObserver*) /usr/local/google/home/sunnyps/src/chromium/src/ui/android/window_android.cc:81
000e0895 cc::ExternalBeginFrameSource::AddObserver(cc::BeginFrameObserver*) /usr/local/google/home/sunnyps/src/chromium/src/cc/scheduler/begin_frame_source.cc:283
0000aef7 ui::DelegatedFrameHostAndroid::AttachToCompositor(ui::WindowAndroidCompositor*) /usr/local/google/home/sunnyps/src/chromium/src/ui/android/delegated_frame_host_android.cc:161
0082bdfd content::RenderWidgetHostViewAndroid::DidCreateNewRendererCompositorFrameSink(cc::mojom::CompositorFrameSinkClient*) /usr/local/google/home/sunnyps/src/chromium/src/content/browser/renderer_host/render_widget_host_view_android.cc:1196
0079c471 content::RenderWidgetHostImpl::RequestCompositorFrameSink(mojo::InterfaceRequest<cc::mojom::CompositorFrameSink>, mojo::InterfacePtr<cc::mojom::CompositorFrameSinkClient>) /usr/local/google/home/sunnyps/src/chromium/src/content/browser/renderer_host/render_widget_host_impl.cc:2573
00760183 content::FrameSinkProviderImpl::CreateForWidget(int, mojo::InterfaceRequest<cc::mojom::CompositorFrameSink>, mojo::InterfacePtr<cc::mojom::CompositorFrameSinkClient>) /usr/local/google/home/sunnyps/src/chromium/src/content/browser/renderer_host/frame_sink_provider_impl.cc:38
00529ec9 content::mojom::FrameSinkProviderStubDispatch::Accept(content::mojom::FrameSinkProvider*, mojo::Message*) /usr/local/google/home/sunnyps/src/chromium/src/out/droid/gen/content/common/frame_sink_provider.mojom.cc:101
0001a0af mojo::internal::MultiplexRouter::ProcessIncomingMessage(mojo::Message*, mojo::internal::MultiplexRouter::ClientCallBehavior, base::SequencedTaskRunner*) /usr/local/google/home/sunnyps/src/chromium/src/mojo/public/cpp/bindings/lib/multiplex_router.cc:876
00019f5b mojo::internal::MultiplexRouter::Accept(mojo::Message*) /usr/local/google/home/sunnyps/src/chromium/src/mojo/public/cpp/bindings/lib/multiplex_router.cc:606
000156ef mojo::Connector::ReadSingleMessage(unsigned int*) /usr/local/google/home/sunnyps/src/chromium/src/mojo/public/cpp/bindings/lib/connector.cc:390
000159a9 mojo::Connector::ReadAllAvailableMessages() /usr/local/google/home/sunnyps/src/chromium/src/mojo/public/cpp/bindings/lib/connector.cc:419
00015c77 void base::internal::Invoker<base::internal::BindState<void (mojo::Connector::*)(unsigned int), base::internal::UnretainedWrapper<mojo::Connector> >, void (unsigned int)>::RunImpl<void (mojo::Connector::* const&)(unsigned int), std::__ndk1::tuple<base::internal::UnretainedWrapper<mojo::Connector> > const&, 0u>(void (mojo::Connector::* const&)(unsigned int), std::__ndk1::tuple<base::internal::UnretainedWrapper<mojo::Connector> > const&, base::IndexSequence<0u>, unsigned int&&) /usr/local/google/home/sunnyps/src/chromium/src/base/bind_internal.h:351
v------> base::Callback<void (unsigned int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>::Run(unsigned int) const & /usr/local/google/home/sunnyps/src/chromium/src/base/callback.h:80
000043f7 mojo::SimpleWatcher::OnHandleReady(int, unsigned int) /usr/local/google/home/sunnyps/src/chromium/src/mojo/public/cpp/system/simple_watcher.cc:266
00004629 void base::internal::InvokeHelper<true, void>::MakeItSo<void (mojo::SimpleWatcher::* const&)(int, unsigned int), base::WeakPtr<mojo::SimpleWatcher> const&, int const&, unsigned int const&>(void (mojo::SimpleWatcher::* const&)(int, unsigned int), base::WeakPtr<mojo::SimpleWatcher> const&, int const&, unsigned int const&) /usr/local/google/home/sunnyps/src/chromium/src/base/bind_internal.h:295
v------> base::Callback<void (), (base::internal::CopyMode)0, (base::internal::RepeatMode)0>::Run() && /usr/local/google/home/sunnyps/src/chromium/src/base/callback.h:91
0008eccf base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask*) /usr/local/google/home/sunnyps/src/chromium/src/base/debug/task_annotator.cc:59
000a6935 base::MessageLoop::RunTask(base::PendingTask*) /usr/local/google/home/sunnyps/src/chromium/src/base/message_loop/message_loop.cc:422
000a6bb5 base::MessageLoop::DeferOrRunPendingTask(base::PendingTask) /usr/local/google/home/sunnyps/src/chromium/src/base/message_loop/message_loop.cc:433
000a6de5 base::MessageLoop::DoWork() /usr/local/google/home/sunnyps/src/chromium/src/base/message_loop/message_loop.cc:540
00401593 content::NestedMessagePumpAndroid::Run(base::MessagePump::Delegate*) /usr/local/google/home/sunnyps/src/chromium/src/content/public/test/nested_message_pump_android.cc:73
000bfd05 base::RunLoop::Run() /usr/local/google/home/sunnyps/src/chromium/src/base/run_loop.cc:111
00414ec3 content::RunThisRunLoop(base::RunLoop*) /usr/local/google/home/sunnyps/src/chromium/src/content/public/test/test_utils.cc:129
003ff88b content::NavigateToURLBlockUntilNavigationsComplete(content::Shell*, GURL const&, int) /usr/local/google/home/sunnyps/src/chromium/src/content/public/test/content_browser_test_utils.cc:49
003ff945 content::NavigateToURL(content::Shell*, GURL const&) /usr/local/google/home/sunnyps/src/chromium/src/content/public/test/content_browser_test_utils.cc:85
002e28e9 content::(anonymous namespace)::TryCreateDuplicateRequestIds(content::Shell*, bool) /usr/local/google/home/sunnyps/src/chromium/src/content/browser/security_exploit_browsertest.cc:146
00407e99 content::BrowserTestBase::ProxyRunTestOnMainThreadLoop() /usr/local/google/home/sunnyps/src/chromium/src/content/public/test/browser_test_base.cc:315
00408531 void base::internal::Invoker<base::internal::BindState<void (content::BrowserTestBase::*)(), base::internal::UnretainedWrapper<content::BrowserTestBase> >, void ()>::RunImpl<void (content::BrowserTestBase::* const&)(), std::__ndk1::tuple<base::internal::UnretainedWrapper<content::BrowserTestBase> > const&, 0u>(void (content::BrowserTestBase::* const&)(), std::__ndk1::tuple<base::internal::UnretainedWrapper<content::BrowserTestBase> > const&, base::IndexSequence<0u>) /usr/local/google/home/sunnyps/src/chromium/src/base/bind_internal.h:351
v------> base::Callback<void (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>::Run() const & /usr/local/google/home/sunnyps/src/chromium/src/base/callback.h:80
0043c575 content::ShellBrowserMainParts::PreMainMessageLoopRun() /usr/local/google/home/sunnyps/src/chromium/src/content/shell/browser/shell_browser_main_parts.cc:196
0064459f content::BrowserMainLoop::PreMainMessageLoopRun() /usr/local/google/home/sunnyps/src/chromium/src/content/browser/browser_main_loop.cc:1130
006456f5 int base::internal::Invoker<base::internal::BindState<int (content::BrowserMainLoop::*)(), base::internal::UnretainedWrapper<content::BrowserMainLoop> >, int ()>::RunImpl<int (content::BrowserMainLoop::* const&)(), std::__ndk1::tuple<base::internal::UnretainedWrapper<content::BrowserMainLoop> > const&, 0u>(int (content::BrowserMainLoop::* const&)(), std::__ndk1::tuple<base::internal::UnretainedWrapper<content::BrowserMainLoop> > const&, base::IndexSequence<0u>) /usr/local/google/home/sunnyps/src/chromium/src/base/bind_internal.h:351
,
Jul 12 2017
This happens when we switch between compositors. We recreate the CFSSupport and lose the LastUsedBeginFrameArgs state. In the above case, a duplicate of the last NORMAL frame is sent as a MISSED frame. But because of the bug in DelayBasedBFS a MISSED frame with new sequence number and different (even smaller) frame time can also be sent. I had an offline discussion with Brian about removing LastUsedBeginFrameArgs since we can't propagate it across the CFSSSupport (soon to be IPC) boundary and there's a lot of complexity in all the BFS implementations to essentially prevent duplicate MISSED frames which are caused by bad observer behavior (Add-Remove-Add in a short time) and harmless most of the time. We should assert that the BFS ticks are monotonically increasing and we have DCHECKs in cc scheduler which should catch duplicate MISSED frames.
,
Jul 14 2017
Assigning to you since you are working on the proper fix.
,
Jul 25 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/c446e452c41c42ce497430ae13f506051d795e64 commit c446e452c41c42ce497430ae13f506051d795e64 Author: Sunny Sachanandani <sunnyps@chromium.org> Date: Tue Jul 25 22:45:41 2017 cc: Fix out of order begin frame DCHECKs. This CL fixes two issues: 1. DelayBasedBFS can go backwards in time because it produces a new sequence number whenever timebase or interval change. 2. ExternalBFS can get frames out of order from the frame sink because the other side doesn't know about the LastUsedBeginFrameArgs state. I plan to make more invasive changes to the BeginFrameSource contract. LastUsedBeginFrameArgs doesn't work across process boundaries. Some filtering of begin frames has to be done at the receiving end. I want to remove LastUsedBeginFrameArgs and make the observers more resilient to out of order frames. That will be a followup CL. R=stanisc,brianderson BUG= 736826 Cq-Include-Trybots: master.tryserver.blink:linux_trusty_blink_rel Change-Id: I1f861e6fec2936fb6ad92e3cb470311655c1f3cd Reviewed-on: https://chromium-review.googlesource.com/569448 Reviewed-by: Brian Anderson <brianderson@chromium.org> Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org> Commit-Queue: Sunny Sachanandani <sunnyps@chromium.org> Cr-Commit-Position: refs/heads/master@{#489470} [modify] https://crrev.com/c446e452c41c42ce497430ae13f506051d795e64/cc/scheduler/begin_frame_source_unittest.cc [modify] https://crrev.com/c446e452c41c42ce497430ae13f506051d795e64/components/viz/common/frame_sinks/begin_frame_source.cc [modify] https://crrev.com/c446e452c41c42ce497430ae13f506051d795e64/components/viz/common/frame_sinks/begin_frame_source.h [modify] https://crrev.com/c446e452c41c42ce497430ae13f506051d795e64/components/viz/service/frame_sinks/frame_sink_manager_unittest.cc
,
Nov 10 2017
Pretty sure last CL fixed this. |
|||||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||||
Comment 1 by stanisc@chromium.org
, Jun 26 2017I didn't introduce this DCHECK, I simply refactored the old code into a new function. Before my change the code in ExternalBeginFrameSource::AddObserver looked like this: - if (last_begin_frame_args_.IsValid()) { - const BeginFrameArgs& last_args = obs->LastUsedBeginFrameArgs(); - if (!last_args.IsValid() || - (last_begin_frame_args_.frame_time > last_args.frame_time)) { - DCHECK( - (last_begin_frame_args_.source_id != last_args.source_id) || - (last_begin_frame_args_.sequence_number > last_args.sequence_number)) - << "current " << last_begin_frame_args_.AsValue()->ToString() - << ", last " << last_args.AsValue()->ToString(); - BeginFrameArgs missed_args = last_begin_frame_args_; - missed_args.type = BeginFrameArgs::MISSED; - obs->OnBeginFrame(missed_args); - } So it looks like this DCHECK would have been hit even without my change: last_begin_frame_args_.frame_time = 8372272012929 (current) last_args.frame_time = 8372271997412 (last) last_begin_frame_args_.sequence_number = 1654 (current) last_args.sequence_number = 1655 (last) The difference between frame_time timestamps is 15517 us.