Repository: cassandra Updated Branches: refs/heads/cassandra-2.1 739f3e37c -> e6f027979
Introduce NoSpamLogger patch by ariel; reviewed by benedict for CASSANDRA-9029 Project: http://git-wip-us.apache.org/repos/asf/cassandra/repo Commit: http://git-wip-us.apache.org/repos/asf/cassandra/commit/5bffaf85 Tree: http://git-wip-us.apache.org/repos/asf/cassandra/tree/5bffaf85 Diff: http://git-wip-us.apache.org/repos/asf/cassandra/diff/5bffaf85 Branch: refs/heads/cassandra-2.1 Commit: 5bffaf850ca3e978baaa8664acc65612d7460d3f Parents: 739f3e3 Author: Ariel Weisberg <ariel.wesib...@datastax.com> Authored: Fri Apr 3 23:27:10 2015 +0100 Committer: T Jake Luciani <j...@apache.org> Committed: Mon May 4 12:21:59 2015 -0400 ---------------------------------------------------------------------- .../apache/cassandra/utils/NoSpamLogger.java | 238 +++++++++++++++++++ .../cassandra/utils/NoSpamLoggerTest.java | 174 ++++++++++++++ 2 files changed, 412 insertions(+) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/cassandra/blob/5bffaf85/src/java/org/apache/cassandra/utils/NoSpamLogger.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/utils/NoSpamLogger.java b/src/java/org/apache/cassandra/utils/NoSpamLogger.java new file mode 100644 index 0000000..9f5d5ce --- /dev/null +++ b/src/java/org/apache/cassandra/utils/NoSpamLogger.java @@ -0,0 +1,238 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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 + * + * 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 org.apache.cassandra.utils; + +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; + +import org.cliffc.high_scale_lib.NonBlockingHashMap; +import org.slf4j.Logger; + +import com.google.common.annotations.VisibleForTesting; + +/** + * Logging that limits each log statement to firing based on time since the statement last fired. + * + * Every logger has a unique timer per statement. Minimum time between logging is set for each statement + * the first time it is used and a subsequent attempt to request that statement with a different minimum time will + * result in the original time being used. No warning is provided if there is a mismatch. + * + * If the statement is cached and used to log directly then only a volatile read will be required in the common case. + * If the Logger is cached then there is a single concurrent hash map lookup + the volatile read. + * If neither the logger nor the statement is cached then it is two concurrent hash map lookups + the volatile read. + * + */ +public class NoSpamLogger +{ + /** + * Levels for programmatically specifying the severity of a log statement + */ + public enum Level + { + INFO, WARN, ERROR; + } + + @VisibleForTesting + static interface Clock + { + long nanoTime(); + } + + @VisibleForTesting + static Clock CLOCK = new Clock() + { + public long nanoTime() + { + return System.nanoTime(); + } + }; + + public class NoSpamLogStatement extends AtomicLong + { + private static final long serialVersionUID = 1L; + + private final String statement; + private final long minIntervalNanos; + + public NoSpamLogStatement(String statement, long minIntervalNanos) + { + this.statement = statement; + this.minIntervalNanos = minIntervalNanos; + } + + private boolean shouldLog(long nowNanos) + { + long expected = get(); + return nowNanos - expected >= minIntervalNanos && compareAndSet(expected, nowNanos); + } + + public void log(Level l, long nowNanos, Object... objects) + { + if (!shouldLog(nowNanos)) return; + + switch (l) + { + case INFO: + wrapped.info(statement, objects); + break; + case WARN: + wrapped.warn(statement, objects); + break; + case ERROR: + wrapped.error(statement, objects); + break; + default: + throw new AssertionError(); + } + } + + public void info(long nowNanos, Object... objects) + { + log(Level.INFO, nowNanos, objects); + } + + public void info(Object... objects) + { + info(CLOCK.nanoTime(), objects); + } + + public void warn(long nowNanos, Object... objects) + { + log(Level.WARN, nowNanos, objects); + } + + public void warn(String s, Object... objects) + { + warn(CLOCK.nanoTime(), s, objects); + } + + public void error(long nowNanos, Object... objects) + { + log(Level.ERROR, nowNanos, objects); + } + + public void error(Object... objects) + { + error(CLOCK.nanoTime(), objects); + } + } + + private static final NonBlockingHashMap<Logger, NoSpamLogger> wrappedLoggers = new NonBlockingHashMap<>(); + + @VisibleForTesting + static void clearWrappedLoggersForTest() + { + wrappedLoggers.clear(); + } + + public static NoSpamLogger getLogger(Logger logger, long minInterval, TimeUnit unit) + { + NoSpamLogger wrapped = wrappedLoggers.get(logger); + if (wrapped == null) + { + wrapped = new NoSpamLogger(logger, minInterval, unit); + NoSpamLogger temp = wrappedLoggers.putIfAbsent(logger, wrapped); + if (temp != null) + wrapped = temp; + } + return wrapped; + } + + public static void log(Logger logger, Level level, long minInterval, TimeUnit unit, String message, Object... objects) + { + log(logger, level, minInterval, unit, CLOCK.nanoTime(), message, objects); + } + + public static void log(Logger logger, Level level, long minInterval, TimeUnit unit, long nowNanos, String message, Object... objects) + { + NoSpamLogger wrapped = getLogger(logger, minInterval, unit); + NoSpamLogStatement statement = wrapped.getStatement(message); + statement.log(level, nowNanos, objects); + } + + public static NoSpamLogStatement getStatement(Logger logger, String message, long minInterval, TimeUnit unit) { + NoSpamLogger wrapped = getLogger(logger, minInterval, unit); + return wrapped.getStatement(message); + } + + private final Logger wrapped; + private final long minIntervalNanos; + private final NonBlockingHashMap<String, NoSpamLogStatement> lastMessage = new NonBlockingHashMap<>(); + + private NoSpamLogger(Logger wrapped, long minInterval, TimeUnit timeUnit) + { + this.wrapped = wrapped; + minIntervalNanos = timeUnit.toNanos(minInterval); + } + + public void info(long nowNanos, String s, Object... objects) + { + log( Level.INFO, s, nowNanos, objects); + } + + public void info(String s, Object... objects) + { + info(CLOCK.nanoTime(), s, objects); + } + + public void warn(long nowNanos, String s, Object... objects) + { + log( Level.WARN, s, nowNanos, objects); + } + + public void warn(String s, Object... objects) + { + warn(CLOCK.nanoTime(), s, objects); + } + + public void error(long nowNanos, String s, Object... objects) + { + log( Level.ERROR, s, nowNanos, objects); + } + + public void error(String s, Object... objects) + { + error(CLOCK.nanoTime(), s, objects); + } + + public void log(Level l, String s, long nowNanos, Object... objects) { + getStatement(s, minIntervalNanos).log(l, nowNanos, objects); + } + + public NoSpamLogStatement getStatement(String s) + { + return getStatement(s, minIntervalNanos); + } + + public NoSpamLogStatement getStatement(String s, long minInterval, TimeUnit unit) { + return getStatement(s, unit.toNanos(minInterval)); + } + + public NoSpamLogStatement getStatement(String s, long minIntervalNanos) + { + NoSpamLogStatement statement = lastMessage.get(s); + if (statement == null) + { + statement = new NoSpamLogStatement(s, minIntervalNanos); + NoSpamLogStatement temp = lastMessage.putIfAbsent(s, statement); + if (temp != null) + statement = temp; + } + return statement; + } +} http://git-wip-us.apache.org/repos/asf/cassandra/blob/5bffaf85/test/unit/org/apache/cassandra/utils/NoSpamLoggerTest.java ---------------------------------------------------------------------- diff --git a/test/unit/org/apache/cassandra/utils/NoSpamLoggerTest.java b/test/unit/org/apache/cassandra/utils/NoSpamLoggerTest.java new file mode 100644 index 0000000..3ad7ab8 --- /dev/null +++ b/test/unit/org/apache/cassandra/utils/NoSpamLoggerTest.java @@ -0,0 +1,174 @@ +/* +* Licensed to the Apache Software Foundation (ASF) under one +* or more contributor license agreements. See the NOTICE file +* distributed with this work for additional information +* regarding copyright ownership. The ASF 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 +* +* 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 org.apache.cassandra.utils; + +import static org.junit.Assert.*; + +import java.util.ArrayList; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.concurrent.TimeUnit; + +import org.apache.cassandra.utils.NoSpamLogger.Level; +import org.apache.cassandra.utils.NoSpamLogger.NoSpamLogStatement; +import org.junit.Before; +import org.junit.BeforeClass; +import org.junit.Test; +import org.slf4j.Logger; +import org.slf4j.helpers.SubstituteLogger; + + +public class NoSpamLoggerTest +{ + Map<Level, List<Pair<String, Object[]>>> logged = new HashMap<>(); + + Logger mock = new SubstituteLogger(null) + { + + @Override + public void info(String statement, Object... args) + { + logged.get(Level.INFO).add(Pair.create(statement, args)); + } + + @Override + public void warn(String statement, Object... args) + { + logged.get(Level.WARN).add(Pair.create(statement, args)); + } + + @Override + public void error(String statement, Object... args) + { + logged.get(Level.ERROR).add(Pair.create(statement, args)); + } + + @Override + public int hashCode() + { + return 42;//It's a valid hash code + } + + @Override + public boolean equals(Object o) + { + return this == o; + } + }; + + + static long now; + + @BeforeClass + public static void setUpClass() throws Exception + { + NoSpamLogger.CLOCK = new NoSpamLogger.Clock() + { + @Override + public long nanoTime() + { + return now; + } + }; + } + + @Before + public void setUp() throws Exception + { + logged.put(Level.INFO, new ArrayList<Pair<String, Object[]>>()); + logged.put(Level.WARN, new ArrayList<Pair<String, Object[]>>()); + logged.put(Level.ERROR, new ArrayList<Pair<String, Object[]>>()); + } + + @Test + public void testNoSpamLogger() throws Exception + { + testLevel(Level.INFO); + testLevel(Level.WARN); + testLevel(Level.ERROR); + } + + private void testLevel(Level l) throws Exception + { + setUp(); + now = 5; + NoSpamLogger.clearWrappedLoggersForTest(); + + NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, "swizzle{}", "a"); + + assertEquals(1, logged.get(l).size()); + + NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, "swizzle{}", "a"); + + assertEquals(1, logged.get(l).size()); + + now += 5; + + NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, "swizzle{}", "a"); + + assertEquals(2, logged.get(l).size()); + } + + private void assertLoggedSizes(int info, int warn, int error) + { + assertEquals(info, logged.get(Level.INFO).size()); + assertEquals(warn, logged.get(Level.WARN).size()); + assertEquals(error, logged.get(Level.ERROR).size()); + } + + @Test + public void testNoSpamLoggerDirect() throws Exception + { + now = 5; + NoSpamLogger logger = NoSpamLogger.getLogger( mock, 5, TimeUnit.NANOSECONDS); + + logger.info("swizzle{}", "a"); + logger.info("swizzle{}", "a"); + logger.warn("swizzle{}", "a"); + logger.error("swizzle{}", "a"); + + assertLoggedSizes(1, 0, 0); + + NoSpamLogStatement statement = logger.getStatement("swizzle2{}", 10, TimeUnit.NANOSECONDS); + statement.warn("a"); + //now is 5 so it won't log + assertLoggedSizes(1, 0, 0); + + now = 10; + statement.warn("a"); + assertLoggedSizes(1, 1, 0); + + } + + @Test + public void testNoSpamLoggerStatementDirect() throws Exception + { + NoSpamLogger.NoSpamLogStatement statement = NoSpamLogger.getStatement( mock, "swizzle{}", 5, TimeUnit.NANOSECONDS); + + now = 5; + + statement.info("swizzle{}", "a"); + statement.info("swizzle{}", "a"); + statement.warn("swizzle{}", "a"); + statement.error("swizzle{}", "a"); + + assertLoggedSizes(1, 0, 0); + } +}
