From e81293b942432e0f55d70511f43e261ef5dfd0f8 Mon Sep 17 00:00:00 2001 From: Robert Varga Date: Tue, 26 Apr 2022 21:22:58 +0200 Subject: [PATCH] Improve SegmentedJournalActor logging Log timing around journal open and each write message. Also include the number of bytes written in each message, so there is a correlation. JIRA: CONTROLLER-2043 Change-Id: I27bb6bc6edf0baf4ec0b3ec0d07f6bfd1adf867e Signed-off-by: Robert Varga --- .../akka/segjournal/DataJournal.java | 3 +- .../akka/segjournal/DataJournalV0.java | 40 +++++++++++-------- .../segjournal/SegmentedJournalActor.java | 15 ++++--- 3 files changed, 36 insertions(+), 22 deletions(-) diff --git a/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournal.java b/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournal.java index 678749b1c1..9ba9394429 100644 --- a/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournal.java +++ b/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournal.java @@ -80,6 +80,7 @@ abstract class DataJournal { * Handle a request to store some messages. * * @param message Request message + * @return number of bytes written */ - abstract void handleWriteMessages(@NonNull WriteMessages message); + abstract long handleWriteMessages(@NonNull WriteMessages message); } diff --git a/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournalV0.java b/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournalV0.java index d422ab14c7..3203d66171 100644 --- a/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournalV0.java +++ b/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/DataJournalV0.java @@ -104,9 +104,10 @@ final class DataJournalV0 extends DataJournal { @Override @SuppressWarnings("checkstyle:illegalCatch") - void handleWriteMessages(final WriteMessages message) { + long handleWriteMessages(final WriteMessages message) { final int count = message.size(); final SegmentedJournalWriter writer = entries.writer(); + long bytes = 0; for (int i = 0; i < count; ++i) { final long mark = writer.getLastIndex(); @@ -115,22 +116,9 @@ final class DataJournalV0 extends DataJournal { final List reprs = CollectionConverters.asJava(request.payload()); LOG.trace("{}: append {}/{}: {} items at mark {}", persistenceId, i, count, reprs.size(), mark); try { - for (PersistentRepr repr : reprs) { - final Object payload = repr.payload(); - if (!(payload instanceof Serializable)) { - throw new UnsupportedOperationException("Non-serializable payload encountered " - + payload.getClass()); - } - - LOG.trace("{}: starting append of {}", persistenceId, payload); - final Indexed entry = writer.append(new ToPersistence(repr)); - final int size = entry.size(); - LOG.trace("{}: finished append of {} with {} bytes at {}", persistenceId, payload, size, - entry.index()); - recordMessageSize(size); - } + bytes += writePayload(writer, reprs); } catch (Exception e) { - LOG.warn("{}: failed to write out request", persistenceId, e); + LOG.warn("{}: failed to write out request {}/{} reverting to {}", persistenceId, i, count, mark, e); message.setFailure(i, e); writer.truncate(mark); continue; @@ -139,5 +127,25 @@ final class DataJournalV0 extends DataJournal { message.setSuccess(i); } writer.flush(); + return bytes; + } + + private long writePayload(final SegmentedJournalWriter writer, final List reprs) { + long bytes = 0; + for (PersistentRepr repr : reprs) { + final Object payload = repr.payload(); + if (!(payload instanceof Serializable)) { + throw new UnsupportedOperationException("Non-serializable payload encountered " + + payload.getClass()); + } + + LOG.trace("{}: starting append of {}", persistenceId, payload); + final Indexed entry = writer.append(new ToPersistence(repr)); + final int size = entry.size(); + LOG.trace("{}: finished append of {} with {} bytes at {}", persistenceId, payload, size, entry.index()); + recordMessageSize(size); + bytes += size; + } + return bytes; } } diff --git a/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/SegmentedJournalActor.java b/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/SegmentedJournalActor.java index e5c5b7807b..d440cbed1c 100644 --- a/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/SegmentedJournalActor.java +++ b/opendaylight/md-sal/sal-akka-segmented-journal/src/main/java/org/opendaylight/controller/akka/segjournal/SegmentedJournalActor.java @@ -19,6 +19,7 @@ import com.codahale.metrics.Meter; import com.codahale.metrics.MetricRegistry; import com.codahale.metrics.Timer; import com.google.common.base.MoreObjects; +import com.google.common.base.Stopwatch; import io.atomix.storage.StorageLevel; import io.atomix.storage.journal.Indexed; import io.atomix.storage.journal.SegmentedJournal; @@ -289,13 +290,16 @@ final class SegmentedJournalActor extends AbstractActor { private void handleWriteMessages(final WriteMessages message) { ensureOpen(); - final long startTicks = System.nanoTime(); + final Stopwatch sw = Stopwatch.createStarted(); final long start = dataJournal.lastWrittenSequenceNr(); + final long bytes = dataJournal.handleWriteMessages(message); + sw.stop(); - dataJournal.handleWriteMessages(message); - - batchWriteTime.update(System.nanoTime() - startTicks, TimeUnit.NANOSECONDS); + batchWriteTime.update(sw.elapsed(TimeUnit.NANOSECONDS), TimeUnit.NANOSECONDS); messageWriteCount.mark(dataJournal.lastWrittenSequenceNr() - start); + + // log message after statistics are updated + LOG.debug("{}: write of {} bytes completed in {}", persistenceId, bytes, sw); } private void handleUnknown(final Object message) { @@ -308,6 +312,7 @@ final class SegmentedJournalActor extends AbstractActor { return; } + final Stopwatch sw = Stopwatch.createStarted(); deleteJournal = SegmentedJournal.builder().withDirectory(directory).withName("delete") .withNamespace(DELETE_NAMESPACE).withMaxSegmentSize(DELETE_SEGMENT_SIZE).build(); final Indexed lastEntry = deleteJournal.writer().getLastEntry(); @@ -316,7 +321,7 @@ final class SegmentedJournalActor extends AbstractActor { dataJournal = new DataJournalV0(persistenceId, messageSize, context().system(), storage, directory, maxEntrySize, maxSegmentSize); dataJournal.deleteTo(lastDelete); - LOG.debug("{}: journal open with last index {}, deleted to {}", persistenceId, + LOG.debug("{}: journal open in {} with last index {}, deleted to {}", persistenceId, sw, dataJournal.lastWrittenSequenceNr(), lastDelete); } } -- 2.36.6