Repository: cassandra Updated Branches: refs/heads/trunk c8d3cc149 -> cb062839f
Utilise NoSpamLogger for rate limited logging patch by ariel; reviewed by benedict for CASSANDRA-8584 Project: http://git-wip-us.apache.org/repos/asf/cassandra/repo Commit: http://git-wip-us.apache.org/repos/asf/cassandra/commit/cb062839 Tree: http://git-wip-us.apache.org/repos/asf/cassandra/tree/cb062839 Diff: http://git-wip-us.apache.org/repos/asf/cassandra/diff/cb062839 Branch: refs/heads/trunk Commit: cb062839ff2480dd868a82ec37e54d502e82fc0d Parents: c8d3cc1 Author: ariel <[email protected]> Authored: Wed Jun 24 12:07:56 2015 +0100 Committer: Benedict Elliott Smith <[email protected]> Committed: Wed Jun 24 12:07:56 2015 +0100 ---------------------------------------------------------------------- .../db/commitlog/AbstractCommitLogService.java | 18 ++++-- .../db/commitlog/MemoryMappedSegment.java | 2 +- .../cassandra/io/sstable/SSTableRewriter.java | 3 +- .../apache/cassandra/io/util/SegmentedFile.java | 2 +- .../org/apache/cassandra/utils/CLibrary.java | 24 +++++--- .../apache/cassandra/utils/NoSpamLogger.java | 65 ++++++++++---------- .../apache/cassandra/utils/CLibraryTest.java | 2 +- .../cassandra/utils/NoSpamLoggerTest.java | 44 ++++++------- 8 files changed, 89 insertions(+), 71 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/src/java/org/apache/cassandra/db/commitlog/AbstractCommitLogService.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/db/commitlog/AbstractCommitLogService.java b/src/java/org/apache/cassandra/db/commitlog/AbstractCommitLogService.java index 2a55600..3479440 100644 --- a/src/java/org/apache/cassandra/db/commitlog/AbstractCommitLogService.java +++ b/src/java/org/apache/cassandra/db/commitlog/AbstractCommitLogService.java @@ -17,6 +17,7 @@ */ package org.apache.cassandra.db.commitlog; +import org.apache.cassandra.utils.NoSpamLogger; import org.apache.cassandra.utils.concurrent.WaitQueue; import org.slf4j.*; @@ -28,8 +29,6 @@ import static org.apache.cassandra.db.commitlog.CommitLogSegment.Allocation; public abstract class AbstractCommitLogService { - // how often should we log syngs that lag behind our desired period - private static final long LAG_REPORT_INTERVAL = TimeUnit.MINUTES.toMillis(5); private Thread thread; private volatile boolean shutdown = false; @@ -112,11 +111,18 @@ public abstract class AbstractCommitLogService syncCount++; totalSyncDuration += now - syncStarted; - if (firstLagAt > 0 && now - firstLagAt >= LAG_REPORT_INTERVAL) + if (firstLagAt > 0) { - logger.warn(String.format("Out of %d commit log syncs over the past %ds with average duration of %.2fms, %d have exceeded the configured commit interval by an average of %.2fms", - syncCount, (now - firstLagAt) / 1000, (double) totalSyncDuration / syncCount, lagCount, (double) syncExceededIntervalBy / lagCount)); - firstLagAt = 0; + //Only reset the lag tracking if it actually logged this time + boolean logged = NoSpamLogger.log( + logger, + NoSpamLogger.Level.WARN, + 5, + TimeUnit.MINUTES, + "Out of {} commit log syncs over the past {}s with average duration of {}ms, {} have exceeded the configured commit interval by an average of {}ms", + syncCount, (now - firstLagAt) / 1000, String.format("%.2f", (double) totalSyncDuration / syncCount), lagCount, String.format("%.2f", (double) syncExceededIntervalBy / lagCount)); + if (logged) + firstLagAt = 0; } // if we have lagged this round, we probably have work to do already so we don't sleep http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/src/java/org/apache/cassandra/db/commitlog/MemoryMappedSegment.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/db/commitlog/MemoryMappedSegment.java b/src/java/org/apache/cassandra/db/commitlog/MemoryMappedSegment.java index e240a91..3a52e11 100644 --- a/src/java/org/apache/cassandra/db/commitlog/MemoryMappedSegment.java +++ b/src/java/org/apache/cassandra/db/commitlog/MemoryMappedSegment.java @@ -99,7 +99,7 @@ public class MemoryMappedSegment extends CommitLogSegment { throw new FSWriteError(e, getPath()); } - CLibrary.trySkipCache(fd, startMarker, nextMarker); + CLibrary.trySkipCache(fd, startMarker, nextMarker, logFile.getAbsolutePath()); } @Override http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/src/java/org/apache/cassandra/io/sstable/SSTableRewriter.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/io/sstable/SSTableRewriter.java b/src/java/org/apache/cassandra/io/sstable/SSTableRewriter.java index 011c7d9..9497bf3 100644 --- a/src/java/org/apache/cassandra/io/sstable/SSTableRewriter.java +++ b/src/java/org/apache/cassandra/io/sstable/SSTableRewriter.java @@ -17,6 +17,7 @@ */ package org.apache.cassandra.io.sstable; +import java.io.File; import java.util.*; import com.google.common.annotations.VisibleForTesting; @@ -160,7 +161,7 @@ public class SSTableRewriter extends Transactional.AbstractTransactional impleme for (SSTableReader reader : transaction.originals()) { RowIndexEntry index = reader.getPosition(key, SSTableReader.Operator.GE); - CLibrary.trySkipCache(fileDescriptors.get(reader.descriptor), 0, index == null ? 0 : index.position); + CLibrary.trySkipCache(fileDescriptors.get(reader.descriptor), 0, index == null ? 0 : index.position, reader.getFilename()); } } else http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/src/java/org/apache/cassandra/io/util/SegmentedFile.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/io/util/SegmentedFile.java b/src/java/org/apache/cassandra/io/util/SegmentedFile.java index fbaa77c..d9d384b 100644 --- a/src/java/org/apache/cassandra/io/util/SegmentedFile.java +++ b/src/java/org/apache/cassandra/io/util/SegmentedFile.java @@ -127,7 +127,7 @@ public abstract class SegmentedFile extends SharedCloseableImpl public void dropPageCache(long before) { - CLibrary.trySkipCache(channel.getFileDescriptor(), 0, before); + CLibrary.trySkipCache(channel.getFileDescriptor(), 0, before, path()); } /** http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/src/java/org/apache/cassandra/utils/CLibrary.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/utils/CLibrary.java b/src/java/org/apache/cassandra/utils/CLibrary.java index fed314b..645a4ce 100644 --- a/src/java/org/apache/cassandra/utils/CLibrary.java +++ b/src/java/org/apache/cassandra/utils/CLibrary.java @@ -19,17 +19,18 @@ package org.apache.cassandra.utils; import java.io.FileDescriptor; import java.io.IOException; -import java.io.RandomAccessFile; import java.lang.reflect.Field; import java.nio.channels.FileChannel; import java.nio.file.Paths; import java.nio.file.StandardOpenOption; +import java.util.concurrent.TimeUnit; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import com.sun.jna.LastErrorException; import com.sun.jna.Native; +import com.sun.jna.Pointer; public final class CLibrary { @@ -86,6 +87,7 @@ public final class CLibrary private static native int open(String path, int flags) throws LastErrorException; private static native int fsync(int fd) throws LastErrorException; private static native int close(int fd) throws LastErrorException; + private static native Pointer strerror(int errnum) throws LastErrorException; private static int errno(RuntimeException e) { @@ -146,24 +148,24 @@ public final class CLibrary public static void trySkipCache(String path, long offset, long len) { - trySkipCache(getfd(path), offset, len); + trySkipCache(getfd(path), offset, len, path); } - public static void trySkipCache(int fd, long offset, long len) + public static void trySkipCache(int fd, long offset, long len, String path) { if (len == 0) - trySkipCache(fd, 0, 0); + trySkipCache(fd, 0, 0, path); while (len > 0) { int sublen = (int) Math.min(Integer.MAX_VALUE, len); - trySkipCache(fd, offset, sublen); + trySkipCache(fd, offset, sublen, path); len -= sublen; offset -= sublen; } } - public static void trySkipCache(int fd, long offset, int len) + public static void trySkipCache(int fd, long offset, int len, String path) { if (fd < 0) return; @@ -172,7 +174,15 @@ public final class CLibrary { if (System.getProperty("os.name").toLowerCase().contains("linux")) { - posix_fadvise(fd, offset, len, POSIX_FADV_DONTNEED); + int result = posix_fadvise(fd, offset, len, POSIX_FADV_DONTNEED); + if (result != 0) + NoSpamLogger.log( + logger, + NoSpamLogger.Level.WARN, + 10, + TimeUnit.MINUTES, + "Failed trySkipCache on file: {} Error: " + strerror(result).getString(0), + path); } } catch (UnsatisfiedLinkError e) http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/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 index 3cc8b5e..84bfa68 100644 --- a/src/java/org/apache/cassandra/utils/NoSpamLogger.java +++ b/src/java/org/apache/cassandra/utils/NoSpamLogger.java @@ -81,9 +81,9 @@ public class NoSpamLogger return nowNanos - expected >= minIntervalNanos && compareAndSet(expected, nowNanos); } - public void log(Level l, long nowNanos, Object... objects) + public boolean log(Level l, long nowNanos, Object... objects) { - if (!shouldLog(nowNanos)) return; + if (!shouldLog(nowNanos)) return false; switch (l) { @@ -99,36 +99,37 @@ public class NoSpamLogger default: throw new AssertionError(); } + return true; } - public void info(long nowNanos, Object... objects) + public boolean info(long nowNanos, Object... objects) { - NoSpamLogStatement.this.log(Level.INFO, nowNanos, objects); + return NoSpamLogStatement.this.log(Level.INFO, nowNanos, objects); } - public void info(Object... objects) + public boolean info(Object... objects) { - NoSpamLogStatement.this.info(CLOCK.nanoTime(), objects); + return NoSpamLogStatement.this.info(CLOCK.nanoTime(), objects); } - public void warn(long nowNanos, Object... objects) + public boolean warn(long nowNanos, Object... objects) { - NoSpamLogStatement.this.log(Level.WARN, nowNanos, objects); + return NoSpamLogStatement.this.log(Level.WARN, nowNanos, objects); } - public void warn(Object... objects) + public boolean warn(Object... objects) { - NoSpamLogStatement.this.warn(CLOCK.nanoTime(), objects); + return NoSpamLogStatement.this.warn(CLOCK.nanoTime(), objects); } - public void error(long nowNanos, Object... objects) + public boolean error(long nowNanos, Object... objects) { - NoSpamLogStatement.this.log(Level.ERROR, nowNanos, objects); + return NoSpamLogStatement.this.log(Level.ERROR, nowNanos, objects); } - public void error(Object... objects) + public boolean error(Object... objects) { - NoSpamLogStatement.this.error(CLOCK.nanoTime(), objects); + return NoSpamLogStatement.this.error(CLOCK.nanoTime(), objects); } } @@ -153,16 +154,16 @@ public class NoSpamLogger return wrapped; } - public static void log(Logger logger, Level level, long minInterval, TimeUnit unit, String message, Object... objects) + public static boolean log(Logger logger, Level level, long minInterval, TimeUnit unit, String message, Object... objects) { - log(logger, level, minInterval, unit, CLOCK.nanoTime(), message, objects); + return 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) + public static boolean 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); + return statement.log(level, nowNanos, objects); } public static NoSpamLogStatement getStatement(Logger logger, String message, long minInterval, TimeUnit unit) @@ -181,38 +182,38 @@ public class NoSpamLogger minIntervalNanos = timeUnit.toNanos(minInterval); } - public void info(long nowNanos, String s, Object... objects) + public boolean info(long nowNanos, String s, Object... objects) { - NoSpamLogger.this.log( Level.INFO, s, nowNanos, objects); + return NoSpamLogger.this.log( Level.INFO, s, nowNanos, objects); } - public void info(String s, Object... objects) + public boolean info(String s, Object... objects) { - NoSpamLogger.this.info(CLOCK.nanoTime(), s, objects); + return NoSpamLogger.this.info(CLOCK.nanoTime(), s, objects); } - public void warn(long nowNanos, String s, Object... objects) + public boolean warn(long nowNanos, String s, Object... objects) { - NoSpamLogger.this.log( Level.WARN, s, nowNanos, objects); + return NoSpamLogger.this.log( Level.WARN, s, nowNanos, objects); } - public void warn(String s, Object... objects) + public boolean warn(String s, Object... objects) { - NoSpamLogger.this.warn(CLOCK.nanoTime(), s, objects); + return NoSpamLogger.this.warn(CLOCK.nanoTime(), s, objects); } - public void error(long nowNanos, String s, Object... objects) + public boolean error(long nowNanos, String s, Object... objects) { - NoSpamLogger.this.log( Level.ERROR, s, nowNanos, objects); + return NoSpamLogger.this.log( Level.ERROR, s, nowNanos, objects); } - public void error(String s, Object... objects) + public boolean error(String s, Object... objects) { - NoSpamLogger.this.error(CLOCK.nanoTime(), s, objects); + return NoSpamLogger.this.error(CLOCK.nanoTime(), s, objects); } - public void log(Level l, String s, long nowNanos, Object... objects) { - NoSpamLogger.this.getStatement(s, minIntervalNanos).log(l, nowNanos, objects); + public boolean log(Level l, String s, long nowNanos, Object... objects) { + return NoSpamLogger.this.getStatement(s, minIntervalNanos).log(l, nowNanos, objects); } public NoSpamLogStatement getStatement(String s) http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/test/unit/org/apache/cassandra/utils/CLibraryTest.java ---------------------------------------------------------------------- diff --git a/test/unit/org/apache/cassandra/utils/CLibraryTest.java b/test/unit/org/apache/cassandra/utils/CLibraryTest.java index be52bed..774ddac 100644 --- a/test/unit/org/apache/cassandra/utils/CLibraryTest.java +++ b/test/unit/org/apache/cassandra/utils/CLibraryTest.java @@ -32,6 +32,6 @@ public class CLibraryTest File file = FileUtils.createTempFile("testSkipCache", "1"); int fd = CLibrary.getfd(file.getPath()); - CLibrary.trySkipCache(fd, 0, 0); + CLibrary.trySkipCache(fd, 0, 0, file.getPath()); } } http://git-wip-us.apache.org/repos/asf/cassandra/blob/cb062839/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 index 0a5a005..afe4968 100644 --- a/test/unit/org/apache/cassandra/utils/NoSpamLoggerTest.java +++ b/test/unit/org/apache/cassandra/utils/NoSpamLoggerTest.java @@ -113,17 +113,17 @@ public class NoSpamLoggerTest setUp(); now = 5; - NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, statement, param); + assertTrue(NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, statement, param)); assertEquals(1, logged.get(l).size()); - NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, statement, param); + assertFalse(NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, statement, param)); assertEquals(1, logged.get(l).size()); now += 5; - NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, statement, param); + assertTrue(NoSpamLogger.log( mock, l, 5, TimeUnit.NANOSECONDS, statement, param)); assertEquals(2, logged.get(l).size()); } @@ -141,20 +141,20 @@ public class NoSpamLoggerTest now = 5; NoSpamLogger logger = NoSpamLogger.getLogger( mock, 5, TimeUnit.NANOSECONDS); - logger.info(statement, param); - logger.info(statement, param); - logger.warn(statement, param); - logger.error(statement, param); + assertTrue(logger.info(statement, param)); + assertFalse(logger.info(statement, param)); + assertFalse(logger.warn(statement, param)); + assertFalse(logger.error(statement, param)); assertLoggedSizes(1, 0, 0); NoSpamLogStatement statement = logger.getStatement("swizzle2{}", 10, TimeUnit.NANOSECONDS); - statement.warn(param); + assertFalse(statement.warn(param)); //now is 5 so it won't log assertLoggedSizes(1, 0, 0); now = 10; - statement.warn(param); + assertTrue(statement.warn(param)); assertLoggedSizes(1, 1, 0); } @@ -166,10 +166,10 @@ public class NoSpamLoggerTest now = 5; - nospam.info(statement, param); - nospam.info(statement, param); - nospam.warn(statement, param); - nospam.error(statement, param); + assertTrue(nospam.info(statement, param)); + assertFalse(nospam.info(statement, param)); + assertFalse(nospam.warn(statement, param)); + assertFalse(nospam.error(statement, param)); assertLoggedSizes(1, 0, 0); } @@ -193,51 +193,51 @@ public class NoSpamLoggerTest { now = 5; - NoSpamLogger.log( mock, Level.INFO, 5, TimeUnit.NANOSECONDS, statement, param); + assertTrue(NoSpamLogger.log( mock, Level.INFO, 5, TimeUnit.NANOSECONDS, statement, param)); checkMock(Level.INFO); now = 10; - NoSpamLogger.log( mock, Level.WARN, 5, TimeUnit.NANOSECONDS, statement, param); + assertTrue(NoSpamLogger.log( mock, Level.WARN, 5, TimeUnit.NANOSECONDS, statement, param)); checkMock(Level.WARN); now = 15; - NoSpamLogger.log( mock, Level.ERROR, 5, TimeUnit.NANOSECONDS, statement, param); + assertTrue(NoSpamLogger.log( mock, Level.ERROR, 5, TimeUnit.NANOSECONDS, statement, param)); checkMock(Level.ERROR); now = 20; NoSpamLogger logger = NoSpamLogger.getLogger(mock, 5, TimeUnit.NANOSECONDS); - logger.info(statement, param); + assertTrue(logger.info(statement, param)); checkMock(Level.INFO); now = 25; - logger.warn(statement, param); + assertTrue(logger.warn(statement, param)); checkMock(Level.WARN); now = 30; - logger.error(statement, param); + assertTrue(logger.error(statement, param)); checkMock(Level.ERROR); NoSpamLogger.NoSpamLogStatement nospamStatement = logger.getStatement(statement); now = 35; - nospamStatement.info(param); + assertTrue(nospamStatement.info(param)); checkMock(Level.INFO); now = 40; - nospamStatement.warn(param); + assertTrue(nospamStatement.warn(param)); checkMock(Level.WARN); now = 45; - nospamStatement.error(param); + assertTrue(nospamStatement.error(param)); checkMock(Level.ERROR); } }
