Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

App-JIT failure for reload sources test after #39869

Open
mkustermann opened this issue Dec 19, 2019 · 6 comments
Open

App-JIT failure for reload sources test after #39869

mkustermann opened this issue Dec 19, 2019 · 6 comments
Labels
area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. gardening

Comments

@mkustermann
Copy link
Member

After cl/128585 landed a app-jit failure started:


/====================================================================\
| service/reload_sources_test broke (Pass -> Timeout, expected Pass) |
\====================================================================/

--- Command "app_jit" (took 37.000526s):
DART_CONFIGURATION=DebugX64 out/DebugX64/dart --snapshot=/b/s/w/ir/out/DebugX64/generated_compilations/app_jitk/runtime_observatory_tests_service_reload_sources_test/out.jitsnapshot --snapshot-kind=app-jit --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages /b/s/w/ir/runtime/observatory/tests/service/reload_sources_test.dart

exit code:
0

stdout:
** Launching SERVICE_TEST_TESTEE=true out/DebugX64/dart --write-service-info=file:///b/s/w/iteKlhk7/dart_serviceXGINTK/service_info.json --profiler --snapshot=/b/s/w/ir/out/DebugX64/generated_compilations/app_jitk/runtime_observatory_tests_service_reload_sources_test/out.jitsnapshot --snapshot-kind=app-jit --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages --enable-vm-service:0 /b/s/w/ir/runtime/observatory/tests/service/reload_sources_test.dart
>testee>out> Observatory listening on http://127.0.0.1:40659/01X2dtWordY=/
>testee>out>
** Signaled to run test queries on http://127.0.0.1:40659/01X2dtWordY=/
Loading VM...
Done loading VM
Running reload_sources_test.dart [1/10]
Paused with PauseBreakpoint
Running reload_sources_test.dart [2/10]
Running reload_sources_test.dart [3/10]
Paused with PauseBreakpoint
Running reload_sources_test.dart [4/10]
>testee>out> 1
Running reload_sources_test.dart [5/10]
Running reload_sources_test.dart [6/10]
Paused with PausePostRequest
Running reload_sources_test.dart [7/10]
Running reload_sources_test.dart [8/10]
Running reload_sources_test.dart [9/10]
Running reload_sources_test.dart [10/10]
All service tests completed successfully.
** Killing script
** Process exited

--- Command "vm" (took 16:00.000556s):
DART_CONFIGURATION=DebugX64 out/DebugX64/dart --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages /b/s/w/ir/out/DebugX64/generated_compilations/app_jitk/runtime_observatory_tests_service_reload_sources_test/out.jitsnapshot

exit code:
null

diagnostics:
Process list including children: [10872, 10879]
Trying to capture stack trace for pid 10872
PID 10872 - process
TID 10872:
#0  0x00007fddd8eb6360 pthread_cond_wait@@GLIBC_2.3.2
#1  0x0000556143688634 dart::Monitor::WaitMicros(long)
#2  0x0000556143ba90aa Dart_RunLoop
#3  0x00005561432af1aa dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
#4  0x00005561432b002c dart::bin::main(int, char**)
#5  0x00005561432b0c79 main
#6  0x00007fddd93ef830 __libc_start_main
#7  0x0000556143284029 _start
TID 10873:
#0  0x00007fddd94d6a13 epoll_wait
#1  0x00005561432b3675 dart::bin::EventHandlerImplementation::Poll(unsigned long)
#2  0x000055614330c8f5 dart::bin::ThreadStart(void*)
#3  0x00007fddd8eb06ba start_thread
#4  0x00007fddd94d641d __clone
TID 10875:
#0  0x00007fddd8eb6360 pthread_cond_wait@@GLIBC_2.3.2
#1  0x0000556143688634 dart::Monitor::WaitMicros(long)
#2  0x000055614392120a dart::BackgroundCompiler::Run()
#3  0x0000556143745e3c dart::ThreadPool::Worker::Loop()
#4  0x0000556143745951 dart::ThreadPool::Worker::Main(unsigned long)
#5  0x0000556143687852 dart::ThreadStart(void*)
#6  0x00007fddd8eb06ba start_thread
#7  0x00007fddd94d641d __clone
TID 10880:
#0  0x00007fddd949b02e __wait
#1  0x00005561432bb848 dart::bin::ExitCodeHandler::ExitCodeHandlerEntry(unsigned long)
#2  0x000055614330c8f5 dart::bin::ThreadStart(void*)
#3  0x00007fddd8eb06ba start_thread
#4  0x00007fddd94d641d __clone


