You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@bookkeeper.apache.org by mm...@apache.org on 2016/11/12 02:37:42 UTC
bookkeeper git commit: BOOKKEEPER-962: Add more journal timing stats
Repository: bookkeeper
Updated Branches:
refs/heads/master 7673febb6 -> 2ba9a2c4f
BOOKKEEPER-962: Add more journal timing stats
It is useful to know the sync latency on the journal to identify disk/filesystem
related latency spikes that will cause all the entries to queue up. In the same
line, it's useful to track the amount of time spent in the journal queue.
Author: Matteo Merli <mm...@yahoo-inc.com>
Reviewers: Sijie Guo <si...@apache.org>
Closes #70 from merlimat/bk-journal-latency
Project: http://git-wip-us.apache.org/repos/asf/bookkeeper/repo
Commit: http://git-wip-us.apache.org/repos/asf/bookkeeper/commit/2ba9a2c4
Tree: http://git-wip-us.apache.org/repos/asf/bookkeeper/tree/2ba9a2c4
Diff: http://git-wip-us.apache.org/repos/asf/bookkeeper/diff/2ba9a2c4
Branch: refs/heads/master
Commit: 2ba9a2c4f7192ec0abaccdfd334025b4ddb9da66
Parents: 7673feb
Author: Matteo Merli <mm...@apache.org>
Authored: Fri Nov 11 18:37:35 2016 -0800
Committer: Matteo Merli <mm...@apache.org>
Committed: Fri Nov 11 18:37:35 2016 -0800
----------------------------------------------------------------------
.../bookie/BookKeeperServerStats.java | 3 +++
.../org/apache/bookkeeper/bookie/Journal.java | 22 ++++++++++++++++++++
2 files changed, 25 insertions(+)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/bookkeeper/blob/2ba9a2c4/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BookKeeperServerStats.java
----------------------------------------------------------------------
diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BookKeeperServerStats.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BookKeeperServerStats.java
index c7919f7..239f923 100644
--- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BookKeeperServerStats.java
+++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BookKeeperServerStats.java
@@ -46,12 +46,15 @@ public interface BookKeeperServerStats {
// Journal Stats
public final static String JOURNAL_SCOPE = "journal";
public final static String JOURNAL_ADD_ENTRY = "JOURNAL_ADD_ENTRY";
+ public final static String JOURNAL_SYNC = "JOURNAL_SYNC";
public final static String JOURNAL_MEM_ADD_ENTRY = "JOURNAL_MEM_ADD_ENTRY";
public final static String JOURNAL_PREALLOCATION = "JOURNAL_PREALLOCATION";
public final static String JOURNAL_FORCE_WRITE_LATENCY = "JOURNAL_FORCE_WRITE_LATENCY";
public final static String JOURNAL_FORCE_WRITE_BATCH_ENTRIES = "JOURNAL_FORCE_WRITE_BATCH_ENTRIES";
public final static String JOURNAL_FORCE_WRITE_BATCH_BYTES = "JOURNAL_FORCE_WRITE_BATCH_BYTES";
public final static String JOURNAL_FLUSH_LATENCY = "JOURNAL_FLUSH_LATENCY";
+ public final static String JOURNAL_QUEUE_LATENCY = "JOURNAL_QUEUE_LATENCY";
+ public final static String JOURNAL_PROCESS_TIME_LATENCY = "JOURNAL_PROCESS_TIME_LATENCY";
public final static String JOURNAL_CREATION_LATENCY = "JOURNAL_CREATION_LATENCY";
// Ledger Storage Stats
http://git-wip-us.apache.org/repos/asf/bookkeeper/blob/2ba9a2c4/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java
----------------------------------------------------------------------
diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java
index eaf66d9..7be0984 100644
--- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java
+++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java
@@ -330,7 +330,9 @@ class Journal extends BookieCriticalThread implements CheckpointSource {
try {
if (shouldForceWrite) {
+ long startTime = MathUtils.nowInNano();
this.logFile.forceWrite(false);
+ journalSyncStats.registerSuccessfulEvent(MathUtils.elapsedNanos(startTime), TimeUnit.NANOSECONDS);
}
lastLogMark.setCurLogMark(this.logId, this.lastFlushedPosition);
@@ -518,8 +520,11 @@ class Journal extends BookieCriticalThread implements CheckpointSource {
// Expose Stats
private final OpStatsLogger journalAddEntryStats;
+ private final OpStatsLogger journalSyncStats;
private final OpStatsLogger journalCreationStats;
private final OpStatsLogger journalFlushStats;
+ private final OpStatsLogger journalProcessTimeStats;
+ private final OpStatsLogger journalQueueStats;
private final OpStatsLogger forceWriteGroupingCountStats;
private final OpStatsLogger forceWriteBatchEntriesStats;
private final OpStatsLogger forceWriteBatchBytesStats;
@@ -561,8 +566,11 @@ class Journal extends BookieCriticalThread implements CheckpointSource {
// Expose Stats
journalAddEntryStats = statsLogger.getOpStatsLogger(JOURNAL_ADD_ENTRY);
+ journalSyncStats = statsLogger.getOpStatsLogger(JOURNAL_SYNC);
journalCreationStats = statsLogger.getOpStatsLogger(JOURNAL_CREATION_LATENCY);
journalFlushStats = statsLogger.getOpStatsLogger(JOURNAL_FLUSH_LATENCY);
+ journalQueueStats = statsLogger.getOpStatsLogger(JOURNAL_QUEUE_LATENCY);
+ journalProcessTimeStats = statsLogger.getOpStatsLogger(JOURNAL_PROCESS_TIME_LATENCY);
forceWriteGroupingCountStats = statsLogger.getOpStatsLogger(JOURNAL_FORCE_WRITE_GROUPING_COUNT);
forceWriteBatchEntriesStats = statsLogger.getOpStatsLogger(JOURNAL_FORCE_WRITE_BATCH_ENTRIES);
forceWriteBatchBytesStats = statsLogger.getOpStatsLogger(JOURNAL_FORCE_WRITE_BATCH_BYTES);
@@ -794,6 +802,8 @@ class Journal extends BookieCriticalThread implements CheckpointSource {
long lastFlushPosition = 0;
boolean groupWhenTimeout = false;
+ long dequeueStartTime = 0L;
+
QueueEntry qe = null;
while (true) {
// new journal file to write
@@ -817,14 +827,26 @@ class Journal extends BookieCriticalThread implements CheckpointSource {
}
if (qe == null) {
+ if (dequeueStartTime != 0) {
+ journalProcessTimeStats.registerSuccessfulEvent(MathUtils.elapsedNanos(dequeueStartTime), TimeUnit.NANOSECONDS);
+ }
+
if (toFlush.isEmpty()) {
qe = queue.take();
+ dequeueStartTime = MathUtils.nowInNano();
+ journalQueueStats.registerSuccessfulEvent(MathUtils.elapsedNanos(qe.enqueueTime), TimeUnit.NANOSECONDS);
} else {
long pollWaitTimeNanos = maxGroupWaitInNanos - MathUtils.elapsedNanos(toFlush.get(0).enqueueTime);
if (flushWhenQueueEmpty || pollWaitTimeNanos < 0) {
pollWaitTimeNanos = 0;
}
qe = queue.poll(pollWaitTimeNanos, TimeUnit.NANOSECONDS);
+ dequeueStartTime = MathUtils.nowInNano();
+
+ if (qe != null) {
+ journalQueueStats.registerSuccessfulEvent(MathUtils.elapsedNanos(qe.enqueueTime), TimeUnit.NANOSECONDS);
+ }
+
boolean shouldFlush = false;
// We should issue a forceWrite if any of the three conditions below holds good
// 1. If the oldest pending entry has been pending for longer than the max wait time