Skip to content

Commit e621d8a

Browse files
Yukei7netudima
Yukei7
authored and
netudima
committed
Introduce separate GCInspector thresholds for concurrent GC events.
For GC like ShenandoahGC/ZGC etc., there are GC events that do not have STW pauses (Concurrent phases). Operator might find it reasonable to use lower thresholds for events require STW pauses and higher thresholds for concurrent phases. gc_concurrent_phase_log_threshold and gc_concurrent_phase_warn_threshold configuration options are introduced in cassandra.yaml Patch by Yuqi Yan; reviewed by Dmitry Konstantinov, Stefan Miklosovic for CASSANDRA-20980 Co-authored-by: Stefan Miklosovic
1 parent 6b57acc commit e621d8a

File tree

8 files changed

+251
-47
lines changed

8 files changed

+251
-47
lines changed

‎CHANGES.txt‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
5.1
2+
* Introduce separate GCInspector thresholds for concurrent GC events (CASSANDRA-20980)
23
* Reduce contention in MemtableAllocator.allocate (CASSANDRA-20226)
34
* Add export, list, import sub-commands for nodetool compressiondictionary (CASSANDRA-20941)
45
* Add support in the binary protocol to allow transactions to have multiple conditions (CASSANDRA-20883)

‎conf/cassandra.yaml‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2048,6 +2048,11 @@ batch_size_fail_threshold: 50KiB
20482048
# Log WARN on any batches not of type LOGGED than span across more partitions than this limit
20492049
unlogged_batch_across_partitions_warn_threshold: 10
20502050

2051+
# GCInspector configs:
2052+
# For GC like ShenandoahGC/ZGC etc., there are GC events that do not have STW pauses (Concurrent phases)
2053+
# Operator might find it reasonable to use lower thresholds for events require STW pauses and higher thresholds
2054+
# for concurrent phases.
2055+
#
20512056
# GC Pauses greater than 200 ms will be logged at INFO level
20522057
# This threshold can be adjusted to minimize logging if necessary
20532058
# Min unit: ms
@@ -2059,6 +2064,17 @@ unlogged_batch_across_partitions_warn_threshold: 10
20592064
# Min unit: ms
20602065
# gc_warn_threshold: 1000ms
20612066

2067+
# GC Concurrent phase greater than 1000 ms will be logged at INFO level
2068+
# This threshold can be adjusted to minimize logging if necessary
2069+
# Min unit: ms
2070+
# gc_concurrent_phase_log_threshold: 1000ms
2071+
2072+
# GC Concurrent phase than gc_concurrent_phase_warn_threshold will be logged at WARN level
2073+
# Adjust the threshold based on your application throughput requirement. Setting to 0
2074+
# will deactivate the feature.
2075+
# Min unit: ms
2076+
# gc_concurrent_phase_warn_threshold: 2000ms
2077+
20622078
# Maximum size of any value in SSTables. Safety measure to detect SSTable corruption
20632079
# early. Any value size larger than this threshold will result into marking an SSTable
20642080
# as corrupted. This should be positive and less than 2GiB.

‎conf/cassandra_latest.yaml‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1913,6 +1913,11 @@ batch_size_fail_threshold: 50KiB
19131913
# Log WARN on any batches not of type LOGGED than span across more partitions than this limit
19141914
unlogged_batch_across_partitions_warn_threshold: 10
19151915

1916+
# GCInspector configs:
1917+
# For GC like ShenandoahGC/ZGC etc., there are GC events that do not have STW pauses.
1918+
# Such events are called Concurrent phases. Operator might find it reasonable to use lower thresholds
1919+
# for events require STW pauses and higher thresholds for concurrent phases.
1920+
#
19161921
# GC Pauses greater than 200 ms will be logged at INFO level
19171922
# This threshold can be adjusted to minimize logging if necessary
19181923
# Min unit: ms
@@ -1924,6 +1929,17 @@ unlogged_batch_across_partitions_warn_threshold: 10
19241929
# Min unit: ms
19251930
# gc_warn_threshold: 1000ms
19261931