Trying to capture stack trace for pid 10879
PID 10879 - process
TID 10879:
#0  0x00007fa779e99360 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055bafac32634 dart::Monitor::WaitMicros(long)
#2  0x000055bafb1530aa Dart_RunLoop
#3  0x000055bafa8591aa dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
#4  0x000055bafa85a02c dart::bin::main(int, char**)
#5  0x000055bafa85ac79 main
#6  0x00007fa77a3d2830 __libc_start_main
#7  0x000055bafa82e029 _start
TID 10881:
#0  0x00007fa77a4b9a13 epoll_wait
#1  0x000055bafa85d675 dart::bin::EventHandlerImplementation::Poll(unsigned long)
#2  0x000055bafa8b68f5 dart::bin::ThreadStart(void*)
#3  0x00007fa779e936ba start_thread
#4  0x00007fa77a4b941d __clone
TID 10882:
#0  0x00007fa779e99360 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055bafac32634 dart::Monitor::WaitMicros(long)
#2  0x000055bafaced318 dart::ThreadInterrupter::ThreadMain(unsigned long)
#3  0x000055bafac31852 dart::ThreadStart(void*)
#4  0x00007fa779e936ba start_thread
#5  0x00007fa77a4b941d __clone
TID 10884:
#0  0x00007fa779e99360 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055bafac32634 dart::Monitor::WaitMicros(long)
#2  0x000055bafab476da dart::KernelCompilationRequest::SendAndWaitForResponse(int, long, char const*, unsigned char const*, long, int, Dart_SourceFile*, bool, char const*, char const*, char const*, dart::MallocGrowableArray<char*> const*)
#3  0x000055bafab47032 dart::KernelIsolate::CompileToKernel(char const*, unsigned char const*, long, int, Dart_SourceFile*, bool, char const*, char const*, char const*)
#4  0x000055bafab2a5d5 dart::IsolateGroupReloadContext::CompileToKernel(bool, char const*, unsigned char const**, long*)
#5  0x000055bafab28c9f dart::IsolateGroupReloadContext::Reload(bool, char const*, char const*, unsigned char const*, long)
#6  0x000055bafab1f476 dart::IsolateGroup::ReloadSources(dart::JSONStream*, bool, char const*, char const*, bool)
#7  0x000055bafacbc615 dart::ReloadSources(dart::Thread*, dart::JSONStream*)
#8  0x000055bafacb3a7f dart::Service::InvokeMethod(dart::Isolate*, dart::Array const&, bool)
#9  0x000055bafacb45be dart::Service::HandleIsolateMessage(dart::Isolate*, dart::Array const&)
#10 0x000055bafab1b4f4 dart::IsolateMessageHandler::HandleMessage(std::__2::unique_ptr<dart::Message, std::__2::default_delete<dart::Message> >)
#11 0x000055bafab5ee3f dart::MessageHandler::HandleMessages(dart::MonitorLocker*, bool, bool)
#12 0x000055bafab5f68f dart::MessageHandler::HandleOOBMessages()
#13 0x000055bafb153baf Dart_HandleServiceMessages
#14 0x000055bafab23f76 dart::Isolate::PauseEventHandler()
#15 0x000055bafaacc3f2 dart::Debugger::Pause(dart::ServiceEvent*)
#16 0x000055bafaadba96 dart::Debugger::SignalPausedEvent(dart::ActivationFrame*, dart::Breakpoint*)
#17 0x000055bafaadbfa0 dart::Debugger::PauseStepping()
#18 0x000055bafaca0e3f dart::DRT_SingleStepHandler(dart::NativeArguments)
#19 0x00007fa7783010a7
TID 10892:
#0  0x00007fa779e99360 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055bafac32634 dart::Monitor::WaitMicros(long)
#2  0x000055bafaecb20a dart::BackgroundCompiler::Run()
#3  0x000055bafacefe3c dart::ThreadPool::Worker::Loop()
#4  0x000055bafacef951 dart::ThreadPool::Worker::Main(unsigned long)
#5  0x000055bafac31852 dart::ThreadStart(void*)
#6  0x00007fa779e936ba start_thread
#7  0x00007fa77a4b941d __clone

eu-stack: dwfl_thread_getframes tid 10884 at 0x7fa7783010a6 in /memfd:dart-codespace (deleted): Callback returned failure


stdout:
** Launching SERVICE_TEST_TESTEE=true out/DebugX64/dart --write-service-info=file:///b/s/w/iteKlhk7/dart_serviceRRKMXY/service_info.json --profiler --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages --enable-vm-service:0 /b/s/w/ir/out/DebugX64/generated_compilations/app_jitk/runtime_observatory_tests_service_reload_sources_test/out.jitsnapshot
>testee>out>
>testee>out> Observatory listening on http://127.0.0.1:34815/jLgG0ENaSv0=/
** Signaled to run test queries on http://127.0.0.1:34815/jLgG0ENaSv0=/
Loading VM...
Done loading VM
Running out.jitsnapshot [1/10]
Paused with PauseBreakpoint
Running out.jitsnapshot [2/10]
>testee>err> kernel-service: Error: Unhandled exception:
>testee>err> Bad state: No element
>testee>err> #0      Iterable.first (dart:core/iterable.dart:520:7)
>testee>err> #1      MappedIterable.first (dart:_internal/iterable.dart:374:31)
>testee>err> #2      lookupOrBuildNewIncrementalCompiler (file:///b/s/w/ir/cache/builder/sdk/pkg/vm/bin/kernel_service.dart:400:45)
>testee>err> #3      _processLoadRequest (file:///b/s/w/ir/cache/builder/sdk/pkg/vm/bin/kernel_service.dart:679:22)
>testee>err> #4      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:174:12)
>testee>err>
>testee>err> Unhandled exception:
>testee>err> Bad state: No element
>testee>err> #0      Iterable.first (dart:core/iterable.dart:520:7)
>testee>err> #1      MappedIterable.first (dart:_internal/iterable.dart:374:31)
>testee>err> #2      lookupOrBuildNewIncrementalCompiler (file:///b/s/w/ir/cache/builder/sdk/pkg/vm/bin/kernel_service.dart:400:45)
>testee>err> #3      _processLoadRequest (file:///b/s/w/ir/cache/builder/sdk/pkg/vm/bin/kernel_service.dart:679:22)
>testee>err> #4      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:174:12)

--- Re-run this test:
python tools/test.py -n app_jitk-linux-debug-x64 service/reload_sources_test

The kernel service seems to fail while trying to build a new incremental compiler.

@jensjoha Could you take a look (since it seemingly started after your change)?
@mkustermann mkustermann added area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. gardening labels Dec 19, 2019
@a-siva a-siva added this to the D28 Release milestone Dec 19, 2019
@jensjoha
Copy link
Contributor

jensjoha commented Jan 7, 2020

This particular issue is fixed with https://dart-review.googlesource.com/c/sdk/+/130374/.

