From c0d960cda4d4a875aea6cb8e9177525d945c6f5d Mon Sep 17 00:00:00 2001 From: Matteo Merli Date: Thu, 3 Nov 2016 05:50:13 +0900 Subject: [PATCH] BOOKKEEPER-962: Add more journal timing stats --- .../bookie/BookKeeperServerStats.java | 3 +++ .../org/apache/bookkeeper/bookie/Journal.java | 22 +++++++++++++++++++ 2 files changed, 25 insertions(+) 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 c7919f71102..239f923f972 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 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 eaf66d9eee9..7be09844e76 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 @@ public int process(boolean shouldForceWrite) throws IOException { 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 @@ static void writePaddingBytes(JournalChannel jc, ByteBuffer paddingBuffer, int j // 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 @@ public Journal(ServerConfiguration conf, LedgerDirsManager ledgerDirsManager, St // 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 @@ public void run() { long lastFlushPosition = 0; boolean groupWhenTimeout = false; + long dequeueStartTime = 0L; + QueueEntry qe = null; while (true) { // new journal file to write @@ -817,14 +827,26 @@ public void run() { } 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