001/**
002 * Licensed to the Apache Software Foundation (ASF) under one
003 * or more contributor license agreements.  See the NOTICE file
004 * distributed with this work for additional information
005 * regarding copyright ownership.  The ASF licenses this file
006 * to you under the Apache License, Version 2.0 (the
007 * "License"); you may not use this file except in compliance
008 * with the License.  You may obtain a copy of the License at
009 *
010 *     http://www.apache.org/licenses/LICENSE-2.0
011 *
012 * Unless required by applicable law or agreed to in writing, software
013 * distributed under the License is distributed on an "AS IS" BASIS,
014 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
015 * See the License for the specific language governing permissions and
016 * limitations under the License.
017 */
018
019package org.apache.hadoop.hbase.mttr;
020
021import static org.junit.Assert.assertEquals;
022import static org.junit.Assume.assumeFalse;
023
024import java.io.IOException;
025import java.util.ArrayList;
026import java.util.concurrent.Callable;
027import java.util.concurrent.ExecutorService;
028import java.util.concurrent.Executors;
029import java.util.concurrent.Future;
030import java.util.concurrent.TimeUnit;
031import org.apache.commons.lang3.RandomStringUtils;
032import org.apache.commons.math3.stat.descriptive.DescriptiveStatistics;
033import org.apache.hadoop.hbase.ClusterStatus;
034import org.apache.hadoop.hbase.IntegrationTestingUtility;
035import org.apache.hadoop.hbase.InvalidFamilyOperationException;
036import org.apache.hadoop.hbase.NamespaceExistException;
037import org.apache.hadoop.hbase.NamespaceNotFoundException;
038import org.apache.hadoop.hbase.TableExistsException;
039import org.apache.hadoop.hbase.TableName;
040import org.apache.hadoop.hbase.TableNotFoundException;
041import org.apache.hadoop.hbase.chaos.actions.Action;
042import org.apache.hadoop.hbase.chaos.actions.MoveRegionsOfTableAction;
043import org.apache.hadoop.hbase.chaos.actions.RestartActiveMasterAction;
044import org.apache.hadoop.hbase.chaos.actions.RestartRsHoldingMetaAction;
045import org.apache.hadoop.hbase.chaos.actions.RestartRsHoldingTableAction;
046import org.apache.hadoop.hbase.chaos.factories.MonkeyConstants;
047import org.apache.hadoop.hbase.client.Admin;
048import org.apache.hadoop.hbase.client.ColumnFamilyDescriptorBuilder;
049import org.apache.hadoop.hbase.client.Put;
050import org.apache.hadoop.hbase.client.Result;
051import org.apache.hadoop.hbase.client.ResultScanner;
052import org.apache.hadoop.hbase.client.RetriesExhaustedException;
053import org.apache.hadoop.hbase.client.Scan;
054import org.apache.hadoop.hbase.client.Table;
055import org.apache.hadoop.hbase.client.TableDescriptor;
056import org.apache.hadoop.hbase.client.TableDescriptorBuilder;
057import org.apache.hadoop.hbase.coprocessor.CoprocessorException;
058import org.apache.hadoop.hbase.filter.KeyOnlyFilter;
059import org.apache.hadoop.hbase.ipc.FatalConnectionException;
060import org.apache.hadoop.hbase.regionserver.NoSuchColumnFamilyException;
061import org.apache.hadoop.hbase.security.AccessDeniedException;
062import org.apache.hbase.thirdparty.com.google.common.base.MoreObjects;
063import org.apache.hadoop.hbase.testclassification.IntegrationTests;
064import org.apache.hadoop.hbase.trace.TraceUtil;
065import org.apache.hadoop.hbase.util.Bytes;
066import org.apache.hadoop.hbase.util.LoadTestTool;
067import org.apache.htrace.core.AlwaysSampler;
068import org.apache.htrace.core.Span;
069import org.apache.htrace.core.TraceScope;
070import org.junit.AfterClass;
071import org.junit.BeforeClass;
072import org.junit.Test;
073import org.junit.experimental.categories.Category;
074import org.slf4j.Logger;
075import org.slf4j.LoggerFactory;
076
077/**
078 * Integration test that should benchmark how fast HBase can recover from failures. This test starts
079 * different threads:
080 * <ol>
081 * <li>
082 * Load Test Tool.<br/>
083 * This runs so that all RegionServers will have some load and WALs will be full.
084 * </li>
085 * <li>
086 * Scan thread.<br/>
087 * This thread runs a very short scan over and over again recording how log it takes to respond.
088 * The longest response is assumed to be the time it took to recover.
089 * </li>
090 * <li>
091 * Put thread.<br/>
092 * This thread just like the scan thread except it does a very small put.
093 * </li>
094 * <li>
095 * Admin thread. <br/>
096 * This thread will continually go to the master to try and get the cluster status.  Just like the
097 * put and scan threads, the time to respond is recorded.
098 * </li>
099 * <li>
100 * Chaos Monkey thread.<br/>
101 * This thread runs a ChaosMonkey.Action.
102 * </li>
103 * </ol>
104 * <p/>
105 * The ChaosMonkey actions currently run are:
106 * <ul>
107 * <li>Restart the RegionServer holding meta.</li>
108 * <li>Move the Regions of meta.</li>
109 * <li>Restart the RegionServer holding the table the scan and put threads are targeting.</li>
110 * <li>Move the Regions of the table used by the scan and put threads.</li>
111 * <li>Restart the master.</li>
112 * </ul>
113 * <p/>
114 * At the end of the test a log line is output on the INFO level containing the timing data that was
115 * collected.
116 */
117@Category(IntegrationTests.class)
118public class IntegrationTestMTTR {
119  /**
120   * Constants.
121   */
122  private static final byte[] FAMILY = Bytes.toBytes("d");
123  private static final Logger LOG = LoggerFactory.getLogger(IntegrationTestMTTR.class);
124  private static long sleepTime;
125  private static final String SLEEP_TIME_KEY = "hbase.IntegrationTestMTTR.sleeptime";
126  private static final long SLEEP_TIME_DEFAULT = 60 * 1000l;
127
128  /**
129   * Configurable table names.
130   */
131  private static TableName tableName;
132  private static TableName loadTableName;
133
134  /**
135   * Util to get at the cluster.
136   */
137  private static IntegrationTestingUtility util;
138
139  /**
140   * Executor for test threads.
141   */
142  private static ExecutorService executorService;
143
144  /**
145   * All of the chaos monkey actions used.
146   */
147  private static Action restartRSAction;
148  private static Action restartMetaAction;
149  private static Action moveMetaRegionsAction;
150  private static Action moveRegionAction;
151  private static Action restartMasterAction;
152
153  /**
154   * The load test tool used to create load and make sure that WALs aren't empty.
155   */
156  private static LoadTestTool loadTool;
157
158
159  @BeforeClass
160  public static void setUp() throws Exception {
161    // Set up the integration test util
162    if (util == null) {
163      util = new IntegrationTestingUtility();
164    }
165
166    // Make sure there are three servers.
167    util.initializeCluster(3);
168
169    // Set up the load test tool.
170    loadTool = new LoadTestTool();
171    loadTool.setConf(util.getConfiguration());
172
173    // Create executor with enough threads to restart rs's,
174    // run scans, puts, admin ops and load test tool.
175    executorService = Executors.newFixedThreadPool(8);
176
177    // Set up the tables needed.
178    setupTables();
179
180    // Set up the actions.
181    sleepTime = util.getConfiguration().getLong(SLEEP_TIME_KEY, SLEEP_TIME_DEFAULT);
182    setupActions();
183  }
184
185  private static void setupActions() throws IOException {
186    // allow a little more time for RS restart actions because RS start depends on having a master
187    // to report to and the master is also being monkeyed.
188    util.getConfiguration().setLong(Action.START_RS_TIMEOUT_KEY, 3 * 60 * 1000);
189
190    // Set up the action that will restart a region server holding a region from our table
191    // because this table should only have one region we should be good.
192    restartRSAction = new RestartRsHoldingTableAction(sleepTime,
193        util.getConnection().getRegionLocator(tableName));
194
195    // Set up the action that will kill the region holding meta.
196    restartMetaAction = new RestartRsHoldingMetaAction(sleepTime);
197
198    // Set up the action that will move the regions of meta.
199    moveMetaRegionsAction = new MoveRegionsOfTableAction(sleepTime,
200        MonkeyConstants.DEFAULT_MOVE_REGIONS_MAX_TIME, TableName.META_TABLE_NAME);
201
202    // Set up the action that will move the regions of our table.
203    moveRegionAction = new MoveRegionsOfTableAction(sleepTime,
204        MonkeyConstants.DEFAULT_MOVE_REGIONS_MAX_TIME, tableName);
205
206    // Kill the master
207    restartMasterAction = new RestartActiveMasterAction(1000);
208
209    // Give the action the access to the cluster.
210    Action.ActionContext actionContext = new Action.ActionContext(util);
211    restartRSAction.init(actionContext);
212    restartMetaAction.init(actionContext);
213    moveMetaRegionsAction.init(actionContext);
214    moveRegionAction.init(actionContext);
215    restartMasterAction.init(actionContext);
216  }
217
218  private static void setupTables() throws IOException {
219    // Get the table name.
220    tableName = TableName.valueOf(util.getConfiguration()
221        .get("hbase.IntegrationTestMTTR.tableName", "IntegrationTestMTTR"));
222
223    loadTableName = TableName.valueOf(util.getConfiguration()
224        .get("hbase.IntegrationTestMTTR.loadTableName", "IntegrationTestMTTRLoadTestTool"));
225
226    if (util.getAdmin().tableExists(tableName)) {
227      util.deleteTable(tableName);
228    }
229
230    if (util.getAdmin().tableExists(loadTableName)) {
231      util.deleteTable(loadTableName);
232    }
233
234    // Create the table.  If this fails then fail everything.
235    TableDescriptor tableDescriptor = util.getAdmin().getDescriptor(tableName);
236    TableDescriptorBuilder builder = TableDescriptorBuilder.newBuilder(tableDescriptor);
237
238    // Make the max file size huge so that splits don't happen during the test.
239    builder.setMaxFileSize(Long.MAX_VALUE);
240
241    ColumnFamilyDescriptorBuilder colDescriptorBldr =
242        ColumnFamilyDescriptorBuilder.newBuilder(FAMILY);
243    colDescriptorBldr.setMaxVersions(1);
244    builder.setColumnFamily(colDescriptorBldr.build());
245    util.getAdmin().createTable(builder.build());
246
247    // Setup the table for LoadTestTool
248    int ret = loadTool.run(new String[]{"-tn", loadTableName.getNameAsString(), "-init_only"});
249    assertEquals("Failed to initialize LoadTestTool", 0, ret);
250  }
251
252  @AfterClass
253  public static void after() throws IOException {
254    // Clean everything up.
255    util.restoreCluster();
256    util = null;
257
258    // Stop the threads so that we know everything is complete.
259    executorService.shutdown();
260    executorService = null;
261
262    // Clean up the actions.
263    moveRegionAction = null;
264    restartMetaAction = null;
265    moveMetaRegionsAction = null;
266    restartRSAction = null;
267    restartMasterAction = null;
268
269    loadTool = null;
270  }
271
272  private static boolean tablesOnMaster() {
273    boolean ret = true;
274    String value = util.getConfiguration().get("hbase.balancer.tablesOnMaster");
275    if( value != null && value.equalsIgnoreCase("none")) {
276      ret = false;
277    }
278    return ret;
279  }
280
281  @Test
282  public void testRestartRsHoldingTable() throws Exception {
283    run(new ActionCallable(restartRSAction), "RestartRsHoldingTableAction");
284  }
285
286  @Test
287  public void testKillRsHoldingMeta() throws Exception {
288    assumeFalse(tablesOnMaster());
289    run(new ActionCallable(restartMetaAction), "KillRsHoldingMeta");
290  }
291
292  @Test
293  public void testMoveMeta() throws Exception {
294    run(new ActionCallable(moveMetaRegionsAction), "MoveMeta");
295  }
296
297  @Test
298  public void testMoveRegion() throws Exception {
299    run(new ActionCallable(moveRegionAction), "MoveRegion");
300  }
301
302  @Test
303  public void testRestartMaster() throws Exception {
304    run(new ActionCallable(restartMasterAction), "RestartMaster");
305  }
306
307  public void run(Callable<Boolean> monkeyCallable, String testName) throws Exception {
308    int maxIters = util.getHBaseClusterInterface().isDistributedCluster() ? 10 : 3;
309    LOG.info("Starting " + testName + " with " + maxIters + " iterations.");
310
311    // Array to keep track of times.
312    ArrayList<TimingResult> resultPuts = new ArrayList<>(maxIters);
313    ArrayList<TimingResult> resultScan = new ArrayList<>(maxIters);
314    ArrayList<TimingResult> resultAdmin = new ArrayList<>(maxIters);
315    long start = System.nanoTime();
316
317    try {
318      // We're going to try this multiple times
319      for (int fullIterations = 0; fullIterations < maxIters; fullIterations++) {
320        // Create and start executing a callable that will kill the servers
321        Future<Boolean> monkeyFuture = executorService.submit(monkeyCallable);
322
323        // Pass that future to the timing Callables.
324        Future<TimingResult> putFuture = executorService.submit(new PutCallable(monkeyFuture));
325        Future<TimingResult> scanFuture = executorService.submit(new ScanCallable(monkeyFuture));
326        Future<TimingResult> adminFuture = executorService.submit(new AdminCallable(monkeyFuture));
327
328        Future<Boolean> loadFuture = executorService.submit(new LoadCallable(monkeyFuture));
329
330        monkeyFuture.get();
331        loadFuture.get();
332
333        // Get the values from the futures.
334        TimingResult putTime = putFuture.get();
335        TimingResult scanTime = scanFuture.get();
336        TimingResult adminTime = adminFuture.get();
337
338        // Store the times to display later.
339        resultPuts.add(putTime);
340        resultScan.add(scanTime);
341        resultAdmin.add(adminTime);
342
343        // Wait some time for everything to settle down.
344        Thread.sleep(5000l);
345      }
346    } catch (Exception e) {
347      long runtimeMs = TimeUnit.MILLISECONDS.convert(System.nanoTime() - start, TimeUnit.NANOSECONDS);
348      LOG.info(testName + " failed after " + runtimeMs + "ms.", e);
349      throw e;
350    }
351
352    long runtimeMs = TimeUnit.MILLISECONDS.convert(System.nanoTime() - start, TimeUnit.NANOSECONDS);
353
354    MoreObjects.ToStringHelper helper = MoreObjects.toStringHelper("MTTRResults")
355        .add("putResults", resultPuts)
356        .add("scanResults", resultScan)
357        .add("adminResults", resultAdmin)
358        .add("totalRuntimeMs", runtimeMs)
359        .add("name", testName);
360
361    // Log the info
362    LOG.info(helper.toString());
363  }
364
365  /**
366   * Class to store results of TimingCallable.
367   *
368   * Stores times and trace id.
369   */
370  private static class TimingResult {
371    DescriptiveStatistics stats = new DescriptiveStatistics();
372    ArrayList<String> traces = new ArrayList<>(10);
373
374    /**
375     * Add a result to this aggregate result.
376     * @param time Time in nanoseconds
377     * @param span Span.  To be kept if the time taken was over 1 second
378     */
379    public void addResult(long time, Span span) {
380      if (span == null) {
381        return;
382      }
383      stats.addValue(TimeUnit.MILLISECONDS.convert(time, TimeUnit.NANOSECONDS));
384      if (TimeUnit.SECONDS.convert(time, TimeUnit.NANOSECONDS) >= 1) {
385        traces.add(span.getTracerId());
386      }
387    }
388
389    @Override
390    public String toString() {
391      MoreObjects.ToStringHelper helper = MoreObjects.toStringHelper(this)
392          .add("numResults", stats.getN())
393          .add("minTime", stats.getMin())
394          .add("meanTime", stats.getMean())
395          .add("maxTime", stats.getMax())
396          .add("25th", stats.getPercentile(25))
397          .add("50th", stats.getPercentile(50))
398          .add("75th", stats.getPercentile(75))
399          .add("90th", stats.getPercentile(90))
400          .add("95th", stats.getPercentile(95))
401          .add("99th", stats.getPercentile(99))
402          .add("99.9th", stats.getPercentile(99.9))
403          .add("99.99th", stats.getPercentile(99.99))
404          .add("traces", traces);
405      return helper.toString();
406    }
407  }
408
409  /**
410   * Base class for actions that need to record the time needed to recover from a failure.
411   */
412  static abstract class TimingCallable implements Callable<TimingResult> {
413    protected final Future<?> future;
414
415    public TimingCallable(Future<?> f) {
416      future = f;
417    }
418
419    @Override
420    public TimingResult call() throws Exception {
421      TimingResult result = new TimingResult();
422      final int maxIterations = 10;
423      int numAfterDone = 0;
424      int resetCount = 0;
425      TraceUtil.addSampler(AlwaysSampler.INSTANCE);
426      // Keep trying until the rs is back up and we've gotten a put through
427      while (numAfterDone < maxIterations) {
428        long start = System.nanoTime();
429        Span span = null;
430        try (TraceScope scope = TraceUtil.createTrace(getSpanName())) {
431          if (scope != null) {
432            span = scope.getSpan();
433          }
434          boolean actionResult = doAction();
435          if (actionResult && future.isDone()) {
436            numAfterDone++;
437          }
438
439        // the following Exceptions derive from DoNotRetryIOException. They are considered
440        // fatal for the purpose of this test. If we see one of these, it means something is
441        // broken and needs investigation. This is not the case for all children of DNRIOE.
442        // Unfortunately, this is an explicit enumeration and will need periodically refreshed.
443        // See HBASE-9655 for further discussion.
444        } catch (AccessDeniedException e) {
445          throw e;
446        } catch (CoprocessorException e) {
447          throw e;
448        } catch (FatalConnectionException e) {
449          throw e;
450        } catch (InvalidFamilyOperationException e) {
451          throw e;
452        } catch (NamespaceExistException e) {
453          throw e;
454        } catch (NamespaceNotFoundException e) {
455          throw e;
456        } catch (NoSuchColumnFamilyException e) {
457          throw e;
458        } catch (TableExistsException e) {
459          throw e;
460        } catch (TableNotFoundException e) {
461          throw e;
462        } catch (RetriesExhaustedException e){
463          throw e;
464
465        // Everything else is potentially recoverable on the application side. For instance, a CM
466        // action kills the RS that hosted a scanner the client was using. Continued use of that
467        // scanner should be terminated, but a new scanner can be created and the read attempted
468        // again.
469        } catch (Exception e) {
470          resetCount++;
471          if (resetCount < maxIterations) {
472            LOG.info("Non-fatal exception while running " + this.toString()
473              + ". Resetting loop counter", e);
474            numAfterDone = 0;
475          } else {
476            LOG.info("Too many unexpected Exceptions. Aborting.", e);
477            throw e;
478          }
479        }
480        result.addResult(System.nanoTime() - start, span);
481      }
482      return result;
483    }
484
485    protected abstract boolean doAction() throws Exception;
486
487    protected String getSpanName() {
488      return this.getClass().getSimpleName();
489    }
490
491    @Override
492    public String toString() {
493      return this.getSpanName();
494    }
495  }
496
497  /**
498   * Callable that will keep putting small amounts of data into a table
499   * until  the future supplied returns.  It keeps track of the max time.
500   */
501  static class PutCallable extends TimingCallable {
502
503    private final Table table;
504
505    public PutCallable(Future<?> f) throws IOException {
506      super(f);
507      this.table = util.getConnection().getTable(tableName);
508    }
509
510    @Override
511    protected boolean doAction() throws Exception {
512      Put p = new Put(Bytes.toBytes(RandomStringUtils.randomAlphanumeric(5)));
513      p.addColumn(FAMILY, Bytes.toBytes("\0"), Bytes.toBytes(RandomStringUtils.randomAscii(5)));
514      table.put(p);
515      return true;
516    }
517
518    @Override
519    protected String getSpanName() {
520      return "MTTR Put Test";
521    }
522  }
523
524  /**
525   * Callable that will keep scanning for small amounts of data until the
526   * supplied future returns.  Returns the max time taken to scan.
527   */
528  static class ScanCallable extends TimingCallable {
529    private final Table table;
530
531    public ScanCallable(Future<?> f) throws IOException {
532      super(f);
533      this.table = util.getConnection().getTable(tableName);
534    }
535
536    @Override
537    protected boolean doAction() throws Exception {
538      ResultScanner rs = null;
539      try {
540        Scan s = new Scan();
541        s.setBatch(2);
542        s.addFamily(FAMILY);
543        s.setFilter(new KeyOnlyFilter());
544        s.setMaxVersions(1);
545
546        rs = table.getScanner(s);
547        Result result = rs.next();
548        return result != null && result.size() > 0;
549      } finally {
550        if (rs != null) {
551          rs.close();
552        }
553      }
554    }
555    @Override
556    protected String getSpanName() {
557      return "MTTR Scan Test";
558    }
559  }
560
561  /**
562   * Callable that will keep going to the master for cluster status.  Returns the max time taken.
563   */
564  static class AdminCallable extends TimingCallable {
565
566    public AdminCallable(Future<?> f) throws IOException {
567      super(f);
568    }
569
570    @Override
571    protected boolean doAction() throws Exception {
572      Admin admin = null;
573      try {
574        admin = util.getAdmin();
575        ClusterStatus status = admin.getClusterStatus();
576        return status != null;
577      } finally {
578        if (admin != null) {
579          admin.close();
580        }
581      }
582    }
583
584    @Override
585    protected String getSpanName() {
586      return "MTTR Admin Test";
587    }
588  }
589
590
591  static class ActionCallable implements Callable<Boolean> {
592    private final Action action;
593
594    public ActionCallable(Action action) {
595      this.action = action;
596    }
597
598    @Override
599    public Boolean call() throws Exception {
600      this.action.perform();
601      return true;
602    }
603  }
604
605  /**
606   * Callable used to make sure the cluster has some load on it.
607   * This callable uses LoadTest tool to
608   */
609  public static class LoadCallable implements Callable<Boolean> {
610
611    private final Future<?> future;
612
613    public LoadCallable(Future<?> f) {
614      future = f;
615    }
616
617    @Override
618    public Boolean call() throws Exception {
619      int colsPerKey = 10;
620      int numServers = util.getHBaseClusterInterface().getInitialClusterMetrics()
621        .getLiveServerMetrics().size();
622      int numKeys = numServers * 5000;
623      int writeThreads = 10;
624
625
626      // Loop until the chaos monkey future is done.
627      // But always go in just in case some action completes quickly
628      do {
629        int ret = loadTool.run(new String[]{
630            "-tn", loadTableName.getNameAsString(),
631            "-write", String.format("%d:%d:%d", colsPerKey, 500, writeThreads),
632            "-num_keys", String.valueOf(numKeys),
633            "-skip_init"
634        });
635        assertEquals("Load failed", 0, ret);
636      } while (!future.isDone());
637
638      return true;
639    }
640  }
641}