Improve SegmentedJournalActor logging
[controller.git] / opendaylight / md-sal / sal-akka-segmented-journal / src / main / java / org / opendaylight / controller / akka / segjournal / SegmentedJournalActor.java
1 /*
2  * Copyright (c) 2019 Pantheon Technologies, s.r.o. and others.  All rights reserved.
3  *
4  * This program and the accompanying materials are made available under the
5  * terms of the Eclipse Public License v1.0 which accompanies this distribution,
6  * and is available at http://www.eclipse.org/legal/epl-v10.html
7  */
8 package org.opendaylight.controller.akka.segjournal;
9
10 import static com.google.common.base.Verify.verifyNotNull;
11 import static java.util.Objects.requireNonNull;
12
13 import akka.actor.AbstractActor;
14 import akka.actor.Props;
15 import akka.persistence.AtomicWrite;
16 import akka.persistence.PersistentRepr;
17 import com.codahale.metrics.Histogram;
18 import com.codahale.metrics.Meter;
19 import com.codahale.metrics.MetricRegistry;
20 import com.codahale.metrics.Timer;
21 import com.google.common.base.MoreObjects;
22 import com.google.common.base.Stopwatch;
23 import io.atomix.storage.StorageLevel;
24 import io.atomix.storage.journal.Indexed;
25 import io.atomix.storage.journal.SegmentedJournal;
26 import io.atomix.storage.journal.SegmentedJournalWriter;
27 import io.atomix.utils.serializer.Namespace;
28 import java.io.File;
29 import java.util.ArrayList;
30 import java.util.List;
31 import java.util.Optional;
32 import java.util.concurrent.TimeUnit;
33 import java.util.function.Consumer;
34 import org.opendaylight.controller.cluster.common.actor.MeteringBehavior;
35 import org.opendaylight.controller.cluster.reporting.MetricsReporter;
36 import org.slf4j.Logger;
37 import org.slf4j.LoggerFactory;
38 import scala.concurrent.Future;
39 import scala.concurrent.Promise;
40
41 /**
42  * This actor handles a single PersistentActor's journal. The journal is split into two {@link SegmentedJournal}s:
43  * <ul>
44  *     <li>A memory-mapped data journal, containing actual data entries</li>
45  *     <li>A simple file journal, containing sequence numbers of last deleted entry</li>
46  * </ul>
47  *
48  * <p>
49  * This is a conscious design decision to minimize the amount of data that is being stored in the data journal while
50  * speeding up normal operations. Since the SegmentedJournal is an append-only linear log and Akka requires the ability
51  * to delete persistence entries, we need ability to mark a subset of a SegmentedJournal as deleted. While we could
52  * treat such delete requests as normal events, this leads to a mismatch between SegmentedJournal indices (as exposed by
53  * {@link Indexed}) and Akka sequence numbers -- requiring us to potentially perform costly deserialization to find the
54  * index corresponding to a particular sequence number, or maintain moderately-complex logic and data structures to
55  * perform that mapping in sub-linear time complexity.
56  *
57  * <p>
58  * Split-file approach allows us to treat sequence numbers and indices as equivalent, without maintaining any explicit
59  * mapping information. The only additional information we need to maintain is the last deleted sequence number.
60  *
61  * @author Robert Varga
62  */
63 final class SegmentedJournalActor extends AbstractActor {
64     abstract static class AsyncMessage<T> {
65         final Promise<T> promise = Promise.apply();
66     }
67
68     private static final class ReadHighestSequenceNr extends AsyncMessage<Long> {
69         private final long fromSequenceNr;
70
71         ReadHighestSequenceNr(final long fromSequenceNr) {
72             this.fromSequenceNr = fromSequenceNr;
73         }
74
75         @Override
76         public String toString() {
77             return MoreObjects.toStringHelper(this).add("fromSequenceNr", fromSequenceNr).toString();
78         }
79     }
80
81     static final class ReplayMessages extends AsyncMessage<Void> {
82         private final long fromSequenceNr;
83         final long toSequenceNr;
84         final long max;
85         final Consumer<PersistentRepr> replayCallback;
86
87         ReplayMessages(final long fromSequenceNr,
88                 final long toSequenceNr, final long max, final Consumer<PersistentRepr> replayCallback) {
89             this.fromSequenceNr = fromSequenceNr;
90             this.toSequenceNr = toSequenceNr;
91             this.max = max;
92             this.replayCallback = requireNonNull(replayCallback);
93         }
94
95         @Override
96         public String toString() {
97             return MoreObjects.toStringHelper(this).add("fromSequenceNr", fromSequenceNr)
98                     .add("toSequenceNr", toSequenceNr).add("max", max).toString();
99         }
100     }
101
102     static final class WriteMessages {
103         private final List<AtomicWrite> requests = new ArrayList<>();
104         private final List<Promise<Optional<Exception>>> results = new ArrayList<>();
105
106         Future<Optional<Exception>> add(final AtomicWrite write) {
107             final Promise<Optional<Exception>> promise = Promise.apply();
108             requests.add(write);
109             results.add(promise);
110             return promise.future();
111         }
112
113         int size() {
114             return requests.size();
115         }
116
117         AtomicWrite getRequest(final int index) {
118             return requests.get(index);
119         }
120
121         void setFailure(final int index, final Exception cause) {
122             results.get(index).success(Optional.of(cause));
123
124         }
125
126         void setSuccess(final int index) {
127             results.get(index).success(Optional.empty());
128         }
129
130         @Override
131         public String toString() {
132             return MoreObjects.toStringHelper(this).add("requests", requests).toString();
133         }
134     }
135
136     private static final class DeleteMessagesTo extends AsyncMessage<Void> {
137         final long toSequenceNr;
138
139         DeleteMessagesTo(final long toSequenceNr) {
140             this.toSequenceNr = toSequenceNr;
141         }
142
143         @Override
144         public String toString() {
145             return MoreObjects.toStringHelper(this).add("toSequenceNr", toSequenceNr).toString();
146         }
147     }
148
149     private static final Logger LOG = LoggerFactory.getLogger(SegmentedJournalActor.class);
150     private static final Namespace DELETE_NAMESPACE = Namespace.builder().register(Long.class).build();
151     private static final int DELETE_SEGMENT_SIZE = 64 * 1024;
152
153     private final String persistenceId;
154     private final StorageLevel storage;
155     private final int maxSegmentSize;
156     private final int maxEntrySize;
157     private final File directory;
158
159     // Tracks the time it took us to write a batch of messages
160     private Timer batchWriteTime;
161     // Tracks the number of individual messages written
162     private Meter messageWriteCount;
163     // Tracks the size distribution of messages
164     private Histogram messageSize;
165
166     private DataJournal dataJournal;
167     private SegmentedJournal<Long> deleteJournal;
168     private long lastDelete;
169
170     SegmentedJournalActor(final String persistenceId, final File directory, final StorageLevel storage,
171             final int maxEntrySize, final int maxSegmentSize) {
172         this.persistenceId = requireNonNull(persistenceId);
173         this.directory = requireNonNull(directory);
174         this.storage = requireNonNull(storage);
175         this.maxEntrySize = maxEntrySize;
176         this.maxSegmentSize = maxSegmentSize;
177     }
178
179     static Props props(final String persistenceId, final File directory, final StorageLevel storage,
180             final int maxEntrySize, final int maxSegmentSize) {
181         return Props.create(SegmentedJournalActor.class, requireNonNull(persistenceId), directory, storage,
182             maxEntrySize, maxSegmentSize);
183     }
184
185     @Override
186     public Receive createReceive() {
187         return receiveBuilder()
188                 .match(DeleteMessagesTo.class, this::handleDeleteMessagesTo)
189                 .match(ReadHighestSequenceNr.class, this::handleReadHighestSequenceNr)
190                 .match(ReplayMessages.class, this::handleReplayMessages)
191                 .match(WriteMessages.class, this::handleWriteMessages)
192                 .matchAny(this::handleUnknown)
193                 .build();
194     }
195
196     @Override
197     public void preStart() throws Exception {
198         LOG.debug("{}: actor starting", persistenceId);
199         super.preStart();
200
201         final MetricRegistry registry = MetricsReporter.getInstance(MeteringBehavior.DOMAIN).getMetricsRegistry();
202         final String actorName = self().path().parent().toStringWithoutAddress() + '/' + directory.getName();
203
204         batchWriteTime = registry.timer(MetricRegistry.name(actorName, "batchWriteTime"));
205         messageWriteCount = registry.meter(MetricRegistry.name(actorName, "messageWriteCount"));
206         messageSize = registry.histogram(MetricRegistry.name(actorName, "messageSize"));
207     }
208
209     @Override
210     public void postStop() throws Exception {
211         LOG.debug("{}: actor stopping", persistenceId);
212         if (dataJournal != null) {
213             dataJournal.close();
214             LOG.debug("{}: data journal closed", persistenceId);
215             dataJournal = null;
216         }
217         if (deleteJournal != null) {
218             deleteJournal.close();
219             LOG.debug("{}: delete journal closed", persistenceId);
220             deleteJournal = null;
221         }
222         LOG.debug("{}: actor stopped", persistenceId);
223         super.postStop();
224     }
225
226     static AsyncMessage<Void> deleteMessagesTo(final long toSequenceNr) {
227         return new DeleteMessagesTo(toSequenceNr);
228     }
229
230     static AsyncMessage<Long> readHighestSequenceNr(final long fromSequenceNr) {
231         return new ReadHighestSequenceNr(fromSequenceNr);
232     }
233
234     static AsyncMessage<Void> replayMessages(final long fromSequenceNr, final long toSequenceNr, final long max,
235             final Consumer<PersistentRepr> replayCallback) {
236         return new ReplayMessages(fromSequenceNr, toSequenceNr, max, replayCallback);
237     }
238
239     private void handleDeleteMessagesTo(final DeleteMessagesTo message) {
240         ensureOpen();
241
242         LOG.debug("{}: delete messages {}", persistenceId, message);
243         final long to = Long.min(dataJournal.lastWrittenSequenceNr(), message.toSequenceNr);
244         LOG.debug("{}: adjusted delete to {}", persistenceId, to);
245
246         if (lastDelete < to) {
247             LOG.debug("{}: deleting entries up to {}", persistenceId, to);
248
249             lastDelete = to;
250             final SegmentedJournalWriter<Long> deleteWriter = deleteJournal.writer();
251             final Indexed<Long> entry = deleteWriter.append(lastDelete);
252             deleteWriter.commit(entry.index());
253             dataJournal.deleteTo(lastDelete);
254
255             LOG.debug("{}: compaction started", persistenceId);
256             dataJournal.compactTo(lastDelete);
257             deleteJournal.compact(entry.index());
258             LOG.debug("{}: compaction finished", persistenceId);
259         } else {
260             LOG.debug("{}: entries up to {} already deleted", persistenceId, lastDelete);
261         }
262
263         message.promise.success(null);
264     }
265
266     private void handleReadHighestSequenceNr(final ReadHighestSequenceNr message) {
267         LOG.debug("{}: looking for highest sequence on {}", persistenceId, message);
268         final Long sequence;
269         if (directory.isDirectory()) {
270             ensureOpen();
271             sequence = dataJournal.lastWrittenSequenceNr();
272         } else {
273             sequence = 0L;
274         }
275
276         LOG.debug("{}: highest sequence is {}", message, sequence);
277         message.promise.success(sequence);
278     }
279
280     private void handleReplayMessages(final ReplayMessages message) {
281         LOG.debug("{}: replaying messages {}", persistenceId, message);
282         ensureOpen();
283
284         final long from = Long.max(lastDelete + 1, message.fromSequenceNr);
285         LOG.debug("{}: adjusted fromSequenceNr to {}", persistenceId, from);
286
287         dataJournal.handleReplayMessages(message, from);
288     }
289
290     private void handleWriteMessages(final WriteMessages message) {
291         ensureOpen();
292
293         final Stopwatch sw = Stopwatch.createStarted();
294         final long start = dataJournal.lastWrittenSequenceNr();
295         final long bytes = dataJournal.handleWriteMessages(message);
296         sw.stop();
297
298         batchWriteTime.update(sw.elapsed(TimeUnit.NANOSECONDS), TimeUnit.NANOSECONDS);
299         messageWriteCount.mark(dataJournal.lastWrittenSequenceNr() - start);
300
301         // log message after statistics are updated
302         LOG.debug("{}: write of {} bytes completed in {}", persistenceId, bytes, sw);
303     }
304
305     private void handleUnknown(final Object message) {
306         LOG.error("{}: Received unknown message {}", persistenceId, message);
307     }
308
309     private void ensureOpen() {
310         if (dataJournal != null) {
311             verifyNotNull(deleteJournal);
312             return;
313         }
314
315         final Stopwatch sw = Stopwatch.createStarted();
316         deleteJournal = SegmentedJournal.<Long>builder().withDirectory(directory).withName("delete")
317                 .withNamespace(DELETE_NAMESPACE).withMaxSegmentSize(DELETE_SEGMENT_SIZE).build();
318         final Indexed<Long> lastEntry = deleteJournal.writer().getLastEntry();
319         lastDelete = lastEntry == null ? 0 : lastEntry.entry();
320
321         dataJournal = new DataJournalV0(persistenceId, messageSize, context().system(), storage, directory,
322             maxEntrySize, maxSegmentSize);
323         dataJournal.deleteTo(lastDelete);
324         LOG.debug("{}: journal open in {} with last index {}, deleted to {}", persistenceId, sw,
325             dataJournal.lastWrittenSequenceNr(), lastDelete);
326     }
327 }