1932+
# GC Concurrent phase greater than 1000 ms will be logged at INFO level
1933+
# This threshold can be adjusted to minimize logging if necessary
1934+
# Min unit: ms
1935+
# gc_concurrent_phase_log_threshold: 1000ms
1936+
1937+
# GC Concurrent phase than gc_concurrent_phase_warn_threshold will be logged at WARN level
1938+
# Adjust the threshold based on your application throughput requirement. Setting to 0
1939+
# will deactivate the feature.
1940+
# Min unit: ms
1941+
# gc_concurrent_phase_warn_threshold: 2000ms
1942+
19271943
# Maximum size of any value in SSTables. Safety measure to detect SSTable corruption
19281944
# early. Any value size larger than this threshold will result into marking an SSTable
19291945
# as corrupted. This should be positive and less than 2GiB.

‎src/java/org/apache/cassandra/config/Config.java‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -593,6 +593,8 @@ public static class SSTableConfig
593593
public volatile DurationSpec.IntMillisecondsBound gc_log_threshold = new DurationSpec.IntMillisecondsBound("200ms");
594594
@Replaces(oldName = "gc_warn_threshold_in_ms", converter = Converters.MILLIS_DURATION_INT, deprecated = true)
595595
public volatile DurationSpec.IntMillisecondsBound gc_warn_threshold = new DurationSpec.IntMillisecondsBound("1s");
596+
public volatile DurationSpec.IntMillisecondsBound gc_concurrent_phase_log_threshold = new DurationSpec.IntMillisecondsBound("1s");
597+
public volatile DurationSpec.IntMillisecondsBound gc_concurrent_phase_warn_threshold = new DurationSpec.IntMillisecondsBound("2s");
596598

597599
// TTL for different types of trace events.
598600
@Replaces(oldName = "tracetype_query_ttl", converter = Converters.SECONDS_DURATION, deprecated=true)

‎src/java/org/apache/cassandra/config/DatabaseDescriptor.java‎

Lines changed: 74 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1220,6 +1220,22 @@ else if (conf.max_value_size.toMebibytes() >= 2048)
12201220
// run audit logging options through sanitation and validation
12211221
if (conf.audit_logging_options != null)
12221222
setAuditLoggingOptions(conf.audit_logging_options);
1223+
1224+
try
1225+
{
1226+
// Run through the validation by setting current values back to their setters, so we are sure that their values are valid.
1227+
// We are catching IllegalArgumentException and translating it to ConfigurationException to comply with
1228+
// rest of the logic in this method. These setters are also called in GCInspectorMXBean were IllegalArgumentException
1229+
// is thrown when arguments are invalid instead ConfigurationException, on purpose.
1230+
DatabaseDescriptor.setGCLogThreshold((int) DatabaseDescriptor.getGCLogThreshold());
1231+
DatabaseDescriptor.setGCWarnThreshold((int) DatabaseDescriptor.getGCWarnThreshold());
1232+
DatabaseDescriptor.setGCConcurrentPhaseLogThreshold(DatabaseDescriptor.getGCConcurrentPhaseLogThreshold());
1233+
DatabaseDescriptor.setGCConcurrentPhaseWarnThreshold(DatabaseDescriptor.getGCConcurrentPhaseWarnThreshold());
1234+
}
1235+
catch (IllegalArgumentException ex)
1236+
{
1237+
throw new ConfigurationException(ex.getMessage());
1238+
}
12231239
}
12241240

12251241
@VisibleForTesting
@@ -4719,14 +4735,17 @@ public static long getGCLogThreshold()
47194735
return conf.gc_log_threshold.toMilliseconds();
47204736
}
47214737

4722-
public static void setGCLogThreshold(int gcLogThreshold)
4738+
public static void setGCLogThreshold(int threshold)
47234739
{
4724-
conf.gc_log_threshold = new DurationSpec.IntMillisecondsBound(gcLogThreshold);
4725-
}
4740+
if (threshold <= 0)
4741+
throw new IllegalArgumentException("Threshold value for gc_log_threshold must be greater than 0");
47264742

