search

mmtk / mmtk-openjdk

OpenJDK binding for MMTk
Other
31 stars 33 forks source link

Fix deadlock related to safepoint sync. #279

Closed wks closed 5 months ago

wks commented 5 months ago

gc_lock now never does safepoint check. We always explicitly enter safepoint via ThreadBlockInVM.

The VM companion thread now lets VM_MMTkSTWOperation (executed by the VM thread) transition the state to _threads_resumed instead of doing it after VMThread::execute returns. This works around a problem where the VM thread fails to unblock the companion thread from VMThread::execute after finishing evaluating VM_MMTkSTWOperation.

Also added the lusearch benchmark from DaCapo 2006 to normal tests. This test case is known to cause deadlock before, and this PR should fix it.

Some minor style changes:

We consistently use the constant Mutex::_no_safepoint_check_flag instead of true when acquiring or waiting for the Monitor.

Slightly updated comments and logs. Logging statements no longer include thread IDs because thread IDs can be turned on by a command line option.

Fixes: https://github.com/mmtk/mmtk-openjdk/issues/278

k-sareen commented 5 months ago

Why was this never a problem when we had the coordinator thread? Also it'd be good to get @tianleq to take a look at this PR since he's spent a lot of time understanding the internal safepoint thread mechanism in HotSpot.

wks commented 5 months ago

Why was this never a problem when we had the coordinator thread?

When we had the coordinator thread, GCRequester contained the variables that record whether GC is triggered, and they were protected by their own mutex lock and condvar. Mutators triggered GC by acquiring that mutex and signalling that condvar; the coordinator thread only acquired that mutex and waited for that condvar after one GC has finished and before the next GC starts. Particularly, the coordinator does not hold any lock in EndOfGC.

After removing the coordinator thread, we removed the mutex and condvar in GCRequester, and there is effectly only one mutex that synchornizes both the mutators and the coordinator. That is the mutex in WorkerMonitor. WorkerMonitor used to be an unmamed pair of (Mutex<()>, Condvar) created by the scheduler, and that was the same mutex and condvar that protected work buckets. As part of the new synchronization mechanism, the last parked GC worker behaves like the old coordinator and executes what used to be done in EndOfGC. It does so while holding the mutex in WorkerMonitor so that other GC workers will not unpark. Mutators also needs to hold that mutex to set "goals" (such as "please do a GC") and notify GC workers to respond to the newly added "goal". Now, you see, mutators cannot trigger GC when the last parked worker is still executing EndOfGC (now named GCWorkScheduler::on_gc_finished). That makes sense because it doesn't make sense to trigger GC before the last GC officially finished. And even if a mutator runs so fast that it tried to trigger GC, the last parked GC worker will eventually finish and release the lock. Actually, resume_mutators is the last thing on_gc_finished does, and after that the worker will release the mutex.

However, the synchronization problem with OpenJDK's VMThread blocked the "companion thread", which in turn blocked the worker executing resume_mutators. That will block mutators that attempted to request GC, and that blocks the next VM operation that attempts to stop the world, and that's what was blocking the companion thread in the first place. Deadlock.

So the reason why this problem only manifests after we removed the coordinator thread is that our synchronization mechanism in mmtk-core changed.

This problem is very likely to reproduce when executing lusearch in DaCapo 2006, but we never run that benchmark in CI.

One reason why lusearch in DaCapo 2006 is likely to trigger the problem is that it executes an awful lot of RevokeBias VM operation. When given a 32M heap, using StickyImmix, it executes 261 RevokeBias VM operations, concentrated in two intervals: 0.92s-1.02s and 2.44s-2.72s. The RevokeBias operations in the former are usually benign because GC is not triggered during that time. The latter interval is likely to cause the problem since RevokeBias operations are often interleaved with GCs. Here is a log with RevokeBias and GC included so you can have a basic idea.

