FATAL:queueing_time_estimator.cc(29)] Check failed: task_start <= task_end.
Reported by
tsniatow...@opera.com,
Mar 21 2017
|
|||||
Issue descriptionChrome Version: based on 58.0.3013 OS: Android What steps will reproduce the problem? (1) Can't tell, really. Have videos playing on some site in a loop, so there's activity. What is the expected result? No DCHECK What happens instead? DCHECK hit This is an one-off DCHECK hit I got. This is on a local build based on a patched chromium, but we have no changes around blink scheduler, so thought I'd file you a FYI bug. Stack Trace: RELADDR FUNCTION FILE:LINE 0008ce83 base::debug::StackTrace::StackTrace() /a/chromium/src/base/debug/stack_trace.cc:195 000a2637 logging::LogMessage::~LogMessage() /a/chromium/src/base/logging.cc:537 00205001 ExpectedQueueingTimeFromTask /a/chromium/src/third_party/WebKit/Source/platform/scheduler/base/queueing_time_estimator.cc:29 002052c3 blink::scheduler::QueueingTimeEstimator::State::OnTopLevelTaskCompleted(blink::scheduler::QueueingTimeEstimator::Client*, base::TimeTicks) /a/chromium/src/third_party/WebKit/Source/platform/scheduler/base/queueing_time_estimator.cc:98 002186c1 blink::scheduler::RendererSchedulerImpl::didProcessTask(blink::scheduler::TaskQueue*, double, double) /a/chromium/src/third_party/WebKit/Source/platform/scheduler/renderer/renderer_scheduler_impl.cc:1755 0020bd2f blink::scheduler::TaskQueueManager::ProcessTaskFromWorkQueue(blink::scheduler::internal::WorkQueue*, bool, blink::scheduler::LazyNow, base::TimeTicks*) /a/chromium/src/third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:549 0020c52f blink::scheduler::TaskQueueManager::DoWork(bool) /a/chromium/src/third_party/WebKit/Source/platform/scheduler/base/task_queue_manager.cc:331 v------> void base::internal::FunctorTraits<void (blink::scheduler::TaskQueueManager::*)(bool), void>::Invoke<base::WeakPtr<blink::scheduler::TaskQueueManager> const&, bool const&>(void (blink::scheduler::TaskQueueManager::*)(bool), base::WeakPtr<blink::scheduler::TaskQueueManager> const&, bool const&) /a/chromium/src/base/bind_internal.h:214 v------> void base::internal::InvokeHelper<true, void>::MakeItSo<void (blink::scheduler::TaskQueueManager::* const&)(bool), base::WeakPtr<blink::scheduler::TaskQueueManager> const&, bool const&>(void (blink::scheduler::TaskQueueManager::* const&)(bool), base::WeakPtr<blink::scheduler::TaskQueueManager> const&, bool const&) /a/chromium/src/base/bind_internal.h:305 v------> void base::internal::Invoker<base::internal::BindState<void (blink::scheduler::TaskQueueManager::*)(bool), base::WeakPtr<blink::scheduler::TaskQueueManager>, bool>, void ()>::RunImpl<void (blink::scheduler::TaskQueueManager::* const&)(bool), std::__ndk1::tuple<base::WeakPtr<blink::scheduler::TaskQueueManager>, bool> const&, 0u, 1u>(void (blink::scheduler::TaskQueueManager::* const&)(bool), std::__ndk1::tuple<base::WeakPtr<blink::scheduler::TaskQueueManager>, bool> const&, base::IndexSequence<0u, 1u>) /a/chromium/src/base/bind_internal.h:364 0020b21d base::internal::Invoker<base::internal::BindState<void (blink::scheduler::TaskQueueManager::*)(bool), base::WeakPtr<blink::scheduler::TaskQueueManager>, bool>, void ()>::Run(base::internal::BindStateBase*) /a/chromium/src/base/bind_internal.h:342 v------> base::internal::RunMixin<base::Callback<void (), (base::internal::CopyMode)0, (base::internal::RepeatMode)0> >::Run() && /a/chromium/src/base/callback.h:68 0008d775 base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask*) /a/chromium/src/base/debug/task_annotator.cc:59 000a95a1 base::MessageLoop::RunTask(base::PendingTask*) /a/chromium/src/base/message_loop/message_loop.cc:441 000a9a0f base::MessageLoop::DeferOrRunPendingTask(base::PendingTask) /a/chromium/src/base/message_loop/message_loop.cc:453 000a9b05 base::MessageLoop::DoWork() /a/chromium/src/base/message_loop/message_loop.cc:548 000ac0e7 base::MessagePumpDefault::Run(base::MessagePump::Delegate*) /a/chromium/src/base/message_loop/message_pump_default.cc:33 000aaf81 base::MessageLoop::RunHandler() /a/chromium/src/base/message_loop/message_loop.cc:405 000c5e79 base::RunLoop::Run() /a/chromium/src/base/run_loop.cc:37 00b2728f content::RendererMain(content::MainFunctionParams const&) /a/chromium/src/content/renderer/renderer_main.cc:200 00bc6619 content::RunNamedProcessTypeMain(std::__ndk1::basic_string<char, std::__ndk1::char_traits<char>, std::__ndk1::allocator<char> > const&, content::MainFunctionParams const&, content::ContentMainDelegate*) /a/chromium/src/content/app/content_main_runner.cc:493 00bc681d content::ContentMainRunnerImpl::Run() /a/chromium/src/content/app/content_main_runner.cc:892 v------> Start /a/chromium/src/content/app/android/content_main.cc:46 00bc6061 Java_org_chromium_content_app_ContentMain_nativeStart /a/chromium/src/out_gn_android_arm/Debug/gen/content/public/android/content_jni_headers/content/jni/ContentMain_jni.h:38 005c3a65 <unknown>
,
Mar 27 2017
Unfortunately no. It happened once on some internal video test site.
,
Mar 27 2017
These times are coming from the RendererScheduler - I don't have any intuition on what could be happening here. It might make sense to add a DCHECK in the RendererScheduler. In RendererSchedulerImpl::didProcessTask, should MainThreadOnly().current_task_start_time == start_time ? didProcessTask could at least DCHECK(start_time <= end_time). https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/scheduler/renderer/renderer_scheduler_impl.cc?rcl=d9bc0ee968d13a9798a8e9b97eb1b1f9514c3808&l=1757
,
Jun 6 2017
This just happened again, again on an Android debug build, but this time around web page load or web contents creation without a lengthy "videos looping" scenerio. Backtrace is shorter, but it's the same DCHECK. This run was based on Chromium 59.0.3071.25, and was in single-process mode.
FATAL:queueing_time_estimator.cc(34)] Check failed: task_start <= task_end
backtrace:
/system/lib/libc.so (tgkill+12)
/system/lib/libc.so (pthread_kill+34)
/system/lib/libc.so (raise+10)
/system/lib/libc.so (__libc_android_abort+34)
/system/lib/libc.so (abort+4)
libbase.cr.so (_ZN4base5debug13BreakDebuggerEv+18)
libbase.cr.so (_ZN7logging10LogMessageD1Ev+604)
libblink_platform.cr.so
libblink_platform.cr.so (_ZN5blink9scheduler21QueueingTimeEstimator5State23OnTopLevelTaskCompletedEPNS1_6ClientEN4base9TimeTicksE+224)
libblink_platform.cr.so (_ZN5blink9scheduler21RendererSchedulerImpl14DidProcessTaskEPNS0_9TaskQueueEdd+62)
libblink_platform.cr.so (_ZN5blink9scheduler16TaskQueueManager24ProcessTaskFromWorkQueueEPNS0_8internal9WorkQueueEbNS0_7LazyNowEPN4base9TimeTicksE+1162)
libblink_platform.cr.so (_ZN5blink9scheduler16TaskQueueManager6DoWorkEb+888)
libblink_platform.cr.so
libbase.cr.so (_ZN4base5debug13TaskAnnotator7RunTaskEPKcPNS_11PendingTaskE+598)
libbase.cr.so (_ZN4base11MessageLoop7RunTaskEPNS_11PendingTaskE+442)
libbase.cr.so (_ZN4base11MessageLoop21DeferOrRunPendingTaskENS_11PendingTaskE+28)
libbase.cr.so (_ZN4base11MessageLoop6DoWorkEv+156)
libbase.cr.so (_ZN4base18MessagePumpDefault3RunEPNS_11MessagePump8DelegateE+90)
libbase.cr.so (_ZN4base11MessageLoop10RunHandlerEv+168)
libbase.cr.so (_ZN4base7RunLoop3RunEv+86)
libbase.cr.so (_ZN4base6Thread3RunEPNS_7RunLoopE+126)
libbase.cr.so (_ZN4base6Thread10ThreadMainEv+686)
libbase.cr.so
/system/lib/libc.so (_ZL15__pthread_startPv+22)
/system/lib/libc.so (__start_thread+6)
No reliable reproduction scenario, but I will try to run the failing test job a couple of times as this one wasn't using any external resources.
,
Jun 6 2017
Whoops, sorry I dropped this. Sami: what do you think of my proposal in #3?
,
Jun 6 2017
Yeah, those two values should be the same. I forget why we we're passing both values to the latter callback but that's the way it works.
,
Jun 28 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/48ea1273a02f225c876093ff16574b8cf2139eee commit 48ea1273a02f225c876093ff16574b8cf2139eee Author: tdresser <tdresser@chromium.org> Date: Wed Jun 28 22:23:50 2017 DCHECK that scheduler tasks have positive duration. We're running into issues with tasks that appear to end before they start. This patch moves the issue upstream a bit. BUG= 703648 Review-Url: https://codereview.chromium.org/2954283003 Cr-Commit-Position: refs/heads/master@{#483171} [modify] https://crrev.com/48ea1273a02f225c876093ff16574b8cf2139eee/third_party/WebKit/Source/platform/scheduler/renderer/renderer_scheduler_impl.cc
,
Aug 1 2017
,
Nov 24 2017
It seems the problem is still there. I just had a random crash on the newly-added DCHECK in an internal build based on Chromium 62.0.3202.89: 11-24 11:41:46.509 5111 5111 F DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** 11-24 11:41:46.510 5111 5111 F DEBUG : Build fingerprint: 'NVIDIA/foster_e/foster:7.0/NRD90M/1915764_910.7870:user/release-keys' 11-24 11:41:46.510 5111 5111 F DEBUG : Revision: '0' 11-24 11:41:46.510 5111 5111 F DEBUG : ABI: 'arm' 11-24 11:41:46.510 5111 5111 F DEBUG : pid: 3447, tid: 3509, name: Chrome_InProcRe >>> com.vewd.core.integration <<< 11-24 11:41:46.510 5111 5111 F DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr -------- 11-24 11:41:46.511 5111 5111 F DEBUG : Abort message: '[3447:3509:1124/114146.368573:194550835:FATAL:renderer_scheduler_impl.cc(1915)] Check failed: start <= end (194560002 bogo-microseconds vs. 194550769 bogo-microseconds) 11-24 11:41:46.511 5111 5111 F DEBUG : #00 0x5bbaaa53 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so+0x000aaa53 11-24 11:41:46.511 5111 5111 F DEBUG : #01 0x5efecaa3 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so+0x0031daa3 11-24 11:41:46.511 5111 5111 F DEBUG : #02 0x5efe6f4b /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so+0x00317f4b 11-24 11:41:46.511 5111 5111 F DEBUG : #03 0x5efe7105 /data/app/com.vewd.core.integrati 11-24 11:41:46.511 5111 5111 F DEBUG : r0 00000000 r1 00000db5 r2 00000006 r3 00000008 11-24 11:41:46.511 5111 5111 F DEBUG : r4 664fe978 r5 00000006 r6 664fe920 r7 0000010c 11-24 11:41:46.511 5111 5111 F DEBUG : r8 664fdd80 r9 000000a8 sl 664fd92c fp 65aae000 11-24 11:41:46.511 5111 5111 F DEBUG : ip 0000000b sp 664fd8a8 lr 4b58cb07 pc 4b58f370 cpsr 680f0010 11-24 11:41:46.525 5111 5111 F DEBUG : 11-24 11:41:46.525 5111 5111 F DEBUG : backtrace: 11-24 11:41:46.528 5111 5111 F DEBUG : #00 pc 0004a370 /system/lib/libc.so (tgkill+12) 11-24 11:41:46.528 5111 5111 F DEBUG : #01 pc 00047b03 /system/lib/libc.so (pthread_kill+34) 11-24 11:41:46.528 5111 5111 F DEBUG : #02 pc 0001db7d /system/lib/libc.so (raise+10) 11-24 11:41:46.528 5111 5111 F DEBUG : #03 pc 000196c9 /system/lib/libc.so (__libc_android_abort+34) 11-24 11:41:46.528 5111 5111 F DEBUG : #04 pc 00017048 /system/lib/libc.so (abort+4) 11-24 11:41:46.529 5111 5111 F DEBUG : #05 pc 00097c5d /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base5debug13BreakDebuggerEv+20) 11-24 11:41:46.529 5111 5111 F DEBUG : #06 pc 000aac85 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN7logging10LogMessageD1Ev+668) 11-24 11:41:46.529 5111 5111 F DEBUG : #07 pc 0031daa1 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so (_ZN5blink9scheduler21RendererSchedulerImpl15OnTaskCompletedEPNS0_19MainThreadTaskQueueERKNS0_9TaskQueue4TaskEN4base9TimeTicksES9_+56) 11-24 11:41:46.529 5111 5111 F DEBUG : #08 pc 00317f49 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so (_ZN5blink9scheduler19MainThreadTaskQueue15OnTaskCompletedERKNS0_9TaskQueue4TaskEN4base9TimeTicksES7_+20) 11-24 11:41:46.529 5111 5111 F DEBUG : #09 pc 00318105 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so 11-24 11:41:46.529 5111 5111 F DEBUG : #10 pc 003180d5 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so 11-24 11:41:46.529 5111 5111 F DEBUG : #11 pc 003180b9 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so 11-24 11:41:46.529 5111 5111 F DEBUG : #12 pc 003180a5 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so 11-24 11:41:46.529 5111 5111 F DEBUG : #13 pc 00309e55 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so 11-24 11:41:46.530 5111 5111 F DEBUG : #14 pc 0030ca0d /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so (_ZN5blink9scheduler16TaskQueueManager24ProcessTaskFromWorkQueueEPNS0_8internal9WorkQueueEbNS0_7LazyNowEPN4base9TimeTicksE+868) 11-24 11:41:46.530 5111 5111 F DEBUG : #15 pc 0030b7e5 /data/app/com.vewd.core.integration-1/lib/arm/libblink_platform.cr.so (_ZN5blink9scheduler16TaskQueueManager6DoWorkEb+472) 11-24 11:41:46.530 5111 5111 F DEBUG : #16 pc 0008e50d /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so 11-24 11:41:46.530 5111 5111 F DEBUG : #17 pc 0009818f /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base5debug13TaskAnnotator7RunTaskEPKcPNS_11PendingTaskE+150) 11-24 11:41:46.530 5111 5111 F DEBUG : #18 pc 000b1133 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base11MessageLoop7RunTaskEPNS_11PendingTaskE+174) 11-24 11:41:46.530 5111 5111 F DEBUG : #19 pc 000b1395 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base11MessageLoop21DeferOrRunPendingTaskENS_11PendingTaskE+40) 11-24 11:41:46.530 5111 5111 F DEBUG : #20 pc 000b168d /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base11MessageLoop13DoDelayedWorkEPNS_9TimeTicksE+272) 11-24 11:41:46.530 5111 5111 F DEBUG : #21 pc 000b2be5 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base18MessagePumpDefault3RunEPNS_11MessagePump8DelegateE+38) 11-24 11:41:46.530 5111 5111 F DEBUG : #22 pc 000b0f3f /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base11MessageLoop3RunEv+58) 11-24 11:41:46.530 5111 5111 F DEBUG : #23 pc 000c9fab /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base7RunLoop3RunEv+94) 11-24 11:41:46.531 5111 5111 F DEBUG : #24 pc 000ea781 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base6Thread3RunEPNS_7RunLoopE+92) 11-24 11:41:46.531 5111 5111 F DEBUG : #25 pc 000eaa27 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so (_ZN4base6Thread10ThreadMainEv+410) 11-24 11:41:46.531 5111 5111 F DEBUG : #26 pc 000e5bf1 /data/app/com.vewd.core.integration-1/lib/arm/libbase.cr.so 11-24 11:41:46.531 5111 5111 F DEBUG : #27 pc 000475d3 /system/lib/libc.so (_ZL15__pthread_startPv+22) 11-24 11:41:46.531 5111 5111 F DEBUG : #28 pc 0001a125 /system/lib/libc.so (__start_thread+6)
,
Feb 1 2018
|
|||||
►
Sign in to add a comment |
|||||
Comment 1 by skyos...@chromium.org
, Mar 27 2017Status: Assigned (was: Untriaged)