4727-
public static EncryptionContext getEncryptionContext()
4728-
{
4729-
return encryptionContext;
4743+
long gcWarnThresholdInMs = getGCWarnThreshold();
4744+
if (gcWarnThresholdInMs != 0 && threshold > gcWarnThresholdInMs)
4745+
throw new IllegalArgumentException("Threshold value for gc_log_threshold (" + threshold + ") must be less than gc_warn_threshold which is currently "
4746+
+ gcWarnThresholdInMs);
4747+
4748+
conf.gc_log_threshold = new DurationSpec.IntMillisecondsBound(threshold);
47304749
}
47314750

47324751
public static long getGCWarnThreshold()
@@ -4736,9 +4755,58 @@ public static long getGCWarnThreshold()
47364755

47374756
public static void setGCWarnThreshold(int threshold)
47384757
{
4758+
if (threshold < 0)
4759+
throw new IllegalArgumentException("Threshold value for gc_warn_threshold must be greater than or equal to 0");
4760+
4761+
long gcLogThresholdInMs = getGCLogThreshold();
4762+
if (threshold != 0 && threshold <= gcLogThresholdInMs)
4763+
throw new IllegalArgumentException("Threshold value for gc_warn_threshold (" + threshold + ") must be greater than gc_log_threshold which is currently "
4764+
+ gcLogThresholdInMs);
4765+
47394766
conf.gc_warn_threshold = new DurationSpec.IntMillisecondsBound(threshold);
47404767
}
47414768

4769+
public static int getGCConcurrentPhaseLogThreshold()
4770+
{
4771+
return conf.gc_concurrent_phase_log_threshold.toMilliseconds();
4772+
}
4773+
4774+
public static void setGCConcurrentPhaseLogThreshold(int threshold)
4775+
{
4776+
if (threshold <= 0)
4777+
throw new IllegalArgumentException("Threshold must be greater than 0");
4778+
4779+
long gcConcurrentPhaseWarnThresholdInMs = getGCConcurrentPhaseWarnThreshold();
4780+
if (gcConcurrentPhaseWarnThresholdInMs != 0 && threshold > gcConcurrentPhaseWarnThresholdInMs)
4781+
throw new IllegalArgumentException("Threshold value for gc_concurrent_phase_log_threshold (" + threshold + ") must be less than gc_concurrent_phase_warn_threshold which is currently "
4782+
+ gcConcurrentPhaseWarnThresholdInMs);
4783+
4784+
conf.gc_concurrent_phase_log_threshold = new DurationSpec.IntMillisecondsBound(threshold);
4785+
}
4786+
4787+
public static int getGCConcurrentPhaseWarnThreshold()
4788+
{
4789+
return conf.gc_concurrent_phase_warn_threshold.toMilliseconds();
4790+
}
4791+
4792+
public static void setGCConcurrentPhaseWarnThreshold(int threshold)
4793+
{
4794+
if (threshold < 0)
4795+
throw new IllegalArgumentException("Threshold value for gc_concurrent_phase_warn_threshold must be greater than or equal to 0");
4796+
4797+
long gcConcurrentPhaseLogThresholdInMs = getGCConcurrentPhaseLogThreshold();
4798+
if (threshold != 0 && threshold <= gcConcurrentPhaseLogThresholdInMs)
4799+
throw new IllegalArgumentException("Threshold value for gc_concurrent_phase_warn_threshold (" + threshold + ") must be greater than gc_concurrent_phase_log_threshold which is currently "
4800+
+ gcConcurrentPhaseLogThresholdInMs);
4801+
4802+
conf.gc_concurrent_phase_warn_threshold = new DurationSpec.IntMillisecondsBound(threshold);
4803+
}
4804+
4805+
public static EncryptionContext getEncryptionContext()
4806+
{
4807+
return encryptionContext;
4808+
}
4809+
47424810
public static boolean isCDCEnabled()
47434811
{
47444812
return conf.cdc_enabled;

‎src/java/org/apache/cassandra/service/GCInspector.java‎

Lines changed: 71 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -173,6 +173,7 @@ public static void register() throws Exception
173173
ObjectName gcName = new ObjectName(ManagementFactory.GARBAGE_COLLECTOR_MXBEAN_DOMAIN_TYPE + ",*");
174174
for (ObjectName name : server.queryNames(gcName, null))
175175
{
176+
logger.info("Notification listener is added for: {}", name);
176177
server.addNotificationListener(name, inspector, null, null);
177178
}
178179
}
@@ -261,6 +262,11 @@ public void handleNotification(final Notification notification, final Object han
261262
duration = total - previousTotal; // may be zero for a really fast collection
262263
}
263264

