Adding package http makes dart run really slow

[knopp]

I'm not sure if this is the right project to report this.

Dart SDK version: 3.4.0-265.0.dev (dev) (Sat Mar 23 01:03:42 2024 -0700) on "macos_arm64"

Steps to reproduce

% dart create -t cli test_1
% cd test_1
% time dart run

outputs

Resolving dependencies in /Users/Matej/Projects/dart/test_1...
Downloading packages...
Got dependencies in /Users/Matej/Projects/dart/test_1.
Building package executable...
Built test_1:test_1.
Positional arguments: []
dart run  0.54s user 0.09s system 137% cpu 0.454 total

add package http

dart pub add http
time dart run

outputs

Resolving dependencies in /Users/Matej/Projects/dart/test_1...
Downloading packages...
Got dependencies in /Users/Matej/Projects/dart/test_1.
Building package executable...
Built test_1:test_1.
Positional arguments: []
dart run  0.64s user 0.11s system 4% cpu 15.846 total

Not sure why this takes 15 seconds. It seems that the main thread is waiting for something

  * frame #0: 0x0000000183e60524 libsystem_kernel.dylib`__psynch_mutexwait + 8
    frame #1: 0x0000000183e9b168 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84
    frame #2: 0x0000000183e98af8 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 248
    frame #3: 0x0000000183e9e688 libsystem_pthread.dylib`_pthread_cond_wait + 1368
    frame #4: 0x00000001044e2610 dart`___lldb_unnamed_symbol4504 + 152
    frame #5: 0x000000010440d324 dart`___lldb_unnamed_symbol1429 + 160
    frame #6: 0x000000010440d954 dart`___lldb_unnamed_symbol1433 + 40
    frame #7: 0x000000010440faa0 dart`___lldb_unnamed_symbol1475 + 1248
    frame #8: 0x000000010440ec84 dart`___lldb_unnamed_symbol1470 + 16
    frame #9: 0x0000000183b1d0e0 dyld`start + 2360

The dart build shipped with Flutter has stripped symbols so it doesn't help much. I'll try running this with custom engine build.

[knopp]

Reproducible with local build (3.4.0-266.0.dev) but only when the package was ran with 255.0 (current flutter main) before.

  * frame #0: 0x0000000183e60524 libsystem_kernel.dylib`__psynch_mutexwait + 8
    frame #1: 0x0000000183e9b168 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84
    frame #2: 0x0000000183e98af8 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 248
    frame #3: 0x0000000183e9e688 libsystem_pthread.dylib`_pthread_cond_wait + 1368
    frame #4: 0x00000001001c4eb0 dart`dart::bin::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at thread_macos.cc:236:18
    frame #5: 0x00000001000a6ec0 dart`dart::bin::DartDevIsolate::DartDevRunner::Run(this=0x00000001024d7d90, create_isolate=<unavailable>, packages_file=<unavailable>, script=<unavailable>, force_no_sound_null_safety=<unavailable>, dart_options=<unavailable>) at dartdev_isolate.cc:114:13
    frame #6: 0x00000001000a7590 dart`dart::bin::DartDevIsolate::RunDartDev(create_isolate=<unavailable>, packages_file=<unavailable>, script=<unavailable>, force_no_sound_null_safety=<unavailable>, dart_options=<unavailable>) at dartdev_isolate.cc:292:11
    frame #7: 0x00000001000a9e94 dart`dart::bin::main(argc=2, argv=0x000000016fd5f418) at main_impl.cc:1418:53
    frame #8: 0x00000001000a8fe4 dart`main(argc=<unavailable>, argv=<unavailable>) at main.cc:9:3
    frame #9: 0x0000000183b1d0e0 dyld`start + 2360

[knopp]

So this is quite weird. I have the same SDK revision (567a19a), when built locally as part of flutter engine (profile/arm64) I don't get the problem. But when using prebuilt SDK shipped with Flutter (same revision), I get the issue.

[knopp]

Actually, I get the issue when I copy (copy, not just symlink) the dart-sdk from engine out into flutter/bin/cache.

[knopp]

