New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 811711 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Feb 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 1
Type: Bug



Sign in to add a comment

"Memlog/MemlogBrowserTest.EndToEnd/13" is flaky

Project Member Reported by chromium...@appspot.gserviceaccount.com, Feb 13 2018

Issue description

"Memlog/MemlogBrowserTest.EndToEnd/13" is flaky.

This issue was created automatically by the chromium-try-flakes app. Please find the right owner to fix the respective test/step and assign this issue to them. If the step/test is infrastructure-related, please add Infra-Troopers label and change issue status to Untriaged. When done, please remove the issue from Sheriff Bug Queue by removing the Sheriff-Chromium label.

We have detected 4 recent flakes. List of all flakes can be found at https://chromium-try-flakes.appspot.com/all_flake_occurrences?key=ahVzfmNocm9taXVtLXRyeS1mbGFrZXNyLwsSBUZsYWtlIiRNZW1sb2cvTWVtbG9nQnJvd3NlclRlc3QuRW5kVG9FbmQvMTMM.

Flaky tests should be disabled within 30 minutes unless culprit CL is found and reverted. Please see more details here: https://sites.google.com/a/chromium.org/dev/developers/tree-sheriffs/sheriffing-bug-queues#triaging-auto-filed-flakiness-bugs
 

Comment 1 by treib@chromium.org, Feb 13 2018

Labels: OS-Windows
Example failure log:

[ RUN      ] Memlog/MemlogBrowserTest.EndToEnd/13
[7152:5208:0212/234136.873:WARNING:chrome_browser_main_win.cc(615)] Command line too long for RegisterApplicationRestart:  --brave-new-test-launcher --cfi-diag=0 --gtest_also_run_disabled_tests --gtest_filter=Memlog/MemlogBrowserTest.EndToEnd/13 --single_process --test-launcher-bot-mode --test-launcher-output="C:\Users\CHROME~2\AppData\Local\Temp\scoped_dir4056_24283\results4056_22776\test_results.xml" --test-launcher-summary-output="e:\b\swarm_slave\w\ios2gp8o\output.json" --user-data-dir="C:\Users\CHROME~2\AppData\Local\Temp\scoped_dir4056_24283\d4056_18323" --disable-offline-auto-reload --no-first-run --no-default-browser-check --enable-logging=stderr --disable-default-apps --wm-window-animations-disabled --disable-component-update --test-type=browser --force-color-profile=srgb --disable-zero-browsers-open-for-tests --memlog=all --memlog-stack-mode=native --ipc-connection-timeout=30 --allow-file-access-from-files --dom-automation --log-gpu-control-list-decisions --disable-backgrounding-occluded-windows --disable-gl-drawing-for-tests --override-use-software-gl-for-tests --force-color-profile=srgb --disable-compositor-ukm-for-tests --enable-features=TestFeatureForBrowserTest1 --disable-features=NetworkPrediction,TestFeatureForBrowserTest2 --flag-switches-begin --flag-switches-end --restore-last-session about:blank
[7304:5804:0212/234137.037:INFO:media_foundation_video_encode_accelerator_win.cc(370)] Windows versions earlier than 8 are not supported.
[7152:5208:0212/234137.267:INFO:memlog_browsertest.cc(79)] Memlog mode: 2
[7152:5208:0212/234137.267:INFO:memlog_browsertest.cc(80)] Memlog stack mode: 1
[7152:5208:0212/234137.267:INFO:memlog_browsertest.cc(81)] Started via command line flag: 1
[6572:3676:0212/234147.515:FATAL:profiling_service.mojom.cc(240)] Check failed: !connected. ProfilingService::DumpProcessesForTracingCallback was destroyed without first either being run or its corresponding binding being closed. It is an error to drop response callbacks which still correspond to an open interface pipe.
Backtrace:
	base::debug::StackTrace::StackTrace [0x02FF2A20+32]
	base::debug::StackTrace::StackTrace [0x02FB6DFD+13]
	logging::LogMessage::~LogMessage [0x02F5C790+80]
	profiling::mojom::ProfilingService_DumpProcessesForTracing_ProxyToResponder::OnIsConnectedComplete [0x01C8F8F9+137]
	?RunOnce@?$Invoker@U?$BindState@P6AX_N@Z$$V@internal@base@@$$A6AX_N@Z@internal@base@@SAXPAVBindStateBase@23@_N@Z [0x0154074E+14]
	base::RepeatingCallback<void __cdecl(bool)>::Run [0x01986063+51]
	std::tuple<base::WeakPtr<mojo::InterfaceEndpointClient>,base::Optional<mojo::DisconnectReason> >::tuple<base::WeakPtr<mojo::InterfaceEndpointClient>,base::Optional<mojo::DisconnectReason> ><std::_Exact_args_t,base::WeakPtr<mojo::InterfaceEndpointClient>,b [0x03B44E4E+1176]
	std::tuple<base::WeakPtr<mojo::InterfaceEndpointClient>,base::Optional<mojo::DisconnectReason> >::tuple<base::WeakPtr<mojo::InterfaceEndpointClient>,base::Optional<mojo::DisconnectReason> ><std::_Exact_args_t,base::WeakPtr<mojo::InterfaceEndpointClient>,b [0x03B44C28+626]
	profiling::mojom::ProfilingService_DumpProcessesForTracing_ProxyToResponder::~ProfilingService_DumpProcessesForTracing_ProxyToResponder [0x01C8F82B+103]
	std::unique_ptr<profiling::mojom::ProfilingService_DumpProcessesForTracing_ProxyToResponder,std::default_delete<profiling::mojom::ProfilingService_DumpProcessesForTracing_ProxyToResponder> >::~unique_ptr<profiling::mojom::ProfilingService_DumpProcessesFor [0x01C8F691+17]
	base::internal::BindState<void (__thiscall profiling::mojom::ProfilingService_DumpProcessesForTracing_ProxyToResponder::*)(std::vector<mojo::StructPtr<profiling::mojom::SharedBufferWithSize>,std::allocator<mojo::StructPtr<profiling::mojom::SharedBufferWit [0x01C8F7B3+19]
	base::internal::CallbackBase::~CallbackBase [0x02F6F569+25]
	profiling::MemlogConnectionManager::DumpProcessesForTracingTracking::~DumpProcessesForTracingTracking [0x061A1176+36]
	profiling::MemlogConnectionManager::DumpProcessesForTracingTracking::`scalar deleting destructor' [0x061A113B+11]
	base::internal::BindState<void (__thiscall content::VideoEncoderShim::*)(scoped_refptr<media::VideoFrame>,int,unsigned int,bool),base::WeakPtr<content::VideoEncoderShim>,scoped_refptr<media::VideoFrame>,int,unsigned int,bool>::Destroy [0x0614E905+53]
	base::internal::CallbackBase::~CallbackBase [0x02F6F569+25]
	std::_Tree<std::_Tmap_traits<unsigned int,std::pair<scoped_refptr<base::SequencedTaskRunner>,base::OnceCallback<void __cdecl(bool,std::map<profiling::AllocationEvent,int,profiling::AllocationEvent::MetadataPartialLess,std::allocator<std::pair<profiling::A [0x061A43E0+44]
	std::_Tree<std::_Tmap_traits<unsigned int,std::pair<scoped_refptr<base::SequencedTaskRunner>,base::OnceCallback<void __cdecl(bool,std::map<profiling::AllocationEvent,int,profiling::AllocationEvent::MetadataPartialLess,std::allocator<std::pair<profiling::A [0x061A40F4+50]
	profiling::AllocationTracker::~AllocationTracker [0x061A53C7+171]
	profiling::MemlogConnectionManager::Connection::~Connection [0x061A0817+33]
	std::unique_ptr<profiling::MemlogConnectionManager::Connection,std::default_delete<profiling::MemlogConnectionManager::Connection> >::reset [0x061A105A+22]
	std::vector<std::pair<unsigned long,std::unique_ptr<profiling::MemlogConnectionManager::Connection,std::default_delete<profiling::MemlogConnectionManager::Connection> > >,std::allocator<std::pair<unsigned long,std::unique_ptr<profiling::MemlogConnectionMa [0x061A1095+45]
	profiling::MemlogConnectionManager::OnConnectionComplete [0x0619FFBF+143]
	base::internal::Invoker<base::internal::BindState<void (__thiscall content::VideoEncoderShim::*)(enum media::VideoEncodeAccelerator::Error),base::WeakPtr<content::VideoEncoderShim>,enum media::VideoEncodeAccelerator::Error>,void __cdecl(void)>::RunOnce [0x04583701+49]
	base::debug::TaskAnnotator::RunTask [0x02FEF007+231]
	base::internal::IncomingTaskQueue::RunTask [0x030129E9+105]
	base::MessageLoop::RunTask [0x02F928C7+519]
	base::MessageLoop::DeferOrRunPendingTask [0x02F92C2D+157]
	base::MessageLoop::DoWork [0x02F92E5A+506]
	base::MessagePumpForIO::DoRunLoop [0x03015E05+133]
	base::MessagePumpWin::Run [0x030151CE+110]
	base::MessageLoop::Run [0x02F92269+169]
	base::RunLoop::Run [0x02F6ADCF+207]
	base::Thread::Run [0x02FA89E4+164]
	base::Thread::ThreadMain [0x02FA8E27+631]
	base::PlatformThread::GetCurrentThreadPriority [0x02F87105+469]
	BaseThreadInitThunk [0x7606336A+18]
	RtlInitializeExceptionChain [0x77B59882+99]
	RtlInitializeExceptionChain [0x77B59855+54]
Received fatal exception EXCEPTION_BREAKPOINT

Comment 2 by treib@chromium.org, Feb 13 2018

Cc: erikc...@chromium.org ajwong@chromium.org
There are currently 4 failures from today, but also one from 2018-02-09 which looks identical.

CCing owners.

Comment 3 by treib@chromium.org, Feb 13 2018

According to the flakiness dashboard [1], many of the MemlogBrowserTest.EndToEnd tests are flaky to varying degrees on multiple platforms, but /13 got much worse on Windows recently, around 2018-02-13 at 7:30 AM GMT. The timing matches CL [2] which looks plausibly related. I'll try reproing locally.

[1] https://test-results.appspot.com/dashboards/flakiness_dashboard.html#tests=Memlog%2FMemlogBrowserTest.EndToEnd%2F
[2] https://chromium-review.googlesource.com/c/chromium/src/+/900222

Comment 4 by treib@chromium.org, Feb 13 2018

I've locally verified that https://crrev.com/c/900222 is indeed the culprit, will revert.

Note to anyone else looking at this: The test in question is only compiled with "is_component_build = false".
Project Member

Comment 5 by bugdroid1@chromium.org, Feb 13 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/1c849e92aef656ed495be99af74442c75243789c

commit 1c849e92aef656ed495be99af74442c75243789c
Author: Marc Treib <treib@chromium.org>
Date: Tue Feb 13 14:30:42 2018

Revert "Clean up of memory instrumentation interface."

This reverts commit 99b4a583f634ba382fd597cda1148cc4299dc2e0.

Reason for revert: Breaks Memlog/MemlogBrowserTest.EndToEnd/13 on Windows; see  crbug.com/811711 

Original change's description:
> Clean up of memory instrumentation interface.
> 
> This CL cleans up both the public interface and private implementation of memory
> instrumentation. It is in preparation for allowing memory instrumentation to
> asynchronously add heap dumps to traces.
> 
> memory_instrumentation supports two interfaces: HeapProfilerHelper and
> Coordinator [specifically RequestGlobalMemoryDump]. They are used by different
> clients, with different privileges, for different purposes. The internal
> implementation used a single code path to support both, which further results in
> leakage of implementation details into the mojom interface, in the form of
> LevelOfDetail::VM_REGIONS_ONLY_FOR_HEAP_PROFILER.
> 
> The previous implementation only allowed 1 global dump to be issued at a time.
> This causes problems for my upcoming refactor, which makes
> memory_instrumentation, during a global dump, request a heap dump from the
> profiling service. The profiling service in turn requests heaps from
> memory_instrumentation, resulting in a deadlock.
> 
> This CL updates the implementation of CoordinatorImpl to use a separate queue of
> |in_progress_vm_region_requests_| to track heap dump requests. These are
> executed as soon as they are received. This CL also removes
> LevelOfDetail::VM_REGIONS_ONLY_FOR_HEAP_PROFILER, and updates
> GetVmRegionsForHeapProfiler to explicitly specify PIDs to dump.
> 
> Bug: 758739
> Change-Id: I1ee41e272ac4379f791abe469e0d8efda42636de
> Reviewed-on: https://chromium-review.googlesource.com/900222
> Commit-Queue: Erik Chen <erikchen@chromium.org>
> Reviewed-by: Daniel Cheng <dcheng@chromium.org>
> Reviewed-by: Ilya Sherman <isherman@chromium.org>
> Reviewed-by: Primiano Tucci <primiano@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#536263}

TBR=dcheng@chromium.org,isherman@chromium.org,primiano@chromium.org,erikchen@chromium.org,lalitm@chromium.org

Change-Id: I6ba2c5548b4fcd2950a3e0a1734a10140c6c152a
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: 758739,  811711 
Reviewed-on: https://chromium-review.googlesource.com/916063
Reviewed-by: Marc Treib <treib@chromium.org>
Commit-Queue: Marc Treib <treib@chromium.org>
Cr-Commit-Position: refs/heads/master@{#536353}
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/browser/metrics/process_memory_metrics_emitter_unittest.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/browser/profiling_host/background_profiling_triggers_unittest.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/browser/profiling_host/profiling_test_driver.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/profiling/memlog_connection_manager.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/profiling/memlog_connection_manager.h
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/profiling/profiling_service.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/chrome/profiling/profiling_service.h
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/coordinator_impl.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/coordinator_impl.h
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/coordinator_impl_unittest.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/queued_request.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/queued_request.h
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/queued_request_dispatcher.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/memory_instrumentation/queued_request_dispatcher.h
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/public/cpp/memory_instrumentation/memory_instrumentation_mojom_traits.cc
[modify] https://crrev.com/1c849e92aef656ed495be99af74442c75243789c/services/resource_coordinator/public/mojom/memory_instrumentation/memory_instrumentation.mojom

Comment 6 by treib@chromium.org, Feb 13 2018

Labels: -Sheriff-Chromium

Comment 7 by treib@chromium.org, Feb 13 2018

Status: Fixed (was: Untriaged)
Cc: treib@chromium.org
Re c#3 - I checked out the link in (1), and didn't see any flakiness [ I was curious about the flakiness before the CL in question ]. Maybe I'm using the dashboard incorrectly? Can you send a link to a flaky failure [prior to 2-13?]

Comment 9 by treib@chromium.org, Feb 13 2018

All the gray/black boxes correspond to flakes. In the link, you'll have to scroll down a bit, e.g. /15 and /16 are quite flaky.
One example for /13 is here:
https://ci.chromium.org/buildbot/chromium.win/Win%207%20Tests%20x64%20(1)/34648
Note that this run still passed, because the test got retried and passed on the second run. But you'll see the failure in the actual logs:
https://logs.chromium.org/v/?s=chromium%2Fbb%2Fchromium.win%2FWin_7_Tests_x64__1_%2F34648%2F%2B%2Frecipes%2Fsteps%2Fbrowser_tests%2F0%2Fstdout
Thanks. Almost all of the cases I looked at were timeouts, and the root cause is the same as the one you locally - the factor that affects whether the test times out or crashes is whether DCHECKs are enabled.
Owner: erikc...@chromium.org
Status: Assigned (was: Fixed)
Project Member

Comment 12 by bugdroid1@chromium.org, Feb 14 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/a6f3feb77a659dee2dd09707203fa43e0d800894

commit a6f3feb77a659dee2dd09707203fa43e0d800894
Author: erikchen <erikchen@chromium.org>
Date: Wed Feb 14 16:21:56 2018

Fix 2 bugs in out of process heap profiling implementation.

Bug 1: When an AllocationTracker is destroyed from a client disconnecting,
queued barrier callbacks would not be run. This would cause the heap dump to
never be emitted.

 Bug 2 : The implementation of MemlogConnectionManager::OnNewConnection called
mojo::SharedBufferHandle::Create, which uses synchronous IPC with the browser
process. This can cause deadlock/timeouts, since the browser process
synchronously waits for the memlog pipe to free up and eventually gives up after
10 seconds, tearing down the allocator shim. The solution is to create a
dedicated thread for calling mojo::SharedBufferHandle::Create, thus avoiding the
deadlock.

Change-Id: Ib3f4143381ce03c353ffe93d45794070e3b007d5
Bug:  811711 
Reviewed-on: https://chromium-review.googlesource.com/917243
Commit-Queue: Erik Chen <erikchen@chromium.org>
Reviewed-by: Primiano Tucci <primiano@chromium.org>
Cr-Commit-Position: refs/heads/master@{#536729}
[modify] https://crrev.com/a6f3feb77a659dee2dd09707203fa43e0d800894/chrome/profiling/allocation_tracker.cc
[modify] https://crrev.com/a6f3feb77a659dee2dd09707203fa43e0d800894/chrome/profiling/memlog_connection_manager.cc
[modify] https://crrev.com/a6f3feb77a659dee2dd09707203fa43e0d800894/chrome/profiling/memlog_connection_manager.h

Status: Fixed (was: Assigned)

Sign in to add a comment