265+
logger.trace("Received GarbageCollectionNotificationInfo with gcId: {}, gcName: {}, " +
266+
"gcCause: {}, gcAction: {}, event duration: {} ms, calculated duration: {} ms",
267+
gcInfo.getId(), info.getGcName(), info.getGcCause(), info.getGcAction(),
268+
gcInfo.getDuration(), duration);
269+
264270
StringBuilder sb = new StringBuilder();
265271
sb.append(info.getGcName()).append(" GC in ").append(duration).append("ms. ");
266272
long bytes = 0;
@@ -287,23 +293,56 @@ public void handleNotification(final Notification notification, final Object han
287293
if (state.compareAndSet(prev, new State(duration, bytes, prev)))
288294
break;
289295
}
290-
291-
if (getGcWarnThresholdInMs() != 0 && duration > getGcWarnThresholdInMs())
292-
logger.warn(sb.toString());
293-
else if (duration > getGcLogThresholdInMs())
294-
logger.info(sb.toString());
295-
else if (logger.isTraceEnabled())
296-
logger.trace(sb.toString());
297296

298-
if (duration > this.getStatusThresholdInMs())
299-
StatusLogger.log();
297+
if (isConcurrentPhase(info.getGcCause(), info.getGcName()))
298+
{
299+
if (getGcConcurrentPhaseWarnThresholdInMs() != 0 && duration > getGcConcurrentPhaseWarnThresholdInMs())
300+
logger.warn(sb.toString());
301+
else if (duration > getGcConcurrentPhaseLogThresholdInMs())
302+
logger.info(sb.toString());
303+
else if (logger.isTraceEnabled())
304+
logger.trace(sb.toString());
305+
306+
if (duration > this.getConcurrentStatusThresholdInMs())
307+
StatusLogger.log();
308+
}
309+
else
310+
{
311+
if (getGcWarnThresholdInMs() != 0 && duration > getGcWarnThresholdInMs())
312+
logger.warn(sb.toString());
313+
else if (duration > getGcLogThresholdInMs())
314+
logger.info(sb.toString());
315+
else if (logger.isTraceEnabled())
316+
logger.trace(sb.toString());
317+
318+
if (duration > this.getStatusThresholdInMs())
319+
StatusLogger.log();
320+
}
300321

301322
// if we just finished an old gen collection and we're still using a lot of memory, try to reduce the pressure
302323
if (gcState.assumeGCIsOldGen)
303324
LifecycleTransaction.rescheduleFailedDeletions();
304325
}
305326
}
306327