Here's complete stacktrace

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x0000000183e60524 libsystem_kernel.dylib`__psynch_mutexwait + 8
    frame #1: 0x0000000183e9b168 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84
    frame #2: 0x0000000183e98af8 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 248
    frame #3: 0x0000000183e9e688 libsystem_pthread.dylib`_pthread_cond_wait + 1368
    frame #4: 0x0000000100d78eb0 dart`dart::bin::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at thread_macos.cc:236:18
    frame #5: 0x0000000100c5aec0 dart`dart::bin::DartDevIsolate::DartDevRunner::Run(this=0x000000010308bd90, create_isolate=<unavailable>, packages_file=<unavailable>, script=<unavailable>, force_no_sound_null_safety=<unavailable>, dart_options=<unavailable>) at dartdev_isolate.cc:114:13
    frame #6: 0x0000000100c5b590 dart`dart::bin::DartDevIsolate::RunDartDev(create_isolate=<unavailable>, packages_file=<unavailable>, script=<unavailable>, force_no_sound_null_safety=<unavailable>, dart_options=<unavailable>) at dartdev_isolate.cc:292:11
    frame #7: 0x0000000100c5de94 dart`dart::bin::main(argc=2, argv=0x000000016f1ab418) at main_impl.cc:1418:53
    frame #8: 0x0000000100c5cfe4 dart`main(argc=<unavailable>, argv=<unavailable>) at main.cc:9:3
    frame #9: 0x0000000183b1d0e0 dyld`start + 2360
  thread #2, name = 'dart:io EventHandler'
    frame #0: 0x0000000183e639c0 libsystem_kernel.dylib`kevent + 8
    frame #1: 0x0000000100c6845c dart`dart::bin::EventHandlerImplementation::EventHandlerEntry(args=105553128980960) at eventhandler_macos.cc:459:23
    frame #2: 0x0000000100d78704 dart`dart::bin::ThreadStart(data_ptr=<unavailable>) at thread_macos.cc:91:3
    frame #3: 0x0000000183e9e034 libsystem_pthread.dylib`_pthread_start + 136
  thread #3, name = 'DartDev Runner'
    frame #0: 0x0000000183e6106c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x0000000183e9e5fc libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x0000000100eef230 dart`dart::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at os_thread_macos.cc:435:18
    frame #3: 0x00000001011fa8d4 dart`::Dart_RunLoop() [inlined] dart::MonitorLocker::Wait(this=<unavailable>, millis=0) at lockers.h:173:22
    frame #4: 0x00000001011fa8c8 dart`::Dart_RunLoop() at dart_api_impl.cc:2020:12
    frame #5: 0x0000000100c5b24c dart`dart::bin::DartDevIsolate::DartDevRunner::RunCallback(args=4345871760) at dartdev_isolate.cc:270:3
    frame #6: 0x0000000100d78704 dart`dart::bin::ThreadStart(data_ptr=<unavailable>) at thread_macos.cc:91:3
    frame #7: 0x0000000183e9e034 libsystem_pthread.dylib`_pthread_start + 136
  thread #4, name = 'DartWorker'
    frame #0: 0x0000000183e6106c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x0000000183e9e628 libsystem_pthread.dylib`_pthread_cond_wait + 1272
    frame #2: 0x0000000100eef218 dart`dart::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at os_thread_macos.cc:449:9
    frame #3: 0x0000000100e0a4f4 dart`dart::MutatorThreadPool::OnEnterIdleLocked(dart::MonitorLocker*) [inlined] dart::MonitorLocker::WaitMicros(this=<unavailable>, micros=<unavailable>) at lockers.h:181:22
    frame #4: 0x0000000100e0a4ec dart`dart::MutatorThreadPool::OnEnterIdleLocked(this=0x0000000154605f30, ml=<unavailable>) at isolate.cc:299:11
    frame #5: 0x0000000100f77e04 dart`dart::ThreadPool::WorkerLoop(this=0x0000000154605f30, worker=0x000060000262c270) at thread_pool.cc:167:7
    frame #6: 0x0000000100f78148 dart`dart::ThreadPool::Worker::Main(args=105553156293232) at thread_pool.cc:330:9
    frame #7: 0x0000000100eee618 dart`dart::ThreadStart(data_ptr=<unavailable>) at os_thread_macos.cc:136:5
    frame #8: 0x0000000183e9e034 libsystem_pthread.dylib`_pthread_start + 136
  thread #5, name = 'DartWorker'
    frame #0: 0x0000000183e6106c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x0000000183e9e628 libsystem_pthread.dylib`_pthread_cond_wait + 1272
    frame #2: 0x0000000100eef218 dart`dart::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at os_thread_macos.cc:449:9
    frame #3: 0x0000000100e0a4f4 dart`dart::MutatorThreadPool::OnEnterIdleLocked(dart::MonitorLocker*) [inlined] dart::MonitorLocker::WaitMicros(this=<unavailable>, micros=<unavailable>) at lockers.h:181:22
    frame #4: 0x0000000100e0a4ec dart`dart::MutatorThreadPool::OnEnterIdleLocked(this=0x0000000156104080, ml=<unavailable>) at isolate.cc:299:11
    frame #5: 0x0000000100f77e04 dart`dart::ThreadPool::WorkerLoop(this=0x0000000156104080, worker=0x0000600002637f00) at thread_pool.cc:167:7
    frame #6: 0x0000000100f78148 dart`dart::ThreadPool::Worker::Main(args=105553156341504) at thread_pool.cc:330:9
    frame #7: 0x0000000100eee618 dart`dart::ThreadStart(data_ptr=<unavailable>) at os_thread_macos.cc:136:5
    frame #8: 0x0000000183e9e034 libsystem_pthread.dylib`_pthread_start + 136
  thread #6
    frame #0: 0x0000000000000000
  thread #7, name = 'dart:io Process.start'
    frame #0: 0x0000000183e6106c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x0000000183e9e5fc libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x0000000100d78eb0 dart`dart::bin::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at thread_macos.cc:236:18
    frame #3: 0x0000000100c7137c dart`dart::bin::ExitCodeHandler::ExitCodeHandlerEntry(param=<unavailable>) at process_macos.cc:194:21
    frame #4: 0x0000000100d78704 dart`dart::bin::ThreadStart(data_ptr=<unavailable>) at thread_macos.cc:91:3
    frame #5: 0x0000000183e9e034 libsystem_pthread.dylib`_pthread_start + 136

