Skip to content

Commit

Permalink
Split up rate limiter classes to simplify LogContext code and reduce …
Browse files Browse the repository at this point in the history
…the size of memory allocations needed in the common case (almost no log statements use both types of rate limiting).

This change should have no impact other than reducing memory footprint.

RELNOTES=Refactored rate limiter classes.
PiperOrigin-RevId: 511823509
  • Loading branch information
hagbard authored and Flogger Team committed Feb 23, 2023
1 parent bd2d607 commit 209a0a4
Show file tree
Hide file tree
Showing 9 changed files with 302 additions and 143 deletions.
Original file line number Diff line number Diff line change
@@ -0,0 +1,57 @@
/*
* Copyright (C) 2014 The Flogger Authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

package com.google.common.flogger;

import static com.google.common.flogger.LogContext.Key.LOG_EVERY_N;

import com.google.common.flogger.backend.Metadata;
import java.util.concurrent.atomic.AtomicLong;

/**
* Rate limiter to support {@code every(N)} functionality. This class is mutable, but thread safe.
*/
final class CountingRateLimiter {
private static final LogSiteMap<CountingRateLimiter> map =
new LogSiteMap<CountingRateLimiter>() {
@Override
protected CountingRateLimiter initialValue() {
return new CountingRateLimiter();
}
};

static boolean shouldLog(Metadata metadata, LogSiteKey logSiteKey) {
// Fast path is "there's no metadata so return true" and this must not allocate.
Integer rateLimitCount = metadata.findValue(LOG_EVERY_N);
if (rateLimitCount == null) {
return true;
}
return map.get(logSiteKey, metadata).incrementAndCheckInvocationCount(rateLimitCount);
}

private final AtomicLong invocationCount = new AtomicLong();

/**
* Increments the invocation count and returns true if it was a multiple of the specified rate
* limit count; implying that the log statement should be emitted. This is invoked during
* post-processing if a rate limiting count was set via {@link LoggingApi#every(int)}.
*/
// Visible for testing.
boolean incrementAndCheckInvocationCount(int rateLimitCount) {
// Assume overflow cannot happen for a Long counter.
return (invocationCount.getAndIncrement() % rateLimitCount) == 0;
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@

package com.google.common.flogger;

import static com.google.common.flogger.LogContext.Key.LOG_AT_MOST_EVERY;
import static com.google.common.flogger.util.Checks.checkNotNull;

import com.google.common.flogger.backend.LogData;
Expand All @@ -25,25 +26,46 @@
import java.util.concurrent.atomic.AtomicLong;

/**
* Statistics for individual log sites for determining when rate limited log statements should be
* emitted. This class is mutable, but thread safe.
* Rate limiter to support {@code atMostEvery(N, units)} functionality. This class is mutable, but
* thread safe.
*/
final class LogSiteStats {
final class DurationRateLimiter {
private static final LogSiteMap<DurationRateLimiter> map =
new LogSiteMap<DurationRateLimiter>() {
@Override
protected DurationRateLimiter initialValue() {
return new DurationRateLimiter();
}
};

/** Creates a period for rate limiting for the specified duration. */
static RateLimitPeriod newRateLimitPeriod(int n, TimeUnit unit) {
return new RateLimitPeriod(n, unit);
}

/**
* Returns whether the log site should log based on the value of the {@code LOG_AT_MOST_EVERY}
* metadata value and the current log site timestamp.
*/
static boolean shouldLogForTimestamp(
Metadata metadata, LogSiteKey logSiteKey, long timestampNanos) {
// Fast path is "there's no metadata so return true" and this must not allocate.
RateLimitPeriod rateLimitPeriod = metadata.findValue(LOG_AT_MOST_EVERY);
if (rateLimitPeriod == null) {
return true;
}
return map.get(logSiteKey, metadata).checkLastTimestamp(timestampNanos, rateLimitPeriod);
}

/**
* Immutable metadata for rate limiting based on a fixed count. This corresponds to the
* LOG_AT_MOST_EVERY metadata key in {@link LogData}. Unlike the metadata for {@code every(N)},
* we need to use a wrapper class here to preserve the time unit information.
* LOG_AT_MOST_EVERY metadata key in {@link LogData}. Unlike the metadata for {@code every(N)}, we
* need to use a wrapper class here to preserve the time unit information.
*/
// TODO: Consider making this a public class to allow backends to handle it explicitly.
static final class RateLimitPeriod {
private final int n;
private final TimeUnit unit;
// Count of the number of log statements skipped in the last period. See during post processing.
// Count of the number of log statements skipped in the last period. Set during post processing.
private int skipCount = -1;

private RateLimitPeriod(int n, TimeUnit unit) {
Expand All @@ -70,12 +92,9 @@ private void setSkipCount(int skipCount) {
@Override
public String toString() {
// TODO: Make this less ugly and internationalization friendly.
StringBuilder out = new StringBuilder()
.append(n)
.append(' ')
.append(unit);
StringBuilder out = new StringBuilder().append(n).append(' ').append(unit);
if (skipCount > 0) {
out.append(" [skipped: ").append(skipCount).append(']');
out.append(" [skipped: ").append(skipCount).append(']');
}
return out.toString();
}
Expand All @@ -96,35 +115,15 @@ public boolean equals(Object obj) {
}
}

private static final LogSiteMap<LogSiteStats> map = new LogSiteMap<LogSiteStats>() {
@Override
protected LogSiteStats initialValue() {
return new LogSiteStats();
}
};

static LogSiteStats getStatsForKey(LogSiteKey logSiteKey, Metadata metadata) {
return map.get(logSiteKey, metadata);
}

private final AtomicLong invocationCount = new AtomicLong();
private final AtomicLong lastTimestampNanos = new AtomicLong();
private final AtomicInteger skippedLogStatements = new AtomicInteger();

/**
* Increments the invocation count and returns true if it was a multiple of the specified rate
* limit count; implying that the log statement should be emitted. This is invoked during
* post-processing if a rate limiting count was set via {@link LoggingApi#every(int)}.
*/
boolean incrementAndCheckInvocationCount(int rateLimitCount) {
return (invocationCount.getAndIncrement() % rateLimitCount) == 0;
}

/**
* Checks whether the current time stamp is after the rate limiting period and if so, updates the
* time stamp and returns true. This is invoked during post-processing if a rate limiting duration
* was set via {@link LoggingApi#atMostEvery(int, TimeUnit)}.
*/
// Visible for testing.
boolean checkLastTimestamp(long timestampNanos, RateLimitPeriod period) {
long lastNanos = lastTimestampNanos.get();
// Avoid a race condition where two threads log at the same time. This is safe as lastNanos
Expand Down
37 changes: 9 additions & 28 deletions api/src/main/java/com/google/common/flogger/LogContext.java
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@
import static com.google.common.flogger.util.Checks.checkNotNull;
import static java.util.concurrent.TimeUnit.NANOSECONDS;

import com.google.common.flogger.LogSiteStats.RateLimitPeriod;
import com.google.common.flogger.DurationRateLimiter.RateLimitPeriod;
import com.google.common.flogger.backend.LogData;
import com.google.common.flogger.backend.Metadata;
import com.google.common.flogger.backend.Platform;
Expand Down Expand Up @@ -524,23 +524,14 @@ protected boolean postProcess(@NullableDecl LogSiteKey logSiteKey) {
if (metadata != null) {
// Without a log site we ignore any log-site specific behaviour.
if (logSiteKey != null) {
// Don't "return true" early from this code since we also need to handle stack size.
// Only get the stats instance when we need it, but cache it if we do. This avoids getting
// an instance for every log statement when the vast majority don't need it.
LogSiteStats stats = null;
Integer rateLimitCount = metadata.findValue(Key.LOG_EVERY_N);
if (rateLimitCount != null) {
stats = ensureStats(stats, logSiteKey, metadata);
if (!stats.incrementAndCheckInvocationCount(rateLimitCount)) {
return false;
}
// Note: The current behaviour for handling multiple rate limiters if not ideal, and there's
// an implicit order here. Ideally all rate limiting would occur in any order, but this is
// actually subtle and needs more work (so for now the old behaviour is preserved).
if (!CountingRateLimiter.shouldLog(metadata, logSiteKey)) {
return false;
}
RateLimitPeriod rateLimitPeriod = metadata.findValue(Key.LOG_AT_MOST_EVERY);
if (rateLimitPeriod != null) {
stats = ensureStats(stats, logSiteKey, metadata);
if (!stats.checkLastTimestamp(getTimestampNanos(), rateLimitPeriod)) {
return false;
}
if (!DurationRateLimiter.shouldLogForTimestamp(metadata, logSiteKey, getTimestampNanos())) {
return false;
}
}

Expand Down Expand Up @@ -574,16 +565,6 @@ protected boolean postProcess(@NullableDecl LogSiteKey logSiteKey) {
return true;
}

// Helper to get the stats instance on demand while reusing an instance if already obtained.
// Usage:
// // Possible null stats here...
// stats = ensureStats(stats, logSiteKey, metadata);
// // Non-null stats here (assigned to variable for next time)
private static LogSiteStats ensureStats(
@NullableDecl LogSiteStats stats, LogSiteKey logSiteKey, Metadata metadata) {
return stats != null ? stats : LogSiteStats.getStatsForKey(logSiteKey, metadata);
}

/**
* Pre-processes log metadata and determines whether we should make the pending logging call.
*
Expand Down Expand Up @@ -783,7 +764,7 @@ public final API atMostEvery(int n, TimeUnit unit) {
// Rate limiting with a zero length period is a no-op, but if the time unit is nanoseconds then
// the value is rounded up inside the rate limit object.
if (n > 0) {
addMetadata(Key.LOG_AT_MOST_EVERY, LogSiteStats.newRateLimitPeriod(n, unit));
addMetadata(Key.LOG_AT_MOST_EVERY, DurationRateLimiter.newRateLimitPeriod(n, unit));
}
return api();
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,82 @@
/*
* Copyright (C) 2014 The Flogger Authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

package com.google.common.flogger;

import static com.google.common.flogger.LogContext.Key.LOG_EVERY_N;
import static com.google.common.truth.Truth.assertThat;

import com.google.common.flogger.testing.FakeLogSite;
import com.google.common.flogger.testing.FakeMetadata;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.junit.runners.JUnit4;

@RunWith(JUnit4.class)
public class CountingRateLimiterTest {
@Test
public void testMetadataKey() {
FakeMetadata metadata = new FakeMetadata().add(LOG_EVERY_N, 3);
LogSite logSite = FakeLogSite.unique();

// The first log is always emitted.
assertThat(CountingRateLimiter.shouldLog(metadata, logSite)).isTrue();
assertThat(CountingRateLimiter.shouldLog(metadata, logSite)).isFalse();
// Not supplying the metadata disables rate limiting.
assertThat(CountingRateLimiter.shouldLog(new FakeMetadata(), logSite)).isTrue();
assertThat(CountingRateLimiter.shouldLog(metadata, logSite)).isFalse();
// The fourth log is emitted (ignoring the case when there was no metadata).
assertThat(CountingRateLimiter.shouldLog(metadata, logSite)).isTrue();
}

@Test
public void testDistinctLogSites() {
FakeMetadata metadata = new FakeMetadata().add(LOG_EVERY_N, 3);
LogSite fooLog = FakeLogSite.unique();
LogSite barLog = FakeLogSite.unique();

// The first log is always emitted.
assertThat(CountingRateLimiter.shouldLog(metadata, fooLog)).isTrue();
assertThat(CountingRateLimiter.shouldLog(metadata, barLog)).isTrue();

assertThat(CountingRateLimiter.shouldLog(metadata, fooLog)).isFalse();
assertThat(CountingRateLimiter.shouldLog(metadata, fooLog)).isFalse();

assertThat(CountingRateLimiter.shouldLog(metadata, barLog)).isFalse();
assertThat(CountingRateLimiter.shouldLog(metadata, barLog)).isFalse();

assertThat(CountingRateLimiter.shouldLog(metadata, fooLog)).isTrue();
assertThat(CountingRateLimiter.shouldLog(metadata, barLog)).isTrue();
}

@Test
public void testIncrementAndCheckInvocationCount() {
CountingRateLimiter limiter = new CountingRateLimiter();

// Always log for the first call.
assertThat(limiter.incrementAndCheckInvocationCount(2)).isTrue();

// Alternating for a rate limit count of 2
assertThat(limiter.incrementAndCheckInvocationCount(2)).isFalse();
assertThat(limiter.incrementAndCheckInvocationCount(2)).isTrue();

// Every third for a rate limit count of 3 (counter starts at 3, so returns true immediately).
assertThat(limiter.incrementAndCheckInvocationCount(3)).isTrue();
assertThat(limiter.incrementAndCheckInvocationCount(3)).isFalse();
assertThat(limiter.incrementAndCheckInvocationCount(3)).isFalse();
assertThat(limiter.incrementAndCheckInvocationCount(3)).isTrue();
}
}
Loading

0 comments on commit 209a0a4

Please sign in to comment.