328+
static boolean isConcurrentPhase(String cause, String name) {
329+
// Mostly taken from: https://github.com/Netflix/spectator/blob/v1.7.x/spectator-ext-gc/src/main/java/com/netflix/spectator/gc/GcLogger.java
330+
// So far the only indicator known is that the cause will be reported as "No GC"
331+
// when using CMS.
332+
//
333+
// For ZGC, behavior was changed in JDK17: https://bugs.openjdk.java.net/browse/JDK-8265136
334+
// For ZGC in older versions, there is no way to accurately get the amount of time
335+
// in STW pauses.
336+
//
337+
// For G1, a new bean is added in JDK20 to indicate time spent in concurrent phases:
338+
// https://bugs.openjdk.org/browse/JDK-8297247
339+
340+
return "No GC".equals(cause) // CMS
341+
|| "G1 Concurrent GC".equals(name) // G1 in JDK20+
342+
|| name.endsWith(" Cycles"); // Shenandoah, ZGC
343+
}
344+
345+
307346
public State getTotalSinceLastCheck()
308347
{
309348
return state.getAndSet(new State());
@@ -378,14 +417,6 @@ private static long getFieldValue(Field field, boolean isAtomicLong)
378417

379418
public void setGcWarnThresholdInMs(long threshold)
380419
{
381-
long gcLogThresholdInMs = getGcLogThresholdInMs();
382-
if (threshold < 0)
383-
throw new IllegalArgumentException("Threshold must be greater than or equal to 0");
384-
if (threshold != 0 && threshold <= gcLogThresholdInMs)
385-
throw new IllegalArgumentException("Threshold must be greater than gcLogThresholdInMs which is currently "
386-
+ gcLogThresholdInMs);
387-
if (threshold > Integer.MAX_VALUE)
388-
throw new IllegalArgumentException("Threshold must be less than Integer.MAX_VALUE");
389420
DatabaseDescriptor.setGCWarnThreshold((int)threshold);
390421
}
391422

@@ -396,15 +427,27 @@ public long getGcWarnThresholdInMs()
396427

397428
public void setGcLogThresholdInMs(long threshold)
398429
{
399-
if (threshold <= 0)
400-
throw new IllegalArgumentException("Threshold must be greater than 0");
430+
DatabaseDescriptor.setGCLogThreshold((int) threshold);
431+
}
432+
433+
public int getGcConcurrentPhaseWarnThresholdInMs()
434+
{
435+
return DatabaseDescriptor.getGCConcurrentPhaseWarnThreshold();
436+
}
401437

402-
long gcWarnThresholdInMs = getGcWarnThresholdInMs();
403-
if (gcWarnThresholdInMs != 0 && threshold > gcWarnThresholdInMs)
404-
throw new IllegalArgumentException("Threshold must be less than gcWarnThresholdInMs which is currently "
405-
+ gcWarnThresholdInMs);
438+
public void setGcConcurrentPhaseWarnThresholdInMs(int threshold)
439+
{
440+
DatabaseDescriptor.setGCConcurrentPhaseWarnThreshold(threshold);
441+
}
406442

407-
DatabaseDescriptor.setGCLogThreshold((int) threshold);
443+
public int getGcConcurrentPhaseLogThresholdInMs()
444+
{
445+
return DatabaseDescriptor.getGCConcurrentPhaseLogThreshold();
446+
}
447+
448+
public void setGcConcurrentPhaseLogThresholdInMs(int threshold)
449+
{
450+
DatabaseDescriptor.setGCConcurrentPhaseLogThreshold(threshold);
408451
}
409452

410453
public long getGcLogThresholdInMs()
@@ -417,4 +460,8 @@ public long getStatusThresholdInMs()
417460
return getGcWarnThresholdInMs() != 0 ? getGcWarnThresholdInMs() : getGcLogThresholdInMs();
418461
}
419462

463+
public long getConcurrentStatusThresholdInMs()
464+
{
465+
return getGcConcurrentPhaseWarnThresholdInMs() != 0 ? getGcConcurrentPhaseWarnThresholdInMs() : getGcConcurrentPhaseLogThresholdInMs();
466+
}
420467
}

‎src/java/org/apache/cassandra/service/GCInspectorMXBean.java‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,10 @@ public interface GCInspectorMXBean
2727
void setGcWarnThresholdInMs(long threshold);
2828
long getGcWarnThresholdInMs();
2929
void setGcLogThresholdInMs(long threshold);
30+
int getGcConcurrentPhaseLogThresholdInMs();
31+
void setGcConcurrentPhaseWarnThresholdInMs(int threshold);
32+
int getGcConcurrentPhaseWarnThresholdInMs();
33+
void setGcConcurrentPhaseLogThresholdInMs(int threshold);
3034
long getGcLogThresholdInMs();
3135
long getStatusThresholdInMs();
3236
}

0 commit comments

Comments
 (0)