A more general problem persists through (and wasn't caused by my CL):

Say you have this file:

$ cat test.dart
import "dart:developer";

main(List<String> args) {
  if (args.isEmpty) {
    print("Done!");
  } else {
    debugger();
    print("Hello!");
  }
}

and you make a app-jit snapshot of it:

$ out/ReleaseX64/dart --snapshot=out.jitsnapshot --snapshot-kind=app-jit test.dart

and remove it or move it so the path no longer exists:

$ mv test.dart test.dart.moved

and run the snapshot in observatory:

$ out/ReleaseX64/dart --observe out.jitsnapshot test

and go to observatory, navigates to the isolate and clicks the Reload Source button at the top:

kernel-service: Error: Unhandled exception:
Bad state: No element
#0      Iterable.first (dart:core/iterable.dart:520:7)
#1      MappedIterable.first (dart:_internal/iterable.dart:374:31)
#2      lookupOrBuildNewIncrementalCompiler (file:///usr/local/google/home/jensj/code/dart-sdk/sdk/pkg/vm/bin/kernel_service.dart:400:45)
#3      _processLoadRequest (file:///usr/local/google/home/jensj/code/dart-sdk/sdk/pkg/vm/bin/kernel_service.dart:679:22)
#4      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:174:12)

Unhandled exception:
Bad state: No element
#0      Iterable.first (dart:core/iterable.dart:520:7)
#1      MappedIterable.first (dart:_internal/iterable.dart:374:31)
#2      lookupOrBuildNewIncrementalCompiler (file:///usr/local/google/home/jensj/code/dart-sdk/sdk/pkg/vm/bin/kernel_service.dart:400:45)
#3      _processLoadRequest (file:///usr/local/google/home/jensj/code/dart-sdk/sdk/pkg/vm/bin/kernel_service.dart:679:22)
#4      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:174:12)

Again, basically the same thing happens (I'm guessing):
It walks though all libraries, and all sources for libraries, checks if the file test.dart is modified --- as it doesn't exist anymore it is reported as being modified. It's send to the kernel isolate which again think it must have a compiler (which it doesn't) and it crashes...

I'll re-assign this issue to @mkustermann who can probably assign a VM engineer to fix that underlying issue.

@jensjoha jensjoha assigned mkustermann and unassigned jensjoha Jan 7, 2020
@mkustermann
Copy link
Member Author

We might simply want to disable using hot-reload for isolates which were started from AppJIT snapshots. This would also make our work on the concurrency easier.

@rmacnak-google wdyt?

dart-bot pushed a commit that referenced this issue Jan 9, 2020
@jensjoha
[VM] Ignore dart scheme scripts in isolate reload
d5b01a1 
After cl/128585 landed a app-jit failure started throwing an error:
>testee>err> kernel-service: Error: Unhandled exception:
>testee>err> Bad state: No element
>testee>err> #0      Iterable.first (dart:core/iterable.dart:520:7)
>testee>err> #1      MappedIterable.first (dart:_internal/iterable.dart:374:31)
>testee>err> #2      lookupOrBuildNewIncrementalCompiler (file:///b/s/w/ir/cache/builder/sdk/pkg/vm/bin/kernel_service.dart:400:45)
>testee>err> #3      _processLoadRequest (file:///b/s/w/ir/cache/builder/sdk/pkg/vm/bin/kernel_service.dart:679:22)
>testee>err> #4      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:174:12)
>testee>err>

This is caused by the change ultimately adding scripts for the used
mixed in files in "LoadedScripts".
In this case "dart:collection/map.dart" (as I recall) was added to it.
When reloading the source, it runs through all libraries that
"isn't dart scheme", and for all of those libraries through all scripts
reported by LoadedScripts for that library (now including something from
the platform), and checking if it has been modified. Checking if it is
modified only works for file:/// uris through, which platform files aren't,
so it just reports true (i.e. the file is modified).
This is then passed to the kernel service which - based on the list of
one file modified - somehow concludes that it has a compiler already
(which it doesn't) and then crashes.

This CL fixes this specific issue by also skipping scripts that are
"dart scheme".

There's still an underlying issue that has nothing to do with cl/128585
though. I'll comment on that in the bug
(#39869).

Bug: 39869
Change-Id: I1a3f2de888ec53c40f4b6b46a369595abae5bb44
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/130374
Commit-Queue: Jens Johansen <jensj@google.com>
Reviewed-by: Martin Kustermann <kustermann@google.com>
@franklinyow
Copy link
Contributor

Is it done?

@mkustermann
Copy link
Member Author

@franklinyow What this issue discusses is not used by any customer AFAIK, so it's low priority in general.

The original issue was fixed, but Jens pointed out another/similar issue. So we won't close the issue yet. Maybe we'll decide to just disable hot-reload if running in AppJIT mode.

@franklinyow franklinyow modified the milestones: D28 Release, D29 Release Mar 23, 2020
@franklinyow
Copy link
Contributor

Moving to D29

@mkustermann mkustermann removed this from the D29 Release milestone Mar 26, 2020
@mkustermann
Copy link
Member Author

Removing milestone. It doesn't affect customers afaik and is low priority.

@mkustermann mkustermann removed their assignment Dec 22, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. gardening
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@mkustermann @a-siva @jensjoha @franklinyow