Mac_ios flutter_view_ios__start_up is 3.00% flaky

The post-submit test builder Mac_ios flutter_view_ios__start_up had a flaky ratio 3.00% for the past (up to) 100 commits, which is above our 2.00% threshold.

One recent flaky example for a same commit: https://ci.chromium.org/ui/p/flutter/builders/prod/Mac_ios%20flutter_view_ios__start_up/3568,%203569
Commit: ad612b5

Flaky builds:
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac_ios%20flutter_view_ios__start_up/3569
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac_ios%20flutter_view_ios__start_up/3568
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac_ios%20flutter_view_ios__start_up/3566
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac_ios%20flutter_view_ios__start_up/3562

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac_ios%20flutter_view_ios__start_up

Please follow https://github.com/flutter/flutter/wiki/Reducing-Test-Flakiness#fixing-flaky-tests to fix the flakiness and enable the test back after validating the fix (internal dashboard to validate: go/flutter_test_flakiness).

@jmagman

Waiting to see whether this is part of #98426

/cc @jmagman

These are different issues. The flake here happened on both mac6. and mac 30, with timing out:

[flutter_view_ios__start_up] [STDOUT] stdout: [  +65 ms] Successfully connected to service protocol: http://127.0.0.1:52824//
[flutter_view_ios__start_up] [STDOUT] stdout: [  +11 ms] Application running.
[flutter_view_ios__start_up] [STDOUT] stdout: [  +14 ms] Connected to iPhone
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Tracing startup on iPhone.
[flutter_view_ios__start_up] [STDOUT] stdout: [   +4 ms] Waiting for application to render first frame...

This test has been very flaky (6 out of top 30 commits): https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac_ios%20flutter_view_ios__start_up

@jmagman

The first instance of this flake was after landing the Engine roll here #98347, however none of the commits in that roll look suspicious. Looking back several commits from there, I'm also not seeing anything that jumps out as a likely cause.

The symptom and timeframe match #97958 to some extent. The app is installed, starts up, but then becomes wedged. In the case of this issue, it's after the Observatory comes up, whereas in 97958 it's before, but I think the debugging approach is probably similar. We need to examine the thread backtraces at the point where the app is wedged.

@jmagman is there any way to do something like #98550 when we already have the Observatory port, or is control over something like that only in the hands of the test harness at that point?

@jmagman

@jmagman is there any way to do something like #98550 when we already have the Observatory port, or is control over something like that only in the hands of the test harness at that point?

The test is timing out at 30 minutes, so we'd need to add a timeout here to give us time to process the failure:

flutter/packages/flutter_tools/lib/src/tracing.dart

Lines 54 to 58 in f4d1bfe

    
           vmService.service.onExtensionEvent.listen((vm_service.Event event) { 
        
             if (event.extensionKind == 'Flutter.FirstFrame') { 
        
               whenFirstFrameRendered.complete(); 
        
             } 
        
           });

lldb is attached, so it should be possible to trigger a bt dump with enough plumbing (that spot in the code doesn't know anything about the device, just the vm).
It would be nice to be able to trigger a spindump/sample of an iOS app from macOS, but I don't think that's possible.

Host logs: https://logs.chromium.org/logs/flutter/buildbucket/cr-buildbucket/8821834660096740417/+/u/run_flutter_view_ios__start_up/test_stdout

[flutter_view_ios__start_up] [STDOUT] stdout: [+1410 ms] Observatory URL on device: http://127.0.0.1:64467//
[flutter_view_ios__start_up] [STDOUT] stdout: [  +25 ms] fopen failed for data file: errno = 2 (No such file or directory)
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Errors found! Invalidating cache...
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Attempting to forward device port 64467 to host port 62239
[flutter_view_ios__start_up] [STDOUT] stdout: [   +1 ms] executing: /opt/s/w/ir/x/w/recipe_cleanup/tmpzipevwf8/flutter sdk/bin/cache/artifacts/usbmuxd/iproxy 62239:64467 --udid 6498800ec2ecd25eeb6293123de8db9f678b8a0d --debug
[flutter_view_ios__start_up] [STDOUT] stdout: [+1041 ms] Forwarded port ForwardedPort HOST:62239 to DEVICE:64467
[flutter_view_ios__start_up] [STDOUT] stdout: [   +2 ms] Forwarded host port 62239 to device port 64467 for Observatory
[flutter_view_ios__start_up] [STDOUT] stdout: [  +45 ms] Installing and launching... (completed in 33.7s)
[flutter_view_ios__start_up] [STDOUT] stdout: [  +14 ms] Connecting to service protocol: http://127.0.0.1:62239//
[flutter_view_ios__start_up] [STDOUT] stdout: [ +141 ms] Launching a Dart Developer Service (DDS) instance at http://127.0.0.1:0/, connecting to VM service at http://127.0.0.1:62239//.
[flutter_view_ios__start_up] [STDOUT] stdout: [ +123 ms] DDS is listening at http://127.0.0.1:62242/8e2jaNDrwtc=/.
[flutter_view_ios__start_up] [STDOUT] stdout: [  +76 ms] Successfully connected to service protocol: http://127.0.0.1:62239//
[flutter_view_ios__start_up] [STDOUT] stdout: [  +15 ms] Application running.
[flutter_view_ios__start_up] [STDOUT] stdout: [  +30 ms] Connected to Godofredo Contreras’s iPhone
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Tracing startup on Godofredo Contreras’s iPhone.
[flutter_view_ios__start_up] [STDOUT] stdout: [   +4 ms] Waiting for application to render first frame...
[timeout]

Device logs:
Debug server connection

Feb 18 19:19:23 debugserver[825] <Notice>: [LaunchAttach] successfully attached to pid 826

Engine up

Feb 18 19:19:50 Runner(Flutter)[826] <Notice>: flutter: Observatory listening on http://127.0.0.1:64467/
...
Feb 18 19:19:50 Runner(UIKitCore)[826] <Notice>: sceneOfRecord: sceneID: sceneID:com.yourcompany.flutterView-default  persistentID: 3D818F3B-89ED-4921-A66A-B35BE0C8E7F2
Feb 18 19:19:50 Runner(libCoreFSCache.dylib)[826] <Error>: fopen failed for data file: errno = 2 (No such file or directory)
Feb 18 19:19:50 Runner(libCoreFSCache.dylib)[826] <Error>: Errors found! Invalidating cache...

A peep later for the same process in an irrelevant subsystem a minute later, then nothing after that.

Feb 18 19:20:49 Runner(CoreAnalytics)[826] <Notice>: Received configuration update from daemon (initial)

Interestingly we have a startup timeline trace, so it's doing something: https://storage.googleapis.com/flutter_logs/flutter/baa2803fe1da00b18c47797abc31db230a64f5df/flutter_view_ios__start_up/c60d2a06-0aaa-4974-b33d-7b4a04cf9bc5/start_up_timeline.json

Adding some logging here: #98957

Current flaky ratio for the past (up to) 100 commits is 8.33%. Flaky number: 2; total number: 24.
One recent flaky example for a same commit: https://ci.chromium.org/ui/p/flutter/builders/prod/Mac_ios%20flutter_view_ios__start_up/64,%2065
Commit: baa2803
Flaky builds:
https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/65
https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/64
https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/52

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac_ios%20flutter_view_ios__start_up

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac_ios%20flutter_view_ios__start_up

The new logging shows up in build 138:

[flutter_view_ios__start_up] [STDOUT] stdout: [   +3 ms] Waiting for application to render first frame...
[flutter_view_ios__start_up] [STDOUT] stdout: [+10016 ms] First frame is taking longer than expected...
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Views:
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] id: _flutterView/0x10583ba20 isolate: isolates/2124306436294215
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Received VM events:
[flutter_view_ios__start_up] [STDOUT] stdout: [        ] Flutter.ServiceExtensionStateChanged: [ExtensionData {extension: ext.flutter.activeDevToolsServerAddress, value: http://127.0.0.1:9100/}]
[flutter_view_ios__start_up] [STDOUT] stdout:            Flutter.ServiceExtensionStateChanged: [ExtensionData {extension: ext.flutter.connectedVmServiceUri, value: http://127.0.0.1:51289/FmQKMskA6K8=/}]
[flutter_view_ios__start_up] [STDOUT] stdout:

[staging pool] current flaky ratio for the past (up to) 100 commits is 2.00%. Flaky number: 2; total number: 100.
One recent flaky example for a same commit: https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/637,%20636
Commit: 3c71219
Flaky builds:
https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/637
https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/636
https://ci.chromium.org/ui/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up/623

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac_ios%20flutter_view_ios__start_up

@keyonghan

623 is a code signing failure.

636 and 637, I suspect ran before the fix.

Assigning @keyonghan to comment on whether the codesigning error from 623 has already been addressed. If so, I believe this issue can be closed.

623 failure is #101861, where devicelab tests are scheduled to run on arm64 bots.

I will use that bug to enforce mac_model for existing devicelab bots to avoid interaction with different bots.

From the historical data, no single flake in recent 50 runs: https://ci.chromium.org/p/flutter/builders/staging/Mac_ios%20flutter_view_ios__start_up?limit=50.

Thanks everyone to address this flaky bug! Closing.

Ensure that the engine frame callbacks are installed if the first sch…

[flutter_releases] Flutter beta 2.13.0-0.2.pre Framework Cherrypicks (#…

This thread has been automatically locked since there has not been any recent activity after it was closed. If you are still experiencing a similar issue, please open a new bug, including the output of flutter doctor -v and a minimal reproduction of the issue.

Navigation Menu

Repository navigation

Mac_ios flutter_view_ios__start_up is 3.00% flaky #98419

69 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	vmService.service.onExtensionEvent.listen((vm_service.Event event) {
	if (event.extensionKind == 'Flutter.FirstFrame') {
	whenFirstFrameRendered.complete();
	}
	});

Mac_ios flutter_view_ios__start_up is 3.00% flaky #98419

Description

Activity

zanderso commented on Feb 14, 2022

keyonghan commented on Feb 14, 2022

keyonghan commented on Feb 15, 2022

zanderso commented on Feb 16, 2022

jmagman commented on Feb 16, 2022

jmagman commented on Feb 23, 2022

jmagman commented on Feb 23, 2022

fluttergithubbot commented on Feb 23, 2022

fluttergithubbot commented on Mar 2, 2022

zanderso commented on Mar 2, 2022

69 remaining items

fluttergithubbot commented on Apr 13, 2022

zanderso commented on Apr 13, 2022

keyonghan commented on Apr 13, 2022

github-actions commented on Apr 27, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions