dart::GCCompactor makes search on pub.dev slow (3.0.0 regression)

[jonasfj]

We recently observed that if we do a loop that makes a search request to pub.dev every 100ms, the requests are fast (~60ms for a simple query).
But if we do the request every 1s instead, the requests are slow (> 1s).

The issue appears to have started after we upgraded from 2.19.6 to 3.0.0.
And debugging it locally, we also find that 2.19.6 doesn't suffer from this behavior.

Credits @mkustermann for tracing this to dart::GCCompactor::VisitPointers

Context: Our search process has a sizable amount of data in-memory and lots of Dart objects / Map / List / Set / String / etc.. So it's not surprising that compacting the heap could be slow. And each search does allocate a bunch of objects that is released when the search request is done.

See dump from perf report --no-children

+   27.30%  DartWorker       dart              [.] non-virtual thunk to dart::GCCompactor::VisitPointers(dart::ObjectPtr*, dart::ObjectPtr*)
+   18.31%  DartWorker       dart              [.] 0x0000000002405f07
+    8.87%  DartWorker       dart              [.] dart::CompactorTask::SlideBlock
+    7.61%  DartWorker       dart              [.] 0x0000000002405f82
+    6.05%  DartWorker       dart              [.] dart::CompactorTask::PlanBlock
+    5.95%  DartWorker       dart              [.] 0x0000000002404172
+    4.29%  DartWorker       dart              [.] dart::UntaggedObject::VisitPointersPredefined
+    3.24%  DartWorker       dart              [.] 0x0000000002405ef9
+    1.91%  DartWorker       dart              [.] 0x0000000002234494
+    1.38%  DartWorker       libc.so.6         [.] pthread_mutex_lock@@GLIBC_2.2.5
+    1.31%  DartWorker       dart              [.] 0x0000000002405efc
+    1.29%  DartWorker       libc.so.6         [.] __GI___pthread_mutex_unlock_usercnt
+    1.04%  DartWorker       dart              [.] 0x0000000002405f0c
     0.41%  DartWorker       dart              [.] 0x0000000002405f05
     0.40%  DartWorker       dart              [.] 0x0000000002405ef4
     0.34%  DartWorker       libc.so.6         [.] _int_free
     0.33%  DartWorker       dart              [.] 0x0000000002404153
     0.31%  DartWorker       dart              [.] 0x000000000240413f
     0.29%  DartWorker       [JIT] tid 856820  [.] *dart.collection___Set&_HashVMBase&SetMixin&_HashBase&_OperatorEqualsAndHashCode&_LinkedHashSetMixin@3220832__getKeyO
     0.28%  DartWorker       [JIT] tid 856820  [.] *PackageNameIndex_searchWord

Recorded request latency

Using Dart 2.19.6

$ for i in {1..30}; do sleep 1; curl -w '%{time_total}\n' -Ls http://localhost:8082/search?q=retry -o /dev/null; done
0.081092
0.082060
0.064795
0.079013
0.076508
0.087800
0.665303 # <-- looks like it happens here too, just less frequently
0.078545
0.072124
0.088390
0.073081
0.086967
0.088025
0.082290
0.077925
0.076373
0.093406
0.073708
0.087810
0.074978
0.076830
0.077917
0.076213
0.087249
0.076254
0.083859
0.077098
0.084421
0.070183
0.082409

Using Dart 3.0.0

# With sleep 1s
$ for i in {1..30}; do sleep 1; curl -w '%{time_total}\n' -Ls http://localhost:8082/search?q=retry -o /dev/null; done
0.108693
1.156937
1.123688
1.130786
1.258260
1.195012
1.178660
1.098746
1.093142
1.131269
1.110011
1.154830
1.149059
1.059845
1.131827
1.143921
1.139439
1.125857
1.147304
1.104930
1.113691
1.140321
1.194772
1.129498
1.108069
1.096956
1.182429
1.179889
1.112675
1.109692

# With sleep 0.1s
$ for i in {1..30}; do sleep 0.1; curl -w '%{time_total}\n' -Ls http://localhost:8082/search?q=retry -o /dev/null; done
0.067815
0.049691
0.069296
0.071330
0.068390
0.089099
0.065786
0.072415
0.063212
0.065470
0.065002
0.065758
0.069631
0.065540
0.056589
0.078862
0.066153
0.064349
0.067683
0.062685
0.065035
0.062776
0.066715
0.063428
0.067500
0.062801
0.065540
0.068821
0.068419
0.065610

[mkustermann]

Maybe the heuristics we use for determining when to run compactor are not ideal (idle time estimation, expected time it takes to compact heap, expected fragmentation of heap, ...).

This can cause pretty big issues for server apps that get low traffic (i.e. mostly idle) - as the compactor may take 1 second so any request that does come gets delayed by that much.

As a siden-note, we may want to allow customers to disable compaction entirely (e.g. --compactor-tasks=0 -- as --use-compactor seems to be off by default and mean something different)

[mkustermann]

@rmacnak-google could you take a look?

[isoos]

Note: the issue may have started with the 2.19.0 -> 2.19.6 upgrade, but the increase in latencies was not that high to look into it.

[rmacnak-google]

Requests every 1s is just the right frequency to get the worst behavior from the standalone VM's idle policy because this is the default value of --idle_duration_micros. If requests are more frequent, the VM won't think it's idle; less frequent and the idle GC will (at least partially) finish before the next request.

Short term, in increasing order of severity

• Idle compaction can indirectly be disabled while leaving idle scavenges on by setting --idle_duration_micros to a value that's only enough time for scavenges. Something like 30ms, though one could look at either the timeline or --verbose_gc to find something specific to this program.
• The idle mechanism can be throttled by setting --idle_timeout_micros to a much larger value like 1 minute.
• The idle mechanism can be completely disabled by setting --idle_timeout_micros=0.

Long term, the compactor will be made incremental.

@jonasfj Could you provide either a timeline from the slow run or instructions on how to reproduce it locally?

[jonasfj]

To start do:

wget https://github.com/jonasfj/pub-dev/archive/refs/heads/reproduce-52513.zip
unzip reproduce-52513.zip 
cd pub-dev-reproduce-52513/
cd app/
dart pub get
DEBUG=* dart bin/fake_server.dart run --read-only

Wait for it to print: LOADED DATA

Compare results from requests with an without 1s sleep:

# Sleeping 1s between requests is causing them to be slow
for i in {1..30}; do sleep 1; curl -w '%{time_total}\n' -Ls http://localhost:8082/search?q=ante -o /dev/null; done
0.907602
1.801583
1.825277
...

# Sleeping 0s between requests makes them less slow
for i in {1..30}; do sleep 0; curl -w '%{time_total}\n' -Ls http://localhost:8082/search?q=ante -o /dev/null; done
1.105817
0.925765
0.875859
0.881853
...

Fair warning I hacked the code a lot to somewhat reproduce this without using data from production :D

The difference between sleep 1s and not, is not as big as we see it in production where we have 300ms vs 3-4s. But it's still very clear that sleeping 1s is a problem.

[a-siva]

@rmacnak-google Can this issue be closed as fixed?

[isoos]

@a-siva: was there any change that we need to be aware of? We are still running pub.dev with a timer that prevents the compactor.

[rmacnak-google]

@a-siva No, disabling idle compaction with --idle_timeout_micros=0 is a work-around. The proper fix is incremental compaction.

[a-siva]

@a-siva No, disabling idle compaction with --idle_timeout_micros=0 is a work-around. The proper fix is incremental compaction.

Can we create an issue for implementation of incremental compaction and close this as a duplicate of that issue.