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.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   * WAL implementation of the ProcedureStore.
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; // 1h
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; // 32M
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   // Variables used for UI display
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     // Init buffer slots
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     // Tunings
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     // WebUI
207     syncMetricsBuffer = new CircularFifoBuffer(
208       conf.getInt(STORE_WAL_SYNC_STATS_COUNT, DEFAULT_SYNC_STATS_COUNT));
209 
210     // Init sync thread
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     // Close the writer
249     closeStream();
250 
251     // Close the old logs
252     // they should be already closed, this is just in case the load fails
253     // and we call start() and then stop()
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         // Get Log-MaxID and recover lease on old logs
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         // Create new state-log
310         if (!rollWriter(flushLogId + 1)) {
311           // someone else has already created this log
312           LOG.debug("someone else has already created log " + flushLogId);
313           continue;
314         }
315 
316         // We have the lease on the log
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     // Nothing to do, If we have only the current log.
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     // Load the old logs
351     Iterator<ProcedureWALFile> it = logs.descendingIterator();
352     it.next(); // Skip the current log
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           // TODO: sideline corrupted log
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       // Serialize the insert
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       // Push the transaction data and wait until it is persisted
406       pushData(PushType.INSERT, slot, proc.getProcId(), subProcIds);
407     } catch (IOException e) {
408       // We are not able to serialize the procedure.
409       // this is a code error, and we are not able to go on.
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       // Serialize the update
427       ProcedureWALFormat.writeUpdate(slot, proc);
428 
429       // Push the transaction data and wait until it is persisted
430       pushData(PushType.UPDATE, slot, proc.getProcId(), null);
431     } catch (IOException e) {
432       // We are not able to serialize the procedure.
433       // this is a code error, and we are not able to go on.
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       // Serialize the delete
450       ProcedureWALFormat.writeDelete(slot, procId);
451 
452       // Push the transaction data and wait until it is persisted
453       pushData(PushType.DELETE, slot, procId, null);
454     } catch (IOException e) {
455       // We are not able to serialize the procedure.
456       // this is a code error, and we are not able to go on.
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       // Wait for the sync to be completed
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       // Notify that there is new data
509       if (slotIndex == 1) {
510         waitCond.signal();
511       }
512 
513       // Notify that the slots are full
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           // Wait until new data is available
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               // no data.. probably a stop() or a periodic roll
581               continue;
582             }
583           }
584           // Wait SYNC_WAIT_MSEC or the signal of "slots full" before flushing
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           // update webui circular buffers (TODO: get rid of allocations)
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           // sync
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       // if the log size has exceeded the roll threshold
768       // or the periodic roll timeout is expired, try to roll the wal.
769       if (totalSynced.get() > rollThreshold || getMillisToNextPeriodicRoll() <= 0) {
770         tryRollWriter();
771       }
772 
773       removeInactiveLogs();
774     }
775   }
776 
777   private boolean rollWriter() throws IOException {
778     // Create new state-log
779     if (!rollWriter(flushLogId + 1)) {
780       LOG.warn("someone else has already created log " + flushLogId);
781       return false;
782     }
783 
784     // We have the lease on the log,
785     // but we should check if someone else has created new files
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     // We have the lease on the log
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   //  Log Files cleaner helpers
867   // ==========================================================================
868   private void removeInactiveLogs() {
869     // Verify if the ProcId of the first oldest is still active. if not remove the file.
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   //  FileSystem Log Files helpers
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    * @return Max-LogID of the specified log file set
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     // TODO: Load the most recent tracker available
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         // try the next one...
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 }