sdk
sdk copied to clipboard
dart-lang
service_2/evaluate_activation_test/* tests went from flaky to RuntimeError on dartk-mac-debug-x64
The tests
service_2/evaluate_activation_test/instance/dds RuntimeError (expected Pass)
service_2/evaluate_activation_test/instance/service RuntimeError (expected Pass)
service_2/evaluate_activation_test/scope/dds RuntimeError (expected Pass)
service_2/evaluate_activation_test/scope/service RuntimeError (expected Pass)
are failing on configurations
dartk-mac-debug-x64
From the log:
00:14 [32m+0[0m[31m -1[0m: evaluate_activation_test_instance.dart (VM Service) [1m[31m[E][0m[0m
NoSuchMethodError: Class 'DartError' has no instance getter 'valueAsString'.
Receiver: Instance of 'DartError'
Tried calling: valueAsString
dart:core-patch/object_patch.dart 54:5 Object.noSuchMethod
xcodebuild/DebugX64/generated_tests/service_2/evaluate_activation_test_instance.dart 92:16 testMethod.<fn>
===== asynchronous gap ===========================
dart:async/zone.dart 1286:19 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 45:22 _asyncThenWrapperHelper
xcodebuild/DebugX64/generated_tests/service_2/evaluate_activation_test_instance.dart testMethod.<fn>
package:stack_trace/src/stack_zone_specification.dart 126:26 StackZoneSpecification._registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 208:15 StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 126:14 StackZoneSpecification._registerUnaryCallback.<fn>
dart:async/zone.dart 1362:47 _rootRunUnary
dart:async/zone.dart 1265:19 _CustomZone.runUnary
dart:async/zone.dart 1170:7 _CustomZone.runUnaryGuarded
dart:async/stream_impl.dart 341:11 _BufferingStreamSubscription._sendData
dart:async/stream_impl.dart 591:14 _DelayedData.perform
dart:async/stream_impl.dart 706:11 _StreamImplEvents.handleNext
dart:async/stream_impl.dart 663:7 _PendingEvents.schedule.<fn>
package:stack_trace/src/stack_zone_specification.dart 208:15 StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 116:48 StackZoneSpecification._registerCallback.<fn>
dart:async/zone.dart 1346:47 _rootRun
dart:async/zone.dart 1258:19 _CustomZone.run
dart:async/zone.dart 1162:7 _CustomZone.runGuarded
dart:async/zone.dart 1202:23 _CustomZone.bindCallbackGuarded.<fn>
package:stack_trace/src/stack_zone_specification.dart 208:15 StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 116:48 StackZoneSpecification._registerCallback.<fn>
dart:async/zone.dart 1354:13 _rootRun
dart:async/zone.dart 1258:19 _CustomZone.run
dart:async/zone.dart 1162:7 _CustomZone.runGuarded
dart:async/zone.dart 1202:23 _CustomZone.bindCallbackGuarded.<fn>
dart:async/schedule_microtask.dart 40:21 _microtaskLoop
dart:async/schedule_microtask.dart 49:5 _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 120:13 _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 185:5 _RawReceivePortImpl._handleMessage
Logs: https://dart-ci.appspot.com/log/vm-kernel-mac-debug-x64/dartk-mac-debug-x64/11311/service_2/evaluate_activation_test/instance/dds https://dart-ci.appspot.com/log/vm-kernel-mac-debug-x64/dartk-mac-debug-x64/11311/service_2/evaluate_activation_test/instance/service https://dart-ci.appspot.com/log/vm-kernel-mac-debug-x64/dartk-mac-debug-x64/11311/service_2/evaluate_activation_test/scope/dds https://dart-ci.appspot.com/log/vm-kernel-mac-debug-x64/dartk-mac-debug-x64/11311/service_2/evaluate_activation_test/scope/service
@bkonyi @rmacnak-google Could you please take a look?
Same for dartk-mac-release-x64 today.
https://dart-ci.appspot.com/log/vm-kernel-mac-release-x64/dartk-mac-release-x64/14869/service_2/evaluate_activation_test/instance/dds
NoSuchMethodError: Class 'DartError' has no instance getter 'valueAsString'.
Receiver: Instance of 'DartError'
Tried calling: valueAsString
It looks like these tests don't pass on any configurations. I'm thinking some behavior changed around the Dart 2 migration and that these tests aren't correct anymore. I'm going to skip these for now and reference this issue.
Just marking that we got a flaky -> RuntimeError from service_2/evaluate_activation_test/instance/dds on dartk-ubsan-linux-release-x64, starting between fa535bbe..565a5257.
Same on dartk-linux-release-simarm today.
https://dart-ci.appspot.com/log/vm-kernel-linux-release-simarm/dartk-linux-release-simarm/15063/service_2/evaluate_activation_test/instance/dds
Same happened on dartk-linux-release-arm64.
Log: https://dart-ci.appspot.com/log/cross-vm-linux-release-arm64/dartk-linux-release-arm64/9827/service_2/evaluate_activation_test/scope/dds
Same on dartk-win-debug-x64c:
https://dart-ci.appspot.com/log/vm-kernel-win-debug-x64c/dartk-win-debug-x64c/488/service_2/evaluate_activation_test/scope/service
flaky -> runtime error: https://dart-ci.appspot.com/log/vm-kernel-checked-linux-release-x64/dartk-checked-linux-release-x64/14967/service_2/evaluate_activation_test/instance/service
Those tests are testing that the debugger can - when breaking at a function - access the state of all variables that are in the lexical scope (including in outer scopes from inner closures).
For example the test has this:
breakHere() {}
use(dynamic v) => v;
class C {
var instVar = 1;
static var classVar = 2;
method(methodParam) {
var methodTemp = 4;
use(methodTemp);
[5].forEach((outerParam) {
var outerTemp = 6;
use(outerTemp);
[7].forEach((innerParam) {
var innerTemp = 8;
use(innerTemp);
breakHere(); // <-- Assumes we can access `this`, even the Dart code doesn't need it.
});
});
}
It seems to me that we're not willing to actually to keep everything alive - just for the possibility of a debugger later attaching & examining the objects. i.e. we prefer to keep less memory alive and have faster code, even in JIT, even in unoptimized code.
If you all agree (/cc @mraleph @alexmarkov @a-siva @rmacnak-google), then I think the test should be re-written to expect the behavior we actually have implemented or want to implement.
(Right now the relevant subtests are failing and are therefore of little use. But we spent SWE time on gardening, looking at flakes, ...)
Related: https://github.com/dart-lang/sdk/issues/20047
I tried this test under devtools interactively and I noticed that when stopped at breakHere in method the 'Variables' window only shows innerTemp and innerParam I would have expected it to at least state that this, methodParam, outerTemp and methodTemp are 'optimized out'.
I agree that we should change the test to reflect this fact that certain values are optimized out.
The test should probably be adjusted to reflect the current implementation, however there is a deeper question of developer experience here and how to balance it with our desire for good performance (and predictability) of JIT.
It is hard to argue with the fact that the current behaviour is unfriendly - as a user I would expect to be able to inspect more variables than compiler lets me.
Maybe there is some improvements we could make in this area - though it is not entirely clear to me how. Maybe an adaptive strategy is possible where if you put a breakpoint into a closure then we recompile things in such a way that instances of the closure which are allocated after the breakpoint was put there capture more information?
We can also probably have a mode in which we disable some of JIT optimizations (like dead variable pruning).
We could even consider reifying / capturing the whole stack frame all the time - though that would introduce considerable difference in GC behavior between JIT and AOT and might lead to unexpected leaks - which people would waste time debugging.
My 2 cents: if a variable isn't used in a scope and is being optimized out by the compiler as a result, is there any benefit in making it inspectable? If we don't currently report variables that are optimized out as optimized out we should at least make sure that we do that, but I doubt it's worth the effort to try and display their values in the debugger.
The test service/evaluate_activation_test/instance/service went flaky -> RuntimeError on vm-linux-release-x64 configuration:
00:13 [32m+0[0m[31m -1[0m: evaluate_activation_test_instance.dart (VM Service) [1m[31m[E][0m[0m
Expected: '123'
Actual: '<optimized out>'
Which: is different.
Expected: 123
Actual: <optimized ...
^
Differ at offset 0
package:matcher/src/expect/expect.dart 149:31 fail
package:matcher/src/expect/expect.dart 144:3 _expect
package:matcher/src/expect/expect.dart 56:3 expect
out/ReleaseX64/generated_tests/service/evaluate_activation_test_instance.dart 87:5 testMethod.<fn>
Result Instance(null)
Expected: true
Actual: <false>
package:matcher/src/expect/expect.dart 149:31 fail
package:matcher/src/expect/expect.dart 144:3 _expect
package:matcher/src/expect/expect.dart 56:3 expect
out/ReleaseX64/generated_tests/service/evaluate_activation_test_instance.dart 114:3 testMethod
===== asynchronous gap ===========================
out/ReleaseX64/generated_tests/service/test_helper.dart 489:17 _ServiceTesterRunner.run.runTest.<fn>.<fn>
===== asynchronous gap ===========================
out/ReleaseX64/generated_tests/service/test_helper.dart 369:9 _ServiceTesterRunner.run.ignoreLateException
===== asynchronous gap ===========================
package:test_api/src/backend/declarer.dart 215:9 Declarer.test.<fn>.<fn>
===== asynchronous gap ===========================
package:test_api/src/backend/declarer.dart 213:7 Declarer.test.<fn>
===== asynchronous gap ===========================
package:test_api/src/backend/invoker.dart 258:9 Invoker._waitForOutstandingCallbacks.<fn>
https://dart-ci.appspot.com/log/vm-linux-release-x64/vm-linux-release-x64/530/service/evaluate_activation_test/instance/service
This happened again today. @aam would you be interested in looking at these expression evaluation tests?
Flakiness caused by these tests timing out once in a while. For example, https://logs.chromium.org/logs/dart/buildbucket/cr-buildbucket/8780081974082306833/+/u/test_results/ignored_flaky_test_failure_logs
The test never reaches https://github.com/dart-lang/sdk/blob/d083c636850a7ecc9a5f84ad2d1db3593742a532/runtime/observatory/tests/service/evaluate_activation_test.dart#L113, doesn't exit from 'rootLib.evaluate'.
Might be the case of an overloaded bot.
/=====================================================================================================\
| service/evaluate_activation_test/instance/dds failed again (RuntimeError -> Timeout, expected Pass) |
\=====================================================================================================/
--- Command "vm" (took 01:01.000386s):
DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart -DUSE_DDS=true --sound-null-safety -Dtest_runner.configuration=vm-linux-release-x64 --ignore-unrecognized-flags --packages=/b/s/w/ir/.dart_tool/package_config.json /b/s/w/ir/out/ReleaseX64/generated_tests/service/evaluate_activation_test_instance.dart
exit code:
1
diagnostics:
Process list including children: [251745, 251830]
Trying to capture stack trace for pid 251745
PID 251745 - process
TID 251745:
#0 0x00007f5525b4d376 pthread_cond_wait@@GLIBC_2.3.2
#1 0x00005634f3c1eb77 dart::Monitor::WaitMicros(long)
#2 0x00005634f408b14a Dart_RunLoop
#3 0x00005634f39d39c2 dart::bin::RunMainIsolate(char const*, char const*, bool, dart::bin::CommandLineOptions*)
#4 0x00005634f39d4720 dart::bin::main(int, char**)
#5 0x00005634f39d371d main
#6 0x00007f5525821083 __libc_start_main
#7 0x00005634f39cd76a _start
TID 251751:
#0 0x00007f552591c46e epoll_wait
#1 0x00005634f39e2ed8 dart::bin::EventHandlerImplementation::Poll(unsigned long)
#2 0x00005634f3add4a2 dart::bin::ThreadStart(void*)
#3 0x00007f5525b46609 start_thread
#4 0x00007f552591c133 __clone
TID 251831:
#0 0x00007f55258dfc7f wait4
#1 0x00005634f39ea118 dart::bin::ExitCodeHandler::ExitCodeHandlerEntry(unsigned long)
#2 0x00005634f3add4a2 dart::bin::ThreadStart(void*)
#3 0x00007f5525b46609 start_thread
#4 0x00007f552591c133 __clone
TID 251933:
#0 0x00007f5525b4d7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x00005634f3c1eb5f dart::Monitor::WaitMicros(long)
#2 0x00005634f3b661dd dart::MutatorThreadPool::OnEnterIdleLocked(dart::MonitorLocker*)
#3 0x00005634f3c9b15d dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#4 0x00005634f3c9b688 dart::ThreadPool::Worker::Main(unsigned long)
#5 0x00005634f3c1e406 dart::ThreadStart(void*)
#6 0x00007f5525b46609 start_thread
#7 0x00007f552591c133 __clone
TID 251934:
#0 0x00007f5525b4d7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x00005634f3c1eb5f dart::Monitor::WaitMicros(long)
#2 0x00005634f3c9b2ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x00005634f3c9b688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x00005634f3c1e406 dart::ThreadStart(void*)
#5 0x00007f5525b46609 start_thread
#6 0x00007f552591c133 __clone
TID 251950:
#0 0x00007f5525b4d7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x00005634f3c1eb5f dart::Monitor::WaitMicros(long)
#2 0x00005634f3c9b2ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x00005634f3c9b688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x00005634f3c1e406 dart::ThreadStart(void*)
#5 0x00007f5525b46609 start_thread
#6 0x00007f552591c133 __clone
TID 251985:
#0 0x00007f5525b4d7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x00005634f3c1eb5f dart::Monitor::WaitMicros(long)
#2 0x00005634f3c9b2ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x00005634f3c9b688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x00005634f3c1e406 dart::ThreadStart(void*)
#5 0x00007f5525b46609 start_thread
#6 0x00007f552591c133 __clone
Trying to capture stack trace for pid 251830
PID 251830 - process
TID 251830:
#0 0x00007f5e8d68a376 pthread_cond_wait@@GLIBC_2.3.2
#1 0x0000559f52ecbb77 dart::Monitor::WaitMicros(long)
#2 0x0000559f5333814a Dart_RunLoop
#3 0x0000559f52c809c2 dart::bin::RunMainIsolate(char const*, char const*, bool, dart::bin::CommandLineOptions*)
#4 0x0000559f52c81720 dart::bin::main(int, char**)
#5 0x0000559f52c8071d main
#6 0x00007f5e8d35e083 __libc_start_main
#7 0x0000559f52c7a76a _start
TID 251832:
#0 0x00007f5e8d45946e epoll_wait
#1 0x0000559f52c8fed8 dart::bin::EventHandlerImplementation::Poll(unsigned long)
#2 0x0000559f52d8a4a2 dart::bin::ThreadStart(void*)
#3 0x00007f5e8d683609 start_thread
#4 0x00007f5e8d459133 __clone
TID 251833:
#0 0x00007f5e8d68a376 pthread_cond_wait@@GLIBC_2.3.2
#1 0x0000559f52ecbb77 dart::Monitor::WaitMicros(long)
#2 0x0000559f52f4760f dart::ThreadInterrupter::ThreadMain(unsigned long)
#3 0x0000559f52ecb406 dart::ThreadStart(void*)
#4 0x00007f5e8d683609 start_thread
#5 0x00007f5e8d459133 __clone
TID 251834:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52ed1d15 dart::SampleBlockProcessor::ThreadMain(unsigned long)
#3 0x0000559f52ecb406 dart::ThreadStart(void*)
#4 0x00007f5e8d683609 start_thread
#5 0x00007f5e8d459133 __clone
TID 251835:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52f482ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x0000559f52ecb406 dart::ThreadStart(void*)
#5 0x00007f5e8d683609 start_thread
#6 0x00007f5e8d459133 __clone
TID 251844:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52f482ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x0000559f52ecb406 dart::ThreadStart(void*)
#5 0x00007f5e8d683609 start_thread
#6 0x00007f5e8d459133 __clone
TID 251845:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52f482ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x0000559f52ecb406 dart::ThreadStart(void*)
#5 0x00007f5e8d683609 start_thread
#6 0x00007f5e8d459133 __clone
TID 251847:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52f482ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x0000559f52ecb406 dart::ThreadStart(void*)
#5 0x00007f5e8d683609 start_thread
#6 0x00007f5e8d459133 __clone
TID 251848:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52f482ff dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#3 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#4 0x0000559f52ecb406 dart::ThreadStart(void*)
#5 0x00007f5e8d683609 start_thread
#6 0x00007f5e8d459133 __clone
TID 251899:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52e131dd dart::MutatorThreadPool::OnEnterIdleLocked(dart::MonitorLocker*)
#3 0x0000559f52f4815d dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#4 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#5 0x0000559f52ecb406 dart::ThreadStart(void*)
#6 0x00007f5e8d683609 start_thread
#7 0x00007f5e8d459133 __clone
TID 251930:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52e131dd dart::MutatorThreadPool::OnEnterIdleLocked(dart::MonitorLocker*)
#3 0x0000559f52f4815d dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#4 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#5 0x0000559f52ecb406 dart::ThreadStart(void*)
#6 0x00007f5e8d683609 start_thread
#7 0x00007f5e8d459133 __clone
TID 251940:
#0 0x00007f5e8d68a7d1 pthread_cond_timedwait@@GLIBC_2.3.2
#1 0x0000559f52ecbb5f dart::Monitor::WaitMicros(long)
#2 0x0000559f52e131dd dart::MutatorThreadPool::OnEnterIdleLocked(dart::MonitorLocker*)
#3 0x0000559f52f4815d dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)
#4 0x0000559f52f48688 dart::ThreadPool::Worker::Main(unsigned long)
#5 0x0000559f52ecb406 dart::ThreadStart(void*)
#6 0x00007f5e8d683609 start_thread
#7 0x00007f5e8d459133 __clone
stdout:
00:00 [32m+0[0m: evaluate_activation_test_instance.dart (DDS)[0m
** Launching SERVICE_TEST_TESTEE=true out/ReleaseX64/dart --disable-dart-dev --write-service-info=file:///b/s/w/itia2w5c01/dart_serviceCRVJLR/service_info.json --profiler -DUSE_DDS=true --sound-null-safety -Dtest_runner.configuration=vm-linux-release-x64 --ignore-unrecognized-flags --packages=/b/s/w/ir/.dart_tool/package_config.json --enable-vm-service:0 /b/s/w/ir/out/ReleaseX64/generated_tests/service/evaluate_activation_test_instance.dart
>testee>out> The Dart VM service is listening on http://127.0.0.1:38003/MgBCEZVA8TM=/
>testee>out>
** Signaled to run test queries on http://127.0.0.1:41239/ae3awYWXKh0=/ (DDS)
Loading VM...
Done loading VM
Running evaluate_activation_test_instance.dart [1/4]
Breakpoint: Breakpoint 1 at evaluate_activation_test_instance.dart:token(374)[unresolved]
Event ServiceEvent(owner='isolates/830363021983679', kind='BreakpointResolved', time=2023-05-25 16:52:46.989)
Event ServiceEvent(owner='isolates/830363021983679', kind='PauseBreakpoint', time=2023-05-25 16:52:46.990)
00:36 [32m+0[0m[31m -1[0m: evaluate_activation_test_instance.dart (DDS) [1m[31m[E][0m[0m
Expected: '123'
Actual: '<optimized out>'
Which: is different.
Expected: 123
Actual: <optimized ...
^
Differ at offset 0
--- Re-run this test:
python3 tools/test.py -n vm-linux-release-x64 service/evaluate_activation_test/instance/dds