Seems to be stuck here for about 15 seconds. I don't quite understand why this only happens when I copy the entire sdk to flutter/bin/cache.

[knopp]

Is there any logging that can be obtained when starting DartDev? The stacktrace doesn't seem to be very helpful, as it doesn't show what exactly what the waiting is for.

[knopp]

So DartDev seems to be sending this almost instantly to the VM:

[1, .dart_tool/pub/bin/test_1/test_1.dart-3.4.0-266.0.dev.snapshot, .dart_tool/package_config.json, false, []]

[knopp]

So the main thread is stuck at monitor_->WaitMicros(Monitor::kNoTimeout);, even though the monitor gets notified in DartDevIsolate::DartDev_Result_Exit: almost immediately.

It seems like the monitor gets notified immediately but RunCallback is holding it until the runloop finishes, that's why the main thread is blocked.

[knopp]

So dartdev main method finishes, but there are still some events pending which prevent the runloop from stopping. I'm guessing related to network I/O

These are the messages received by RunLoop after the delay (assuming a timeout somewhere).

[>] Posting message:
	len:        7
	source:     <native code>
	dest:       dartdev
	dest_port:  4026228539302727
[<] Handling message:
	len:        7
	handler:    dartdev
	port:       4026228539302727
[>] Posting message:
	len:        10
	source:     <native code>
	dest:       dartdev
	dest_port:  375847752348831
[>] Posting message:
	len:        10
	source:     <native code>
	dest:       dartdev
	dest_port:  375847752348831
[-] Closing port:
	handler:    SSLCertContextTrustEvaluate
	port:       7577917443237711
[.] Message handled (OK):
	len:        7
	handler:    dartdev
	port:       4026228539302727
[<] Handling message:
	len:        10
	handler:    dartdev
	port:       375847752348831
[.] Message handled (OK):
	len:        10
	handler:    dartdev
	port:       375847752348831
[<] Handling message:
	len:        10
	handler:    dartdev
	port:       375847752348831
[-] Closing port:
	handler:    dartdev
	port:       375847752348831
[.] Message handled (OK):
	len:        10
	handler:    dartdev
	port:       375847752348831
[-] Stopping message handler (OK):
	handler:    dartdev

[knopp]

