Skip to content

Flaky flutter drive test on Moto G4 with --trace-startup #59263

Closed
Closed
Flaky flutter drive test on Moto G4 with --trace-startup#59263
Labels
a: tests"flutter test", flutter_test, or one of our testsr: invalidIssue is closed as not validt: flutter driver"flutter driver", flutter_drive, or a driver testtoolAffects the "flutter" command-line tool. See also t: labels.

Description

@CareF
CareF
opened on Jun 11, 2020

Very often when I run flutter drive for a test case in macrobenchmarks, with option --trace-startup (which is the case we run for devicelab. This issue is talking about running locally though.), the app crashes on the device with message "Unfortunately, macrobenchmarks has stopped." resulting in test fail. This only happens to Moto G4 but not Pixel 4.
The notice on host machine shows:

VMServiceFlutterDriver: Instance of '_WebSocketImpl' is closed with an unexpected code 1005
VMServiceFlutterDriver: Instance of '_WebSocketImpl' is closed with an unexpected code 1005

Any suggestion about what can check is appreciated!

Activity

  1. CareF
    added
    team-infraOwned by Infrastructure team
    on Jun 11, 2020

  2. CareF commented on Jun 11, 2020

    @CareF
    CareF
    on Jun 11, 2020
    ContributorAuthor

    Some logging if it will be helpful:

    [cull_opacity_perf__timeline_summary] [STDOUT] stderr: [        ] VMServiceFlutterDriver: Instance of '_WebSocketImpl' is closed with an unexpected code 1005
