View Javadoc

1   /**
2    * Licensed to the Apache Software Foundation (ASF) under one
3    * or more contributor license agreements.  See the NOTICE file
4    * distributed with this work for additional information
5    * regarding copyright ownership.  The ASF licenses this file
6    * to you under the Apache License, Version 2.0 (the
7    * "License"); you may not use this file except in compliance
8    * with the License.  You may obtain a copy of the License at
9    *
10   *     http://www.apache.org/licenses/LICENSE-2.0
11   *
12   * Unless required by applicable law or agreed to in writing, software
13   * distributed under the License is distributed on an "AS IS" BASIS,
14   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15   * See the License for the specific language governing permissions and
16   * limitations under the License.
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   * WAL implementation of the ProcedureStore.
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; // 1h
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; // 32M
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   // Variables used for UI display
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     // Init buffer slots
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     // Tunings
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     // WebUI
206     syncMetricsBuffer = new CircularFifoBuffer(
207       conf.getInt(STORE_WAL_SYNC_STATS_COUNT, DEFAULT_SYNC_STATS_COUNT));
208 
209     // Init sync thread
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     // Close the writer
248     closeStream();
249 
250     // Close the old logs
251     // they should be already closed, this is just in case the load fails
252     // and we call start() and then stop()
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         // Get Log-MaxID and recover lease on old logs
300         flushLogId = initOldLogs(oldLogs);
301 
302         // Create new state-log
303         if (!rollWriter(flushLogId + 1)) {
304           // someone else has already created this log
305           LOG.debug("someone else has already created log " + flushLogId);
306           continue;
307         }
308 
309         // We have the lease on the log
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     // Nothing to do, If we have only the current log.
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     // Load the old logs
344     Iterator<ProcedureWALFile> it = logs.descendingIterator();
345     it.next(); // Skip the current log
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           // TODO: sideline corrupted log
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       // Serialize the insert
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       // Push the transaction data and wait until it is persisted
399       pushData(PushType.INSERT, slot, proc.getProcId(), subProcIds);
400     } catch (IOException e) {
401       // We are not able to serialize the procedure.
402       // this is a code error, and we are not able to go on.
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       // Serialize the update
420       ProcedureWALFormat.writeUpdate(slot, proc);
421 
422       // Push the transaction data and wait until it is persisted
423       pushData(PushType.UPDATE, slot, proc.getProcId(), null);
424     } catch (IOException e) {
425       // We are not able to serialize the procedure.
426       // this is a code error, and we are not able to go on.
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       // Serialize the delete
443       ProcedureWALFormat.writeDelete(slot, procId);
444 
445       // Push the transaction data and wait until it is persisted
446       pushData(PushType.DELETE, slot, procId, null);
447     } catch (IOException e) {
448       // We are not able to serialize the procedure.
449       // this is a code error, and we are not able to go on.
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       // Wait for the sync to be completed
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       // Notify that there is new data
502       if (slotIndex == 1) {
503         waitCond.signal();
504       }
505 
506       // Notify that the slots are full
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           // Wait until new data is available
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               // no data.. probably a stop() or a periodic roll
574               continue;
575             }
576           }
577           // Wait SYNC_WAIT_MSEC or the signal of "slots full" before flushing
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           // update webui circular buffers (TODO: get rid of allocations)
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           // sync
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       // if the log size has exceeded the roll threshold
761       // or the periodic roll timeout is expired, try to roll the wal.
762       if (totalSynced.get() > rollThreshold || getMillisToNextPeriodicRoll() <= 0) {
763         tryRollWriter();
764       }
765 
766       removeInactiveLogs();
767     }
768   }
769 
770   private boolean rollWriter() throws IOException {
771     // Create new state-log
772     if (!rollWriter(flushLogId + 1)) {
773       LOG.warn("someone else has already created log " + flushLogId);
774       return false;
775     }
776 
777     // We have the lease on the log,
778     // but we should check if someone else has created new files
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     // We have the lease on the log
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   //  Log Files cleaner helpers
860   // ==========================================================================
861   private void removeInactiveLogs() {
862     // Verify if the ProcId of the first oldest is still active. if not remove the file.
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   //  FileSystem Log Files helpers
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    * @return Max-LogID of the specified log file set
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     // TODO: Load the most recent tracker available
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         // try the next one...
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 }