Okay, so the problem is a 15 second idle timeout applied because of keepAlive connection in pub http client. dartdev should probably close the globalHttpClient from pub.

To confirm the above modifying dartdev.dart fixes the problem.

import 'package:pub/src/http.dart';

/// The entry point for dartdev.
Future<void> main(List<String> args, SendPort? port) async {
  await runDartdev(args, port);
  globalHttpClient.close();
}
...

[lrhn]

Impressive sleuthing!

Sounds very probable. I've had similar unexpected "hangs" at exit of my own scripts that use HttpClient, until I learned to close it properly.
If there are some (if not all) paths through dartdev that doesn't close a HttpClient, we should figure out where that happens.

If it's only the script itself that uses an http client, then the script should close its own client. (Check if that stoned your problem, if it's your own program which keeps the Dart process alive after both it and dartdev have ended.)

If the script using an http client makes dartdev wait, then we should worry about whether it can be affected by the rubbing program in other ways. Meaning to be - very aware of any process-wide properties that are used after the user program has run.

[knopp]

To elaborate, pub seems to close its globalHttpClient only when running as command:

https://github.com/dart-lang/pub/blob/2ce3da14f442394257680bb16e848626e5996420/lib/src/command.dart#L247-L250

dartdev is however using pub as package, and thus the http client is never closed. In this case dartdev calls getExecutableForCommand from pub, which in turn will attempt to get advisories for the http dependency package, which fires up the http client, but never closes it. This keeps the dartdev run loop alive until the connection keepAlive timeout expires.

Not sure why this manifests now, maybe the client before had connection:close or the pub server or reverse proxy had disabled keepalives.

Also maybe it's not clear from the description. This all happens before any of my code even starts getting executed.
dart run first starts dartdev isolate and will not run the main program before the dartdev isolate RunLoop finishes. It is this thread:

 thread #3, name = 'DartDev Runner'
    frame #0: 0x0000000183e6106c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x0000000183e9e5fc libsystem_pthread.dylib`_pthread_cond_wait + 1228
    frame #2: 0x0000000100eef230 dart`dart::Monitor::WaitMicros(this=<unavailable>, micros=<unavailable>) at os_thread_macos.cc:435:18
    frame #3: 0x00000001011fa8d4 dart`::Dart_RunLoop() [inlined] dart::MonitorLocker::Wait(this=<unavailable>, millis=0) at lockers.h:173:22
    frame #4: 0x00000001011fa8c8 dart`::Dart_RunLoop() at dart_api_impl.cc:2020:12
    frame #5: 0x0000000100c5b24c dart`dart::bin::DartDevIsolate::DartDevRunner::RunCallback(args=4345871760) at dartdev_isolate.cc:270:3
    frame #6: 0x0000000100d78704 dart`dart::bin::ThreadStart(data_ptr=<unavailable>) at thread_macos.cc:91:3
    frame #7: 0x0000000183e9e034 libsystem_pthread.dylib`_pthread_start + 136

It holds the DartDevRunner::monitor_ and until the this thread finishes, the main thread won't resume and launch the main program. And the runloop is stuck until the pub http client is closed.

[bkonyi]

I'll second lrhn's assessment: excellent debugging!

I'm able to reproduce, albeit in a different fashion:

1. dart create -t cli test_1
2. Add an invalid dependency to pubspec.yaml (e.g., http: 10.0.0)
3. dart run

Resolving dependencies in /private/tmp/test_1... 
Because test_1 depends on http 10.0.0 which doesn't match any versions, version solving failed.


You can try the following suggestion to make the pubspec resolve:
* Consider downgrading your constraint on http: dart pub add http:^1.2.1

real	0m15.955s
user	0m1.088s
sys	0m0.227s

I can confirm that adding the patch from #55289 (comment) fixes the issue.

@sigurdm @jonasfj, are we okay with reaching into package:pub/src/http.dart and closing globalHttpClient directly from DartDev? It looks like we should be safe to call close() multiple times, so this won't cause any issues when the client is closed by the dart pub command handler. If that's not okay, can we get a cleanup() method added to package:pub?

[sigurdm]

Ohh what an oversight.

I think we should better close the client inside pub - here:
https://github.com/dart-lang/pub/blob/e08f72021717ddb36fb883884fefcd0fa7aa86b4/lib/pub.dart#L52

I'll make a PR.