Skip to content

flutter_gallery__memory_nav is falky #58690

Closed
#58838
Closed
flutter_gallery__memory_nav is falky#58690
#58838
Assignees
goderbauer
Labels
P0Critical issues such as a build break or regressionc: flakeTests that sometimes, but not always, incorrectly passengineflutter/engine related. See also e: labels.frameworkflutter/packages/flutter repository. See also f: labels.platform-androidAndroid applications specifically
Milestone
1.20 - June 2020

Description

@goderbauer
goderbauer
opened on Jun 4, 2020

We need to fix the flakiness or delete the test if it is no longer relevant.

Broken out from #58338 /cc @Hixie

Activity

  1. goderbauer
    added
    platform-androidAndroid applications specifically
    frameworkflutter/packages/flutter repository. See also f: labels.
    engineflutter/engine related. See also e: labels.
    team: flakes
    P1
    on Jun 4, 2020
  2. goderbauer
    self-assigned this
    on Jun 4, 2020

  3. goderbauer commented on Jun 4, 2020

    @goderbauer
    goderbauer
    on Jun 4, 2020
    MemberAuthor

    From the logs, the test appears to time out waiting for this future:

    flutter/dev/devicelab/lib/tasks/perf_tests.dart

    Line 675 in 7261b98

    await receivedNextMessage;

    Here is the log of a successful run:

    awaiting "done" message...
2020-06-03T21:58:39.171946: adb logcat: 06-03 21:57:49.184  8490  8507 I flutter : Tapping... (iteration 0)
2020-06-03T21:58:39.495400: adb logcat: 06-03 21:57:49.506  8490  8507 I flutter : Backing out...
2020-06-03T21:58:39.882061: adb logcat: 06-03 21:57:49.892  8490  8507 I flutter : Tapping... (iteration 1)
2020-06-03T21:58:40.213917: adb logcat: 06-03 21:57:50.225  8490  8507 I flutter : Backing out...
2020-06-03T21:58:40.655548: adb logcat: 06-03 21:57:50.666  8490  8507 I flutter : Tapping... (iteration 2)
2020-06-03T21:58:41.000001: adb logcat: 06-03 21:57:51.011  8490  8507 I flutter : Backing out...
2020-06-03T21:58:41.388952: adb logcat: 06-03 21:57:51.396  8490  8507 I flutter : Tapping... (iteration 3)
2020-06-03T21:58:41.736013: adb logcat: 06-03 21:57:51.745  8490  8507 I flutter : Backing out...
2020-06-03T21:58:42.121588: adb logcat: 06-03 21:57:52.132  8490  8507 I flutter : Tapping... (iteration 4)
2020-06-03T21:58:42.469309: adb logcat: 06-03 21:57:52.479  8490  8507 I flutter : Backing out...
2020-06-03T21:58:42.877538: adb logcat: 06-03 21:57:52.887  8490  8507 I flutter : Tapping... (iteration 5)
2020-06-03T21:58:43.235414: adb logcat: 06-03 21:57:53.248  8490  8507 I flutter : Backing out...
2020-06-03T21:58:43.642086: adb logcat: 06-03 21:57:53.653  8490  8507 I flutter : Tapping... (iteration 6)
2020-06-03T21:58:43.931455: adb logcat: 06-03 21:57:53.943  1469 30483 I ActivityManager: Killing 7709:com.android.chrome/u0a78 (adj 906): empty #13
2020-06-03T21:58:43.989316: adb logcat: 06-03 21:57:54.000  8490  8507 I flutter : Backing out...
2020-06-03T21:58:44.425483: adb logcat: 06-03 21:57:54.437  8490  8507 I flutter : Tapping... (iteration 7)
2020-06-03T21:58:44.773014: adb logcat: 06-03 21:57:54.785  8490  8507 I flutter : Backing out...
2020-06-03T21:58:45.215304: adb logcat: 06-03 21:57:55.228  8490  8507 I flutter : Tapping... (iteration 8)
2020-06-03T21:58:45.575641: adb logcat: 06-03 21:57:55.587  8490  8507 I flutter : Backing out...
2020-06-03T21:58:45.962027: adb logcat: 06-03 21:57:55.973  8490  8507 I flutter : Tapping... (iteration 9)
2020-06-03T21:58:46.312834: adb logcat: 06-03 21:57:56.322  8490  8507 I flutter : Backing out...
2020-06-03T21:58:46.709043: adb logcat: 06-03 21:57:56.721  8490  8507 I flutter : Tapping... (iteration 10)
2020-06-03T21:58:47.062309: adb logcat: 06-03 21:57:57.074  8490  8507 I flutter : Backing out...
2020-06-03T21:58:47.123794: adb logcat: 06-03 21:57:57.135  1469  6358 I ActivityManager: Killing 8186:com.android.providers.calendar/u0a15 (adj 906): empty #13
2020-06-03T21:58:47.468815: adb logcat: 06-03 21:57:57.479  8490  8507 I flutter : Tapping... (iteration 11)
2020-06-03T21:58:47.832145: adb logcat: 06-03 21:57:57.842  8490  8507 I flutter : Backing out...
2020-06-03T21:58:48.218847: adb logcat: 06-03 21:57:58.228  8490  8507 I flutter : Tapping... (iteration 12)
2020-06-03T21:58:48.566030: adb logcat: 06-03 21:57:58.577  8490  8507 I flutter : Backing out...
2020-06-03T21:58:48.952094: adb logcat: 06-03 21:57:58.962  8490  8507 I flutter : Tapping... (iteration 13)
2020-06-03T21:58:49.302420: adb logcat: 06-03 21:57:59.312  8490  8507 I flutter : Backing out...
2020-06-03T21:58:49.718462: adb logcat: 06-03 21:57:59.731  8490  8507 I flutter : Tapping... (iteration 14)
2020-06-03T21:58:50.068905: adb logcat: 06-03 21:58:00.081  8490  8507 I flutter : Backing out...
2020-06-03T21:58:50.480411: adb logcat: 06-03 21:58:00.492  8490  8507 I flutter : ==== MEMORY BENCHMARK ==== DONE ====
2020-06-03T21:58:50.482340: snapshotting memory usage...

    Here of a failed run:

    awaiting "done" message...
2020-06-03T22:01:26.214259: adb logcat: 06-03 22:00:00.009  5083  5083 I ActivityManager: Killing 19943:com.google.android.partnersetup/u0a39 (adj 906): empty #13
2020-06-03T22:01:31.079082: adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: Sending non-protected broadcast com.motorola.actions.DAYS_SINCE_ACTIVATION_INCREMENTED from system 5537:com.motorola.actions/u0a49 pkg com.motorola.actions
adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: java.lang.Throwable
adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: 	at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:18226)
adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: 	at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:18826)
adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: 	at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:512)
adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: 	at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2906)
adb logcat: 06-03 22:00:04.872  5083 17138 E ActivityManager: 	at android.os.Binder.execTransact(Binder.java:565)
2020-06-03T22:14:31.737320: Task timed out in framework.dart after 0:15:00.000000.
TimeoutException after 0:15:00.000000: Future not completed
2020-06-03T22:14:31.737418: 
Cleaning up after task...
2020-06-03T22:14:32.740146: Force-quitting process:
command : /home/flutter/Android/Sdk/platform-tools/adb -s ZY223TDZ45 logcat ActivityManager:I flutter:V *:F
  started : 2020-06-03 21:59:34.199277
  pid     : 23010
2020-06-03T22:14:32.746111: "/home/flutter/Android/Sdk/platform-tools/adb" exit code: -15
2020-06-03T22:14:32.746450: adb logcat process terminated with exit code -15
2020-06-03T22:14:32.753579: Task failed: adb logcat failed with exit code -15.
2020-06-03T22:14:32.753675: 

