Reduce excessive gcstress mode logging.
Increase the default log thresholds by 10x in gcstress mode
to silence most logging (but still log pathological cases).
On the other hand, still log at least one GC per 10 seconds,
so that we preserve some informational value and progress.
Furthermore, the sampling is biased to reporting expensive GCs.
Bug: 170871390
Test: jdwp tests in gcstress mode.
Change-Id: I1747f0af3dcf313d9eb1a657bdfb8e0802f74993
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index d9cd1f5..a3dd3c7 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -203,6 +203,12 @@
#endif
#endif
+// Log GC on regular (but fairly large) intervals during GC stress mode.
+// It is expected that the other runtime options will be used to reduce the usual logging.
+// This allows us to make the logging much less verbose while still reporting some
+// progress (biased towards expensive GCs), and while still reporting pathological cases.
+static constexpr int64_t kGcStressModeGcLogSampleFrequencyNs = MsToNs(10000);
+
static inline bool CareAboutPauseTimes() {
return Runtime::Current()->InJankPerceptibleProcessState();
}
@@ -2730,6 +2736,16 @@
log_gc = log_gc || pause >= long_pause_log_threshold_;
}
}
+ bool is_sampled = false;
+ if (UNLIKELY(gc_stress_mode_)) {
+ static std::atomic_int64_t accumulated_duration_ns = 0;
+ accumulated_duration_ns += duration;
+ if (accumulated_duration_ns >= kGcStressModeGcLogSampleFrequencyNs) {
+ accumulated_duration_ns -= kGcStressModeGcLogSampleFrequencyNs;
+ log_gc = true;
+ is_sampled = true;
+ }
+ }
if (log_gc) {
const size_t percent_free = GetPercentFree();
const size_t current_heap_size = GetBytesAllocated();
@@ -2740,6 +2756,7 @@
<< ((i != pause_times.size() - 1) ? "," : "");
}
LOG(INFO) << gc_cause << " " << collector->GetName()
+ << (is_sampled ? " (sampled)" : "")
<< " GC freed " << current_gc_iteration_.GetFreedObjects() << "("
<< PrettySize(current_gc_iteration_.GetFreedBytes()) << ") AllocSpace objects, "
<< current_gc_iteration_.GetFreedLargeObjects() << "("
diff --git a/runtime/gc/heap.h b/runtime/gc/heap.h
index 5cad3f1..31075b1 100644
--- a/runtime/gc/heap.h
+++ b/runtime/gc/heap.h
@@ -140,7 +140,9 @@
static constexpr size_t kDefaultMaxFree = 2 * MB;
static constexpr size_t kDefaultMinFree = kDefaultMaxFree / 4;
static constexpr size_t kDefaultLongPauseLogThreshold = MsToNs(5);
+ static constexpr size_t kDefaultLongPauseLogThresholdGcStress = MsToNs(50);
static constexpr size_t kDefaultLongGCLogThreshold = MsToNs(100);
+ static constexpr size_t kDefaultLongGCLogThresholdGcStress = MsToNs(1000);
static constexpr size_t kDefaultTLABSize = 32 * KB;
static constexpr double kDefaultTargetUtilization = 0.75;
static constexpr double kDefaultHeapGrowthMultiplier = 2.0;
diff --git a/runtime/parsed_options.cc b/runtime/parsed_options.cc
index 1bd905d..f896511 100644
--- a/runtime/parsed_options.cc
+++ b/runtime/parsed_options.cc
@@ -743,6 +743,13 @@
args.Set(M::HeapGrowthLimit, args.GetOrDefault(M::MemoryMaximumSize));
}
+ // Increase log thresholds for GC stress mode to avoid excessive log spam.
+ if (args.GetOrDefault(M::GcOption).gcstress_) {
+ args.SetIfMissing(M::AlwaysLogExplicitGcs, false);
+ args.SetIfMissing(M::LongPauseLogThreshold, gc::Heap::kDefaultLongPauseLogThresholdGcStress);
+ args.SetIfMissing(M::LongGCLogThreshold, gc::Heap::kDefaultLongGCLogThresholdGcStress);
+ }
+
*runtime_options = std::move(args);
return true;
}
diff --git a/tools/run-libcore-tests.py b/tools/run-libcore-tests.py
index 2eb3093..ba3c090 100755
--- a/tools/run-libcore-tests.py
+++ b/tools/run-libcore-tests.py
@@ -182,19 +182,11 @@
if args.mode != "jvm":
cmd.append("--timeout {}".format(get_timeout_secs()))
-
- # Suppress explicit gc logs that are triggered an absurd number of times by these tests.
- cmd.append("--vm-arg -XX:AlwaysLogExplicitGcs:false")
cmd.append("--toolchain d8 --language CUR")
if args.jit:
cmd.append("--vm-arg -Xcompiler-option --vm-arg --compiler-filter=quicken")
cmd.append("--vm-arg -Xusejit:{}".format(str(args.jit).lower()))
- if args.gcstress:
- # Bump pause threshold as long pauses cause explicit gc logging to occur irrespective
- # of -XX:AlwayLogExplicitGcs:false.
- cmd.append("--vm-arg -XX:LongPauseLogThreshold=15") # 15 ms (default: 5ms))
-
# Suppress color codes if not attached to a terminal
if not sys.stdout.isatty():
cmd.append("--no-color")