[cull_opacity_perf__timeline_summary] [STDOUT] stderr: [+4343 ms] VMServiceFlutterDriver: VM is taking an unusually long time to respond to being told to start tracing...
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [+37725 ms] 00:45 +0 -1: cull_opacity_perf [E]
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [   +1 ms]   TimeoutException after 0:00:45.000000: Test timed out after 45 seconds.
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [  +18 ms]   package:test_api/src/backend/invoker.dart 333:28               Invoker._handleError.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1182:47                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 331:10               Invoker._handleError
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 287:9                Invoker.heartbeat.<fn>.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 286:38               Invoker.heartbeat.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/stack_zone_specification.dart 209:15   StackZoneSpecification._run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/stack_zone_specification.dart 119:48   StackZoneSpecification._registerCallback.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1021:23                                   _CustomZone.bindCallback.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async-patch/timer_patch.dart 18:15                        Timer._createTimer.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/timer_impl.dart 397:19                      _Timer._runTimers
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/timer_impl.dart 428:5                       _Timer._handleMessage
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/isolate_patch.dart 168:12                   _RawReceivePortImpl._handleMessage
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   ===== asynchronous gap ===========================
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1114:19                                   _CustomZone.registerCallback
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1020:22                                   _CustomZone.bindCallback
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1263:21                                   _rootCreateTimer
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1154:19                                   _CustomZone.createTimer
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 285:34               Invoker.heartbeat
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 239:5                Invoker.waitForOutstandingCallbacks
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/declarer.dart 170:33              Declarer.test.<fn>.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1630:10                                   _runZoned
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1550:10                                   runZoned
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/declarer.dart 169:13              Declarer.test.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 400:30               Invoker._onRun.<fn>.<fn>.<fn>.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/future.dart 174:37                                  new Future.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/stack_zone_specification.dart 209:15   StackZoneSpecification._run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/stack_zone_specification.dart 119:48   StackZoneSpecification._registerCallback.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1182:47                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 997:7                                     _CustomZone.runGuarded
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1037:23                                   _CustomZone.bindCallbackGuarded.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/stack_zone_specification.dart 209:15   StackZoneSpecification._run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/stack_zone_specification.dart 119:48   StackZoneSpecification._registerCallback.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1021:23                                   _CustomZone.bindCallback.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async-patch/timer_patch.dart 18:15                        Timer._createTimer.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/timer_impl.dart 397:19                      _Timer._runTimers
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/timer_impl.dart 428:5                       _Timer._handleMessage
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/isolate_patch.dart 168:12                   _RawReceivePortImpl._handleMessage
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   ===== asynchronous gap ===========================
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1114:19                                   _CustomZone.registerCallback
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1036:22                                   _CustomZone.bindCallbackGuarded
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/timer.dart 52:45                                    new Timer
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/timer.dart 89:9                                     Timer.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/future.dart 172:11                                  new Future
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 399:21               Invoker._onRun.<fn>.<fn>.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1630:10                                   _runZoned
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1550:10                                   runZoned
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 387:9                Invoker._onRun.<fn>.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 438:15               Invoker._guardIfGuarded
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 386:7                Invoker._onRun.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/chain.dart 101:24                      Chain.capture.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1630:10                                   _runZoned
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1550:10                                   runZoned
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:stack_trace/src/chain.dart 99:12                       Chain.capture
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/invoker.dart 385:11               Invoker._onRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   package:test_api/src/backend/live_test_controller.dart 152:11  LiveTestController.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/future.dart 200:37                                  new Future.microtask.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1182:47                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 997:7                                     _CustomZone.runGuarded
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1037:23                                   _CustomZone.bindCallbackGuarded.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1190:13                                   _rootRun
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1093:19                                   _CustomZone.run
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 997:7                                     _CustomZone.runGuarded
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/zone.dart 1037:23                                   _CustomZone.bindCallbackGuarded.<fn>
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/schedule_microtask.dart 41:21                       _microtaskLoop
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:async/schedule_microtask.dart 50:5                        _startMicrotaskLoop
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/isolate_patch.dart 118:13                   _runPendingImmediateCallback
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ]   dart:isolate-patch/isolate_patch.dart 169:5                    _RawReceivePortImpl._handleMessage
[cull_opacity_perf__timeline_summary] [STDOUT] stdout: [        ] 00:45 +0 -1: Some tests failed.

  3. CareF commented on Jun 11, 2020

    @CareF
    CareF
    on Jun 11, 2020
    ContributorAuthor

    It seems that this happens more often to tests that lasts for longer time and is computationally more intense.
    For example cubic_bezier_perf__timeline_summary works fine, but cull_opacity_perf__timeline_summary fails.
    We suspect it's because limited memory.

  4. jason-simmons commented on Jun 12, 2020

    @jason-simmons
    jason-simmons
    on Jun 12, 2020
    Member

    Recently there was a similar issue (#57756) where the application process on the device ran out of memory and was killed while running a benchmark. The peak memory usage occurred when the app was serializing the timeline events as JSON in response to a request by the benchmark script.

    Retrieving the timeline in smaller chunks helped (verify that you have the patch: cd7dfd0). Beyond that, try reducing the duration of the benchmark.

  5. flar commented on Jul 27, 2020

    @flar
    flar
    on Jul 27, 2020
    Contributor

    We should also look at the trace event stream as it may have a lot of bloat. There is a mechanism in there to tokenize some common strings, but many of our events contain event-specific additional data and that data is reported as strings and those strings are not tokenized - they are strdup()'d, even if they are common strings like "0" and "1". This is a big waste as it adds a lot of toString overhead and then malloc fragmentation.

    This bloat not only affects the data stored in the app while accumulating the events, but it also bloats the data sent over the connection when the events are dumped.

  6. digiter
    added
    a: tests"flutter test", flutter_test, or one of our tests
    and removed
    team-infraOwned by Infrastructure team
    on Jul 30, 2020
  7. darshankawar
    added
    t: flutter driver"flutter driver", flutter_drive, or a driver test
    toolAffects the "flutter" command-line tool. See also t: labels.
    on Jul 31, 2020
  8. darshankawar
    added
    team-infraOwned by Infrastructure team
    passed first triage
    on Apr 14, 2021
  9. godofredoc
    removed
    team-infraOwned by Infrastructure team
    on Apr 15, 2021

  10. darshankawar commented on Oct 11, 2022

    @darshankawar
    darshankawar
    on Oct 11, 2022
    Member

    @CareF
    Considering the age of this issue, could you confirm if this behavior occurs using latest version of framework ?
    Would be good to know the status so we can update it accordingly.

  11. darshankawar
    added
    waiting for responseThe Flutter team cannot make further progress on this issue until the original reporter responds
    on Oct 11, 2022

  12. CareF commented on Oct 11, 2022

    @CareF
    CareF
    on Oct 11, 2022
    ContributorAuthor

    I no longer have the device to test it. Sorry. I posted this issue when I was an intern member in the flutter team. I would assume this is most likely already solved.

  13. CareF
    closed this as completedon Oct 11, 2022
  14. github-actions
    removed
    waiting for responseThe Flutter team cannot make further progress on this issue until the original reporter responds
    on Oct 11, 2022
  15. darshankawar
    added
    r: invalidIssue is closed as not valid
    on Oct 12, 2022

  16. github-actions commented on Oct 26, 2022

    @github-actions
    github-actionsbot
    on Oct 26, 2022

    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.

  17. github-actions
    locked as resolved and limited conversation to collaborators on Oct 26, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    a: tests"flutter test", flutter_test, or one of our testsr: invalidIssue is closed as not validt: flutter driver"flutter driver", flutter_drive, or a driver testtoolAffects the "flutter" command-line tool. See also t: labels.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions