Flaky vm/dart/appjit_determinism_test failure

[mkustermann]

From this log:

FAILED: dartk-vm product_x64 vm/dart/appjit_determinism_test
Expected: Pass
Actual: RuntimeError

--- Command "vm" (took 02.000488s):
DART_CONFIGURATION=ProductX64 xcodebuild/ProductX64/dart --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages /b/s/w/ir/runtime/tests/vm/dart/appjit_determinism_test.dart

exit code:
255

stdout:
+ xcodebuild/ProductX64/dart --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages --deterministic --snapshot=/b/s/w/it1i5tr1/3f4ZRq/snapshot1 --snapshot-kind=app-jit /b/s/w/ir/runtime/tests/vm/dart/appjit_determinism_test.dart --child
+ xcodebuild/ProductX64/dart --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages --deterministic --snapshot=/b/s/w/it1i5tr1/3f4ZRq/snapshot2 --snapshot-kind=app-jit /b/s/w/ir/runtime/tests/vm/dart/appjit_determinism_test.dart --child

stderr:
Unhandled exception:
Expect.fail('Snapshots are not bitwise equal!')
#0      checkDeterministicSnapshot (file:///b/s/w/ir/runtime/tests/vm/dart/snapshot_test_helper.dart)
#1      _RootZone.runUnary (dart:async/zone.dart:1379:54)
#2      _FutureListener.handleValue (dart:async/future_impl.dart:129:18)
#3      Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:642:45)
#4      Future._propagateToListeners (dart:async/future_impl.dart:671:32)
#5      Future._completeWithValue (dart:async/future_impl.dart:486:5)
#6      Future._asyncComplete.<anonymous closure> (dart:async/future_impl.dart:516:7)
#7      _microtaskLoop (dart:async/schedule_microtask.dart:41:21)
#8      _startMicrotaskLoop (dart:async/schedule_microtask.dart:50:5)
#9      _runPendingImmediateCallback (dart:isolate/runtime/libisolate_patch.dart:115:13)
#10     _RawReceivePortImpl._handleMessage (dart:isolate/runtime/libisolate_patch.dart:172:5)

--- Re-run this test:
python tools/test.py -m product -n dartk-mac-product-x64 vm/dart/appjit_determinism_test

(There were two issues with this test before, in #34638 and #34973, both of which got addressed)

@mraleph
@rmacnak-google Do you know any recent changes which could've caused this?

[rmacnak-google]

No, the most recent changes to raw_object.h look fine.

I'm not having much luck trying to reproduce. I'll update the test to report the position of the difference so next time we can at least say what type of object is different.

[sjindel-google]

This reproduced again today, and your debugging statement appears to have triggered: https://logs.chromium.org/logs/dart/buildbucket/cr-buildbucket.appspot.com/8930438607350824704/+/steps/vm_tests_shard_2/0/stdout

[rmacnak-google]

The first difference is in an array of length 2050 that starts with

740
0
sentinel
sentinel
sentinel
sentinel
sentinel
sentinel
Type: class 'Iterable', args:[TypeArguments: (@0x7fa48aeeedd1 H136b15d) [TypeParameter: name T; index: 0; function: expand; bound: Object]]
sentinel
sentinel
sentinel
sentinel
sentinel
Type: class 'Iterable', args:[TypeArguments: (@0x7fa48aee4be1 H3b65393c) [TypeParameter: name T; index: 0; function: whereType; bound: Object]]

so probably the canonical type table.

[rmacnak-google]

The type cluster appears before the array cluster, but the outputs differ first in the array cluster, so I think we've got the same types with a different hashing. The hashes for types are all in terms of CIDs, which are stable, so my suspicion is there's non-determinism in the order the types are created that results in non-determinism in the order of types that have a hash collision appear in the table.

[sjindel-google]

Failed again on https://logs.chromium.org/logs/dart/buildbucket/cr-buildbucket.appspot.com/8929890694507142016/+/steps/vm_tests_shard_2/0/stdout.

[rmacnak-google]

This one differed in the symbol table:

Data + 5f990: array len 2050
Data + 5f994: element 1175
Data + 5f997: element 0
Data + 5f999: element _queryParameters@0150898
Data + 5f99c: element _stateIncomplete@7048458
Data + 5f99f: element sentinel
Data + 5f9a0: element 71
Data + 5f9a3: element sentinel
Data + 5f9a4: element sentinel
Data + 5f9a5: element sentinel
Data + 5f9a6: element _AsyncAwaitCompleter@7048458.
Data + 5f9a9: element escapeDelimiters
Data + 5f9ac: element timerMillisecondClock
Data + 5f9af: element @Timer@Timer._createPeriodicTimer
Data + 5f9b2: element TrustTypeAnnotations
Data + 5f9b5: element isValidKey
Data + 5f9b8: element otherZone
Data + 5f9bb: element sentinel
Data + 5f9bc: element sentinel
Data + 5f9bd: element _currentUriBase@21232984
Data + 5f9c0: element sentinel
Data + 5f9c1: element what
Data + 5f9c4: element sentinel
Data + 5f9c5: element sentinel
Data + 5f9c6: element packageConfigString
Data + 5f9c9: element sentinel
Data + 5f9ca: element sentinel
Data + 5f9cb: element sentinel    ******************first difference is here
Data + 5f9cc: element _closeInternal@1026248
Data + 5f9cf: element sentinel
Data + 5f9d0: element sentinel

[dcharkes]

Today again:
https://logs.chromium.org/logs/dart/buildbucket/cr-buildbucket.appspot.com/8929427141012865088/+/steps/vm_tests_shard_2/0/stdout

And links for last Friday:
https://logs.chromium.org/logs/dart/buildbucket/cr-buildbucket.appspot.com/8929691224870693440/+/steps/vm_tests_shard_2/0/stdout
https://logs.chromium.org/logs/dart/buildbucket/cr-buildbucket.appspot.com/8929704572002017296/+/steps/vm_tests_shard_2/0/stdout