Improper DEFAULT_MAX_NURSERY?

[qinsoon]

Our current DEFAULT_MAX_NURSERY is set to 1G on 64bits machine.

mmtk-core/src/util/options.rs

Line 83 in 9edb453

pub const DEFAULT_MAX_NURSERY: usize = (1 << 20) << LOG_BYTES_IN_MBYTE;

According to collection_required() in Gen, nursery is not considered as full (to trigger a nursery GC) unless its reserved pages reach the max nursery size (1G).

mmtk-core/src/plan/generational/global.rs

Lines 114 to 115 in 9edb453

	let nursery_full = self.nursery.reserved_pages()
	>= (conversions::bytes_to_pages_up(self.common.base.options.get_max_nursery()));

If the heap size is smaller than 1G and we do not set nursery size explicitly, we always trigger full heap GCs, and never trigger a nursery GC.

[k-sareen]

If the heap size is smaller than 1G and we do not set nursery size explicitly, we always trigger full heap GCs, and never trigger a nursery GC.

That's not true, right? I don't remember noticing this while I fixed the nursery size options. The function which actually controls a full-heap GC is require_full_heap_collection [1], not collection_required.

Did you have a trace showcasing this behaviour you've mentioned?

EDIT: See here [2, 3].

[1]:

mmtk-core/src/plan/generational/global.rs

Lines 147 to 193 in 9edb453

	/// Check if we should do a full heap GC. It returns true if we should have a full heap GC.
	/// It also sets gc_full_heap based on the result.
	pub fn requires_full_heap_collection<P: Plan>(&self, plan: &P) -> bool {
	// Allow the same 'true' block for if-else.
	// The conditions are complex, and it is easier to read if we put them to separate if blocks.
	#[allow(clippy::if_same_then_else)]
	let is_full_heap = if crate::plan::generational::FULL_NURSERY_GC {
	// For barrier overhead measurements, we always do full gc in nursery collections.
	true
	} else if self
	.common
	.base
	.user_triggered_collection
	.load(Ordering::SeqCst)
	&& *self.common.base.options.full_heap_system_gc
	{
	// User triggered collection, and we force full heap for user triggered collection
	true
	} else if self.next_gc_full_heap.load(Ordering::SeqCst)
	|| self
	.common
	.base
	.cur_collection_attempts
	.load(Ordering::SeqCst)
	> 1
	{
	// Forces full heap collection
	true
	} else if self.virtual_memory_exhausted(plan) {
	true
	} else {
	plan.get_total_pages() <= plan.get_reserved_pages()
	};
	self.gc_full_heap.store(is_full_heap, Ordering::SeqCst);
	info!(
	"{}",
	if is_full_heap {
	"Full heap GC"
	} else {
	"Nursery GC"
	}
	);
	is_full_heap
	}

[2]:

mmtk-core/src/plan/generational/copying/global.rs

Line 86 in 4bb37f8

let is_full_heap = self.requires_full_heap_collection();

[3]:

mmtk-core/src/plan/generational/immix/global.rs

Line 115 in 4bb37f8

let is_full_heap = self.requires_full_heap_collection();

[qinsoon]

If nursery.reserved_pages is always smaller than nursery_max_size, then we will not trigger a GC because of nursery being full. In that case, we will trigger a GC if plan.reserved_pages is larger plan.total_pages, and that will be a full heap GC.

[k-sareen]

So in other words, only highly allocating/generational workloads work as intended... Hmm. From memory we discussed that a large nursery limit was fine since it's the "unbounded" nursery. Surely one can argue that nursery size is a tuning parameter specific to each workload and in order to get best performance, they may have to tune it?

[qinsoon]

So in other words, only highly allocating/generational workloads work as intended...

It is not about work load. It is max nursery size and heap size. If max nursery size is larger than heap size, we will not have nursery GCs. For example, the default max nursery value (1G) is very likely to be larger than normal 2x-6x heap sizes we use for most dacapo benchmarks. If that happens, we will not see nursery GCs.

I believe we have the same issue for Java MMTk. But their default max nursery is 32M, which is more likely to be smaller than usual heap sizes we use for Dacapo.

Hmm. From memory we discussed that a large nursery limit was fine since it's the "unbounded" nursery. Surely one can argue that nursery size is a tuning parameter specific to each workload and in order to get best performance, they may have to tune it?

Right. You would need to set nursery size along with heap size, and make sure they match each other.

[k-sareen]

