8270100: Fix some inaccurate GC logging #4727
Conversation
|
👋 Welcome back simonis! A progress list of the required criteria for merging this PR into |
Webrevs
|
|
Can you share the complete flags and the benchmark for easy reproducing? Somehow I can't reproduce the gc logs; the flags and the benchmark I used:
|
|
Hi @albertnetymk, to see the first issue, you have to make the initial heap smaller than the the maximum heap. It can easily seen with your command line. Before the change: $ java -XX:+UseSerialGC -Xms100m -Xmx2g '-Xlog:gc,gc+heap*=trace' -jar /share/soware/Java/dacapo-9.12-MR1-bach.jar h2 -s huge -n 1 | grep "allowed 0K extra"
[1,339s][trace][gc,ergo,heap ] GC(11) [allowed 0K extra for 0 threads]
[2,066s][trace][gc,ergo,heap ] GC(17) [allowed 0K extra for 0 threads]
[3,323s][trace][gc,ergo,heap ] GC(23) [allowed 0K extra for 0 threads]
[5,560s][trace][gc,ergo,heap ] GC(29) [allowed 0K extra for 0 threads]
...After the change: $ java -XX:+UseSerialGC -Xms100m -Xmx2g '-Xlog:gc,gc+heap*=trace' -jar /share/soware/Java/dacapo-9.12-MR1-bach.jar h2 -s huge -n 1 | grep "allowed 0K extra"
[1,397s][trace][gc,ergo,heap ] GC(11) [allowed 5K extra for 1 threads]
[2,202s][trace][gc,ergo,heap ] GC(17) [allowed 5K extra for 1 threads]
[3,468s][trace][gc,ergo,heap ] GC(23) [allowed 5K extra for 1 threads]
[5,699s][trace][gc,ergo,heap ] GC(29) [allowed 5K extra for 1 threads]
...To see the second issue, you obviously will have to shrink the heap and set $ java -XX:+UseSerialGC -Xms100m -Xmx1g '-Xlog:gc,gc+heap*=trace' -XX:-ShrinkHeapInSteps Uncommit
...
[9,759s][trace][gc,heap ] GC(11) shrinking: initSize: 68288,0K maximum_desired_capacity: 90337,3K
[9,759s][trace][gc,heap ] GC(11) shrink_bytes: 572226,7K current_shrink_factor: 0 new shrink factor: 0 _min_heap_delta_bytes: 192,0K
[9,780s][trace][gc,heap ] GC(11) Shrinking tenured generation from 662564K to 90340K
...After the change: $ java -XX:+UseSerialGC -Xms100m -Xmx1g '-Xlog:gc,gc+heap*=trace' -XX:-ShrinkHeapInSteps Uncommit
...
[3,941s][trace][gc,heap ] GC(11) shrinking: initSize: 68288,0K maximum_desired_capacity: 92130,6K
[3,941s][trace][gc,heap ] GC(11) shrink_bytes: 575773,4K current_shrink_factor: 100 new shrink factor: 100 _min_heap_delta_bytes: 192,0K
[3,958s][trace][gc,heap ] GC(11) Shrinking tenured generation from 667904K to 92132K
...Here's the example program: import java.io.IOException;
import java.nio.file.FileSystems;
import java.nio.file.Files;
import java.nio.file.Path;
public class Uncommit {
static class KB {
int[] kb;
public KB() {
kb = new int[256];
}
}
static class MB {
KB[] mb;
public MB() {
mb = new KB[1024];
for (int i = 0; i < mb.length; i++) {
mb[i] = new KB();
}
}
}
static class GB {
MB[] gb;
public GB() {
gb = new MB[1024];
for (int i = 0; i < gb.length; i++) {
gb[i] = new MB();
}
}
}
static void printRSS() throws IOException {
Files.lines(FileSystems.getDefault().getPath("/proc/self/status")).
filter(l -> l.startsWith("VmRSS")).
forEach(System.out::println);
}
public static void main(String[] args) throws Exception {
System.out.println("Calling System.gc()");
System.gc();
printRSS();
System.out.println("\nPress <Enter>");
System.console().readLine();
int size = Integer.parseInt(args.length > 0 ? args[0] : "512");
MB mb[] = new MB[size];
for (int i = 0; i < size; i++) {
mb[i] = new MB();
}
System.out.println("Successfully allocated " + size + "MB memory");
printRSS();
System.out.println("\nPress <Enter>");
System.console().readLine();
for (int i = 0; i < size; i++) {
mb[i] = null;
}
System.out.println("Successfully unlinked " + size + "MB memory");
printRSS();
System.out.println("\nPress <Enter>");
System.console().readLine();
int gcs = 5;
if (args.length > 1) {
gcs = Integer.parseInt(args[1]);
}
for (int i = 1; i <= gcs; i++) {
System.gc();
System.out.println("Performed " + i + ". System.gc()\n");
printRSS();
System.out.println("Press <Enter>");
System.console().readLine();
}
}
} |
|
Thank you for the instruction, with which I can reproduce both issues. As for the first fix, int threads_count = Threads::number_of_non_daemon_threads();;
size_t thread_increase_size = threads_count * NewSizeThreadIncrease;
log_trace(gc, ergo, heap)(
" [allowed " SIZE_FORMAT "K extra for %d threads]",
thread_increase_size/K, threads_count);As for the second fix, I think the following is more symmetric: if (ShrinkHeapInSteps) {
// assign current_shrink_factor and _shrink_factor
} else {
// Shink 100% to the desired value
_shrink_factor = current_shrink_factor = 100;
}PS: currently, the assignment of assert(_shrink_factor <= 100, "invalid shrink factor");
size_t current_shrink_factor = _shrink_factor;
_shrink_factor = 0; |
|
For the second fix, I don't see why assigning to 100 to |
I don't view a method call and accessing a global as much duplication. Anyway, this is subjective.
Having a logic-free (does nothing but print) logger brings less surprise. IOW, many expect a logger faithfully reflect the actual internal states with no distortion.
That's true, but I prefer that the logger doesn't know
I see; thank you for pointing it out. How about sth like this? void CardGeneration::compute_new_size() {
...
if (capacity_after_gc < minimum_desired_capacity) {
...
// expanding the heap; reset shrink factor
_shrink_factor = 0;
return;
}
if (capacity_after_gc > maximum_desired_capacity) {
...
if (ShrinkHeapInSteps) {
current_shrink_factor = _shrink_factor;
_shrink_factor = ...
} else {
// Shrink 100% to the desired value
current_shrink_factor = _shrink_factor = 100;
}
// log internal states
}
} |
|
@albertnetymk your latest proposal is still changing the current semantics. Before, the shrink factor was reset on every invocation of My patch is really just a trivial fix of some logging errors. I'm not against changing or improving it, but before I introduce any behavioral changes, I'd like to hear a second opinion. |
|
I would prefer to not change semantics for heap sizing without lots of testing, and discussing the results. People have come to expect particular behavior, and actually "decaying" the shrink factor on every s - s - s - n - n - ... lots of n ... - n - s On the last s, the GC would shrink 100% of the suggested value, which is kind of surprising given that the many "no-changes" gcs that would have indicated the application is kind of stable now (or you started another round in your benchmark). Generally it is also a good idea to be very reluctant with heap decreases as it typically has a significant performance impact during further operation. Too much heap shrinking tends to also just cause the next gc(s) to increase the heap again, i.e. ending up in wasted cpu time :) Fwiw, for this issue, I would split Repeating the calculation at the logging as suggested by @albertnetymk gives different results on boundary conditions (i.e. the overflow checks are missing. Strangely on any overflow condition, I agree with @albertnetymk that it is preferable to not have the conditions in the log message to make them as simple as possible - so I would probably just set Calling Of course, I did not run and test my suggestions. Three people, three opinions, but maybe there's a middle ground to be found somewhere :p |
Indeed, my suggestion is flawed.
Agree.
Sounds good to me. Re |
|
@albertnetymk, @tschatzl thanks for your feedback. From what I understand we all agree that this change should only fix the reported GC logging issues without changing the semantics or behavior of the underlying GC algorithm. My new version of the fix tries to achieve exactly this based on your recommendations:
With these changes the logging issues are fixed without any change in functionality. |
|
@simonis This change now passes all automated pre-integration checks. ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details. After integration, the commit message for the final commit will be: You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed. At the time when this comment was updated there had been 68 new commits pushed to the
As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details. ➡️ To integrate this PR with the above commit message to the |
|
Thanks for the reviews @albertnetymk, @tschatzl! |
|
/integrate |
|
Going to push as commit fb86d13.
Your commit was automatically rebased without conflicts. |
openjdk
bot
added
integrated
If running with
-Xlog:gc+heap*=tracethe JVM will print the extra per thread amount which is added to the new generation on resize:Currently this will always print "0K extra for 0 threads" no matter how much extra space was added.
Also, the shrink factor will always be printed to be 0%, even if we run with
-XX:-ShrinkHeapInStepswhich pins the shrink factor at 100%:The fix is trivial.
Progress
Issue
Reviewers
Reviewing
Using
gitCheckout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/4727/head:pull/4727$ git checkout pull/4727Update a local copy of the PR:
$ git checkout pull/4727$ git pull https://git.openjdk.java.net/jdk pull/4727/headUsing Skara CLI tools
Checkout this PR locally:
$ git pr checkout 4727View PR using the GUI difftool:
$ git pr show -t 4727Using diff file
Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/4727.diff