Stack trace:
2020-06-03T22:14:32.774029: dart:async                                                 _StreamController.addError
package:flutter_devicelab/framework/adb.dart 423:20        AndroidDevice.logcat.<fn>.<fn>
===== asynchronous gap ===========================
dart:async                                                 Future.then
package:flutter_devicelab/framework/adb.dart 420:26        AndroidDevice.logcat.<fn>
===== asynchronous gap ===========================
dart:async                                                 _asyncThenWrapperHelper
package:flutter_devicelab/framework/adb.dart               AndroidDevice.logcat.<fn>
dart:async                                                 _StreamImpl.listen
package:flutter_devicelab/tasks/perf_tests.dart 603:60     MemoryTest.run.<fn>
===== asynchronous gap ===========================
dart:async                                                 _asyncThenWrapperHelper
package:flutter_devicelab/tasks/perf_tests.dart            MemoryTest.run.<fn>
package:flutter_devicelab/framework/utils.dart 463:24      inDirectory
package:flutter_devicelab/tasks/perf_tests.dart 595:12     MemoryTest.run
package:flutter_devicelab/framework/framework.dart 170:36  _TaskRunner._performTask.<fn>
package:stack_trace                                        Chain.capture
package:flutter_devicelab/framework/framework.dart 169:11  _TaskRunner._performTask
package:flutter_devicelab/framework/framework.dart 101:41  _TaskRunner.run

    The test appears to be waiting for the "==== MEMORY BENCHMARK ==== DONE ====" message in the logcat, which never appears.

  4. Hixie commented on Jun 4, 2020

    @Hixie
    Hixie
    on Jun 4, 2020
    Contributor

    That implies something is going wrong in this block:

      debugPrint('Scrolling...');
  final Finder list = find.byKey(const Key('ImageList'));
  final Finder lastItem = find.byKey(const Key('image_${numItems - 1}'));
  do {
    await controller.drag(list, const Offset(0.0, -30.0));
    await Future<void>.delayed(const Duration(milliseconds: 20));
  } while (!lastItem.precache());

  5. Hixie commented on Jun 4, 2020

    @Hixie
    Hixie
    on Jun 4, 2020
    Contributor

    Maybe we're overshooting?

  6. Hixie commented on Jun 4, 2020

    @Hixie
    Hixie
    on Jun 4, 2020
    Contributor

    cc @HansMuller

  7. goderbauer commented on Jun 4, 2020

    @goderbauer
    goderbauer
    on Jun 4, 2020
    MemberAuthor

    @Hixie are you talking about this code?

    flutter/dev/integration_tests/flutter_gallery/test_memory/image_cache_memory.dart

    Lines 54 to 62 in e167181

    debugPrint('Scrolling...');
    final Finder list = find.byKey(const Key('ImageList'));
    final Finder lastItem = find.byKey(const Key('image_${numItems - 1}'));
    do {
    await controller.drag(list, const Offset(0.0, -30.0));
    await Future<void>.delayed(const Duration(milliseconds: 20));
    } while (!lastItem.precache());
    debugPrint('==== MEMORY BENCHMARK ==== DONE ====');

    I was actually suspecting this code insted:

    flutter/dev/integration_tests/flutter_gallery/test_memory/memory_nav.dart

    Lines 75 to 85 in e167181

    for (int iteration = 0; iteration < 15; iteration += 1) {
    debugPrint('Tapping... (iteration $iteration)');
    await controller.tap(demoItem);
    await endOfAnimation();
    debugPrint('Backing out...');
    await controller.tap(find.byTooltip('Back'));
    await endOfAnimation();
    await Future<void>.delayed(const Duration(milliseconds: 50));
    }
    debugPrint('==== MEMORY BENCHMARK ==== DONE ====');

  8. goderbauer commented on Jun 4, 2020

    @goderbauer
    goderbauer
    on Jun 4, 2020
    MemberAuthor

    It appears that on the app side, this future never completes:

    flutter/dev/integration_tests/flutter_gallery/test_memory/memory_nav.dart

    Line 42 in e167181

    await ready.future;

    That's implying that the tap issued by the test never reaches the tap handler in the app:

    flutter/dev/integration_tests/flutter_gallery/test_memory/memory_nav.dart

    Lines 27 to 31 in e167181

    runApp(GestureDetector(
    onTap: () {
    debugPrint('Received tap.');
    ready.complete();
    },

    This is where the test issues the tap:

    flutter/dev/devicelab/lib/tasks/perf_tests.dart

    Lines 673 to 675 in 7261b98

    await device.tap(100, 100);
    print('awaiting "done" message...');
    await receivedNextMessage;

  9. Hixie commented on Jun 4, 2020

    @Hixie
    Hixie
    on Jun 4, 2020
    Contributor

    Oh you're right. I got tricked by the GitHub search results when I searched for "MEMORY BENCHMARK". :-)

  10. Hixie commented on Jun 4, 2020

    @Hixie
    Hixie
    on Jun 4, 2020
    Contributor

    Weird. I wonder if there's a dialog on the screen or something. We only say we're ready 50ms after we're done rendering the frame, why would a tap not get detected?

  11. goderbauer commented on Jun 4, 2020

    @goderbauer
    goderbauer
    on Jun 4, 2020
    MemberAuthor

    Good question! Unfortunately, I am not able to reproduce the flake locally on my Pixel 4, so I can't really experiment with it. I am wondering if for some reason the engine is not ready to forward the touch:

    https://github.com/flutter/engine/blob/b3e7732cf9b3fa628c769fa3f3f4f1494b5d0e98/shell/platform/android/io/flutter/embedding/android/FlutterView.java#L680-L695

    Does the view maybe think the engine is not attached yet and discard the tap?

  12. goderbauer commented on Jun 5, 2020

    @goderbauer
    goderbauer
    on Jun 5, 2020
    MemberAuthor

    Increasing the time we wait before tapping the device by 10x didn't fix the flake. Makes me think that the device not being ready is not the problem.

  13. goderbauer commented on Jun 5, 2020

    @goderbauer
    goderbauer
    on Jun 5, 2020
    MemberAuthor

    Interestingly, the test seems to flake out consistently when running on one of these bots:

    • flutter-devicelab-linux-2
    • flutter-devicelab-linux-3
    • flutter-devicelab-linux-5
    • flutter-devicelab-linux-6
    • flutter-devicelab-linux-7

    On flutter-devicelab-linux-1 and flutter-devicelab-linux-4 it consistently passes.

  14. goderbauer commented on Jun 5, 2020

    @goderbauer
    goderbauer
    on Jun 5, 2020
    MemberAuthor

    That's a similar observation that @gspencergoog made while investigating the other flake: #58691

    And sure enough, similar to the other failure when this one fails I also see the keyboard crash in the logs:

    2020-06-04T17:35:40.177114: adb logcat: 06-04 17:35:04.418 23070 23082 I ActivityManager: Killing 19989:com.google.android.inputmethod.latin/u0a94 (adj 200): crash

    When the test passes, the line about the keyboard crash is missing...

    Maybe the cause of the flake is the same after all...

  15. goderbauer commented on Jun 5, 2020

    @goderbauer
    goderbauer
    on Jun 5, 2020
    MemberAuthor

    To be more precise, when the test runs on devices with the following serials it is pretty much guaranteed to pass: ZY223D6B7B and ZY22465WKN. On all other devices, it is pretty much guaranteed to fail. This is exactly the same as #58691.

  16. goderbauer
    added this to the 1.20 - June 2020 milestone on Jun 5, 2020
  17. gspencergoog
    closed this as completedin #58838on Jun 8, 2020

  18. github-actions commented on Aug 20, 2021

    @github-actions
    github-actionsbot
    on Aug 20, 2021

    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.

  19. github-actions
    locked as resolved and limited conversation to collaborators on Aug 20, 2021
  20. flutter-triage-bot
    added
    P0Critical issues such as a build break or regression
    and removed
    P1
    on Jun 28, 2023
  21. flutter-triage-bot
    added
    c: flakeTests that sometimes, but not always, incorrectly pass
    on Jul 7, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

P0Critical issues such as a build break or regressionc: flakeTests that sometimes, but not always, incorrectly passengineflutter/engine related. See also e: labels.frameworkflutter/packages/flutter repository. See also f: labels.platform-androidAndroid applications specifically

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions