View Javadoc

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