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