You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by be...@apache.org on 2015/06/24 13:08:14 UTC
cassandra git commit: Utilise NoSpamLogger for rate limited logging
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 <ar...@datastax.com>
Authored: Wed Jun 24 12:07:56 2015 +0100
Committer: Benedict Elliott Smith <be...@apache.org>
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);
}
}