wks@luna ~/o/dacapo [1]> grep "Evaluating.*RevokeBias\|End of GC" lusearch-2006.log
[0.827s][446824] Evaluating safepoint VM operation: RevokeBias
[0.923s][446824] Evaluating safepoint VM operation: RevokeBias
[0.923s][446824] Evaluating safepoint VM operation: RevokeBias
[0.923s][446824] Evaluating safepoint VM operation: RevokeBias
[0.924s][446824] Evaluating safepoint VM operation: RevokeBias
[0.924s][446824] Evaluating safepoint VM operation: RevokeBias
[0.924s][446824] Evaluating safepoint VM operation: RevokeBias
[0.924s][446824] Evaluating safepoint VM operation: RevokeBias
[0.924s][446824] Evaluating safepoint VM operation: RevokeBias
[0.925s][446824] Evaluating safepoint VM operation: RevokeBias
[0.925s][446824] Evaluating safepoint VM operation: RevokeBias
[0.926s][446824] Evaluating safepoint VM operation: RevokeBias
[0.927s][446824] Evaluating safepoint VM operation: RevokeBias
[0.927s][446824] Evaluating safepoint VM operation: RevokeBias
[0.929s][446824] Evaluating safepoint VM operation: RevokeBias
[0.930s][446824] Evaluating safepoint VM operation: RevokeBias
[0.931s][446824] Evaluating safepoint VM operation: RevokeBias
[0.931s][446824] Evaluating safepoint VM operation: RevokeBias
[0.932s][446824] Evaluating safepoint VM operation: RevokeBias
[0.934s][446824] Evaluating safepoint VM operation: RevokeBias
[0.972s][446824] Evaluating safepoint VM operation: RevokeBias
[0.973s][446824] Evaluating safepoint VM operation: RevokeBias
[0.974s][446824] Evaluating safepoint VM operation: RevokeBias
[0.974s][446824] Evaluating safepoint VM operation: RevokeBias
[0.975s][446824] Evaluating safepoint VM operation: RevokeBias
[0.975s][446824] Evaluating safepoint VM operation: RevokeBias
[0.975s][446824] Evaluating safepoint VM operation: RevokeBias
[0.975s][446824] Evaluating safepoint VM operation: BulkRevokeBias
[0.980s][446824] Evaluating safepoint VM operation: RevokeBias
[0.980s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.980s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.981s][446824] Evaluating safepoint VM operation: RevokeBias
[0.981s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.981s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.981s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.981s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.981s][446824] Evaluating safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.982s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.983s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.983s][446824] Evaluating safepoint VM operation: RevokeBias
[0.983s][446824] Evaluating safepoint VM operation: RevokeBias
[0.985s][446824] Evaluating safepoint VM operation: RevokeBias
[0.985s][446824] Evaluating safepoint VM operation: RevokeBias
[0.985s][446824] Evaluating safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: BulkRevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.986s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.988s][446824] Evaluating safepoint VM operation: RevokeBias
[0.988s][446824] Evaluating safepoint VM operation: RevokeBias
[0.988s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.989s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.991s][446824] Evaluating safepoint VM operation: RevokeBias
[0.991s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.991s][446824] Evaluating coalesced safepoint VM operation: BulkRevokeBias
[0.992s][446824] Evaluating safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: BulkRevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[0.992s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.006s][446824] Evaluating safepoint VM operation: RevokeBias
[1.006s][446824] Evaluating safepoint VM operation: RevokeBias
[1.007s][446824] Evaluating safepoint VM operation: RevokeBias
[1.007s][446824] Evaluating safepoint VM operation: RevokeBias
[1.007s][446824] Evaluating safepoint VM operation: RevokeBias
[1.009s][446824] Evaluating safepoint VM operation: RevokeBias
[1.009s][446824] Evaluating safepoint VM operation: RevokeBias
[1.009s][446824] Evaluating safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: BulkRevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.011s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.013s][446824] Evaluating safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: BulkRevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.014s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.017s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.018s][446824] Evaluating safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: BulkRevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[1.019s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (1714/8192 pages, took 20 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (1915/8192 pages, took 6 ms)
[1.108s][446824] Evaluating safepoint VM operation: RevokeBias
[1.108s][446824] Evaluating coalesced safepoint VM operation: RevokeBias
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2110/8192 pages, took 3 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2287/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2500/8192 pages, took 6 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2691/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2878/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3097/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3282/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3485/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3715/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3950/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (4153/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (4363/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (4558/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (4760/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (4971/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (5165/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (5376/8192 pages, took 9 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (5571/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (5757/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (5959/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (6154/8192 pages, took 6 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2667/8192 pages, took 12 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (2878/8192 pages, took 6 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3081/8192 pages, took 6 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3291/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3485/8192 pages, took 5 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3696/8192 pages, took 4 ms)
[2024-05-28T06:48:39Z INFO  mmtk::scheduler::scheduler] End of GC (3891/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4120/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4330/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4525/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4709/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4895/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5106/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5335/8192 pages, took 6 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5538/8192 pages, took 6 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5749/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5959/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (6162/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (2718/8192 pages, took 14 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (2929/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3107/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3310/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3536/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3764/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3993/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4188/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4423/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4660/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4852/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5073/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5258/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5452/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5646/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5857/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (6078/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (6281/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (2750/8192 pages, took 11 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (2996/8192 pages, took 6 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3223/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3418/8192 pages, took 6 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3629/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3823/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4017/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4220/8192 pages, took 6 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4407/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4600/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4785/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4998/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5173/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5352/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5520/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5713/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5908/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (6119/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (6314/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (2786/8192 pages, took 11 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3004/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3231/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3410/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3604/8192 pages, took 4 ms)
[2.446s][446824] Evaluating safepoint VM operation: RevokeBias
[2.450s][446824] Evaluating safepoint VM operation: RevokeBias
[2.450s][446824] Evaluating safepoint VM operation: RevokeBias
[2.450s][446824] Evaluating safepoint VM operation: RevokeBias
[2.450s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (3798/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4001/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4196/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4390/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4592/8192 pages, took 4 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4785/8192 pages, took 5 ms)
[2.533s][446824] Evaluating safepoint VM operation: RevokeBias
[2.535s][446824] Evaluating safepoint VM operation: RevokeBias
[2.535s][446824] Evaluating safepoint VM operation: RevokeBias
[2.535s][446824] Evaluating safepoint VM operation: RevokeBias
[2.540s][446824] Evaluating safepoint VM operation: RevokeBias
[2.541s][446824] Evaluating safepoint VM operation: RevokeBias
[2.542s][446824] Evaluating safepoint VM operation: RevokeBias
[2.542s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (4998/8192 pages, took 4 ms)
[2.554s][446824] Evaluating safepoint VM operation: RevokeBias
[2.555s][446824] Evaluating safepoint VM operation: RevokeBias
[2.555s][446824] Evaluating safepoint VM operation: RevokeBias
[2.556s][446824] Evaluating safepoint VM operation: RevokeBias
[2.557s][446824] Evaluating safepoint VM operation: RevokeBias
[2.558s][446824] Evaluating safepoint VM operation: RevokeBias
[2.558s][446824] Evaluating safepoint VM operation: RevokeBias
[2.558s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5181/8192 pages, took 4 ms)
[2.573s][446824] Evaluating safepoint VM operation: RevokeBias
[2.575s][446824] Evaluating safepoint VM operation: RevokeBias
[2.575s][446824] Evaluating safepoint VM operation: RevokeBias
[2.575s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5392/8192 pages, took 5 ms)
[2.595s][446824] Evaluating safepoint VM operation: RevokeBias
[2.596s][446824] Evaluating safepoint VM operation: RevokeBias
[2.596s][446824] Evaluating safepoint VM operation: RevokeBias
[2.596s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5587/8192 pages, took 5 ms)
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5765/8192 pages, took 4 ms)
[2.621s][446824] Evaluating safepoint VM operation: RevokeBias
[2.622s][446824] Evaluating safepoint VM operation: RevokeBias
[2.623s][446824] Evaluating safepoint VM operation: RevokeBias
[2.623s][446824] Evaluating safepoint VM operation: RevokeBias
[2.623s][446824] Evaluating safepoint VM operation: RevokeBias
[2.623s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:40Z INFO  mmtk::scheduler::scheduler] End of GC (5975/8192 pages, took 4 ms)
[2.640s][446824] Evaluating safepoint VM operation: RevokeBias
[2.640s][446824] Evaluating safepoint VM operation: RevokeBias
[2.640s][446824] Evaluating safepoint VM operation: RevokeBias
[2.640s][446824] Evaluating safepoint VM operation: RevokeBias
[2.644s][446824] Evaluating safepoint VM operation: RevokeBias
[2.646s][446824] Evaluating safepoint VM operation: RevokeBias
[2.646s][446824] Evaluating safepoint VM operation: BulkRevokeBias
[2.647s][446824] Evaluating safepoint VM operation: RevokeBias
[2.648s][446824] Evaluating safepoint VM operation: RevokeBias
[2.650s][446824] Evaluating safepoint VM operation: RevokeBias
[2.652s][446824] Evaluating safepoint VM operation: RevokeBias
[2.653s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:41Z INFO  mmtk::scheduler::scheduler] End of GC (6154/8192 pages, took 2 ms)
[2.665s][446824] Evaluating safepoint VM operation: RevokeBias
[2.666s][446824] Evaluating safepoint VM operation: RevokeBias
[2.667s][446824] Evaluating safepoint VM operation: RevokeBias
[2.669s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:41Z INFO  mmtk::scheduler::scheduler] End of GC (2345/8192 pages, took 19 ms)
[2.694s][446824] Evaluating safepoint VM operation: RevokeBias
[2.695s][446824] Evaluating safepoint VM operation: RevokeBias
[2.701s][446824] Evaluating safepoint VM operation: RevokeBias
[2.703s][446824] Evaluating safepoint VM operation: RevokeBias
[2024-05-28T06:48:41Z INFO  mmtk::scheduler::scheduler] End of GC (2558/8192 pages, took 3 ms)
[2.712s][446824] Evaluating safepoint VM operation: RevokeBias
[2.714s][446824] Evaluating safepoint VM operation: RevokeBias
[2.714s][446824] Evaluating safepoint VM operation: RevokeBias
[2.715s][446824] Evaluating safepoint VM operation: RevokeBias
[2.716s][446824] Evaluating safepoint VM operation: RevokeBias
[2.716s][446824] Evaluating safepoint VM operation: RevokeBias
[2.719s][446824] Evaluating safepoint VM operation: BulkRevokeBias
[2.719s][446824] Evaluating safepoint VM operation: BulkRevokeBias
[2024-05-28T06:48:41Z INFO  mmtk::scheduler::scheduler] End of GC (2727/8192 pages, took 3 ms)
[2024-05-28T06:48:41Z INFO  mmtk::scheduler::scheduler] End of GC (2897/8192 pages, took 2 ms)
[2024-05-28T06:48:41Z INFO  mmtk::scheduler::scheduler] End of GC (2995/8192 pages, took 4 ms)

In comparison, in DaCapo 2006, it doesn't execute any RevokeBias in antlr, only one in pmd, and only three in luindex. In DaCapo Bach, lusearch executes 55 RevokeBias, concentrated during the 0.94s-1.08s interval during 2.5 second of execution time. The luserach in DaCapo Chopin is interesting. It executes 200+ RevokeBias in the first 3 seconds when the benchmark is being prepared, and 5 RevokeBias at the end of the benchmark. But during the 50 seconds of the main part of the benchmark, only one RevokeBias is executed.

I think the lusearch benchmark may have changed its behavior a lot during the course of 2006, Bach (2009) and Chopin (2023). Since it doesn't appear often in the modern lusearch, we didn't notice that was a problem.

qinsoon commented 5 months ago

I added @wenyuzhao as the other reviewer, and removed myself from the list.