1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19 package org.apache.hadoop.hbase.procedure2.store.wal;
20
21 import java.io.FileNotFoundException;
22 import java.io.IOException;
23 import java.util.ArrayList;
24 import java.util.Arrays;
25 import java.util.Collections;
26 import java.util.HashSet;
27 import java.util.Iterator;
28 import java.util.LinkedList;
29 import java.util.Set;
30 import java.util.concurrent.LinkedTransferQueue;
31 import java.util.concurrent.TimeUnit;
32 import java.util.concurrent.atomic.AtomicBoolean;
33 import java.util.concurrent.atomic.AtomicLong;
34 import java.util.concurrent.atomic.AtomicReference;
35 import java.util.concurrent.locks.Condition;
36 import java.util.concurrent.locks.ReentrantLock;
37
38 import org.apache.commons.collections.buffer.CircularFifoBuffer;
39 import org.apache.commons.logging.Log;
40 import org.apache.commons.logging.LogFactory;
41 import org.apache.hadoop.conf.Configuration;
42 import org.apache.hadoop.fs.FSDataOutputStream;
43 import org.apache.hadoop.fs.FileAlreadyExistsException;
44 import org.apache.hadoop.fs.FileStatus;
45 import org.apache.hadoop.fs.FileSystem;
46 import org.apache.hadoop.fs.Path;
47 import org.apache.hadoop.fs.PathFilter;
48 import org.apache.hadoop.hbase.classification.InterfaceAudience;
49 import org.apache.hadoop.hbase.classification.InterfaceStability;
50 import org.apache.hadoop.hbase.procedure2.Procedure;
51 import org.apache.hadoop.hbase.procedure2.store.ProcedureStoreBase;
52 import org.apache.hadoop.hbase.procedure2.store.ProcedureStoreTracker;
53 import org.apache.hadoop.hbase.procedure2.util.ByteSlot;
54 import org.apache.hadoop.hbase.procedure2.util.StringUtils;
55 import org.apache.hadoop.hbase.protobuf.generated.ProcedureProtos.ProcedureWALHeader;
56 import org.apache.hadoop.hbase.util.Threads;
57 import org.apache.hadoop.ipc.RemoteException;
58
59 import com.google.common.annotations.VisibleForTesting;
60
61
62
63
64 @InterfaceAudience.Private
65 @InterfaceStability.Evolving
66 public class WALProcedureStore extends ProcedureStoreBase {
67 private static final Log LOG = LogFactory.getLog(WALProcedureStore.class);
68
69 public interface LeaseRecovery {
70 void recoverFileLease(FileSystem fs, Path path) throws IOException;
71 }
72
73 private static final String MAX_RETRIES_BEFORE_ROLL_CONF_KEY =
74 "hbase.procedure.store.wal.max.retries.before.roll";
75 private static final int DEFAULT_MAX_RETRIES_BEFORE_ROLL = 3;
76
77 private static final String WAIT_BEFORE_ROLL_CONF_KEY =
78 "hbase.procedure.store.wal.wait.before.roll";
79 private static final int DEFAULT_WAIT_BEFORE_ROLL = 500;
80
81 private static final String ROLL_RETRIES_CONF_KEY =
82 "hbase.procedure.store.wal.max.roll.retries";
83 private static final int DEFAULT_ROLL_RETRIES = 3;
84
85 private static final String MAX_SYNC_FAILURE_ROLL_CONF_KEY =
86 "hbase.procedure.store.wal.sync.failure.roll.max";
87 private static final int DEFAULT_MAX_SYNC_FAILURE_ROLL = 3;
88
89 private static final String PERIODIC_ROLL_CONF_KEY =
90 "hbase.procedure.store.wal.periodic.roll.msec";
91 private static final int DEFAULT_PERIODIC_ROLL = 60 * 60 * 1000;
92
93 private static final String SYNC_WAIT_MSEC_CONF_KEY = "hbase.procedure.store.wal.sync.wait.msec";
94 private static final int DEFAULT_SYNC_WAIT_MSEC = 100;
95
96 private static final String USE_HSYNC_CONF_KEY = "hbase.procedure.store.wal.use.hsync";
97 private static final boolean DEFAULT_USE_HSYNC = true;
98
99 private static final String ROLL_THRESHOLD_CONF_KEY = "hbase.procedure.store.wal.roll.threshold";
100 private static final long DEFAULT_ROLL_THRESHOLD = 32 * 1024 * 1024;
101
102 private static final String STORE_WAL_SYNC_STATS_COUNT =
103 "hbase.procedure.store.wal.sync.stats.count";
104 private static final int DEFAULT_SYNC_STATS_COUNT = 10;
105
106 private final LinkedList<ProcedureWALFile> logs = new LinkedList<ProcedureWALFile>();
107 private final ProcedureStoreTracker storeTracker = new ProcedureStoreTracker();
108 private final ReentrantLock lock = new ReentrantLock();
109 private final Condition waitCond = lock.newCondition();
110 private final Condition slotCond = lock.newCondition();
111 private final Condition syncCond = lock.newCondition();
112
113 private final LeaseRecovery leaseRecovery;
114 private final Configuration conf;
115 private final FileSystem fs;
116 private final Path logDir;
117
118 private final AtomicReference<Throwable> syncException = new AtomicReference<Throwable>();
119 private final AtomicBoolean loading = new AtomicBoolean(true);
120 private final AtomicBoolean inSync = new AtomicBoolean(false);
121 private final AtomicLong totalSynced = new AtomicLong(0);
122 private final AtomicLong lastRollTs = new AtomicLong(0);
123
124 private LinkedTransferQueue<ByteSlot> slotsCache = null;
125 private Set<ProcedureWALFile> corruptedLogs = null;
126 private FSDataOutputStream stream = null;
127 private long flushLogId = 0;
128 private int slotIndex = 0;
129 private Thread syncThread;
130 private ByteSlot[] slots;
131
132 private int maxRetriesBeforeRoll;
133 private int maxSyncFailureRoll;
134 private int waitBeforeRoll;
135 private int rollRetries;
136 private int periodicRollMsec;
137 private long rollThreshold;
138 private boolean useHsync;
139 private int syncWaitMsec;
140
141
142 private CircularFifoBuffer syncMetricsBuffer;
143
144 public static class SyncMetrics {
145 private long timestamp;
146 private long syncWaitMs;
147 private long totalSyncedBytes;
148 private int syncedEntries;
149 private float syncedPerSec;
150
151 public long getTimestamp() {
152 return timestamp;
153 }
154
155 public long getSyncWaitMs() {
156 return syncWaitMs;
157 }
158
159 public long getTotalSyncedBytes() {
160 return totalSyncedBytes;
161 }
162
163 public long getSyncedEntries() {
164 return syncedEntries;
165 }
166
167 public float getSyncedPerSec() {
168 return syncedPerSec;
169 }
170 }
171
172 public WALProcedureStore(final Configuration conf, final FileSystem fs, final Path logDir,
173 final LeaseRecovery leaseRecovery) {
174 this.fs = fs;
175 this.conf = conf;
176 this.logDir = logDir;
177 this.leaseRecovery = leaseRecovery;
178 }
179
180 @Override
181 public void start(int numSlots) throws IOException {
182 if (!setRunning(true)) {
183 return;
184 }
185
186
187 loading.set(true);
188 slots = new ByteSlot[numSlots];
189 slotsCache = new LinkedTransferQueue();
190 while (slotsCache.size() < numSlots) {
191 slotsCache.offer(new ByteSlot());
192 }
193
194
195 maxRetriesBeforeRoll =
196 conf.getInt(MAX_RETRIES_BEFORE_ROLL_CONF_KEY, DEFAULT_MAX_RETRIES_BEFORE_ROLL);
197 maxSyncFailureRoll = conf.getInt(MAX_SYNC_FAILURE_ROLL_CONF_KEY, DEFAULT_MAX_SYNC_FAILURE_ROLL);
198 waitBeforeRoll = conf.getInt(WAIT_BEFORE_ROLL_CONF_KEY, DEFAULT_WAIT_BEFORE_ROLL);
199 rollRetries = conf.getInt(ROLL_RETRIES_CONF_KEY, DEFAULT_ROLL_RETRIES);
200 rollThreshold = conf.getLong(ROLL_THRESHOLD_CONF_KEY, DEFAULT_ROLL_THRESHOLD);
201 periodicRollMsec = conf.getInt(PERIODIC_ROLL_CONF_KEY, DEFAULT_PERIODIC_ROLL);
202 syncWaitMsec = conf.getInt(SYNC_WAIT_MSEC_CONF_KEY, DEFAULT_SYNC_WAIT_MSEC);
203 useHsync = conf.getBoolean(USE_HSYNC_CONF_KEY, DEFAULT_USE_HSYNC);
204
205
206 syncMetricsBuffer = new CircularFifoBuffer(
207 conf.getInt(STORE_WAL_SYNC_STATS_COUNT, DEFAULT_SYNC_STATS_COUNT));
208
209
210 syncThread = new Thread("WALProcedureStoreSyncThread") {
211 @Override
212 public void run() {
213 try {
214 syncLoop();
215 } catch (Throwable e) {
216 LOG.error("Got an exception from the sync-loop", e);
217 if (!isSyncAborted()) {
218 sendAbortProcessSignal();
219 }
220 }
221 }
222 };
223 syncThread.start();
224 }
225
226 @Override
227 public void stop(boolean abort) {
228 if (!setRunning(false)) {
229 return;
230 }
231
232 LOG.info("Stopping the WAL Procedure Store");
233 sendStopSignal();
234
235 if (!abort) {
236 try {
237 while (syncThread.isAlive()) {
238 sendStopSignal();
239 syncThread.join(250);
240 }
241 } catch (InterruptedException e) {
242 LOG.warn("join interrupted", e);
243 Thread.currentThread().interrupt();
244 }
245 }
246
247
248 closeStream();
249
250
251
252
253 for (ProcedureWALFile log: logs) {
254 log.close();
255 }
256 logs.clear();
257 }
258
259 private void sendStopSignal() {
260 if (lock.tryLock()) {
261 try {
262 waitCond.signalAll();
263 syncCond.signalAll();
264 } finally {
265 lock.unlock();
266 }
267 }
268 }
269
270 @Override
271 public int getNumThreads() {
272 return slots == null ? 0 : slots.length;
273 }
274
275 public ProcedureStoreTracker getStoreTracker() {
276 return storeTracker;
277 }
278
279 public ArrayList<ProcedureWALFile> getActiveLogs() {
280 lock.lock();
281 try {
282 return new ArrayList<ProcedureWALFile>(logs);
283 } finally {
284 lock.unlock();
285 }
286 }
287
288 public Set<ProcedureWALFile> getCorruptedLogs() {
289 return corruptedLogs;
290 }
291
292 @Override
293 public void recoverLease() throws IOException {
294 lock.lock();
295 try {
296 LOG.info("Starting WAL Procedure Store lease recovery");
297 FileStatus[] oldLogs = getLogFiles();
298 while (isRunning()) {
299
300 flushLogId = initOldLogs(oldLogs);
301
302
303 if (!rollWriter(flushLogId + 1)) {
304
305 LOG.debug("someone else has already created log " + flushLogId);
306 continue;
307 }
308
309
310 oldLogs = getLogFiles();
311 if (getMaxLogId(oldLogs) > flushLogId) {
312 if (LOG.isDebugEnabled()) {
313 LOG.debug("Someone else created new logs. Expected maxLogId < " + flushLogId);
314 }
315 logs.getLast().removeFile();
316 continue;
317 }
318
319 LOG.info("Lease acquired for flushLogId: " + flushLogId);
320 break;
321 }
322 } finally {
323 lock.unlock();
324 }
325 }
326
327 @Override
328 public void load(final ProcedureLoader loader) throws IOException {
329 if (logs.isEmpty()) {
330 throw new RuntimeException("recoverLease() must be called before loading data");
331 }
332
333
334 if (logs.size() == 1) {
335 if (LOG.isDebugEnabled()) {
336 LOG.debug("No state logs to replay.");
337 }
338 loader.setMaxProcId(0);
339 loading.set(false);
340 return;
341 }
342
343
344 Iterator<ProcedureWALFile> it = logs.descendingIterator();
345 it.next();
346 try {
347 ProcedureWALFormat.load(it, storeTracker, new ProcedureWALFormat.Loader() {
348 @Override
349 public void setMaxProcId(long maxProcId) {
350 loader.setMaxProcId(maxProcId);
351 }
352
353 @Override
354 public void load(ProcedureIterator procIter) throws IOException {
355 loader.load(procIter);
356 }
357
358 @Override
359 public void handleCorrupted(ProcedureIterator procIter) throws IOException {
360 loader.handleCorrupted(procIter);
361 }
362
363 @Override
364 public void markCorruptedWAL(ProcedureWALFile log, IOException e) {
365 if (corruptedLogs == null) {
366 corruptedLogs = new HashSet<ProcedureWALFile>();
367 }
368 corruptedLogs.add(log);
369
370 }
371 });
372 } finally {
373 loading.set(false);
374 }
375 }
376
377 @Override
378 public void insert(final Procedure proc, final Procedure[] subprocs) {
379 if (LOG.isTraceEnabled()) {
380 LOG.trace("Insert " + proc + ", subproc=" + Arrays.toString(subprocs));
381 }
382
383 ByteSlot slot = acquireSlot();
384 try {
385
386 long[] subProcIds = null;
387 if (subprocs != null) {
388 ProcedureWALFormat.writeInsert(slot, proc, subprocs);
389 subProcIds = new long[subprocs.length];
390 for (int i = 0; i < subprocs.length; ++i) {
391 subProcIds[i] = subprocs[i].getProcId();
392 }
393 } else {
394 assert !proc.hasParent();
395 ProcedureWALFormat.writeInsert(slot, proc);
396 }
397
398
399 pushData(PushType.INSERT, slot, proc.getProcId(), subProcIds);
400 } catch (IOException e) {
401
402
403 LOG.fatal("Unable to serialize one of the procedure: proc=" + proc +
404 ", subprocs=" + Arrays.toString(subprocs), e);
405 throw new RuntimeException(e);
406 } finally {
407 releaseSlot(slot);
408 }
409 }
410
411 @Override
412 public void update(final Procedure proc) {
413 if (LOG.isTraceEnabled()) {
414 LOG.trace("Update " + proc);
415 }
416
417 ByteSlot slot = acquireSlot();
418 try {
419
420 ProcedureWALFormat.writeUpdate(slot, proc);
421
422
423 pushData(PushType.UPDATE, slot, proc.getProcId(), null);
424 } catch (IOException e) {
425
426
427 LOG.fatal("Unable to serialize the procedure: " + proc, e);
428 throw new RuntimeException(e);
429 } finally {
430 releaseSlot(slot);
431 }
432 }
433
434 @Override
435 public void delete(final long procId) {
436 if (LOG.isTraceEnabled()) {
437 LOG.trace("Delete " + procId);
438 }
439
440 ByteSlot slot = acquireSlot();
441 try {
442
443 ProcedureWALFormat.writeDelete(slot, procId);
444
445
446 pushData(PushType.DELETE, slot, procId, null);
447 } catch (IOException e) {
448
449
450 LOG.fatal("Unable to serialize the procedure: " + procId, e);
451 throw new RuntimeException(e);
452 } finally {
453 releaseSlot(slot);
454 }
455 }
456
457 private ByteSlot acquireSlot() {
458 ByteSlot slot = slotsCache.poll();
459 return slot != null ? slot : new ByteSlot();
460 }
461
462 private void releaseSlot(final ByteSlot slot) {
463 slot.reset();
464 slotsCache.offer(slot);
465 }
466
467 private enum PushType { INSERT, UPDATE, DELETE };
468
469 private long pushData(final PushType type, final ByteSlot slot,
470 final long procId, final long[] subProcIds) {
471 if (!isRunning()) {
472 throw new RuntimeException("the store must be running before inserting data");
473 }
474 if (logs.isEmpty()) {
475 throw new RuntimeException("recoverLease() must be called before inserting data");
476 }
477
478 long logId = -1;
479 lock.lock();
480 try {
481
482 while (true) {
483 if (!isRunning()) {
484 throw new RuntimeException("store no longer running");
485 } else if (isSyncAborted()) {
486 throw new RuntimeException("sync aborted", syncException.get());
487 } else if (inSync.get()) {
488 syncCond.await();
489 } else if (slotIndex == slots.length) {
490 slotCond.signal();
491 syncCond.await();
492 } else {
493 break;
494 }
495 }
496
497 updateStoreTracker(type, procId, subProcIds);
498 slots[slotIndex++] = slot;
499 logId = flushLogId;
500
501
502 if (slotIndex == 1) {
503 waitCond.signal();
504 }
505
506
507 if (slotIndex == slots.length) {
508 waitCond.signal();
509 slotCond.signal();
510 }
511
512 syncCond.await();
513 } catch (InterruptedException e) {
514 Thread.currentThread().interrupt();
515 sendAbortProcessSignal();
516 throw new RuntimeException(e);
517 } finally {
518 lock.unlock();
519 if (isSyncAborted()) {
520 throw new RuntimeException("sync aborted", syncException.get());
521 }
522 }
523 return logId;
524 }
525
526 private void updateStoreTracker(final PushType type,
527 final long procId, final long[] subProcIds) {
528 switch (type) {
529 case INSERT:
530 if (subProcIds == null) {
531 storeTracker.insert(procId);
532 } else {
533 storeTracker.insert(procId, subProcIds);
534 }
535 break;
536 case UPDATE:
537 storeTracker.update(procId);
538 break;
539 case DELETE:
540 storeTracker.delete(procId);
541 break;
542 default:
543 throw new RuntimeException("invalid push type " + type);
544 }
545 }
546
547 private boolean isSyncAborted() {
548 return syncException.get() != null;
549 }
550
551 private void syncLoop() throws Throwable {
552 long totalSyncedToStore = 0;
553 inSync.set(false);
554 lock.lock();
555 try {
556 while (isRunning()) {
557 try {
558
559 if (slotIndex == 0) {
560 if (!loading.get()) {
561 periodicRoll();
562 }
563
564 if (LOG.isTraceEnabled()) {
565 float rollTsSec = getMillisFromLastRoll() / 1000.0f;
566 LOG.trace(String.format("Waiting for data. flushed=%s (%s/sec)",
567 StringUtils.humanSize(totalSynced.get()),
568 StringUtils.humanSize(totalSynced.get() / rollTsSec)));
569 }
570
571 waitCond.await(getMillisToNextPeriodicRoll(), TimeUnit.MILLISECONDS);
572 if (slotIndex == 0) {
573
574 continue;
575 }
576 }
577
578 final long syncWaitSt = System.currentTimeMillis();
579 if (slotIndex != slots.length) {
580 slotCond.await(syncWaitMsec, TimeUnit.MILLISECONDS);
581 }
582
583 final long currentTs = System.currentTimeMillis();
584 final long syncWaitMs = currentTs - syncWaitSt;
585 final float rollSec = getMillisFromLastRoll() / 1000.0f;
586 final float syncedPerSec = totalSyncedToStore / rollSec;
587 if (LOG.isTraceEnabled() && (syncWaitMs > 10 || slotIndex < slots.length)) {
588 LOG.trace(String.format("Sync wait %s, slotIndex=%s , totalSynced=%s (%s/sec)",
589 StringUtils.humanTimeDiff(syncWaitMs), slotIndex,
590 StringUtils.humanSize(totalSyncedToStore),
591 StringUtils.humanSize(syncedPerSec)));
592 }
593
594
595 final SyncMetrics syncMetrics = new SyncMetrics();
596 syncMetrics.timestamp = currentTs;
597 syncMetrics.syncWaitMs = syncWaitMs;
598 syncMetrics.syncedEntries = slotIndex;
599 syncMetrics.totalSyncedBytes = totalSyncedToStore;
600 syncMetrics.syncedPerSec = syncedPerSec;
601 syncMetricsBuffer.add(syncMetrics);
602
603
604 inSync.set(true);
605 long slotSize = syncSlots();
606 logs.getLast().addToSize(slotSize);
607 totalSyncedToStore = totalSynced.addAndGet(slotSize);
608 slotIndex = 0;
609 inSync.set(false);
610 } catch (InterruptedException e) {
611 Thread.currentThread().interrupt();
612 sendAbortProcessSignal();
613 syncException.compareAndSet(null, e);
614 throw e;
615 } catch (Throwable t) {
616 syncException.compareAndSet(null, t);
617 throw t;
618 } finally {
619 syncCond.signalAll();
620 }
621 }
622 } finally {
623 lock.unlock();
624 }
625 }
626
627 public ArrayList<SyncMetrics> getSyncMetrics() {
628 lock.lock();
629 try {
630 return new ArrayList<SyncMetrics>(syncMetricsBuffer);
631 } finally {
632 lock.unlock();
633 }
634 }
635
636 private long syncSlots() throws Throwable {
637 int retry = 0;
638 int logRolled = 0;
639 long totalSynced = 0;
640 do {
641 try {
642 totalSynced = syncSlots(stream, slots, 0, slotIndex);
643 break;
644 } catch (Throwable e) {
645 LOG.warn("unable to sync slots, retry=" + retry);
646 if (++retry >= maxRetriesBeforeRoll) {
647 if (logRolled >= maxSyncFailureRoll) {
648 LOG.error("Sync slots after log roll failed, abort.", e);
649 sendAbortProcessSignal();
650 throw e;
651 }
652
653 if (!rollWriterOrDie()) {
654 throw e;
655 }
656
657 logRolled++;
658 retry = 0;
659 }
660 }
661 } while (isRunning());
662 return totalSynced;
663 }
664
665 protected long syncSlots(FSDataOutputStream stream, ByteSlot[] slots, int offset, int count)
666 throws IOException {
667 long totalSynced = 0;
668 for (int i = 0; i < count; ++i) {
669 ByteSlot data = slots[offset + i];
670 data.writeTo(stream);
671 totalSynced += data.size();
672 }
673
674 if (useHsync) {
675 stream.hsync();
676 } else {
677 stream.hflush();
678 }
679 sendPostSyncSignal();
680
681 if (LOG.isTraceEnabled()) {
682 LOG.trace("Sync slots=" + count + '/' + slots.length +
683 ", flushed=" + StringUtils.humanSize(totalSynced));
684 }
685 return totalSynced;
686 }
687
688 private boolean rollWriterOrDie() {
689 for (int i = 0; i < rollRetries; ++i) {
690 if (i > 0) Threads.sleepWithoutInterrupt(waitBeforeRoll * i);
691
692 try {
693 if (rollWriter()) {
694 return true;
695 }
696 } catch (IOException e) {
697 LOG.warn("Unable to roll the log, attempt=" + (i + 1), e);
698 }
699 }
700 LOG.fatal("Unable to roll the log");
701 sendAbortProcessSignal();
702 throw new RuntimeException("unable to roll the log");
703 }
704
705 private boolean tryRollWriter() {
706 try {
707 return rollWriter();
708 } catch (IOException e) {
709 LOG.warn("Unable to roll the log", e);
710 return false;
711 }
712 }
713
714 public long getMillisToNextPeriodicRoll() {
715 if (lastRollTs.get() > 0 && periodicRollMsec > 0) {
716 return periodicRollMsec - getMillisFromLastRoll();
717 }
718 return Long.MAX_VALUE;
719 }
720
721 public long getMillisFromLastRoll() {
722 return (System.currentTimeMillis() - lastRollTs.get());
723 }
724
725 @VisibleForTesting
726 protected void periodicRollForTesting() throws IOException {
727 lock.lock();
728 try {
729 periodicRoll();
730 } finally {
731 lock.unlock();
732 }
733 }
734
735 @VisibleForTesting
736 protected boolean rollWriterForTesting() throws IOException {
737 lock.lock();
738 try {
739 return rollWriter();
740 } finally {
741 lock.unlock();
742 }
743 }
744
745 private void periodicRoll() throws IOException {
746 if (storeTracker.isEmpty()) {
747 if (LOG.isTraceEnabled()) {
748 LOG.trace("no active procedures");
749 }
750 tryRollWriter();
751 removeAllLogs(flushLogId - 1);
752 } else {
753 if (storeTracker.isUpdated()) {
754 if (LOG.isTraceEnabled()) {
755 LOG.trace("all the active procedures are in the latest log");
756 }
757 removeAllLogs(flushLogId - 1);
758 }
759
760
761
762 if (totalSynced.get() > rollThreshold || getMillisToNextPeriodicRoll() <= 0) {
763 tryRollWriter();
764 }
765
766 removeInactiveLogs();
767 }
768 }
769
770 private boolean rollWriter() throws IOException {
771
772 if (!rollWriter(flushLogId + 1)) {
773 LOG.warn("someone else has already created log " + flushLogId);
774 return false;
775 }
776
777
778
779 if (getMaxLogId(getLogFiles()) > flushLogId) {
780 LOG.warn("Someone else created new logs. Expected maxLogId < " + flushLogId);
781 logs.getLast().removeFile();
782 return false;
783 }
784
785
786 return true;
787 }
788
789 private boolean rollWriter(final long logId) throws IOException {
790 assert logId > flushLogId : "logId=" + logId + " flushLogId=" + flushLogId;
791 assert lock.isHeldByCurrentThread() : "expected to be the lock owner. " + lock.isLocked();
792
793 ProcedureWALHeader header = ProcedureWALHeader.newBuilder()
794 .setVersion(ProcedureWALFormat.HEADER_VERSION)
795 .setType(ProcedureWALFormat.LOG_TYPE_STREAM)
796 .setMinProcId(storeTracker.getMinProcId())
797 .setLogId(logId)
798 .build();
799
800 FSDataOutputStream newStream = null;
801 Path newLogFile = null;
802 long startPos = -1;
803 newLogFile = getLogFilePath(logId);
804 try {
805 newStream = fs.create(newLogFile, false);
806 } catch (FileAlreadyExistsException e) {
807 LOG.error("Log file with id=" + logId + " already exists", e);
808 return false;
809 } catch (RemoteException re) {
810 LOG.warn("failed to create log file with id=" + logId, re);
811 return false;
812 }
813 try {
814 ProcedureWALFormat.writeHeader(newStream, header);
815 startPos = newStream.getPos();
816 } catch (IOException ioe) {
817 LOG.warn("Encountered exception writing header", ioe);
818 newStream.close();
819 return false;
820 }
821
822 closeStream();
823
824 storeTracker.resetUpdates();
825 stream = newStream;
826 flushLogId = logId;
827 totalSynced.set(0);
828 long rollTs = System.currentTimeMillis();
829 lastRollTs.set(rollTs);
830 logs.add(new ProcedureWALFile(fs, newLogFile, header, startPos, rollTs));
831
832 if (LOG.isDebugEnabled()) {
833 LOG.debug("Roll new state log: " + logId);
834 }
835 return true;
836 }
837
838 private void closeStream() {
839 try {
840 if (stream != null) {
841 try {
842 ProcedureWALFile log = logs.getLast();
843 log.setProcIds(storeTracker.getUpdatedMinProcId(), storeTracker.getUpdatedMaxProcId());
844 long trailerSize = ProcedureWALFormat.writeTrailer(stream, storeTracker);
845 log.addToSize(trailerSize);
846 } catch (IOException e) {
847 LOG.warn("Unable to write the trailer: " + e.getMessage());
848 }
849 stream.close();
850 }
851 } catch (IOException e) {
852 LOG.error("Unable to close the stream", e);
853 } finally {
854 stream = null;
855 }
856 }
857
858
859
860
861 private void removeInactiveLogs() {
862
863 while (logs.size() > 1) {
864 ProcedureWALFile log = logs.getFirst();
865 if (storeTracker.isTracking(log.getMinProcId(), log.getMaxProcId())) {
866 break;
867 }
868 removeLogFile(log);
869 }
870 }
871
872 private void removeAllLogs(long lastLogId) {
873 if (logs.size() <= 1) return;
874
875 if (LOG.isDebugEnabled()) {
876 LOG.debug("Remove all state logs with ID less than " + lastLogId);
877 }
878 while (logs.size() > 1) {
879 ProcedureWALFile log = logs.getFirst();
880 if (lastLogId < log.getLogId()) {
881 break;
882 }
883 removeLogFile(log);
884 }
885 }
886
887 private boolean removeLogFile(final ProcedureWALFile log) {
888 try {
889 if (LOG.isDebugEnabled()) {
890 LOG.debug("Remove log: " + log);
891 }
892 log.removeFile();
893 logs.remove(log);
894 LOG.info("Remove log: " + log);
895 LOG.info("Removed logs: " + logs);
896 if (logs.size() == 0) { LOG.error("Expected at least one log"); }
897 assert logs.size() > 0 : "expected at least one log";
898 } catch (IOException e) {
899 LOG.error("Unable to remove log: " + log, e);
900 return false;
901 }
902 return true;
903 }
904
905
906
907
908 public Path getLogDir() {
909 return this.logDir;
910 }
911
912 public FileSystem getFileSystem() {
913 return this.fs;
914 }
915
916 protected Path getLogFilePath(final long logId) throws IOException {
917 return new Path(logDir, String.format("state-%020d.log", logId));
918 }
919
920 private static long getLogIdFromName(final String name) {
921 int end = name.lastIndexOf(".log");
922 int start = name.lastIndexOf('-') + 1;
923 while (start < end) {
924 if (name.charAt(start) != '0')
925 break;
926 start++;
927 }
928 return Long.parseLong(name.substring(start, end));
929 }
930
931 private FileStatus[] getLogFiles() throws IOException {
932 try {
933 return fs.listStatus(logDir, new PathFilter() {
934 @Override
935 public boolean accept(Path path) {
936 String name = path.getName();
937 return name.startsWith("state-") && name.endsWith(".log");
938 }
939 });
940 } catch (FileNotFoundException e) {
941 LOG.warn("Log directory not found: " + e.getMessage());
942 return null;
943 }
944 }
945
946 private static long getMaxLogId(final FileStatus[] logFiles) {
947 long maxLogId = 0;
948 if (logFiles != null && logFiles.length > 0) {
949 for (int i = 0; i < logFiles.length; ++i) {
950 maxLogId = Math.max(maxLogId, getLogIdFromName(logFiles[i].getPath().getName()));
951 }
952 }
953 return maxLogId;
954 }
955
956
957
958
959 private long initOldLogs(final FileStatus[] logFiles) throws IOException {
960 this.logs.clear();
961
962 long maxLogId = 0;
963 if (logFiles != null && logFiles.length > 0) {
964 for (int i = 0; i < logFiles.length; ++i) {
965 final Path logPath = logFiles[i].getPath();
966 leaseRecovery.recoverFileLease(fs, logPath);
967 maxLogId = Math.max(maxLogId, getLogIdFromName(logPath.getName()));
968
969 ProcedureWALFile log = initOldLog(logFiles[i]);
970 if (log != null) {
971 this.logs.add(log);
972 }
973 }
974 Collections.sort(this.logs);
975 initTrackerFromOldLogs();
976 }
977 return maxLogId;
978 }
979
980 private void initTrackerFromOldLogs() {
981
982 if (!logs.isEmpty()) {
983 ProcedureWALFile log = logs.getLast();
984 try {
985 log.readTracker(storeTracker);
986 } catch (IOException e) {
987 LOG.warn("Unable to read tracker for " + log + " - " + e.getMessage());
988
989 storeTracker.reset();
990 storeTracker.setPartialFlag(true);
991 }
992 }
993 }
994
995 private ProcedureWALFile initOldLog(final FileStatus logFile) throws IOException {
996 ProcedureWALFile log = new ProcedureWALFile(fs, logFile);
997 if (logFile.getLen() == 0) {
998 LOG.warn("Remove uninitialized log: " + logFile);
999 log.removeFile();
1000 return null;
1001 }
1002 if (LOG.isDebugEnabled()) {
1003 LOG.debug("Opening state-log: " + logFile);
1004 }
1005 try {
1006 log.open();
1007 } catch (ProcedureWALFormat.InvalidWALDataException e) {
1008 LOG.warn("Remove uninitialized log: " + logFile, e);
1009 log.removeFile();
1010 return null;
1011 } catch (IOException e) {
1012 String msg = "Unable to read state log: " + logFile;
1013 LOG.error(msg, e);
1014 throw new IOException(msg, e);
1015 }
1016
1017 if (log.isCompacted()) {
1018 try {
1019 log.readTrailer();
1020 } catch (IOException e) {
1021 LOG.warn("Unfinished compacted log: " + logFile, e);
1022 log.removeFile();
1023 return null;
1024 }
1025 }
1026 return log;
1027 }
1028 }