Can we gather stats on this? I feel like something is amiss -- I don't remember getting Number of GC ~ Number of major GCs. There is a counter for the major GCs, so we should be able to know how many nursery GCs happen.

[qinsoon]

For example, the following always triggers full heap GCs. The default max nursery is 1G, and the heap size is set to 80M. The heap is full before the nursery is full -- so every GC is full heap.

MMTK_PLAN=GenImmix build/linux-x86_64-normal-server-release/jdk/bin/java -XX:MetaspaceSize=500M -XX:+DisableExplicitGC -XX:-TieredCompilation -XX:+UseThirdPartyHeap -Xms80M -Xmx80M -cp /usr/share/benchmarks/dacapo/dacapo-2006-10-MR2.jar Harness fop

[2023-01-02T22:40:11Z INFO  mmtk::memory_manager] Initialized MMTk with GenImmix
===== DaCapo fop starting =====
[2023-01-02T22:40:12Z INFO  mmtk::util::heap::gc_trigger] [POLL] nursery: Triggering collection
[2023-01-02T22:40:12Z INFO  mmtk::plan::generational::global] Full heap GC
[2023-01-02T22:40:12Z INFO  mmtk::scheduler::gc_work] End of GC
[2023-01-02T22:40:13Z INFO  mmtk::util::heap::gc_trigger] [POLL] nursery: Triggering collection
[2023-01-02T22:40:13Z INFO  mmtk::plan::generational::global] Full heap GC
[2023-01-02T22:40:13Z INFO  mmtk::scheduler::gc_work] End of GC
===== DaCapo fop PASSED in 1348 msec =====

If you set MMTK_NURSERY=Bounded:30000000 (30M) to the above command, we will see nursery GC.

MMTK_NURSERY=Bounded:30000000 MMTK_PLAN=GenImmix build/linux-x86_64-normal-server-release/jdk/bin/java -XX:MetaspaceSize=500M -XX:+DisableExplicitGC -XX:-TieredCompilation -XX:+UseThirdPartyHeap -Xms80M -Xmx80M -cp /usr/share/benchmarks/dacapo/dacapo-2006-10-MR2.jar Harness fop

[2023-01-02T22:26:19Z INFO  mmtk::memory_manager] Initialized MMTk with GenImmix
===== DaCapo fop starting =====
[2023-01-02T22:26:20Z INFO  mmtk::util::heap::gc_trigger] [POLL] nursery: Triggering collection
[2023-01-02T22:26:20Z INFO  mmtk::plan::generational::global] Nursery GC
[2023-01-02T22:26:20Z INFO  mmtk::scheduler::gc_work] End of GC
[2023-01-02T22:26:20Z INFO  mmtk::util::heap::gc_trigger] [POLL] nursery: Triggering collection
[2023-01-02T22:26:20Z INFO  mmtk::plan::generational::global] Nursery GC
[2023-01-02T22:26:20Z INFO  mmtk::scheduler::gc_work] End of GC
[2023-01-02T22:26:20Z INFO  mmtk::util::heap::gc_trigger] [POLL] nursery: Triggering collection
[2023-01-02T22:26:20Z INFO  mmtk::plan::generational::global] Nursery GC
[2023-01-02T22:26:20Z INFO  mmtk::scheduler::gc_work] End of GC
===== DaCapo fop PASSED in 1359 msec =====

[k-sareen]

