diff --git a/core/src/main/java/com/linecorp/armeria/common/util/AndSampler.java b/core/src/main/java/com/linecorp/armeria/common/util/AndSampler.java new file mode 100644 index 00000000000..1a6e3e71516 --- /dev/null +++ b/core/src/main/java/com/linecorp/armeria/common/util/AndSampler.java @@ -0,0 +1,37 @@ +/* + * Copyright 2023 LINE Corporation + * + * LINE Corporation licenses this file to you 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: + * + * https://www.apache.org/licenses/LICENSE-2.0 + */ +package com.linecorp.armeria.common.util; + +/** + * Sample if both of the samplers sample. + */ +final class AndSampler implements Sampler { + + private final Sampler left; + private final Sampler right; + + AndSampler(Sampler left, Sampler right) { + this.left = left; + this.right = right; + } + + @Override + public boolean isSampled(T t) { + // Assign the variables otherwise the short-circuiting will cause sampler to not be used. + final boolean leftSampled = left.isSampled(t); + final boolean rightSampled = right.isSampled(t); + return leftSampled && rightSampled; + } + + @Override + public String toString() { + return left + " and " + right; + } +} diff --git a/core/src/main/java/com/linecorp/armeria/common/util/OrSampler.java b/core/src/main/java/com/linecorp/armeria/common/util/OrSampler.java new file mode 100644 index 00000000000..98759bb5b3f --- /dev/null +++ b/core/src/main/java/com/linecorp/armeria/common/util/OrSampler.java @@ -0,0 +1,37 @@ +/* + * Copyright 2023 LINE Corporation + * + * LINE Corporation licenses this file to you 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: + * + * https://www.apache.org/licenses/LICENSE-2.0 + */ +package com.linecorp.armeria.common.util; + +/** + * Sample if one of the samplers samples. + */ +final class OrSampler implements Sampler { + + private final Sampler left; + private final Sampler right; + + OrSampler(Sampler left, Sampler right) { + this.left = left; + this.right = right; + } + + @Override + public boolean isSampled(T t) { + // Assign the variables otherwise the short-circuiting will cause sampler to not be used. + final boolean leftSampled = left.isSampled(t); + final boolean rightSampled = right.isSampled(t); + return leftSampled || rightSampled; + } + + @Override + public String toString() { + return left + " or " + right; + } +} diff --git a/core/src/main/java/com/linecorp/armeria/common/util/Sampler.java b/core/src/main/java/com/linecorp/armeria/common/util/Sampler.java index 2969df2a61c..f0cede79e08 100644 --- a/core/src/main/java/com/linecorp/armeria/common/util/Sampler.java +++ b/core/src/main/java/com/linecorp/armeria/common/util/Sampler.java @@ -29,6 +29,8 @@ */ package com.linecorp.armeria.common.util; +import static java.util.Objects.requireNonNull; + /** * Sampler is responsible for deciding if a particular trace should be "sampled", i.e. whether the * overhead of tracing will occur and/or if a trace will be reported to the collection tier. @@ -42,6 +44,76 @@ */ @FunctionalInterface public interface Sampler { + + /** + * Returns a sampler that applies logical or operator to both samplers decisions. + */ + default Sampler or(Sampler other) { + return new OrSampler<>(this, requireNonNull(other, "other")); + } + + /** + * Returns a sampler that applies logical and operator to both samplers decisions. + */ + default Sampler and(Sampler other) { + return new AndSampler<>(this, requireNonNull(other, "other")); + } + + /** + * Returns a sampler that applies logical not operator to the sampler decision. + */ + default Sampler not() { + return object -> !isSampled(object); + } + + /** + * Returns a sampler that returns {@code true} if the value is greater than the given value. + */ + static > Sampler greaterThan(T val) { + requireNonNull(val, "val"); + return object -> object.compareTo(val) > 0; + } + + /** + * Returns a sampler that returns {@code true} if the value is less than or equal to the given value. + */ + static > Sampler greaterThanOrEqual(T val) { + requireNonNull(val, "val"); + return object -> object.compareTo(val) >= 0; + } + + /** + * Returns a sampler that returns {@code true} if the value is less than the given value. + */ + static > Sampler lessThan(T val) { + requireNonNull(val, "val"); + return object -> object.compareTo(val) < 0; + } + + /** + * Returns a sampler that returns {@code true} if the value is less than or equal to the given value. + */ + static > Sampler lessThanOrEqual(T val) { + requireNonNull(val, "val"); + return object -> object.compareTo(val) <= 0; + } + + /** + * Returns a sampler that returns {@code true} if the value is equal to the given value. + */ + static > Sampler equal(T val) { + requireNonNull(val, "val"); + return object -> object.compareTo(val) == 0; + } + + /** + * Returns a sampler that returns {@code true} if the value is inside the percentile distribution + * in the given time window. + */ + static Sampler percentile(float percentile, long windowMilliseconds) { + return new TimeWindowPercentileSampler(percentile, windowMilliseconds); + } + /** * Returns a probabilistic sampler which samples at the specified {@code probability} * between {@code 0.0} and {@code 1.0}. diff --git a/core/src/main/java/com/linecorp/armeria/common/util/TimeWindowPercentileSampler.java b/core/src/main/java/com/linecorp/armeria/common/util/TimeWindowPercentileSampler.java new file mode 100644 index 00000000000..bd0ca9ff42b --- /dev/null +++ b/core/src/main/java/com/linecorp/armeria/common/util/TimeWindowPercentileSampler.java @@ -0,0 +1,107 @@ +/* + * Copyright 2023 LINE Corporation + * + * LINE Corporation licenses this file to you 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: + * + * https://www.apache.org/licenses/LICENSE-2.0 + */ +package com.linecorp.armeria.common.util; + +import java.time.Duration; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.MoreObjects; + +import com.linecorp.armeria.common.metric.MoreMeters; + +import io.micrometer.core.instrument.Clock; +import io.micrometer.core.instrument.distribution.DistributionStatisticConfig; +import io.micrometer.core.instrument.distribution.HistogramSnapshot; +import io.micrometer.core.instrument.distribution.TimeWindowPercentileHistogram; + +/** + * Sample if the value is less than the percentile of the values in the last window. + */ +final class TimeWindowPercentileSampler implements Sampler { + + private final float percentile; + private final long windowLengthMillis; + private final TimeWindowPercentileHistogram histogram; + private final long snapshotUpdateNanos; + private static final long DEFAULT_SNAPSHOT_UPDATE_NANOS = TimeUnit.SECONDS.toNanos(1); + private long lastSnapshotNanos; + private HistogramSnapshot histogramSnapshot; + + private final Clock clock; + private final AtomicReference isTakingSnapshot = new AtomicReference<>(false); + + TimeWindowPercentileSampler(float percentile, long windowLengthMillis) { + this(percentile, windowLengthMillis, Clock.SYSTEM, DEFAULT_SNAPSHOT_UPDATE_NANOS); + } + + @VisibleForTesting + TimeWindowPercentileSampler(float percentile, long windowLengthMillis, Clock clock, + long snapshotUpdateNanos) { + this.percentile = percentile; + this.windowLengthMillis = windowLengthMillis; + + final DistributionStatisticConfig distributionStatisticConfig = + DistributionStatisticConfig.builder() + .percentilesHistogram(false) + .percentiles(percentile) + .expiry(Duration.ofMillis(windowLengthMillis)) + .build() + .merge(MoreMeters.distributionStatisticConfig()); + this.histogram = new TimeWindowPercentileHistogram(clock, distributionStatisticConfig, true); + this.snapshotUpdateNanos = snapshotUpdateNanos; + this.histogramSnapshot = histogram.takeSnapshot(0, 0, 0); + this.clock = clock; + this.lastSnapshotNanos = clock.monotonicTime(); + } + + @VisibleForTesting + static TimeWindowPercentileSampler create(float percentile, long windowLengthMillis, + long snapshotUpdateNanos) { + return new TimeWindowPercentileSampler(percentile, windowLengthMillis, Clock.SYSTEM, + snapshotUpdateNanos); + } + + @Override + public boolean isSampled(Long t) { + histogram.recordLong(t); + + System.out.println("lastSnapshotNanos: " + lastSnapshotNanos); + System.out.println("snapshotUpdateNanos: " + snapshotUpdateNanos); + System.out.println("clock.monotonicTime(): " + clock.monotonicTime()); + + if (lastSnapshotNanos + snapshotUpdateNanos <= clock.monotonicTime()) { + if (isTakingSnapshot.compareAndSet(false, true)) { + // Two threads reach here back to back. Make sure snapshot is not taken very recently before + // we acquired the lock. + if (lastSnapshotNanos + snapshotUpdateNanos <= clock.monotonicTime()) { + System.out.println("Taking snapshot"); + histogramSnapshot = histogram.takeSnapshot(0, 0, 0); + lastSnapshotNanos = clock.monotonicTime(); + isTakingSnapshot.set(false); + } + } + } + + final Double percentileValue = histogramSnapshot.percentileValues()[0].value(); + return t >= percentileValue.longValue(); + } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this) + .omitNullValues() + .add("percentile", percentile) + .add("windowLengthMillis", windowLengthMillis) + .add("snapshotUpdateNanos", snapshotUpdateNanos) + .toString(); + } +} diff --git a/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecorator.java b/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecorator.java index 3f56a31ff6d..08f921756fa 100644 --- a/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecorator.java +++ b/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecorator.java @@ -83,6 +83,28 @@ */ float failureSamplingRate() default -1.0f; + /** + * Sample the requests if they are slower than the {@code slowRequestSamplingPercentile} percent + * of the requests. + */ + float slowRequestSamplingPercentile() default -1.0f; + + /** + * Slow request percentiles are calculated over the last {@code slowRequestSamplingWindowMillis}. + */ + long slowRequestSamplingWindowMillis() default 10 * 60 * 1000; + + /** + * Don't sample the requests if they are faster than the {@code slowRequestSamplingLowerBoundMillis()}. + * Should be used with {@link #slowRequestSamplingUpperBoundMillis()}. + */ + long slowRequestSamplingLowerBoundMillis() default 0L; + + /** + * Always sample the requests if they are slower than the {@code slowRequestSamplingUpperBoundMillis()}. + */ + long slowRequestSamplingUpperBoundMillis() default Long.MAX_VALUE; + /** * The order of decoration, where a {@link Decorator} of lower value will be applied first. */ diff --git a/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecoratorFactoryFunction.java b/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecoratorFactoryFunction.java index 5d1e19fe7d1..7ca1d20dd85 100644 --- a/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecoratorFactoryFunction.java +++ b/core/src/main/java/com/linecorp/armeria/server/annotation/decorator/LoggingDecoratorFactoryFunction.java @@ -21,6 +21,7 @@ import com.linecorp.armeria.server.HttpService; import com.linecorp.armeria.server.annotation.DecoratorFactoryFunction; import com.linecorp.armeria.server.logging.LoggingService; +import com.linecorp.armeria.server.logging.LoggingServiceBuilder; /** * A factory which creates a {@link LoggingService} decorator. @@ -38,15 +39,26 @@ public final class LoggingDecoratorFactoryFunction implements DecoratorFactoryFu final float failureSamplingRate = parameter.failureSamplingRate() >= 0.0f ? parameter.failureSamplingRate() : parameter.samplingRate(); - return LoggingService.builder() - .logWriter(LogWriter.builder() - .requestLogLevel(parameter.requestLogLevel()) - .successfulResponseLogLevel( - parameter.successfulResponseLogLevel()) - .failureResponseLogLevel(parameter.failureResponseLogLevel()) - .build()) - .successSamplingRate(successSamplingRate) - .failureSamplingRate(failureSamplingRate) - .newDecorator(); + final LogWriter logWriter = LogWriter.builder() + .requestLogLevel(parameter.requestLogLevel()) + .successfulResponseLogLevel(parameter.successfulResponseLogLevel()) + .failureResponseLogLevel(parameter.failureResponseLogLevel()) + .build(); + final LoggingServiceBuilder builder + = LoggingService.builder() + .logWriter(logWriter) + .successSamplingRate(successSamplingRate) + .failureSamplingRate(failureSamplingRate); + + if ( + parameter.slowRequestSamplingPercentile() >= 0.0f || + parameter.slowRequestSamplingUpperBoundMillis() >= 0 + ) { + builder.slowRequestSamplingPercentile(parameter.slowRequestSamplingPercentile(), + parameter.slowRequestSamplingWindowMillis(), + parameter.slowRequestSamplingLowerBoundMillis(), + parameter.slowRequestSamplingUpperBoundMillis()); + } + return builder.newDecorator(); } } diff --git a/core/src/main/java/com/linecorp/armeria/server/logging/LoggingService.java b/core/src/main/java/com/linecorp/armeria/server/logging/LoggingService.java index de34fd5054a..eded8d9c50c 100644 --- a/core/src/main/java/com/linecorp/armeria/server/logging/LoggingService.java +++ b/core/src/main/java/com/linecorp/armeria/server/logging/LoggingService.java @@ -61,17 +61,23 @@ public static LoggingServiceBuilder builder() { LoggingService(HttpService delegate, LogWriter logWriter, Sampler successSampler, - Sampler failureSampler) { + Sampler failureSampler, + Sampler slowRequestSampler) { super(requireNonNull(delegate, "delegate")); this.logWriter = requireNonNull(logWriter, "logWriter"); requireNonNull(successSampler, "successSampler"); requireNonNull(failureSampler, "failureSampler"); sampler = requestLog -> { final ServiceRequestContext ctx = (ServiceRequestContext) requestLog.context(); + final boolean isSlow = slowRequestSampler.isSampled(requestLog.totalDurationNanos()); + final boolean successOrFailure; if (ctx.config().successFunction().isSuccess(ctx, requestLog)) { - return successSampler.isSampled(ctx); + successOrFailure = successSampler.isSampled(ctx); + } else { + successOrFailure = failureSampler.isSampled(ctx); } - return failureSampler.isSampled(ctx); + + return successOrFailure || isSlow; }; } diff --git a/core/src/main/java/com/linecorp/armeria/server/logging/LoggingServiceBuilder.java b/core/src/main/java/com/linecorp/armeria/server/logging/LoggingServiceBuilder.java index 84934c2defd..ffc80313d87 100644 --- a/core/src/main/java/com/linecorp/armeria/server/logging/LoggingServiceBuilder.java +++ b/core/src/main/java/com/linecorp/armeria/server/logging/LoggingServiceBuilder.java @@ -19,6 +19,7 @@ import static com.google.common.base.Preconditions.checkArgument; import static java.util.Objects.requireNonNull; +import java.util.concurrent.TimeUnit; import java.util.function.BiFunction; import java.util.function.Function; import java.util.function.Predicate; @@ -50,6 +51,8 @@ public final class LoggingServiceBuilder extends LoggingDecoratorBuilder { private Sampler failureSampler = Sampler.always(); + private Sampler slowRequestSampler = Sampler.never(); + LoggingServiceBuilder() {} /** @@ -107,6 +110,14 @@ public LoggingServiceBuilder failureSampler( return this; } + /** + * Sets the {@link Sampler} that determines whether a request is slow enough to be logged. + */ + public LoggingServiceBuilder slowRequestSampler(Sampler slowRequestSampler) { + this.slowRequestSampler = requireNonNull(slowRequestSampler, "slowRequestSampler"); + return this; + } + /** * Sets the rate at which to sample requests to log. Any number between {@code 0.0} and {@code 1.0} will * cause a random sample of the failure requests to be logged. @@ -118,12 +129,71 @@ public LoggingServiceBuilder failureSamplingRate(float failureSamplingRate) { return failureSampler(Sampler.random(failureSamplingRate)); } + /** + * Sets conditions to sample slow requests. + * + *

If {slowRequestPercentile} is 0.99, {windowMilliseconds} is 60000, we will sample requests that are + * slower than 99% of the requests within 1-minute time window. This will make sure our sampling adapts the + * traffic pattern. For example, traffic can be very low during the night thus our average response time + * will be pretty low. Therefore, our p99s should be lower than the midday traffic. + * Otherwise, we won't log any p99s during night.

+ * + *

If we set {slowRequestSamplingLowerBoundMilliseconds} to 100, we won't sample any request that took + * less than 1000ms. This is useful to filter out requests that are too fast to be considered + * as slow requests. If your endpoint performs pretty healthy, you shouldn't see any slow request logs.

+ * + *

If we set {slowRequestSamplingUpperBoundMilliseconds} to 1000, we will sample any request that + * took more than 1000 milliseconds. This is useful to make sure we log slow requests even if + * they are not in the p99 percentile. If your service is unhealthy, this will make sure any slow request + * is logged into your system.

+ * + * @param slowRequestPercentile percentile of slow requests. + * @param windowMilliseconds window size to calculate percentile. + * @param slowRequestSamplingLowerBoundMilliseconds lower bound of slow requests. + * Any request that took less than this amount of time won't be sampled. + * @param slowRequestSamplingUpperBoundMilliseconds upper bound of slow requests. + * Any request that took more than this amount of time will be sampled regardless + * of their percentile. + * + */ + public LoggingServiceBuilder slowRequestSamplingPercentile(float slowRequestPercentile, + long windowMilliseconds, + long slowRequestSamplingLowerBoundMilliseconds, + long slowRequestSamplingUpperBoundMilliseconds) { + // Check if configuration is valid. A valid configuration requires at least one parameter to be set + // correctly. Either `slowRequestPercentile` or `slowRequestSamplingUpperBoundMilliseconds` should be + // set to a value that would trigger sampling. + if ((slowRequestPercentile <= 0.0 || windowMilliseconds <= 0) && + slowRequestSamplingUpperBoundMilliseconds == Long.MAX_VALUE) { + // Ignore the invalid configuration. + return this; + } + + // Samplers should use Nanoseconds as the unit. + final Sampler percentileMatches; + if (0.0 <= slowRequestPercentile && slowRequestPercentile <= 1.0) { + percentileMatches = Sampler.percentile(slowRequestPercentile, windowMilliseconds); + } else { + percentileMatches = Sampler.never(); + } + + final long slowEnoughNanos = TimeUnit.MILLISECONDS.toNanos(slowRequestSamplingLowerBoundMilliseconds); + final Sampler isSlowEnough = Sampler.greaterThanOrEqual(slowEnoughNanos); + + final long verySlowNanos = TimeUnit.MILLISECONDS.toNanos(slowRequestSamplingUpperBoundMilliseconds); + final Sampler isVerySlow = Sampler.greaterThan(verySlowNanos); + + return slowRequestSampler( + isVerySlow.or(isSlowEnough.and(percentileMatches)) + ); + } + /** * Returns a newly-created {@link LoggingService} decorating {@link HttpService} based on the properties * of this builder. */ public LoggingService build(HttpService delegate) { - return new LoggingService(delegate, logWriter(), successSampler, failureSampler); + return new LoggingService(delegate, logWriter(), successSampler, failureSampler, slowRequestSampler); } /** diff --git a/core/src/test/java/com/linecorp/armeria/common/util/SamplerTest.java b/core/src/test/java/com/linecorp/armeria/common/util/SamplerTest.java index 3e3c5302508..33deb9d21e2 100644 --- a/core/src/test/java/com/linecorp/armeria/common/util/SamplerTest.java +++ b/core/src/test/java/com/linecorp/armeria/common/util/SamplerTest.java @@ -88,4 +88,100 @@ void badOf() { assertThatThrownBy(() -> Sampler.of("rate-limiting=")).isInstanceOf(IllegalArgumentException.class); assertThatThrownBy(() -> Sampler.of("rate-limiting=x")).isInstanceOf(IllegalArgumentException.class); } + + @Test + void andOr() { + final Sampler alwaysAndAlwaysSampler = Sampler.always().and(Sampler.always()); + for (int i = 0; i < 10; i++) { + assertThat(alwaysAndAlwaysSampler.isSampled(i)).isTrue(); + } + + final Sampler alwaysOrAlwaysSampler = Sampler.always().or(Sampler.always()); + for (int i = 0; i < 10; i++) { + assertThat(alwaysOrAlwaysSampler.isSampled(i)).isTrue(); + } + + final Sampler neverOrAlwaysSampler = Sampler.never().or(Sampler.always()); + for (int i = 0; i < 10; i++) { + assertThat(neverOrAlwaysSampler.isSampled(i)).isTrue(); + } + + final Sampler neverAndAlwaysSampler = Sampler.never().and(Sampler.always()); + for (int i = 0; i < 10; i++) { + assertThat(neverAndAlwaysSampler.isSampled(i)).isFalse(); + } + + final Sampler notNeverSampler = Sampler.never().not(); + for (int i = 0; i < 10; i++) { + assertThat(notNeverSampler.isSampled(i)).isTrue(); + } + + final Sampler notAlwaysSampler = Sampler.always().not(); + for (int i = 0; i < 10; i++) { + assertThat(notAlwaysSampler.isSampled(i)).isFalse(); + } + } + + private static class SampleOnce implements Sampler { + int count; + + @Override + public boolean isSampled(Object object) { + return count++ == 0; + } + + public void reset() { + count = 0; + } + } + + @Test + void andOrNotShortCircuited() { + final SampleOnce first = new SampleOnce(); + final SampleOnce second = new SampleOnce(); + + assertThat(first.and(second).isSampled(0)).isTrue(); + assertThat(first.isSampled(0)).isFalse(); + assertThat(second.isSampled(0)).isFalse(); + + first.reset(); + second.reset(); + + assertThat(first.or(second).isSampled(0)).isTrue(); + assertThat(first.isSampled(0)).isFalse(); + assertThat(second.isSampled(0)).isFalse(); + + first.reset(); + second.reset(); + + assertThat(second.and(second).isSampled(0)).isFalse(); + } + + @Test + void compare() { + final Sampler greaterThanOne = Sampler.greaterThan(1); + assertThat(greaterThanOne.isSampled(0)).isFalse(); + assertThat(greaterThanOne.isSampled(1)).isFalse(); + assertThat(greaterThanOne.isSampled(2)).isTrue(); + + final Sampler greaterThanOrEqualOne = Sampler.greaterThanOrEqual(1); + assertThat(greaterThanOrEqualOne.isSampled(0)).isFalse(); + assertThat(greaterThanOrEqualOne.isSampled(1)).isTrue(); + assertThat(greaterThanOrEqualOne.isSampled(2)).isTrue(); + + final Sampler lessThanOne = Sampler.lessThan(1); + assertThat(lessThanOne.isSampled(0)).isTrue(); + assertThat(lessThanOne.isSampled(1)).isFalse(); + assertThat(lessThanOne.isSampled(2)).isFalse(); + + final Sampler lessThanOrEqualOne = Sampler.lessThanOrEqual(1); + assertThat(lessThanOrEqualOne.isSampled(0)).isTrue(); + assertThat(lessThanOrEqualOne.isSampled(1)).isTrue(); + assertThat(lessThanOrEqualOne.isSampled(2)).isFalse(); + + final Sampler equalOne = Sampler.equal(1); + assertThat(equalOne.isSampled(0)).isFalse(); + assertThat(equalOne.isSampled(1)).isTrue(); + assertThat(equalOne.isSampled(2)).isFalse(); + } } diff --git a/core/src/test/java/com/linecorp/armeria/common/util/TimeWindowPercentileSamplerTest.java b/core/src/test/java/com/linecorp/armeria/common/util/TimeWindowPercentileSamplerTest.java new file mode 100644 index 00000000000..50d21c2f9ce --- /dev/null +++ b/core/src/test/java/com/linecorp/armeria/common/util/TimeWindowPercentileSamplerTest.java @@ -0,0 +1,96 @@ +/* + * Copyright 2023 LINE Corporation + * + * LINE Corporation licenses this file to you 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: + * + * https://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.linecorp.armeria.common.util; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.concurrent.TimeUnit; + +import org.junit.jupiter.api.Test; + +public class TimeWindowPercentileSamplerTest { + @Test + public void testSamplingMinimumPercentile() { + final Sampler sampler = TimeWindowPercentileSampler.create(0.0f, + TimeUnit.SECONDS.toMillis(60), 0L); + + // Should sample everything + assertThat(sampler.isSampled(10L)).isTrue(); + assertThat(sampler.isSampled(20L)).isTrue(); + assertThat(sampler.isSampled(0L)).isTrue(); + } + + @Test + public void testSamplingMaximumPercentile() { + final Sampler sampler = TimeWindowPercentileSampler.create(1.0f, + TimeUnit.SECONDS.toMillis(60), 0L); + + // Should only sample the maximum value + assertThat(sampler.isSampled(10L)).isTrue(); + assertThat(sampler.isSampled(20L)).isTrue(); + assertThat(sampler.isSampled(0L)).isFalse(); + assertThat(sampler.isSampled(19L)).isFalse(); + assertThat(sampler.isSampled(20L)).isTrue(); + assertThat(sampler.isSampled(21L)).isTrue(); + assertThat(sampler.isSampled(20L)).isFalse(); + } + + @Test + public void testSamplingWindowExpires() throws InterruptedException { + final long windowLength = TimeUnit.SECONDS.toMillis(1); + final Sampler sampler = TimeWindowPercentileSampler.create(1.0f, windowLength, 0L); + + // Should only sample the maximum value + assertThat(sampler.isSampled(20L)).isTrue(); + assertThat(sampler.isSampled(19L)).isFalse(); + + // Sliding window expires, new maximum should be 19 + Thread.sleep(windowLength + 1L); + assertThat(sampler.isSampled(19L)).isTrue(); + } + + @Test + public void testSampling0_5Percentile() { + final Sampler sampler = TimeWindowPercentileSampler.create(.5f, + TimeUnit.SECONDS.toMillis(60), 0L); + + // Create a uniform distribution of 1000 values from 1 to 1000 + for (long i = 1; i <= 1000; i++) { + sampler.isSampled(i); + } + + // 0.5 percentile should be approximately 500 + assertThat(sampler.isSampled(501L)).isTrue(); + assertThat(sampler.isSampled(499L)).isFalse(); + } + + @Test + public void testSampling0_95Percentile() { + final Sampler sampler = TimeWindowPercentileSampler.create(.95f, + TimeUnit.SECONDS.toMillis(60), 0); + + // Create a uniform distribution of 1000 values from 1 to 1000 + for (long i = 1; i <= 1000; i++) { + sampler.isSampled(i); + } + + // 0.95 percentile is roughly 950, but not exactly + assertThat(sampler.isSampled(951L)).isTrue(); + assertThat(sampler.isSampled(952L)).isTrue(); + assertThat(sampler.isSampled(0L)).isFalse(); + } +} diff --git a/core/src/test/java/com/linecorp/armeria/internal/server/annotation/DecoratorAnnotationUtilTest.java b/core/src/test/java/com/linecorp/armeria/internal/server/annotation/DecoratorAnnotationUtilTest.java index d15fc0a8ecf..3570f8367b1 100644 --- a/core/src/test/java/com/linecorp/armeria/internal/server/annotation/DecoratorAnnotationUtilTest.java +++ b/core/src/test/java/com/linecorp/armeria/internal/server/annotation/DecoratorAnnotationUtilTest.java @@ -122,6 +122,24 @@ void ofUserDefinedRepeatableDecorator() throws NoSuchMethodException { assertThat(udd2.value()).isEqualTo(2); } + @Test + void ofSlowSamplingRequest() throws Exception { + final List list = + DecoratorAnnotationUtil.collectDecorators(TestClass.class, + TestClass.class.getMethod("slowRequestSampling")); + + assertThat(values(list)).containsExactly(Decorator1.class, + LoggingDecoratorFactoryFunction.class, + LoggingDecoratorFactoryFunction.class); + + final LoggingDecorator loggingDecorator = (LoggingDecorator) list.get(2).annotation(); + + assertThat(loggingDecorator.slowRequestSamplingPercentile()).isEqualTo(0.5f); + assertThat(loggingDecorator.slowRequestSamplingLowerBoundMillis()).isEqualTo(1L); + assertThat(loggingDecorator.slowRequestSamplingUpperBoundMillis()).isEqualTo(10L); + assertThat(loggingDecorator.slowRequestSamplingWindowMillis()).isEqualTo(100L); + } + private static List> values(List list) { return list.stream() .map(DecoratorAndOrder::annotation) @@ -189,6 +207,13 @@ public String globalScopeOrdering() { public String userDefinedRepeatableDecorator() { return ""; } + + @LoggingDecorator( + slowRequestSamplingPercentile = 0.5f, slowRequestSamplingLowerBoundMillis = 1L, + slowRequestSamplingUpperBoundMillis = 10L, slowRequestSamplingWindowMillis = 100L) + public String slowRequestSampling() { + return ""; + } } @Retention(RetentionPolicy.RUNTIME) diff --git a/core/src/test/java/com/linecorp/armeria/server/logging/LoggingServiceTest.java b/core/src/test/java/com/linecorp/armeria/server/logging/LoggingServiceTest.java index 1670c748f92..8c6389af071 100644 --- a/core/src/test/java/com/linecorp/armeria/server/logging/LoggingServiceTest.java +++ b/core/src/test/java/com/linecorp/armeria/server/logging/LoggingServiceTest.java @@ -52,6 +52,7 @@ import com.linecorp.armeria.common.logging.LogLevel; import com.linecorp.armeria.common.logging.LogWriter; import com.linecorp.armeria.common.logging.RegexBasedSanitizer; +import com.linecorp.armeria.common.util.Sampler; import com.linecorp.armeria.internal.common.logging.LoggingTestUtil; import com.linecorp.armeria.internal.testing.ImmediateEventLoop; import com.linecorp.armeria.server.HttpResponseException; @@ -659,4 +660,102 @@ void sanitizerAndLogWriterCanNotSetTogether() { .hasMessageContaining( "The logWriter and the log properties cannot be set together."); } + + @Test + void slowRequestSampler() throws Exception { + final ServiceRequestContext ctx = serviceRequestContext(); + final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause); + when(logger.isDebugEnabled()).thenReturn(true); + final LoggingService service = + LoggingService.builder() + .slowRequestSampler(Sampler.always()) + .logWriter(LogWriter.builder() + .logger(logger) + .build()) + .samplingRate(0.0f) + .newDecorator() + .apply(delegate); + + service.serve(ctx, ctx.request()); + + verify(logger).debug(matches(".*Response:.*totalDuration=.*")); + } + + @Test + void slowRequestSamplerNever() throws Exception { + final ServiceRequestContext ctx = serviceRequestContext(); + final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause); + final LoggingService service = + LoggingService.builder() + .slowRequestSampler(Sampler.never()) + .logWriter(LogWriter.builder() + .logger(logger) + .build()) + .samplingRate(0.0f) + .newDecorator() + .apply(delegate); + + service.serve(ctx, ctx.request()); + + verifyNoInteractions(logger); + } + + @Test + void slowRequestSamplerPercentage() throws Exception { + final ServiceRequestContext ctx = serviceRequestContext(); + final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause); + when(logger.isDebugEnabled()).thenReturn(true); + final LoggingService service = + LoggingService.builder() + .slowRequestSamplingPercentile(1.0f, 60_000L, 0L, Long.MAX_VALUE) + .logWriter(LogWriter.builder() + .logger(logger) + .build()) + .samplingRate(0.0f) + .newDecorator() + .apply(delegate); + + service.serve(ctx, ctx.request()); + + verify(logger).debug(matches(".*Response:.*totalDuration=.*")); + } + + @Test + void slowRequestSamplerUpperBound() throws Exception { + final ServiceRequestContext ctx = serviceRequestContext(); + final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause); + when(logger.isDebugEnabled()).thenReturn(true); + final LoggingService service = + LoggingService.builder() + .slowRequestSamplingPercentile(0.0f, 60_000L, 0L, 1L) + .logWriter(LogWriter.builder() + .logger(logger) + .build()) + .samplingRate(0.0f) + .newDecorator() + .apply(delegate); + + service.serve(ctx, ctx.request()); + + verify(logger).debug(matches(".*Response:.*totalDuration=.*")); + } + + @Test + void slowRequestSamplerLowerBound() throws Exception { + final ServiceRequestContext ctx = serviceRequestContext(); + final Logger logger = LoggingTestUtil.newMockLogger(ctx, capturedCause); + final LoggingService service = + LoggingService.builder() + .slowRequestSamplingPercentile(1.0f, 60_000L, 10000L, Long.MAX_VALUE) + .logWriter(LogWriter.builder() + .logger(logger) + .build()) + .samplingRate(0.0f) + .newDecorator() + .apply(delegate); + + service.serve(ctx, ctx.request()); + + verifyNoInteractions(logger); + } }