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  package org.apache.hadoop.hbase.regionserver.wal;
19  
20  import static org.apache.hadoop.hbase.wal.DefaultWALProvider.WAL_FILE_NAME_DELIMITER;
21  
22  import java.io.FileNotFoundException;
23  import java.io.IOException;
24  import java.io.InterruptedIOException;
25  import java.io.OutputStream;
26  import java.lang.management.MemoryUsage;
27  import java.lang.reflect.InvocationTargetException;
28  import java.net.URLEncoder;
29  import java.util.ArrayList;
30  import java.util.Arrays;
31  import java.util.Comparator;
32  import java.util.List;
33  import java.util.Map;
34  import java.util.NavigableMap;
35  import java.util.Set;
36  import java.util.concurrent.BlockingQueue;
37  import java.util.concurrent.ConcurrentHashMap;
38  import java.util.concurrent.ConcurrentSkipListMap;
39  import java.util.concurrent.CopyOnWriteArrayList;
40  import java.util.concurrent.CountDownLatch;
41  import java.util.concurrent.ExecutionException;
42  import java.util.concurrent.ExecutorService;
43  import java.util.concurrent.Executors;
44  import java.util.concurrent.LinkedBlockingQueue;
45  import java.util.concurrent.TimeUnit;
46  import java.util.concurrent.atomic.AtomicBoolean;
47  import java.util.concurrent.atomic.AtomicInteger;
48  import java.util.concurrent.atomic.AtomicLong;
49  import java.util.concurrent.locks.ReentrantLock;
50  
51  import org.apache.commons.logging.Log;
52  import org.apache.commons.logging.LogFactory;
53  import org.apache.hadoop.conf.Configuration;
54  import org.apache.hadoop.fs.FSDataOutputStream;
55  import org.apache.hadoop.fs.FileStatus;
56  import org.apache.hadoop.fs.FileSystem;
57  import org.apache.hadoop.fs.Path;
58  import org.apache.hadoop.fs.PathFilter;
59  import org.apache.hadoop.hbase.Cell;
60  import org.apache.hadoop.hbase.CellUtil;
61  import org.apache.hadoop.hbase.HBaseConfiguration;
62  import org.apache.hadoop.hbase.HConstants;
63  import org.apache.hadoop.hbase.HRegionInfo;
64  import org.apache.hadoop.hbase.HTableDescriptor;
65  import org.apache.hadoop.hbase.classification.InterfaceAudience;
66  import org.apache.hadoop.hbase.exceptions.TimeoutIOException;
67  import org.apache.hadoop.hbase.io.util.HeapMemorySizeUtil;
68  import org.apache.hadoop.hbase.util.Bytes;
69  import org.apache.hadoop.hbase.util.ClassSize;
70  import org.apache.hadoop.hbase.util.DrainBarrier;
71  import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
72  import org.apache.hadoop.hbase.util.FSUtils;
73  import org.apache.hadoop.hbase.util.HasThread;
74  import org.apache.hadoop.hbase.util.Threads;
75  import org.apache.hadoop.hbase.wal.DefaultWALProvider;
76  import org.apache.hadoop.hbase.wal.WAL;
77  import org.apache.hadoop.hbase.wal.WALFactory;
78  import org.apache.hadoop.hbase.wal.WALKey;
79  import org.apache.hadoop.hbase.wal.WALPrettyPrinter;
80  import org.apache.hadoop.hbase.wal.WALProvider.Writer;
81  import org.apache.hadoop.hbase.wal.WALSplitter;
82  import org.apache.hadoop.hdfs.DFSOutputStream;
83  import org.apache.hadoop.hdfs.client.HdfsDataOutputStream;
84  import org.apache.hadoop.hdfs.protocol.DatanodeInfo;
85  import org.apache.hadoop.util.StringUtils;
86  import org.apache.htrace.NullScope;
87  import org.apache.htrace.Span;
88  import org.apache.htrace.Trace;
89  import org.apache.htrace.TraceScope;
90  
91  import com.google.common.annotations.VisibleForTesting;
92  import com.lmax.disruptor.BlockingWaitStrategy;
93  import com.lmax.disruptor.EventHandler;
94  import com.lmax.disruptor.ExceptionHandler;
95  import com.lmax.disruptor.LifecycleAware;
96  import com.lmax.disruptor.TimeoutException;
97  import com.lmax.disruptor.dsl.Disruptor;
98  import com.lmax.disruptor.dsl.ProducerType;
99  
100 /**
101  * Implementation of {@link WAL} to go against {@link FileSystem}; i.e. keep WALs in HDFS.
102  * Only one WAL is ever being written at a time.  When a WAL hits a configured maximum size,
103  * it is rolled.  This is done internal to the implementation.
104  *
105  * <p>As data is flushed from the MemStore to other on-disk structures (files sorted by
106  * key, hfiles), a WAL becomes obsolete. We can let go of all the log edits/entries for a given
107  * HRegion-sequence id.  A bunch of work in the below is done keeping account of these region
108  * sequence ids -- what is flushed out to hfiles, and what is yet in WAL and in memory only.
109  *
110  * <p>It is only practical to delete entire files. Thus, we delete an entire on-disk file
111  * <code>F</code> when all of the edits in <code>F</code> have a log-sequence-id that's older
112  * (smaller) than the most-recent flush.
113  *
114  * <p>To read an WAL, call {@link WALFactory#createReader(org.apache.hadoop.fs.FileSystem,
115  * org.apache.hadoop.fs.Path)}.
116  *
117  * <h2>Failure Semantic</h2>
118  * If an exception on append or sync, roll the WAL because the current WAL is now a lame duck;
119  * any more appends or syncs will fail also with the same original exception. If we have made
120  * successful appends to the WAL and we then are unable to sync them, our current semantic is to
121  * return error to the client that the appends failed but also to abort the current context,
122  * usually the hosting server. We need to replay the WALs. TODO: Change this semantic. A roll of
123  * WAL may be sufficient as long as we have flagged client that the append failed. TODO:
124  * replication may pick up these last edits though they have been marked as failed append (Need to
125  * keep our own file lengths, not rely on HDFS).
126  */
127 @InterfaceAudience.Private
128 public class FSHLog implements WAL {
129   // IMPLEMENTATION NOTES:
130   //
131   // At the core is a ring buffer.  Our ring buffer is the LMAX Disruptor.  It tries to
132   // minimize synchronizations and volatile writes when multiple contending threads as is the case
133   // here appending and syncing on a single WAL.  The Disruptor is configured to handle multiple
134   // producers but it has one consumer only (the producers in HBase are IPC Handlers calling append
135   // and then sync).  The single consumer/writer pulls the appends and syncs off the ring buffer.
136   // When a handler calls sync, it is given back a future. The producer 'blocks' on the future so
137   // it does not return until the sync completes.  The future is passed over the ring buffer from
138   // the producer/handler to the consumer thread where it does its best to batch up the producer
139   // syncs so one WAL sync actually spans multiple producer sync invocations.  How well the
140   // batching works depends on the write rate; i.e. we tend to batch more in times of
141   // high writes/syncs.
142   //
143   // Calls to append now also wait until the append has been done on the consumer side of the
144   // disruptor.  We used to not wait but it makes the implemenation easier to grok if we have
145   // the region edit/sequence id after the append returns.
146   //
147   // TODO: Handlers need to coordinate appending AND syncing.  Can we have the threads contend
148   // once only?  Probably hard given syncs take way longer than an append.
149   //
150   // The consumer threads pass the syncs off to multiple syncing threads in a round robin fashion
151   // to ensure we keep up back-to-back FS sync calls (FS sync calls are the long poll writing the
152   // WAL).  The consumer thread passes the futures to the sync threads for it to complete
153   // the futures when done.
154   //
155   // The 'sequence' in the below is the sequence of the append/sync on the ringbuffer.  It
156   // acts as a sort-of transaction id.  It is always incrementing.
157   //
158   // The RingBufferEventHandler class hosts the ring buffer consuming code.  The threads that
159   // do the actual FS sync are implementations of SyncRunner.  SafePointZigZagLatch is a
160   // synchronization class used to halt the consumer at a safe point --  just after all outstanding
161   // syncs and appends have completed -- so the log roller can swap the WAL out under it.
162 
163   private static final Log LOG = LogFactory.getLog(FSHLog.class);
164 
165   private static final int DEFAULT_SLOW_SYNC_TIME_MS = 100; // in ms
166 
167   private static final int DEFAULT_WAL_SYNC_TIMEOUT_MS = 5 * 60 * 1000; // in ms, 5min
168 
169   /**
170    * The nexus at which all incoming handlers meet.  Does appends and sync with an ordering.
171    * Appends and syncs are each put on the ring which means handlers need to
172    * smash up against the ring twice (can we make it once only? ... maybe not since time to append
173    * is so different from time to sync and sometimes we don't want to sync or we want to async
174    * the sync).  The ring is where we make sure of our ordering and it is also where we do
175    * batching up of handler sync calls.
176    */
177   private final Disruptor<RingBufferTruck> disruptor;
178 
179   /**
180    * An executorservice that runs the disruptor AppendEventHandler append executor.
181    */
182   private final ExecutorService appendExecutor;
183 
184   /**
185    * This fellow is run by the above appendExecutor service but it is all about batching up appends
186    * and syncs; it may shutdown without cleaning out the last few appends or syncs.  To guard
187    * against this, keep a reference to this handler and do explicit close on way out to make sure
188    * all flushed out before we exit.
189    */
190   private final RingBufferEventHandler ringBufferEventHandler;
191 
192   /**
193    * Map of {@link SyncFuture}s owned by Thread objects. Used so we reuse SyncFutures.
194    * Thread local is used so JVM can GC the terminated thread for us. See HBASE-21228
195    * <p>
196    */
197   private final ThreadLocal<SyncFuture> cachedSyncFutures;
198 
199   /**
200    * The highest known outstanding unsync'd WALEdit sequence number where sequence number is the
201    * ring buffer sequence.  Maintained by the ring buffer consumer.
202    */
203   private volatile long highestUnsyncedSequence = -1;
204 
205   /**
206    * Updated to the ring buffer sequence of the last successful sync call.  This can be less than
207    * {@link #highestUnsyncedSequence} for case where we have an append where a sync has not yet
208    * come in for it.  Maintained by the syncing threads.
209    */
210   private final AtomicLong highestSyncedSequence = new AtomicLong(0);
211 
212   /**
213    * file system instance
214    */
215   protected final FileSystem fs;
216 
217   /**
218    * WAL directory, where all WAL files would be placed.
219    */
220   private final Path fullPathLogDir;
221 
222   /**
223    * dir path where old logs are kept.
224    */
225   private final Path fullPathArchiveDir;
226 
227   /**
228    * Matches just those wal files that belong to this wal instance.
229    */
230   private final PathFilter ourFiles;
231 
232   /**
233    * Prefix of a WAL file, usually the region server name it is hosted on.
234    */
235   private final String logFilePrefix;
236 
237   /**
238    * Suffix included on generated wal file names
239    */
240   private final String logFileSuffix;
241 
242   /**
243    * Prefix used when checking for wal membership.
244    */
245   private final String prefixPathStr;
246 
247   private final WALCoprocessorHost coprocessorHost;
248 
249   /**
250    * conf object
251    */
252   protected final Configuration conf;
253 
254   /** Listeners that are called on WAL events. */
255   private final List<WALActionsListener> listeners =
256     new CopyOnWriteArrayList<WALActionsListener>();
257 
258   @Override
259   public void registerWALActionsListener(final WALActionsListener listener) {
260     this.listeners.add(listener);
261   }
262 
263   @Override
264   public boolean unregisterWALActionsListener(final WALActionsListener listener) {
265     return this.listeners.remove(listener);
266   }
267 
268   @Override
269   public WALCoprocessorHost getCoprocessorHost() {
270     return coprocessorHost;
271   }
272 
273   /**
274    * FSDataOutputStream associated with the current SequenceFile.writer
275    */
276   private FSDataOutputStream hdfs_out;
277 
278   // All about log rolling if not enough replicas outstanding.
279 
280   // Minimum tolerable replicas, if the actual value is lower than it, rollWriter will be triggered
281   private final int minTolerableReplication;
282 
283   private final int slowSyncNs;
284 
285   private final long walSyncTimeout;
286 
287   // If live datanode count is lower than the default replicas value,
288   // RollWriter will be triggered in each sync(So the RollWriter will be
289   // triggered one by one in a short time). Using it as a workaround to slow
290   // down the roll frequency triggered by checkLowReplication().
291   private final AtomicInteger consecutiveLogRolls = new AtomicInteger(0);
292 
293   private final int lowReplicationRollLimit;
294 
295   // If consecutiveLogRolls is larger than lowReplicationRollLimit,
296   // then disable the rolling in checkLowReplication().
297   // Enable it if the replications recover.
298   private volatile boolean lowReplicationRollEnabled = true;
299 
300   /**
301    * Class that does accounting of sequenceids in WAL subsystem. Holds oldest outstanding
302    * sequence id as yet not flushed as well as the most recent edit sequence id appended to the
303    * WAL. Has facility for answering questions such as "Is it safe to GC a WAL?".
304    */
305   private SequenceIdAccounting sequenceIdAccounting = new SequenceIdAccounting();
306 
307   /**
308    * Current log file.
309    */
310   volatile Writer writer;
311 
312   /** The barrier used to ensure that close() waits for all log rolls and flushes to finish. */
313   private final DrainBarrier closeBarrier = new DrainBarrier();
314 
315   /**
316    * This lock makes sure only one log roll runs at a time. Should not be taken while any other
317    * lock is held. We don't just use synchronized because that results in bogus and tedious
318    * findbugs warning when it thinks synchronized controls writer thread safety.  It is held when
319    * we are actually rolling the log.  It is checked when we are looking to see if we should roll
320    * the log or not.
321    */
322   private final ReentrantLock rollWriterLock = new ReentrantLock(true);
323 
324   private volatile boolean closed = false;
325   private final AtomicBoolean shutdown = new AtomicBoolean(false);
326 
327   // The timestamp (in ms) when the log file was created.
328   private final AtomicLong filenum = new AtomicLong(-1);
329 
330   // Number of transactions in the current Wal.
331   private final AtomicInteger numEntries = new AtomicInteger(0);
332 
333   // If > than this size, roll the log.
334   private final long logrollsize;
335 
336   /**
337    * The total size of wal
338    */
339   private AtomicLong totalLogSize = new AtomicLong(0);
340 
341   /*
342    * If more than this many logs, force flush of oldest region to oldest edit
343    * goes to disk.  If too many and we crash, then will take forever replaying.
344    * Keep the number of logs tidy.
345    */
346   private final int maxLogs;
347 
348   /** Number of log close errors tolerated before we abort */
349   private final int closeErrorsTolerated;
350 
351   private final AtomicInteger closeErrorCount = new AtomicInteger();
352 
353   // Last time to check low replication on hlog's pipeline
354   private volatile long lastTimeCheckLowReplication = EnvironmentEdgeManager.currentTime();
355 
356 
357   /**
358    * WAL Comparator; it compares the timestamp (log filenum), present in the log file name.
359    * Throws an IllegalArgumentException if used to compare paths from different wals.
360    */
361   final Comparator<Path> LOG_NAME_COMPARATOR = new Comparator<Path>() {
362     @Override
363     public int compare(Path o1, Path o2) {
364       long t1 = getFileNumFromFileName(o1);
365       long t2 = getFileNumFromFileName(o2);
366       if (t1 == t2) return 0;
367       return (t1 > t2) ? 1 : -1;
368     }
369   };
370 
371   /**
372    * Map of WAL log file to the latest sequence ids of all regions it has entries of.
373    * The map is sorted by the log file creation timestamp (contained in the log file name).
374    */
375   private NavigableMap<Path, Map<byte[], Long>> byWalRegionSequenceIds =
376     new ConcurrentSkipListMap<Path, Map<byte[], Long>>(LOG_NAME_COMPARATOR);
377 
378   /**
379    * Exception handler to pass the disruptor ringbuffer.  Same as native implementation only it
380    * logs using our logger instead of java native logger.
381    */
382   static class RingBufferExceptionHandler implements ExceptionHandler {
383     @Override
384     public void handleEventException(Throwable ex, long sequence, Object event) {
385       LOG.error("Sequence=" + sequence + ", event=" + event, ex);
386       throw new RuntimeException(ex);
387     }
388 
389     @Override
390     public void handleOnStartException(Throwable ex) {
391       LOG.error(ex);
392       throw new RuntimeException(ex);
393     }
394 
395     @Override
396     public void handleOnShutdownException(Throwable ex) {
397       LOG.error(ex);
398       throw new RuntimeException(ex);
399     }
400   }
401 
402   /**
403    * Constructor.
404    *
405    * @param fs filesystem handle
406    * @param root path for stored and archived wals
407    * @param logDir dir where wals are stored
408    * @param conf configuration to use
409    * @throws IOException
410    */
411   public FSHLog(final FileSystem fs, final Path root, final String logDir, final Configuration conf)
412       throws IOException {
413     this(fs, root, logDir, HConstants.HREGION_OLDLOGDIR_NAME, conf, null, true, null, null);
414   }
415 
416   /**
417    * Create an edit log at the given <code>dir</code> location.
418    *
419    * You should never have to load an existing log. If there is a log at
420    * startup, it should have already been processed and deleted by the time the
421    * WAL object is started up.
422    *
423    * @param fs filesystem handle
424    * @param rootDir path to where logs and oldlogs
425    * @param logDir dir where wals are stored
426    * @param archiveDir dir where wals are archived
427    * @param conf configuration to use
428    * @param listeners Listeners on WAL events. Listeners passed here will
429    * be registered before we do anything else; e.g. the
430    * Constructor {@link #rollWriter()}.
431    * @param failIfWALExists If true IOException will be thrown if files related to this wal
432    *        already exist.
433    * @param prefix should always be hostname and port in distributed env and
434    *        it will be URL encoded before being used.
435    *        If prefix is null, "wal" will be used
436    * @param suffix will be url encoded. null is treated as empty. non-empty must start with
437    *        {@link DefaultWALProvider#WAL_FILE_NAME_DELIMITER}
438    * @throws IOException
439    */
440   public FSHLog(final FileSystem fs, final Path rootDir, final String logDir,
441       final String archiveDir, final Configuration conf,
442       final List<WALActionsListener> listeners,
443       final boolean failIfWALExists, final String prefix, final String suffix)
444       throws IOException {
445     this.fs = fs;
446     this.fullPathLogDir = new Path(rootDir, logDir);
447     this.fullPathArchiveDir = new Path(rootDir, archiveDir);
448     this.conf = conf;
449 
450     if (!fs.exists(fullPathLogDir) && !fs.mkdirs(fullPathLogDir)) {
451       throw new IOException("Unable to mkdir " + fullPathLogDir);
452     }
453 
454     if (!fs.exists(this.fullPathArchiveDir)) {
455       if (!fs.mkdirs(this.fullPathArchiveDir)) {
456         throw new IOException("Unable to mkdir " + this.fullPathArchiveDir);
457       }
458     }
459 
460     // If prefix is null||empty then just name it wal
461     this.logFilePrefix =
462       prefix == null || prefix.isEmpty() ? "wal" : URLEncoder.encode(prefix, "UTF8");
463     // we only correctly differentiate suffices when numeric ones start with '.'
464     if (suffix != null && !(suffix.isEmpty()) && !(suffix.startsWith(WAL_FILE_NAME_DELIMITER))) {
465       throw new IllegalArgumentException("WAL suffix must start with '" + WAL_FILE_NAME_DELIMITER +
466           "' but instead was '" + suffix + "'");
467     }
468     // Now that it exists, set the storage policy for the entire directory of wal files related to
469     // this FSHLog instance
470     FSUtils.setStoragePolicy(fs, conf, this.fullPathLogDir, HConstants.WAL_STORAGE_POLICY,
471       HConstants.DEFAULT_WAL_STORAGE_POLICY);
472     this.logFileSuffix = (suffix == null) ? "" : URLEncoder.encode(suffix, "UTF8");
473     this.prefixPathStr = new Path(fullPathLogDir,
474         logFilePrefix + WAL_FILE_NAME_DELIMITER).toString();
475 
476     this.ourFiles = new PathFilter() {
477       @Override
478       public boolean accept(final Path fileName) {
479         // The path should start with dir/<prefix> and end with our suffix
480         final String fileNameString = fileName.toString();
481         if (!fileNameString.startsWith(prefixPathStr)) {
482           return false;
483         }
484         if (logFileSuffix.isEmpty()) {
485           // in the case of the null suffix, we need to ensure the filename ends with a timestamp.
486           return org.apache.commons.lang.StringUtils.isNumeric(
487               fileNameString.substring(prefixPathStr.length()));
488         } else if (!fileNameString.endsWith(logFileSuffix)) {
489           return false;
490         }
491         return true;
492       }
493     };
494 
495     if (failIfWALExists) {
496       final FileStatus[] walFiles = FSUtils.listStatus(fs, fullPathLogDir, ourFiles);
497       if (null != walFiles && 0 != walFiles.length) {
498         throw new IOException("Target WAL already exists within directory " + fullPathLogDir);
499       }
500     }
501 
502     // Register listeners.  TODO: Should this exist anymore?  We have CPs?
503     if (listeners != null) {
504       for (WALActionsListener i: listeners) {
505         registerWALActionsListener(i);
506       }
507     }
508     this.coprocessorHost = new WALCoprocessorHost(this, conf);
509 
510     // Get size to roll log at. Roll at 95% of HDFS block size so we avoid crossing HDFS blocks
511     // (it costs a little x'ing bocks)
512     final long blocksize = this.conf.getLong("hbase.regionserver.hlog.blocksize",
513         FSUtils.getDefaultBlockSize(this.fs, this.fullPathLogDir));
514     this.logrollsize =
515       (long)(blocksize * conf.getFloat("hbase.regionserver.logroll.multiplier", 0.95f));
516 
517     float memstoreRatio = conf.getFloat(HeapMemorySizeUtil.MEMSTORE_SIZE_KEY,
518       conf.getFloat(HeapMemorySizeUtil.MEMSTORE_SIZE_OLD_KEY,
519         HeapMemorySizeUtil.DEFAULT_MEMSTORE_SIZE));
520     boolean maxLogsDefined = conf.get("hbase.regionserver.maxlogs") != null;
521     if(maxLogsDefined){
522       LOG.warn("'hbase.regionserver.maxlogs' was deprecated.");
523     }
524     this.maxLogs = conf.getInt("hbase.regionserver.maxlogs",
525         Math.max(32, calculateMaxLogFiles(memstoreRatio, logrollsize)));
526     this.minTolerableReplication = conf.getInt("hbase.regionserver.hlog.tolerable.lowreplication",
527         FSUtils.getDefaultReplication(fs, this.fullPathLogDir));
528     this.lowReplicationRollLimit =
529       conf.getInt("hbase.regionserver.hlog.lowreplication.rolllimit", 5);
530     this.closeErrorsTolerated = conf.getInt("hbase.regionserver.logroll.errors.tolerated", 0);
531     int maxHandlersCount = conf.getInt(HConstants.REGION_SERVER_HANDLER_COUNT, 200);
532 
533     LOG.info("WAL configuration: blocksize=" + StringUtils.byteDesc(blocksize) +
534       ", rollsize=" + StringUtils.byteDesc(this.logrollsize) +
535       ", prefix=" + this.logFilePrefix + ", suffix=" + logFileSuffix + ", logDir=" +
536       this.fullPathLogDir + ", archiveDir=" + this.fullPathArchiveDir);
537 
538     // rollWriter sets this.hdfs_out if it can.
539     rollWriter();
540 
541     this.slowSyncNs =
542         1000000 * conf.getInt("hbase.regionserver.hlog.slowsync.ms",
543           DEFAULT_SLOW_SYNC_TIME_MS);
544     this.walSyncTimeout = conf.getLong("hbase.regionserver.hlog.sync.timeout",
545         DEFAULT_WAL_SYNC_TIMEOUT_MS);
546 
547     // This is the 'writer' -- a single threaded executor.  This single thread 'consumes' what is
548     // put on the ring buffer.
549     String hostingThreadName = Thread.currentThread().getName();
550     this.appendExecutor = Executors.
551       newSingleThreadExecutor(Threads.getNamedThreadFactory(hostingThreadName + ".append"));
552     // Preallocate objects to use on the ring buffer.  The way that appends and syncs work, we will
553     // be stuck and make no progress if the buffer is filled with appends only and there is no
554     // sync. If no sync, then the handlers will be outstanding just waiting on sync completion
555     // before they return.
556     final int preallocatedEventCount =
557       this.conf.getInt("hbase.regionserver.wal.disruptor.event.count", 1024 * 16);
558     // Using BlockingWaitStrategy.  Stuff that is going on here takes so long it makes no sense
559     // spinning as other strategies do.
560     this.disruptor =
561       new Disruptor<RingBufferTruck>(RingBufferTruck.EVENT_FACTORY, preallocatedEventCount,
562         this.appendExecutor, ProducerType.MULTI, new BlockingWaitStrategy());
563     // Advance the ring buffer sequence so that it starts from 1 instead of 0,
564     // because SyncFuture.NOT_DONE = 0.
565     this.disruptor.getRingBuffer().next();
566     this.ringBufferEventHandler =
567       new RingBufferEventHandler(conf.getInt("hbase.regionserver.hlog.syncer.count", 5),
568         maxHandlersCount);
569     this.disruptor.handleExceptionsWith(new RingBufferExceptionHandler());
570     this.disruptor.handleEventsWith(new RingBufferEventHandler [] {this.ringBufferEventHandler});
571     this.cachedSyncFutures = new ThreadLocal<SyncFuture>() {
572       @Override
573       protected SyncFuture initialValue() {
574         return new SyncFuture();
575       }
576     };
577     // Starting up threads in constructor is a no no; Interface should have an init call.
578     this.disruptor.start();
579   }
580 
581   private int calculateMaxLogFiles(float memstoreSizeRatio, long logRollSize) {
582     long max = -1L;
583     final MemoryUsage usage = HeapMemorySizeUtil.safeGetHeapMemoryUsage();
584     if (usage != null) {
585       max = usage.getMax();
586     }
587     int maxLogs = Math.round(max * memstoreSizeRatio * 2 / logRollSize);
588     return maxLogs;
589   }
590 
591   /**
592    * Get the backing files associated with this WAL.
593    * @return may be null if there are no files.
594    */
595   protected FileStatus[] getFiles() throws IOException {
596     return FSUtils.listStatus(fs, fullPathLogDir, ourFiles);
597   }
598 
599   /**
600    * Currently, we need to expose the writer's OutputStream to tests so that they can manipulate
601    * the default behavior (such as setting the maxRecoveryErrorCount value for example (see
602    * {@link TestWALReplay#testReplayEditsWrittenIntoWAL()}). This is done using reflection on the
603    * underlying HDFS OutputStream.
604    * NOTE: This could be removed once Hadoop1 support is removed.
605    * @return null if underlying stream is not ready.
606    */
607   @VisibleForTesting
608   OutputStream getOutputStream() {
609     FSDataOutputStream fsdos = this.hdfs_out;
610     if (fsdos == null) return null;
611     return fsdos.getWrappedStream();
612   }
613 
614   @Override
615   public byte [][] rollWriter() throws FailedLogCloseException, IOException {
616     return rollWriter(false);
617   }
618 
619   /**
620    * retrieve the next path to use for writing.
621    * Increments the internal filenum.
622    */
623   private Path getNewPath() throws IOException {
624     this.filenum.set(System.currentTimeMillis());
625     Path newPath = getCurrentFileName();
626     while (fs.exists(newPath)) {
627       this.filenum.incrementAndGet();
628       newPath = getCurrentFileName();
629     }
630     return newPath;
631   }
632 
633   Path getOldPath() {
634     long currentFilenum = this.filenum.get();
635     Path oldPath = null;
636     if (currentFilenum > 0) {
637       // ComputeFilename  will take care of meta wal filename
638       oldPath = computeFilename(currentFilenum);
639     } // I presume if currentFilenum is <= 0, this is first file and null for oldPath if fine?
640     return oldPath;
641   }
642 
643   /**
644    * Tell listeners about pre log roll.
645    * @throws IOException
646    */
647   private void tellListenersAboutPreLogRoll(final Path oldPath, final Path newPath)
648   throws IOException {
649     coprocessorHost.preWALRoll(oldPath, newPath);
650 
651     if (!this.listeners.isEmpty()) {
652       for (WALActionsListener i : this.listeners) {
653         i.preLogRoll(oldPath, newPath);
654       }
655     }
656   }
657 
658   /**
659    * Tell listeners about post log roll.
660    * @throws IOException
661    */
662   private void tellListenersAboutPostLogRoll(final Path oldPath, final Path newPath)
663   throws IOException {
664     if (!this.listeners.isEmpty()) {
665       for (WALActionsListener i : this.listeners) {
666         i.postLogRoll(oldPath, newPath);
667       }
668     }
669 
670     coprocessorHost.postWALRoll(oldPath, newPath);
671   }
672 
673   /**
674    * Run a sync after opening to set up the pipeline.
675    * @param nextWriter
676    * @param startTimeNanos
677    */
678   private void preemptiveSync(final ProtobufLogWriter nextWriter) {
679     long startTimeNanos = System.nanoTime();
680     try {
681       nextWriter.sync();
682       postSync(System.nanoTime() - startTimeNanos, 0);
683     } catch (IOException e) {
684       // optimization failed, no need to abort here.
685       LOG.warn("pre-sync failed but an optimization so keep going", e);
686     }
687   }
688 
689   @Override
690   public byte [][] rollWriter(boolean force) throws FailedLogCloseException, IOException {
691     rollWriterLock.lock();
692     try {
693       // Return if nothing to flush.
694       if (!force && (this.writer != null && this.numEntries.get() <= 0)) return null;
695       byte [][] regionsToFlush = null;
696       if (this.closed) {
697         LOG.debug("WAL closed. Skipping rolling of writer");
698         return regionsToFlush;
699       }
700       if (!closeBarrier.beginOp()) {
701         LOG.debug("WAL closing. Skipping rolling of writer");
702         return regionsToFlush;
703       }
704       TraceScope scope = Trace.startSpan("FSHLog.rollWriter");
705       try {
706         Path oldPath = getOldPath();
707         Path newPath = getNewPath();
708         // Any exception from here on is catastrophic, non-recoverable so we currently abort.
709         Writer nextWriter = this.createWriterInstance(newPath);
710         FSDataOutputStream nextHdfsOut = null;
711         if (nextWriter instanceof ProtobufLogWriter) {
712           nextHdfsOut = ((ProtobufLogWriter)nextWriter).getStream();
713           // If a ProtobufLogWriter, go ahead and try and sync to force setup of pipeline.
714           // If this fails, we just keep going.... it is an optimization, not the end of the world.
715           preemptiveSync((ProtobufLogWriter)nextWriter);
716         }
717         tellListenersAboutPreLogRoll(oldPath, newPath);
718         // NewPath could be equal to oldPath if replaceWriter fails.
719         newPath = replaceWriter(oldPath, newPath, nextWriter, nextHdfsOut);
720         tellListenersAboutPostLogRoll(oldPath, newPath);
721         // Can we delete any of the old log files?
722         if (getNumRolledLogFiles() > 0) {
723           cleanOldLogs();
724           regionsToFlush = findRegionsToForceFlush();
725         }
726       } finally {
727         closeBarrier.endOp();
728         assert scope == NullScope.INSTANCE || !scope.isDetached();
729         scope.close();
730       }
731       return regionsToFlush;
732     } finally {
733       rollWriterLock.unlock();
734     }
735   }
736 
737   /**
738    * This method allows subclasses to inject different writers without having to
739    * extend other methods like rollWriter().
740    *
741    * @return Writer instance
742    */
743   protected Writer createWriterInstance(final Path path) throws IOException {
744     return DefaultWALProvider.createWriter(conf, fs, path, false);
745   }
746 
747   /**
748    * Archive old logs. A WAL is eligible for archiving if all its WALEdits have been flushed.
749    * @throws IOException
750    */
751   private void cleanOldLogs() throws IOException {
752     List<Path> logsToArchive = null;
753     // For each log file, look at its Map of regions to highest sequence id; if all sequence ids
754     // are older than what is currently in memory, the WAL can be GC'd.
755     for (Map.Entry<Path, Map<byte[], Long>> e : this.byWalRegionSequenceIds.entrySet()) {
756       Path log = e.getKey();
757       Map<byte[], Long> sequenceNums = e.getValue();
758       if (this.sequenceIdAccounting.areAllLower(sequenceNums)) {
759         if (logsToArchive == null) logsToArchive = new ArrayList<Path>();
760         logsToArchive.add(log);
761         if (LOG.isTraceEnabled()) LOG.trace("WAL file ready for archiving " + log);
762       }
763     }
764     if (logsToArchive != null) {
765       for (Path p : logsToArchive) {
766         this.totalLogSize.addAndGet(-this.fs.getFileStatus(p).getLen());
767         archiveLogFile(p);
768         this.byWalRegionSequenceIds.remove(p);
769       }
770     }
771   }
772 
773   /**
774    * If the number of un-archived WAL files is greater than maximum allowed, check the first
775    * (oldest) WAL file, and returns those regions which should be flushed so that it can
776    * be archived.
777    * @return regions (encodedRegionNames) to flush in order to archive oldest WAL file.
778    * @throws IOException
779    */
780   byte[][] findRegionsToForceFlush() throws IOException {
781     byte [][] regions = null;
782     int logCount = getNumRolledLogFiles();
783     if (logCount > this.maxLogs && logCount > 0) {
784       Map.Entry<Path, Map<byte[], Long>> firstWALEntry =
785         this.byWalRegionSequenceIds.firstEntry();
786       regions = this.sequenceIdAccounting.findLower(firstWALEntry.getValue());
787     }
788     if (regions != null) {
789       StringBuilder sb = new StringBuilder();
790       for (int i = 0; i < regions.length; i++) {
791         if (i > 0) sb.append(", ");
792         sb.append(Bytes.toStringBinary(regions[i]));
793       }
794       LOG.info("Too many WALs; count=" + logCount + ", max=" + this.maxLogs +
795         "; forcing flush of " + regions.length + " regions(s): " + sb.toString());
796     }
797     return regions;
798   }
799 
800   /**
801    * Used to manufacture race condition reliably. For testing only.
802    * @see #beforeWaitOnSafePoint()
803    */
804   @VisibleForTesting
805   protected void afterCreatingZigZagLatch() {}
806 
807   /**
808    * @see #afterCreatingZigZagLatch()
809    */
810   @VisibleForTesting
811   protected void beforeWaitOnSafePoint() {};
812 
813   /**
814    * Cleans up current writer closing it and then puts in place the passed in
815    * <code>nextWriter</code>.
816    *
817    * In the case of creating a new WAL, oldPath will be null.
818    *
819    * In the case of rolling over from one file to the next, none of the params will be null.
820    *
821    * In the case of closing out this FSHLog with no further use newPath, nextWriter, and
822    * nextHdfsOut will be null.
823    *
824    * @param oldPath may be null
825    * @param newPath may be null
826    * @param nextWriter may be null
827    * @param nextHdfsOut may be null
828    * @return the passed in <code>newPath</code>
829    * @throws IOException if there is a problem flushing or closing the underlying FS
830    */
831   Path replaceWriter(final Path oldPath, final Path newPath, Writer nextWriter,
832       final FSDataOutputStream nextHdfsOut)
833   throws IOException {
834     // Ask the ring buffer writer to pause at a safe point.  Once we do this, the writer
835     // thread will eventually pause. An error hereafter needs to release the writer thread
836     // regardless -- hence the finally block below.  Note, this method is called from the FSHLog
837     // constructor BEFORE the ring buffer is set running so it is null on first time through
838     // here; allow for that.
839     SyncFuture syncFuture = null;
840     SafePointZigZagLatch zigzagLatch = null;
841     long sequence = -1L;
842     if (this.ringBufferEventHandler != null) {
843       // Get sequence first to avoid dead lock when ring buffer is full
844       // Considering below sequence
845       // 1. replaceWriter is called and zigzagLatch is initialized
846       // 2. ringBufferEventHandler#onEvent is called and arrives at #attainSafePoint(long) then wait
847       // on safePointReleasedLatch
848       // 3. Since ring buffer is full, if we get sequence when publish sync, the replaceWriter
849       // thread will wait for the ring buffer to be consumed, but the only consumer is waiting
850       // replaceWriter thread to release safePointReleasedLatch, which causes a deadlock
851       sequence = getSequenceOnRingBuffer();
852       zigzagLatch = this.ringBufferEventHandler.attainSafePoint();
853     }
854     afterCreatingZigZagLatch();
855     TraceScope scope = Trace.startSpan("FSHFile.replaceWriter");
856     try {
857       // Wait on the safe point to be achieved.  Send in a sync in case nothing has hit the
858       // ring buffer between the above notification of writer that we want it to go to
859       // 'safe point' and then here where we are waiting on it to attain safe point.  Use
860       // 'sendSync' instead of 'sync' because we do not want this thread to block waiting on it
861       // to come back.  Cleanup this syncFuture down below after we are ready to run again.
862       try {
863         if (zigzagLatch != null) {
864           // use assert to make sure no change breaks the logic that
865           // sequence and zigzagLatch will be set together
866           assert sequence > 0L : "Failed to get sequence from ring buffer";
867           Trace.addTimelineAnnotation("awaiting safepoint");
868           syncFuture = zigzagLatch.waitSafePoint(publishSyncOnRingBuffer(sequence));
869         }
870       } catch (FailedSyncBeforeLogCloseException e) {
871         // If unflushed/unsynced entries on close, it is reason to abort.
872         if (isUnflushedEntries()) throw e;
873         LOG.warn("Failed sync-before-close but no outstanding appends; closing WAL: " +
874           e.getMessage());
875       }
876 
877       // It is at the safe point.  Swap out writer from under the blocked writer thread.
878       // TODO: This is close is inline with critical section.  Should happen in background?
879       try {
880         if (this.writer != null) {
881           Trace.addTimelineAnnotation("closing writer");
882           this.writer.close();
883           Trace.addTimelineAnnotation("writer closed");
884         }
885         this.closeErrorCount.set(0);
886       } catch (IOException ioe) {
887         int errors = closeErrorCount.incrementAndGet();
888         if (!isUnflushedEntries() && (errors <= this.closeErrorsTolerated)) {
889           LOG.warn("Riding over failed WAL close of " + oldPath + ", cause=\"" +
890             ioe.getMessage() + "\", errors=" + errors +
891             "; THIS FILE WAS NOT CLOSED BUT ALL EDITS SYNCED SO SHOULD BE OK");
892         } else {
893           throw ioe;
894         }
895       }
896       this.writer = nextWriter;
897       this.hdfs_out = nextHdfsOut;
898       int oldNumEntries = this.numEntries.get();
899       this.numEntries.set(0);
900       final String newPathString = (null == newPath ? null : FSUtils.getPath(newPath));
901       if (oldPath != null) {
902         this.byWalRegionSequenceIds.put(oldPath, this.sequenceIdAccounting.resetHighest());
903         long oldFileLen = this.fs.getFileStatus(oldPath).getLen();
904         this.totalLogSize.addAndGet(oldFileLen);
905         LOG.info("Rolled WAL " + FSUtils.getPath(oldPath) + " with entries=" + oldNumEntries +
906           ", filesize=" + StringUtils.byteDesc(oldFileLen) + "; new WAL " +
907           newPathString);
908       } else {
909         LOG.info("New WAL " + newPathString);
910       }
911     } catch (InterruptedException ie) {
912       // Perpetuate the interrupt
913       Thread.currentThread().interrupt();
914     } catch (IOException e) {
915       long count = getUnflushedEntriesCount();
916       LOG.error("Failed close of WAL writer " + oldPath + ", unflushedEntries=" + count, e);
917       throw new FailedLogCloseException(oldPath + ", unflushedEntries=" + count, e);
918     } finally {
919       try {
920         // Let the writer thread go regardless, whether error or not.
921         if (zigzagLatch != null) {
922           zigzagLatch.releaseSafePoint();
923           // syncFuture will be null if we failed our wait on safe point above. Otherwise, if
924           // latch was obtained successfully, the sync we threw in either trigger the latch or it
925           // got stamped with an exception because the WAL was damaged and we could not sync. Now
926           // the write pipeline has been opened up again by releasing the safe point, process the
927           // syncFuture we got above. This is probably a noop but it may be stale exception from
928           // when old WAL was in place. Catch it if so.
929           if (syncFuture != null) {
930             try {
931               blockOnSync(syncFuture);
932             } catch (IOException ioe) {
933               if (LOG.isTraceEnabled()) LOG.trace("Stale sync exception", ioe);
934             }
935           }
936         }
937       } finally {
938         scope.close();
939       }
940     }
941     return newPath;
942   }
943 
944   long getUnflushedEntriesCount() {
945     long highestSynced = this.highestSyncedSequence.get();
946     return highestSynced > this.highestUnsyncedSequence?
947       0: this.highestUnsyncedSequence - highestSynced;
948   }
949 
950   boolean isUnflushedEntries() {
951     return getUnflushedEntriesCount() > 0;
952   }
953 
954   /*
955    * only public so WALSplitter can use.
956    * @return archived location of a WAL file with the given path p
957    */
958   public static Path getWALArchivePath(Path archiveDir, Path p) {
959     return new Path(archiveDir, p.getName());
960   }
961 
962   private void archiveLogFile(final Path p) throws IOException {
963     Path newPath = getWALArchivePath(this.fullPathArchiveDir, p);
964     // Tell our listeners that a log is going to be archived.
965     if (!this.listeners.isEmpty()) {
966       for (WALActionsListener i : this.listeners) {
967         i.preLogArchive(p, newPath);
968       }
969     }
970     LOG.info("Archiving " + p + " to " + newPath);
971     if (!FSUtils.renameAndSetModifyTime(this.fs, p, newPath)) {
972       throw new IOException("Unable to rename " + p + " to " + newPath);
973     }
974     // Tell our listeners that a log has been archived.
975     if (!this.listeners.isEmpty()) {
976       for (WALActionsListener i : this.listeners) {
977         i.postLogArchive(p, newPath);
978       }
979     }
980   }
981 
982   /**
983    * This is a convenience method that computes a new filename with a given
984    * file-number.
985    * @param filenum to use
986    * @return Path
987    */
988   protected Path computeFilename(final long filenum) {
989     if (filenum < 0) {
990       throw new RuntimeException("WAL file number can't be < 0");
991     }
992     String child = logFilePrefix + WAL_FILE_NAME_DELIMITER + filenum + logFileSuffix;
993     return new Path(fullPathLogDir, child);
994   }
995 
996   /**
997    * This is a convenience method that computes a new filename with a given
998    * using the current WAL file-number
999    * @return Path
1000    */
1001   public Path getCurrentFileName() {
1002     return computeFilename(this.filenum.get());
1003   }
1004 
1005   @Override
1006   public String toString() {
1007     return "FSHLog " + logFilePrefix + ":" + logFileSuffix + "(num " + filenum + ")";
1008   }
1009 
1010 /**
1011  * A log file has a creation timestamp (in ms) in its file name ({@link #filenum}.
1012  * This helper method returns the creation timestamp from a given log file.
1013  * It extracts the timestamp assuming the filename is created with the
1014  * {@link #computeFilename(long filenum)} method.
1015  * @param fileName
1016  * @return timestamp, as in the log file name.
1017  */
1018   protected long getFileNumFromFileName(Path fileName) {
1019     if (fileName == null) throw new IllegalArgumentException("file name can't be null");
1020     if (!ourFiles.accept(fileName)) {
1021       throw new IllegalArgumentException("The log file " + fileName +
1022           " doesn't belong to this WAL. (" + toString() + ")");
1023     }
1024     final String fileNameString = fileName.toString();
1025     String chompedPath = fileNameString.substring(prefixPathStr.length(),
1026         (fileNameString.length() - logFileSuffix.length()));
1027     return Long.parseLong(chompedPath);
1028   }
1029 
1030   @Override
1031   public void close() throws IOException {
1032     shutdown();
1033     final FileStatus[] files = getFiles();
1034     if (null != files && 0 != files.length) {
1035       for (FileStatus file : files) {
1036         Path p = getWALArchivePath(this.fullPathArchiveDir, file.getPath());
1037         // Tell our listeners that a log is going to be archived.
1038         if (!this.listeners.isEmpty()) {
1039           for (WALActionsListener i : this.listeners) {
1040             i.preLogArchive(file.getPath(), p);
1041           }
1042         }
1043 
1044         if (!FSUtils.renameAndSetModifyTime(fs, file.getPath(), p)) {
1045           throw new IOException("Unable to rename " + file.getPath() + " to " + p);
1046         }
1047         // Tell our listeners that a log was archived.
1048         if (!this.listeners.isEmpty()) {
1049           for (WALActionsListener i : this.listeners) {
1050             i.postLogArchive(file.getPath(), p);
1051           }
1052         }
1053       }
1054       LOG.debug("Moved " + files.length + " WAL file(s) to " +
1055         FSUtils.getPath(this.fullPathArchiveDir));
1056     }
1057     LOG.info("Closed WAL: " + toString());
1058   }
1059 
1060   @Override
1061   public void shutdown() throws IOException {
1062     if (shutdown.compareAndSet(false, true)) {
1063       try {
1064         // Prevent all further flushing and rolling.
1065         closeBarrier.stopAndDrainOps();
1066       } catch (InterruptedException e) {
1067         LOG.error("Exception while waiting for cache flushes and log rolls", e);
1068         Thread.currentThread().interrupt();
1069       }
1070 
1071       // Shutdown the disruptor.  Will stop after all entries have been processed.  Make sure we
1072       // have stopped incoming appends before calling this else it will not shutdown.  We are
1073       // conservative below waiting a long time and if not elapsed, then halting.
1074       if (this.disruptor != null) {
1075         long timeoutms = conf.getLong("hbase.wal.disruptor.shutdown.timeout.ms", 60000);
1076         try {
1077           this.disruptor.shutdown(timeoutms, TimeUnit.MILLISECONDS);
1078         } catch (TimeoutException e) {
1079           LOG.warn("Timed out bringing down disruptor after " + timeoutms + "ms; forcing halt " +
1080             "(It is a problem if this is NOT an ABORT! -- DATALOSS!!!!)");
1081           this.disruptor.halt();
1082           this.disruptor.shutdown();
1083         }
1084       }
1085       // With disruptor down, this is safe to let go.
1086       if (this.appendExecutor !=  null) this.appendExecutor.shutdown();
1087 
1088       // Tell our listeners that the log is closing
1089       if (!this.listeners.isEmpty()) {
1090         for (WALActionsListener i : this.listeners) {
1091           i.logCloseRequested();
1092         }
1093       }
1094       this.closed = true;
1095       if (LOG.isDebugEnabled()) {
1096         LOG.debug("Closing WAL writer in " + FSUtils.getPath(fullPathLogDir));
1097       }
1098       if (this.writer != null) {
1099         this.writer.close();
1100         this.writer = null;
1101       }
1102     }
1103   }
1104 
1105   @edu.umd.cs.findbugs.annotations.SuppressWarnings(value="NP_NULL_ON_SOME_PATH_EXCEPTION",
1106       justification="Will never be null")
1107   @Override
1108   public long append(final HTableDescriptor htd, final HRegionInfo hri, final WALKey key,
1109       final WALEdit edits, final boolean inMemstore) throws IOException {
1110     if (this.closed) throw new IOException("Cannot append; log is closed");
1111     // Make a trace scope for the append.  It is closed on other side of the ring buffer by the
1112     // single consuming thread.  Don't have to worry about it.
1113     TraceScope scope = Trace.startSpan("FSHLog.append");
1114 
1115     // This is crazy how much it takes to make an edit.  Do we need all this stuff!!!!????  We need
1116     // all this to make a key and then below to append the edit, we need to carry htd, info,
1117     // etc. all over the ring buffer.
1118     FSWALEntry entry = null;
1119     long sequence = this.disruptor.getRingBuffer().next();
1120     try {
1121       RingBufferTruck truck = this.disruptor.getRingBuffer().get(sequence);
1122       // TODO: reuse FSWALEntry as we do SyncFuture rather create per append.
1123       entry = new FSWALEntry(sequence, key, edits, htd, hri, inMemstore);
1124       truck.loadPayload(entry, scope.detach());
1125     } finally {
1126       this.disruptor.getRingBuffer().publish(sequence);
1127     }
1128     return sequence;
1129   }
1130 
1131   /**
1132    * Thread to runs the hdfs sync call. This call takes a while to complete.  This is the longest
1133    * pole adding edits to the WAL and this must complete to be sure all edits persisted.  We run
1134    * multiple threads sync'ng rather than one that just syncs in series so we have better
1135    * latencies; otherwise, an edit that arrived just after a sync started, might have to wait
1136    * almost the length of two sync invocations before it is marked done.
1137    * <p>When the sync completes, it marks all the passed in futures done.  On the other end of the
1138    * sync future is a blocked thread, usually a regionserver Handler.  There may be more than one
1139    * future passed in the case where a few threads arrive at about the same time and all invoke
1140    * 'sync'.  In this case we'll batch up the invocations and run one filesystem sync only for a
1141    * batch of Handler sync invocations.  Do not confuse these Handler SyncFutures with the futures
1142    * an ExecutorService returns when you call submit. We have no use for these in this model. These
1143    * SyncFutures are 'artificial', something to hold the Handler until the filesystem sync
1144    * completes.
1145    */
1146   private class SyncRunner extends HasThread {
1147     private volatile long sequence;
1148     // Keep around last exception thrown. Clear on successful sync.
1149     private final BlockingQueue<SyncFuture> syncFutures;
1150     private volatile SyncFuture takeSyncFuture = null;
1151 
1152     /**
1153      * UPDATE!
1154      * @param syncs the batch of calls to sync that arrived as this thread was starting; when done,
1155      * we will put the result of the actual hdfs sync call as the result.
1156      * @param sequence The sequence number on the ring buffer when this thread was set running.
1157      * If this actual writer sync completes then all appends up this point have been
1158      * flushed/synced/pushed to datanodes.  If we fail, then the passed in <code>syncs</code>
1159      * futures will return the exception to their clients; some of the edits may have made it out
1160      * to data nodes but we will report all that were part of this session as failed.
1161      */
1162     SyncRunner(final String name, final int maxHandlersCount) {
1163       super(name);
1164       // LinkedBlockingQueue because of
1165       // http://www.javacodegeeks.com/2010/09/java-best-practices-queue-battle-and.html
1166       // Could use other blockingqueues here or concurrent queues.
1167       //
1168       // We could let the capacity be 'open' but bound it so we get alerted in pathological case
1169       // where we cannot sync and we have a bunch of threads all backed up waiting on their syncs
1170       // to come in.  LinkedBlockingQueue actually shrinks when you remove elements so Q should
1171       // stay neat and tidy in usual case.  Let the max size be three times the maximum handlers.
1172       // The passed in maxHandlerCount is the user-level handlers which is what we put up most of
1173       // but HBase has other handlers running too -- opening region handlers which want to write
1174       // the meta table when succesful (i.e. sync), closing handlers -- etc.  These are usually
1175       // much fewer in number than the user-space handlers so Q-size should be user handlers plus
1176       // some space for these other handlers.  Lets multiply by 3 for good-measure.
1177       this.syncFutures = new LinkedBlockingQueue<SyncFuture>(maxHandlersCount * 3);
1178     }
1179 
1180     void offer(final long sequence, final SyncFuture [] syncFutures, final int syncFutureCount) {
1181       // Set sequence first because the add to the queue will wake the thread if sleeping.
1182       this.sequence = sequence;
1183       for (int i = 0; i < syncFutureCount; ++i) {
1184         this.syncFutures.add(syncFutures[i]);
1185       }
1186     }
1187 
1188     /**
1189      * Release the passed <code>syncFuture</code>
1190      * @param syncFuture
1191      * @param currentSequence
1192      * @param t
1193      * @return Returns 1.
1194      */
1195     private int releaseSyncFuture(final SyncFuture syncFuture, final long currentSequence,
1196         final Throwable t) {
1197       if (!syncFuture.done(currentSequence, t)) throw new IllegalStateException();
1198       // This function releases one sync future only.
1199       return 1;
1200     }
1201 
1202     /**
1203      * Release all SyncFutures whose sequence is <= <code>currentSequence</code>.
1204      * @param currentSequence
1205      * @param t May be non-null if we are processing SyncFutures because an exception was thrown.
1206      * @return Count of SyncFutures we let go.
1207      */
1208     private int releaseSyncFutures(final long currentSequence, final Throwable t) {
1209       int syncCount = 0;
1210       for (SyncFuture syncFuture; (syncFuture = this.syncFutures.peek()) != null;) {
1211         if (syncFuture.getRingBufferSequence() > currentSequence) break;
1212         releaseSyncFuture(syncFuture, currentSequence, t);
1213         if (!this.syncFutures.remove(syncFuture)) {
1214           throw new IllegalStateException(syncFuture.toString());
1215         }
1216         syncCount++;
1217       }
1218       return syncCount;
1219     }
1220 
1221     /**
1222      * @param sequence The sequence we ran the filesystem sync against.
1223      * @return Current highest synced sequence.
1224      */
1225     private long updateHighestSyncedSequence(long sequence) {
1226       long currentHighestSyncedSequence;
1227       // Set the highestSyncedSequence IFF our current sequence id is the 'highest'.
1228       do {
1229         currentHighestSyncedSequence = highestSyncedSequence.get();
1230         if (currentHighestSyncedSequence >= sequence) {
1231           // Set the sync number to current highwater mark; might be able to let go more
1232           // queued sync futures
1233           sequence = currentHighestSyncedSequence;
1234           break;
1235         }
1236       } while (!highestSyncedSequence.compareAndSet(currentHighestSyncedSequence, sequence));
1237       return sequence;
1238     }
1239 
1240     boolean areSyncFuturesReleased() {
1241       // check whether there is no sync futures offered, and no in-flight sync futures that is being
1242       // processed.
1243       return syncFutures.size() <= 0
1244           && takeSyncFuture == null;
1245     }
1246 
1247     public void run() {
1248       long currentSequence;
1249       while (!isInterrupted()) {
1250         int syncCount = 0;
1251 
1252         try {
1253           while (true) {
1254             takeSyncFuture = null;
1255             // We have to process what we 'take' from the queue
1256             takeSyncFuture = this.syncFutures.take();
1257             currentSequence = this.sequence;
1258             long syncFutureSequence = takeSyncFuture.getRingBufferSequence();
1259             if (syncFutureSequence > currentSequence) {
1260               throw new IllegalStateException("currentSequence=" + syncFutureSequence +
1261                 ", syncFutureSequence=" + syncFutureSequence);
1262             }
1263             // See if we can process any syncfutures BEFORE we go sync.
1264             long currentHighestSyncedSequence = highestSyncedSequence.get();
1265             if (currentSequence < currentHighestSyncedSequence) {
1266               syncCount += releaseSyncFuture(takeSyncFuture, currentHighestSyncedSequence, null);
1267               // Done with the 'take'.  Go around again and do a new 'take'.
1268               continue;
1269             }
1270             break;
1271           }
1272           // I got something.  Lets run.  Save off current sequence number in case it changes
1273           // while we run.
1274           TraceScope scope = Trace.continueSpan(takeSyncFuture.getSpan());
1275           long start = System.nanoTime();
1276           Throwable lastException = null;
1277           try {
1278             Trace.addTimelineAnnotation("syncing writer");
1279             writer.sync();
1280             Trace.addTimelineAnnotation("writer synced");
1281             currentSequence = updateHighestSyncedSequence(currentSequence);
1282           } catch (IOException e) {
1283             LOG.error("Error syncing, request close of WAL", e);
1284             lastException = e;
1285           } catch (Exception e) {
1286             LOG.warn("UNEXPECTED", e);
1287             lastException = e;
1288           } finally {
1289             // reattach the span to the future before releasing.
1290             takeSyncFuture.setSpan(scope.detach());
1291             // First release what we 'took' from the queue.
1292             syncCount += releaseSyncFuture(takeSyncFuture, currentSequence, lastException);
1293             // Can we release other syncs?
1294             syncCount += releaseSyncFutures(currentSequence, lastException);
1295             if (lastException != null) requestLogRoll();
1296             else checkLogRoll();
1297           }
1298           postSync(System.nanoTime() - start, syncCount);
1299         } catch (InterruptedException e) {
1300           // Presume legit interrupt.
1301           Thread.currentThread().interrupt();
1302         } catch (Throwable t) {
1303           LOG.warn("UNEXPECTED, continuing", t);
1304         }
1305       }
1306     }
1307   }
1308 
1309   /**
1310    * Schedule a log roll if needed.
1311    */
1312   public void checkLogRoll() {
1313     // Will return immediately if we are in the middle of a WAL log roll currently.
1314     if (!rollWriterLock.tryLock()) return;
1315     boolean lowReplication;
1316     try {
1317       lowReplication = checkLowReplication();
1318     } finally {
1319       rollWriterLock.unlock();
1320     }
1321     try {
1322       if (lowReplication || writer != null && writer.getLength() > logrollsize) {
1323         requestLogRoll(lowReplication);
1324       }
1325     } catch (IOException e) {
1326       LOG.warn("Writer.getLength() failed; continuing", e);
1327     }
1328   }
1329 
1330   /*
1331    * @return true if number of replicas for the WAL is lower than threshold
1332    */
1333   private boolean checkLowReplication() {
1334     boolean logRollNeeded = false;
1335     this.lastTimeCheckLowReplication = EnvironmentEdgeManager.currentTime();
1336     // if the number of replicas in HDFS has fallen below the configured
1337     // value, then roll logs.
1338     try {
1339       int numCurrentReplicas = getLogReplication();
1340       if (numCurrentReplicas != 0 && numCurrentReplicas < this.minTolerableReplication) {
1341         if (this.lowReplicationRollEnabled) {
1342           if (this.consecutiveLogRolls.get() < this.lowReplicationRollLimit) {
1343             LOG.warn("HDFS pipeline error detected. " + "Found "
1344                 + numCurrentReplicas + " replicas but expecting no less than "
1345                 + this.minTolerableReplication + " replicas. "
1346                 + " Requesting close of WAL. current pipeline: "
1347                 + Arrays.toString(getPipeLine()));
1348             logRollNeeded = true;
1349             // If rollWriter is requested, increase consecutiveLogRolls. Once it
1350             // is larger than lowReplicationRollLimit, disable the
1351             // LowReplication-Roller
1352             this.consecutiveLogRolls.getAndIncrement();
1353           } else {
1354             LOG.warn("Too many consecutive RollWriter requests, it's a sign of "
1355                 + "the total number of live datanodes is lower than the tolerable replicas.");
1356             this.consecutiveLogRolls.set(0);
1357             this.lowReplicationRollEnabled = false;
1358           }
1359         }
1360       } else if (numCurrentReplicas >= this.minTolerableReplication) {
1361         if (!this.lowReplicationRollEnabled) {
1362           // The new writer's log replicas is always the default value.
1363           // So we should not enable LowReplication-Roller. If numEntries
1364           // is lower than or equals 1, we consider it as a new writer.
1365           if (this.numEntries.get() <= 1) {
1366             return logRollNeeded;
1367           }
1368           // Once the live datanode number and the replicas return to normal,
1369           // enable the LowReplication-Roller.
1370           this.lowReplicationRollEnabled = true;
1371           LOG.info("LowReplication-Roller was enabled.");
1372         }
1373       }
1374     } catch (Exception e) {
1375       LOG.warn("DFSOutputStream.getNumCurrentReplicas failed because of " + e +
1376         ", continuing...");
1377     }
1378     return logRollNeeded;
1379   }
1380 
1381   private SyncFuture publishSyncOnRingBuffer(long sequence) {
1382     return publishSyncOnRingBuffer(sequence, null);
1383   }
1384 
1385   private long getSequenceOnRingBuffer() {
1386     return this.disruptor.getRingBuffer().next();
1387   }
1388 
1389   private SyncFuture publishSyncOnRingBuffer(Span span) {
1390     long sequence = this.disruptor.getRingBuffer().next();
1391     return publishSyncOnRingBuffer(sequence, span);
1392   }
1393 
1394   private SyncFuture publishSyncOnRingBuffer(long sequence, Span span) {
1395     SyncFuture syncFuture = getSyncFuture(sequence, span);
1396     try {
1397       RingBufferTruck truck = this.disruptor.getRingBuffer().get(sequence);
1398       truck.loadPayload(syncFuture);
1399     } finally {
1400       this.disruptor.getRingBuffer().publish(sequence);
1401     }
1402     return syncFuture;
1403   }
1404 
1405   // Sync all known transactions
1406   private Span publishSyncThenBlockOnCompletion(Span span) throws IOException {
1407     return blockOnSync(publishSyncOnRingBuffer(span));
1408   }
1409 
1410   private Span blockOnSync(final SyncFuture syncFuture) throws IOException {
1411     // Now we have published the ringbuffer, halt the current thread until we get an answer back.
1412     try {
1413       syncFuture.get(walSyncTimeout);
1414       return syncFuture.getSpan();
1415     } catch (TimeoutIOException tioe) {
1416       // SyncFuture reuse by thread, if TimeoutIOException happens, ringbuffer
1417       // still refer to it, so if this thread use it next time may get a wrong
1418       // result.
1419       this.cachedSyncFutures.remove();
1420       throw tioe;
1421     } catch (InterruptedException ie) {
1422       LOG.warn("Interrupted", ie);
1423       throw convertInterruptedExceptionToIOException(ie);
1424     } catch (ExecutionException e) {
1425       throw ensureIOException(e.getCause());
1426     }
1427   }
1428 
1429   private IOException convertInterruptedExceptionToIOException(final InterruptedException ie) {
1430     Thread.currentThread().interrupt();
1431     IOException ioe = new InterruptedIOException();
1432     ioe.initCause(ie);
1433     return ioe;
1434   }
1435 
1436   private SyncFuture getSyncFuture(final long sequence, Span span) {
1437     return cachedSyncFutures.get().reset(sequence);
1438   }
1439 
1440   private void postSync(final long timeInNanos, final int handlerSyncs) {
1441     if (timeInNanos > this.slowSyncNs) {
1442       String msg =
1443           new StringBuilder().append("Slow sync cost: ")
1444               .append(timeInNanos / 1000000).append(" ms, current pipeline: ")
1445               .append(Arrays.toString(getPipeLine())).toString();
1446       Trace.addTimelineAnnotation(msg);
1447       LOG.info(msg);
1448     }
1449     if (!listeners.isEmpty()) {
1450       for (WALActionsListener listener : listeners) {
1451         listener.postSync(timeInNanos, handlerSyncs);
1452       }
1453     }
1454   }
1455 
1456   private long postAppend(final Entry e, final long elapsedTime) throws IOException {
1457     long len = 0;
1458     if (!listeners.isEmpty()) {
1459       for (Cell cell : e.getEdit().getCells()) {
1460         len += CellUtil.estimatedSerializedSizeOf(cell);
1461       }
1462       for (WALActionsListener listener : listeners) {
1463         listener.postAppend(len, elapsedTime, e.getKey(), e.getEdit());
1464       }
1465     }
1466     return len;
1467   }
1468 
1469 
1470   /**
1471    * This method gets the datanode replication count for the current WAL.
1472    *
1473    * If the pipeline isn't started yet or is empty, you will get the default
1474    * replication factor.  Therefore, if this function returns 0, it means you
1475    * are not properly running with the HDFS-826 patch.
1476    * @throws InvocationTargetException
1477    * @throws IllegalAccessException
1478    * @throws IllegalArgumentException
1479    *
1480    * @throws Exception
1481    */
1482   @VisibleForTesting
1483   int getLogReplication() {
1484     try {
1485       //in standalone mode, it will return 0
1486       if (this.hdfs_out instanceof HdfsDataOutputStream) {
1487         return ((HdfsDataOutputStream) this.hdfs_out).getCurrentBlockReplication();
1488       }
1489     } catch (IOException e) {
1490       LOG.info("", e);
1491     }
1492     return 0;
1493   }
1494 
1495   @Override
1496   public void sync() throws IOException {
1497     TraceScope scope = Trace.startSpan("FSHLog.sync");
1498     try {
1499       scope = Trace.continueSpan(publishSyncThenBlockOnCompletion(scope.detach()));
1500     } finally {
1501       assert scope == NullScope.INSTANCE || !scope.isDetached();
1502       scope.close();
1503     }
1504   }
1505 
1506   @Override
1507   public void sync(long txid) throws IOException {
1508     if (this.highestSyncedSequence.get() >= txid){
1509       // Already sync'd.
1510       return;
1511     }
1512     TraceScope scope = Trace.startSpan("FSHLog.sync");
1513     try {
1514       scope = Trace.continueSpan(publishSyncThenBlockOnCompletion(scope.detach()));
1515     } finally {
1516       assert scope == NullScope.INSTANCE || !scope.isDetached();
1517       scope.close();
1518     }
1519   }
1520 
1521   // public only until class moves to o.a.h.h.wal
1522   public void requestLogRoll() {
1523     requestLogRoll(false);
1524   }
1525 
1526   private void requestLogRoll(boolean tooFewReplicas) {
1527     if (!this.listeners.isEmpty()) {
1528       for (WALActionsListener i: this.listeners) {
1529         i.logRollRequested(tooFewReplicas);
1530       }
1531     }
1532   }
1533 
1534   // public only until class moves to o.a.h.h.wal
1535   /** @return the number of rolled log files */
1536   public int getNumRolledLogFiles() {
1537     return byWalRegionSequenceIds.size();
1538   }
1539 
1540   // public only until class moves to o.a.h.h.wal
1541   /** @return the number of log files in use */
1542   public int getNumLogFiles() {
1543     // +1 for current use log
1544     return getNumRolledLogFiles() + 1;
1545   }
1546 
1547   // public only until class moves to o.a.h.h.wal
1548   /** @return the size of log files in use */
1549   public long getLogFileSize() {
1550     return this.totalLogSize.get();
1551   }
1552 
1553   @Override
1554   public Long startCacheFlush(final byte[] encodedRegionName, Set<byte[]> families) {
1555     if (!closeBarrier.beginOp()) {
1556       LOG.info("Flush not started for " + Bytes.toString(encodedRegionName) + "; server closing.");
1557       return null;
1558     }
1559     return this.sequenceIdAccounting.startCacheFlush(encodedRegionName, families);
1560   }
1561 
1562   @Override
1563   public void completeCacheFlush(final byte [] encodedRegionName) {
1564     this.sequenceIdAccounting.completeCacheFlush(encodedRegionName);
1565     closeBarrier.endOp();
1566   }
1567 
1568   @Override
1569   public void abortCacheFlush(byte[] encodedRegionName) {
1570     this.sequenceIdAccounting.abortCacheFlush(encodedRegionName);
1571     closeBarrier.endOp();
1572   }
1573 
1574   @VisibleForTesting
1575   boolean isLowReplicationRollEnabled() {
1576       return lowReplicationRollEnabled;
1577   }
1578 
1579   public static final long FIXED_OVERHEAD = ClassSize.align(
1580     ClassSize.OBJECT + (5 * ClassSize.REFERENCE) +
1581     ClassSize.ATOMIC_INTEGER + Bytes.SIZEOF_INT + (3 * Bytes.SIZEOF_LONG));
1582 
1583 
1584   private static void split(final Configuration conf, final Path p) throws IOException {
1585     FileSystem fs = FSUtils.getWALFileSystem(conf);
1586     if (!fs.exists(p)) {
1587       throw new FileNotFoundException(p.toString());
1588     }
1589     if (!fs.getFileStatus(p).isDirectory()) {
1590       throw new IOException(p + " is not a directory");
1591     }
1592 
1593     final Path baseDir = FSUtils.getWALRootDir(conf);
1594     final Path archiveDir = new Path(baseDir, HConstants.HREGION_OLDLOGDIR_NAME);
1595     WALSplitter.split(baseDir, p, archiveDir, fs, conf, WALFactory.getInstance(conf));
1596   }
1597 
1598 
1599   @Override
1600   public long getEarliestMemstoreSeqNum(byte[] encodedRegionName) {
1601     // Used by tests. Deprecated as too subtle for general usage.
1602     return this.sequenceIdAccounting.getLowestSequenceId(encodedRegionName);
1603   }
1604 
1605   @Override
1606   public long getEarliestMemstoreSeqNum(byte[] encodedRegionName, byte[] familyName) {
1607     // This method is used by tests and for figuring if we should flush or not because our
1608     // sequenceids are too old. It is also used reporting the master our oldest sequenceid for use
1609     // figuring what edits can be skipped during log recovery. getEarliestMemStoreSequenceId
1610     // from this.sequenceIdAccounting is looking first in flushingOldestStoreSequenceIds, the
1611     // currently flushing sequence ids, and if anything found there, it is returning these. This is
1612     // the right thing to do for the reporting oldest sequenceids to master; we won't skip edits if
1613     // we crash during the flush. For figuring what to flush, we might get requeued if our sequence
1614     // id is old even though we are currently flushing. This may mean we do too much flushing.
1615     return this.sequenceIdAccounting.getLowestSequenceId(encodedRegionName, familyName);
1616   }
1617 
1618   /**
1619    * This class is used coordinating two threads holding one thread at a
1620    * 'safe point' while the orchestrating thread does some work that requires the first thread
1621    * paused: e.g. holding the WAL writer while its WAL is swapped out from under it by another
1622    * thread.
1623    *
1624    * <p>Thread A signals Thread B to hold when it gets to a 'safe point'.  Thread A wait until
1625    * Thread B gets there. When the 'safe point' has been attained, Thread B signals Thread A.
1626    * Thread B then holds at the 'safe point'.  Thread A on notification that Thread B is paused,
1627    * goes ahead and does the work it needs to do while Thread B is holding.  When Thread A is done,
1628    * it flags B and then Thread A and Thread B continue along on their merry way.  Pause and
1629    * signalling 'zigzags' between the two participating threads.  We use two latches -- one the
1630    * inverse of the other -- pausing and signaling when states are achieved.
1631    *
1632    * <p>To start up the drama, Thread A creates an instance of this class each time it would do
1633    * this zigzag dance and passes it to Thread B (these classes use Latches so it is one shot
1634    * only). Thread B notices the new instance (via reading a volatile reference or how ever) and it
1635    * starts to work toward the 'safe point'.  Thread A calls {@link #waitSafePoint()} when it
1636    * cannot proceed until the Thread B 'safe point' is attained. Thread A will be held inside in
1637    * {@link #waitSafePoint()} until Thread B reaches the 'safe point'.  Once there, Thread B
1638    * frees Thread A by calling {@link #safePointAttained()}.  Thread A now knows Thread B
1639    * is at the 'safe point' and that it is holding there (When Thread B calls
1640    * {@link #safePointAttained()} it blocks here until Thread A calls {@link #releaseSafePoint()}).
1641    * Thread A proceeds to do what it needs to do while Thread B is paused.  When finished,
1642    * it lets Thread B lose by calling {@link #releaseSafePoint()} and away go both Threads again.
1643    */
1644   static class SafePointZigZagLatch {
1645     /**
1646      * Count down this latch when safe point attained.
1647      */
1648     private volatile CountDownLatch safePointAttainedLatch = new CountDownLatch(1);
1649     /**
1650      * Latch to wait on.  Will be released when we can proceed.
1651      */
1652     private volatile CountDownLatch safePointReleasedLatch = new CountDownLatch(1);
1653 
1654     private void checkIfSyncFailed(SyncFuture syncFuture) throws FailedSyncBeforeLogCloseException {
1655       if (syncFuture.isThrowable()) {
1656         throw new FailedSyncBeforeLogCloseException(syncFuture.getThrowable());
1657       }
1658     }
1659 
1660     /**
1661      * For Thread A to call when it is ready to wait on the 'safe point' to be attained. Thread A
1662      * will be held in here until Thread B calls {@link #safePointAttained()}
1663      * @param syncFuture We need this as barometer on outstanding syncs.  If it comes home with an
1664      *          exception, then something is up w/ our syncing.
1665      * @return The passed <code>syncFuture</code>
1666      */
1667     SyncFuture waitSafePoint(SyncFuture syncFuture) throws InterruptedException,
1668         FailedSyncBeforeLogCloseException {
1669       while (!this.safePointAttainedLatch.await(1, TimeUnit.MILLISECONDS)) {
1670         checkIfSyncFailed(syncFuture);
1671       }
1672       checkIfSyncFailed(syncFuture);
1673       return syncFuture;
1674     }
1675 
1676     /**
1677      * Called by Thread B when it attains the 'safe point'.  In this method, Thread B signals
1678      * Thread A it can proceed. Thread B will be held in here until {@link #releaseSafePoint()}
1679      * is called by Thread A.
1680      * @throws InterruptedException
1681      */
1682     void safePointAttained() throws InterruptedException {
1683       this.safePointAttainedLatch.countDown();
1684       this.safePointReleasedLatch.await();
1685     }
1686 
1687     /**
1688      * Called by Thread A when it is done with the work it needs to do while Thread B is
1689      * halted.  This will release the Thread B held in a call to {@link #safePointAttained()}
1690      */
1691     void releaseSafePoint() {
1692       this.safePointReleasedLatch.countDown();
1693     }
1694 
1695     /**
1696      * @return True is this is a 'cocked', fresh instance, and not one that has already fired.
1697      */
1698     boolean isCocked() {
1699       return this.safePointAttainedLatch.getCount() > 0 &&
1700         this.safePointReleasedLatch.getCount() > 0;
1701     }
1702   }
1703 
1704   /**
1705    * Handler that is run by the disruptor ringbuffer consumer. Consumer is a SINGLE
1706    * 'writer/appender' thread.  Appends edits and starts up sync runs.  Tries its best to batch up
1707    * syncs.  There is no discernible benefit batching appends so we just append as they come in
1708    * because it simplifies the below implementation.  See metrics for batching effectiveness
1709    * (In measurement, at 100 concurrent handlers writing 1k, we are batching > 10 appends and 10
1710    * handler sync invocations for every actual dfsclient sync call; at 10 concurrent handlers,
1711    * YMMV).
1712    * <p>Herein, we have an array into which we store the sync futures as they come in.  When we
1713    * have a 'batch', we'll then pass what we have collected to a SyncRunner thread to do the
1714    * filesystem sync.  When it completes, it will then call
1715    * {@link SyncFuture#done(long, Throwable)} on each of SyncFutures in the batch to release
1716    * blocked Handler threads.
1717    * <p>I've tried various effects to try and make latencies low while keeping throughput high.
1718    * I've tried keeping a single Queue of SyncFutures in this class appending to its tail as the
1719    * syncs coming and having sync runner threads poll off the head to 'finish' completed
1720    * SyncFutures.  I've tried linkedlist, and various from concurrent utils whether
1721    * LinkedBlockingQueue or ArrayBlockingQueue, etc.  The more points of synchronization, the
1722    * more 'work' (according to 'perf stats') that has to be done; small increases in stall
1723    * percentages seem to have a big impact on throughput/latencies.  The below model where we have
1724    * an array into which we stash the syncs and then hand them off to the sync thread seemed like
1725    * a decent compromise.  See HBASE-8755 for more detail.
1726    */
1727   class RingBufferEventHandler implements EventHandler<RingBufferTruck>, LifecycleAware {
1728     private final SyncRunner [] syncRunners;
1729     private final SyncFuture [] syncFutures;
1730     // Had 'interesting' issues when this was non-volatile.  On occasion, we'd not pass all
1731     // syncFutures to the next sync'ing thread.
1732     private volatile int syncFuturesCount = 0;
1733     private volatile SafePointZigZagLatch zigzagLatch;
1734     /**
1735      * Set if we get an exception appending or syncing so that all subsequence appends and syncs
1736      * on this WAL fail until WAL is replaced.
1737      */
1738     private Exception exception = null;
1739     /**
1740      * Object to block on while waiting on safe point.
1741      */
1742     private final Object safePointWaiter = new Object();
1743     private volatile boolean shutdown = false;
1744 
1745     /**
1746      * Which syncrunner to use next.
1747      */
1748     private int syncRunnerIndex;
1749 
1750     RingBufferEventHandler(final int syncRunnerCount, final int maxHandlersCount) {
1751       this.syncFutures = new SyncFuture[maxHandlersCount];
1752       this.syncRunners = new SyncRunner[syncRunnerCount];
1753       for (int i = 0; i < syncRunnerCount; i++) {
1754         this.syncRunners[i] = new SyncRunner("sync." + i, maxHandlersCount);
1755       }
1756     }
1757 
1758     private void cleanupOutstandingSyncsOnException(final long sequence, final Exception e) {
1759       // There could be handler-count syncFutures outstanding.
1760       for (int i = 0; i < this.syncFuturesCount; i++) this.syncFutures[i].done(sequence, e);
1761       this.syncFuturesCount = 0;
1762     }
1763 
1764     /**
1765      * @return True if outstanding sync futures still
1766      */
1767     private boolean isOutstandingSyncs() {
1768       // Look at SyncFutures in the EventHandler
1769       for (int i = 0; i < this.syncFuturesCount; i++) {
1770         if (!this.syncFutures[i].isDone()) return true;
1771       }
1772 
1773       return false;
1774     }
1775 
1776     private boolean isOutstandingSyncsFromRunners() {
1777       // Look at SyncFutures in the SyncRunners
1778       for (SyncRunner syncRunner: syncRunners) {
1779         if(syncRunner.isAlive() && !syncRunner.areSyncFuturesReleased()) {
1780           return true;
1781         }
1782       }
1783       return false;
1784     }
1785 
1786     @Override
1787     // We can set endOfBatch in the below method if at end of our this.syncFutures array
1788     public void onEvent(final RingBufferTruck truck, final long sequence, boolean endOfBatch)
1789     throws Exception {
1790       // Appends and syncs are coming in order off the ringbuffer.  We depend on this fact.  We'll
1791       // add appends to dfsclient as they come in.  Batching appends doesn't give any significant
1792       // benefit on measurement.  Handler sync calls we will batch up. If we get an exception
1793       // appending an edit, we fail all subsequent appends and syncs with the same exception until
1794       // the WAL is reset. It is important that we not short-circuit and exit early this method.
1795       // It is important that we always go through the attainSafePoint on the end. Another thread,
1796       // the log roller may be waiting on a signal from us here and will just hang without it.
1797 
1798       try {
1799         if (truck.hasSyncFuturePayload()) {
1800           this.syncFutures[this.syncFuturesCount++] = truck.unloadSyncFuturePayload();
1801           // Force flush of syncs if we are carrying a full complement of syncFutures.
1802           if (this.syncFuturesCount == this.syncFutures.length) endOfBatch = true;
1803         } else if (truck.hasFSWALEntryPayload()) {
1804           TraceScope scope = Trace.continueSpan(truck.unloadSpanPayload());
1805           try {
1806             FSWALEntry entry = truck.unloadFSWALEntryPayload();
1807             if (this.exception != null) {
1808               // We got an exception on an earlier attempt at append. Do not let this append
1809               // go through. Fail it but stamp the sequenceid into this append though failed.
1810               // We need to do this to close the latch held down deep in WALKey...that is waiting
1811               // on sequenceid assignment otherwise it will just hang out (The #append method
1812               // called below does this also internally).
1813               entry.stampRegionSequenceId();
1814               // Return to keep processing events coming off the ringbuffer
1815               return;
1816             }
1817             append(entry);
1818           } catch (Exception e) {
1819             // Failed append. Record the exception.
1820             this.exception = e;
1821             // invoking cleanupOutstandingSyncsOnException when append failed with exception,
1822             // it will cleanup existing sync requests recorded in syncFutures but not offered to SyncRunner yet,
1823             // so there won't be any sync future left over if no further truck published to disruptor.
1824             cleanupOutstandingSyncsOnException(sequence,
1825                 this.exception instanceof DamagedWALException ? this.exception
1826                     : new DamagedWALException("On sync", this.exception));
1827             // Return to keep processing events coming off the ringbuffer
1828             return;
1829           } finally {
1830             assert scope == NullScope.INSTANCE || !scope.isDetached();
1831             scope.close(); // append scope is complete
1832           }
1833         } else {
1834           // What is this if not an append or sync. Fail all up to this!!!
1835           cleanupOutstandingSyncsOnException(sequence,
1836             new IllegalStateException("Neither append nor sync"));
1837           // Return to keep processing.
1838           return;
1839         }
1840 
1841         // TODO: Check size and if big go ahead and call a sync if we have enough data.
1842         // This is a sync. If existing exception, fall through. Else look to see if batch.
1843         if (this.exception == null) {
1844           // If not a batch, return to consume more events from the ring buffer before proceeding;
1845           // we want to get up a batch of syncs and appends before we go do a filesystem sync.
1846           if (!endOfBatch || this.syncFuturesCount <= 0) return;
1847           // syncRunnerIndex is bound to the range [0, Integer.MAX_INT - 1] as follows:
1848           //   * The maximum value possible for syncRunners.length is Integer.MAX_INT
1849           //   * syncRunnerIndex starts at 0 and is incremented only here
1850           //   * after the increment, the value is bounded by the '%' operator to [0, syncRunners.length),
1851           //     presuming the value was positive prior to the '%' operator.
1852           //   * after being bound to [0, Integer.MAX_INT - 1], the new value is stored in syncRunnerIndex
1853           //     ensuring that it can't grow without bound and overflow.
1854           //   * note that the value after the increment must be positive, because the most it could have
1855           //     been prior was Integer.MAX_INT - 1 and we only increment by 1.
1856           this.syncRunnerIndex = (this.syncRunnerIndex + 1) % this.syncRunners.length;
1857           try {
1858             // Below expects that the offer 'transfers' responsibility for the outstanding syncs to
1859             // the syncRunner. We should never get an exception in here.
1860             this.syncRunners[this.syncRunnerIndex].offer(sequence, this.syncFutures,
1861               this.syncFuturesCount);
1862           } catch (Exception e) {
1863             // Should NEVER get here.
1864             requestLogRoll();
1865             this.exception = new DamagedWALException("Failed offering sync", e);
1866           }
1867         }
1868         // We may have picked up an exception above trying to offer sync
1869         if (this.exception != null) {
1870           cleanupOutstandingSyncsOnException(sequence,
1871             this.exception instanceof DamagedWALException?
1872               this.exception:
1873               new DamagedWALException("On sync", this.exception));
1874         }
1875         attainSafePoint(sequence);
1876         this.syncFuturesCount = 0;
1877       } catch (Throwable t) {
1878         LOG.error("UNEXPECTED!!! syncFutures.length=" + this.syncFutures.length, t);
1879       }
1880     }
1881 
1882     SafePointZigZagLatch attainSafePoint() {
1883       this.zigzagLatch = new SafePointZigZagLatch();
1884       return this.zigzagLatch;
1885     }
1886 
1887     /**
1888      * Check if we should attain safe point.  If so, go there and then wait till signalled before
1889      * we proceeding.
1890      */
1891     private void attainSafePoint(final long currentSequence) {
1892       if (this.zigzagLatch == null || !this.zigzagLatch.isCocked()) return;
1893       // If here, another thread is waiting on us to get to safe point.  Don't leave it hanging.
1894       beforeWaitOnSafePoint();
1895       try {
1896         // Wait on outstanding syncers; wait for them to finish syncing (unless we've been
1897         // shutdown or unless our latch has been thrown because we have been aborted or unless
1898         // this WAL is broken and we can't get a sync/append to complete).
1899         while ((!this.shutdown && this.zigzagLatch.isCocked()
1900             && highestSyncedSequence.get() < currentSequence &&
1901             // We could be in here and all syncs are failing or failed. Check for this. Otherwise
1902             // we'll just be stuck here for ever. In other words, ensure there syncs running.
1903             isOutstandingSyncs())
1904             // Wait for all SyncRunners to finish their work so that we can replace the writer
1905             || isOutstandingSyncsFromRunners()) {
1906           synchronized (this.safePointWaiter) {
1907             this.safePointWaiter.wait(0, 1);
1908           }
1909         }
1910         // Tell waiting thread we've attained safe point. Can clear this.throwable if set here
1911         // because we know that next event through the ringbuffer will be going to a new WAL
1912         // after we do the zigzaglatch dance.
1913         this.exception = null;
1914         this.zigzagLatch.safePointAttained();
1915       } catch (InterruptedException e) {
1916         LOG.warn("Interrupted ", e);
1917         Thread.currentThread().interrupt();
1918       }
1919     }
1920 
1921     /**
1922      * Append to the WAL.  Does all CP and WAL listener calls.
1923      * @param entry
1924      * @throws Exception
1925      */
1926     void append(final FSWALEntry entry) throws Exception {
1927       // TODO: WORK ON MAKING THIS APPEND FASTER. DOING WAY TOO MUCH WORK WITH CPs, PBing, etc.
1928       atHeadOfRingBufferEventHandlerAppend();
1929 
1930       long start = EnvironmentEdgeManager.currentTime();
1931       byte [] encodedRegionName = entry.getKey().getEncodedRegionName();
1932       long regionSequenceId = WALKey.NO_SEQUENCE_ID;
1933       try {
1934         // We are about to append this edit; update the region-scoped sequence number.  Do it
1935         // here inside this single appending/writing thread.  Events are ordered on the ringbuffer
1936         // so region sequenceids will also be in order.
1937         regionSequenceId = entry.stampRegionSequenceId();
1938         // Edits are empty, there is nothing to append.  Maybe empty when we are looking for a
1939         // region sequence id only, a region edit/sequence id that is not associated with an actual
1940         // edit. It has to go through all the rigmarole to be sure we have the right ordering.
1941         if (entry.getEdit().isEmpty()) {
1942           return;
1943         }
1944 
1945         // Coprocessor hook.
1946         if (!coprocessorHost.preWALWrite(entry.getHRegionInfo(), entry.getKey(),
1947             entry.getEdit())) {
1948           if (entry.getEdit().isReplay()) {
1949             // Set replication scope null so that this won't be replicated
1950             entry.getKey().setScopes(null);
1951           }
1952         }
1953         if (!listeners.isEmpty()) {
1954           for (WALActionsListener i: listeners) {
1955             // TODO: Why does listener take a table description and CPs take a regioninfo?  Fix.
1956             i.visitLogEntryBeforeWrite(entry.getHTableDescriptor(), entry.getKey(),
1957               entry.getEdit());
1958           }
1959         }
1960 
1961         writer.append(entry);
1962         assert highestUnsyncedSequence < entry.getSequence();
1963         highestUnsyncedSequence = entry.getSequence();
1964         sequenceIdAccounting.update(encodedRegionName, entry.getFamilyNames(), regionSequenceId,
1965           entry.isInMemstore());
1966         coprocessorHost.postWALWrite(entry.getHRegionInfo(), entry.getKey(), entry.getEdit());
1967         // Update metrics.
1968         postAppend(entry, EnvironmentEdgeManager.currentTime() - start);
1969       } catch (Exception e) {
1970         String msg = "Append sequenceId=" + regionSequenceId + ", requesting roll of WAL";
1971         LOG.warn(msg, e);
1972         requestLogRoll();
1973         throw new DamagedWALException(msg, e);
1974       }
1975       numEntries.incrementAndGet();
1976     }
1977 
1978     @Override
1979     public void onStart() {
1980       for (SyncRunner syncRunner: this.syncRunners) syncRunner.start();
1981     }
1982 
1983     @Override
1984     public void onShutdown() {
1985       for (SyncRunner syncRunner: this.syncRunners) syncRunner.interrupt();
1986     }
1987   }
1988 
1989   /**
1990    * Exposed for testing only.  Use to tricks like halt the ring buffer appending.
1991    */
1992   @VisibleForTesting
1993   void atHeadOfRingBufferEventHandlerAppend() {
1994     // Noop
1995   }
1996 
1997   private static IOException ensureIOException(final Throwable t) {
1998     return (t instanceof IOException)? (IOException)t: new IOException(t);
1999   }
2000 
2001   private static void usage() {
2002     System.err.println("Usage: FSHLog <ARGS>");
2003     System.err.println("Arguments:");
2004     System.err.println(" --dump  Dump textual representation of passed one or more files");
2005     System.err.println("         For example: " +
2006       "FSHLog --dump hdfs://example.com:9000/hbase/.logs/MACHINE/LOGFILE");
2007     System.err.println(" --split Split the passed directory of WAL logs");
2008     System.err.println("         For example: " +
2009       "FSHLog --split hdfs://example.com:9000/hbase/.logs/DIR");
2010   }
2011 
2012   /**
2013    * Pass one or more log file names and it will either dump out a text version
2014    * on <code>stdout</code> or split the specified log files.
2015    *
2016    * @param args
2017    * @throws IOException
2018    */
2019   public static void main(String[] args) throws IOException {
2020     if (args.length < 2) {
2021       usage();
2022       System.exit(-1);
2023     }
2024     // either dump using the WALPrettyPrinter or split, depending on args
2025     if (args[0].compareTo("--dump") == 0) {
2026       WALPrettyPrinter.run(Arrays.copyOfRange(args, 1, args.length));
2027     } else if (args[0].compareTo("--perf") == 0) {
2028       LOG.fatal("Please use the WALPerformanceEvaluation tool instead. i.e.:");
2029       LOG.fatal("\thbase org.apache.hadoop.hbase.wal.WALPerformanceEvaluation --iterations " +
2030           args[1]);
2031       System.exit(-1);
2032     } else if (args[0].compareTo("--split") == 0) {
2033       Configuration conf = HBaseConfiguration.create();
2034       for (int i = 1; i < args.length; i++) {
2035         try {
2036           Path logPath = new Path(args[i]);
2037           FSUtils.setFsDefault(conf, logPath);
2038           split(conf, logPath);
2039         } catch (IOException t) {
2040           t.printStackTrace(System.err);
2041           System.exit(-1);
2042         }
2043       }
2044     } else {
2045       usage();
2046       System.exit(-1);
2047     }
2048   }
2049 
2050   /**
2051    * This method gets the pipeline for the current WAL.
2052    */
2053   @VisibleForTesting
2054   DatanodeInfo[] getPipeLine() {
2055     if (this.hdfs_out != null) {
2056       if (this.hdfs_out.getWrappedStream() instanceof DFSOutputStream) {
2057         return ((DFSOutputStream) this.hdfs_out.getWrappedStream()).getPipeline();
2058       }
2059     }
2060     return new DatanodeInfo[0];
2061   }
2062 
2063   /**
2064    *
2065    * @return last time on checking low replication
2066    */
2067   public long getLastTimeCheckLowReplication() {
2068     return this.lastTimeCheckLowReplication;
2069   }
2070 }