This run is from a while ago but is from my PR comment here (#630 (comment)), but it seems like the majorGC != GC [1]. Maybe the counter is broken then...? I guess we need to remove the is_nursery_full check and replace it with something else.

[1]: https://squirrel.anu.edu.au/plotty/kunals/bench-test/#0|2022-07-27-nursery-pr-performance-boar-2022-07-27-Wed-153152&benchmark^build^buildstring^invocation^iteration^mmtk_gc&GC^majorGC^time^time.other^time.stw&|10&iteration^1^4&mmtk_gc^1^GenImmix|70&build^nursery-pr

[k-sareen]

Yes this is reproducible on current mmtk-core master + mmtk-openjdk master.

For GenImmix + fop:

============================ MMTk Statistics Totals ============================
GC      time.other      time.stw        majorGC total-work.time.min     total-work.time.max     total-work.time.total   total-work.count
16      850.32  71.35   16      inf     -inf    0.000   0
Total time: 921.67 ms
------------------------------ End MMTk Statistics -----------------------------
===== DaCapo evaluation-git-6e411f33 fop PASSED in 922 msec =====

But not reproducible on mmtk-core 8afe96d and mmtk-openjdk 688791e, which actually introduced the bounded nursery.

For GenImmix + fop:

============================ MMTk Statistics Totals ============================
GC      time.other      time.stw        majorGC total-work.time.max     total-work.time.min     total-work.time.total   total-work.count
48      940.76  151.32  2       -inf    inf     0.000   0
Total time: 1092.08 ms
------------------------------ End MMTk Statistics -----------------------------
===== DaCapo evaluation-git-6e411f33 fop PASSED in 1092 msec =====

So the regression was introduced between August 2022 and January 2023. The most likely candidate is the GC trigger one: 2300ce1.

The static cost of a GC unfortunately outweighs the gains from nursery GC, so the older commit is slower (than non-generational counterpart) as discussed here #594 and previous meetings.

[qinsoon]

Thanks @k-sareen . I figured out why it could trigger nursery GCs in 8afe96d, but not in the current master. The problem I talked about in this issue also exists in 8afe96d: GC is triggered because of heap being full (not nursery being full). The difference is after the GC is triggered, master always treats the GC as full heap GC (which is obvious as the heap was full), but 8afe96d may treat it as nursery GC.

The difference is from another change in 2300ce1. L72 (pr.clear_request(pages_reserved)) was before block_for_gc() in 8afe96d, but it is moved to after block_for_gc() in 2300ce1 (this change was for a different reason). So in 8afe96d, there are a few pending allocation pages that are counted when we decide to trigger GC, but they are not counted when we decide nursery/full heap GC.

mmtk-core/src/policy/space.rs

Lines 69 to 72 in 06237f1

	debug!("Collection required");
	assert!(allow_gc, "GC is not allowed here: collection is not initialized (did you call initialize_collection()?).");
	VM::VMCollection::block_for_gc(VMMutatorThread(tls)); // We have checked that this is mutator
	pr.clear_request(pages_reserved); // clear the pages after GC. We need those reserved pages so we can compute new heap size properly.

This is what happens for 8afe96d:

MMTK_PLAN=GenImmix build/linux-x86_64-normal-server-release/jdk/bin/java -XX:MetaspaceSize=500M -XX:+DisableExplicitGC -XX:-TieredCompilation -XX:+UseThirdPartyHeap -Xms80M -Xmx80M -cp /usr/share/benchmarks/dacapo/dacapo-2006-10-MR2.jar Harness fop

[2023-01-04T04:52:52Z TRACE mmtk::plan::generational::global] nursery = 9864, max nursery =268435456
// Nursery is not full
[2023-01-04T04:52:52Z DEBUG mmtk::plan::global] self.get_reserved_pages()=20483, self.get_total_pages()=20480
// But heap is full - Do GC
[2023-01-04T04:52:52Z INFO  mmtk::plan::global]   [POLL] nursery: Triggering collection
// Clear current pending allocation pages (reserved pages is now 20467 down from 20483)
[2023-01-04T04:52:52Z TRACE mmtk::plan::generational::global] full heap? false (total 20480, reserve 20467)
// So heap is not full - Do nursery GC
[2023-01-04T04:52:52Z INFO  mmtk::plan::generational::global] Nursery GC
[2023-01-04T04:52:52Z INFO  mmtk::scheduler::gc_work] End of GC

Though this triggers a nursery GC, I don't feel this is intended. I would say it was a bug that makes it possible to trigger nursery GCs in 8afe96d, the problem we discussed in this issue still exists in 8afe96d.

[k-sareen]

Going by the GC Handbook, what we want is an Appel-style nursery (Chapter 9, pg. 121). A heap-full collection should always be nursery GC unless the nursery space is less than some minimum threshold (i.e. the should_next_gc_be_full_heap() function). So really, it's our way of triggering nursery GCs that is incorrect.

Edit: I agree that it just happened to work for the previous commit, but I would posit a heap-full collection for an Appel-style nursery should not be a full-heap GC. Full-heap GCs should only occur if-and-when the nursery size (i.e. reserved pages) is less than the minimum nursery size (2 MB iirc). This would be consistent with Appel-style nursery and generational hypothesis.

[k-sareen]

I think the terminology of "heap-full" and "full-heap" is perhaps confusing us. Heap-full is just when we are out of space to allocate. I don't see why a full-heap GC is required for that case, since theoretically we could reclaim enough space with a nursery GC in order to service the allocation and continue the program. A full-heap GC should only happen if the nursery is too small to allocate further into and/or if the virtual memory is exhausted which is a similar case. (Maybe we should rename "heap-full" to something else?)