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}