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 */ 018package org.apache.hadoop.hbase.regionserver.wal; 019 020import static org.awaitility.Awaitility.await; 021import static org.hamcrest.MatcherAssert.assertThat; 022import static org.hamcrest.Matchers.greaterThan; 023import static org.junit.jupiter.api.Assertions.assertEquals; 024import static org.junit.jupiter.api.Assertions.assertFalse; 025import static org.junit.jupiter.api.Assertions.assertNotNull; 026import static org.junit.jupiter.api.Assertions.assertTrue; 027 028import java.io.IOException; 029import java.time.Duration; 030import java.util.concurrent.Executors; 031import java.util.concurrent.ScheduledExecutorService; 032import java.util.concurrent.atomic.AtomicBoolean; 033import org.apache.hadoop.conf.Configuration; 034import org.apache.hadoop.fs.FileSystem; 035import org.apache.hadoop.hbase.HBaseTestingUtil; 036import org.apache.hadoop.hbase.HConstants; 037import org.apache.hadoop.hbase.ServerName; 038import org.apache.hadoop.hbase.SingleProcessHBaseCluster; 039import org.apache.hadoop.hbase.StartTestingClusterOption; 040import org.apache.hadoop.hbase.TableName; 041import org.apache.hadoop.hbase.Waiter; 042import org.apache.hadoop.hbase.client.Admin; 043import org.apache.hadoop.hbase.client.ColumnFamilyDescriptorBuilder; 044import org.apache.hadoop.hbase.client.Get; 045import org.apache.hadoop.hbase.client.Put; 046import org.apache.hadoop.hbase.client.RegionInfo; 047import org.apache.hadoop.hbase.client.Result; 048import org.apache.hadoop.hbase.client.Table; 049import org.apache.hadoop.hbase.client.TableDescriptor; 050import org.apache.hadoop.hbase.client.TableDescriptorBuilder; 051import org.apache.hadoop.hbase.regionserver.HRegion; 052import org.apache.hadoop.hbase.regionserver.HRegionServer; 053import org.apache.hadoop.hbase.regionserver.Store; 054import org.apache.hadoop.hbase.util.Bytes; 055import org.apache.hadoop.hbase.util.Threads; 056import org.apache.hadoop.hbase.wal.AbstractFSWALProvider; 057import org.apache.hadoop.hbase.wal.WAL; 058import org.apache.hadoop.hbase.wal.WALFactory; 059import org.apache.hadoop.hbase.wal.WALProvider; 060import org.apache.hadoop.hdfs.MiniDFSCluster; 061import org.junit.jupiter.api.AfterAll; 062import org.junit.jupiter.api.AfterEach; 063import org.junit.jupiter.api.BeforeAll; 064import org.junit.jupiter.api.BeforeEach; 065import org.junit.jupiter.api.Test; 066import org.junit.jupiter.api.TestInfo; 067import org.slf4j.Logger; 068import org.slf4j.LoggerFactory; 069 070import org.apache.hbase.thirdparty.com.google.common.util.concurrent.ThreadFactoryBuilder; 071 072/** 073 * Test log deletion as logs are rolled. 074 */ 075public abstract class AbstractTestLogRolling { 076 private static final Logger LOG = LoggerFactory.getLogger(AbstractTestLogRolling.class); 077 protected HRegionServer server; 078 protected String tableName; 079 protected byte[] value; 080 protected FileSystem fs; 081 protected MiniDFSCluster dfsCluster; 082 protected Admin admin; 083 protected SingleProcessHBaseCluster cluster; 084 protected static final HBaseTestingUtil TEST_UTIL = new HBaseTestingUtil(); 085 private String name; 086 protected static int syncLatencyMillis; 087 private static int rowNum = 1; 088 private static final AtomicBoolean slowSyncHookCalled = new AtomicBoolean(); 089 protected static ScheduledExecutorService EXECUTOR; 090 091 public AbstractTestLogRolling() { 092 this.server = null; 093 this.tableName = null; 094 095 String className = this.getClass().getName(); 096 StringBuilder v = new StringBuilder(className); 097 while (v.length() < 1000) { 098 v.append(className); 099 } 100 this.value = Bytes.toBytes(v.toString()); 101 } 102 103 // Need to override this setup so we can edit the config before it gets sent 104 // to the HDFS & HBase cluster startup. 105 @BeforeAll 106 public static void setUpBeforeClass() throws Exception { 107 /**** configuration for testLogRolling ****/ 108 // Force a region split after every 768KB 109 Configuration conf = TEST_UTIL.getConfiguration(); 110 conf.setLong(HConstants.HREGION_MAX_FILESIZE, 768L * 1024L); 111 112 // We roll the log after every 32 writes 113 conf.setInt("hbase.regionserver.maxlogentries", 32); 114 115 conf.setInt("hbase.regionserver.logroll.errors.tolerated", 2); 116 conf.setInt("hbase.rpc.timeout", 10 * 1000); 117 118 // For less frequently updated regions flush after every 2 flushes 119 conf.setInt("hbase.hregion.memstore.optionalflushcount", 2); 120 121 // We flush the cache after every 8192 bytes 122 conf.setInt(HConstants.HREGION_MEMSTORE_FLUSH_SIZE, 8192); 123 124 // Increase the amount of time between client retries 125 conf.setLong("hbase.client.pause", 10 * 1000); 126 127 // Reduce thread wake frequency so that other threads can get 128 // a chance to run. 129 conf.setInt(HConstants.THREAD_WAKE_FREQUENCY, 2 * 1000); 130 131 // disable low replication check for log roller to get a more stable result 132 // TestWALOpenAfterDNRollingStart will test this option. 133 conf.setLong("hbase.regionserver.hlog.check.lowreplication.interval", 24L * 60 * 60 * 1000); 134 135 // For slow sync threshold test: roll after 5 slow syncs in 10 seconds 136 conf.setInt(FSHLog.SLOW_SYNC_ROLL_THRESHOLD, 5); 137 conf.setInt(FSHLog.SLOW_SYNC_ROLL_INTERVAL_MS, 10 * 1000); 138 // For slow sync threshold test: roll once after a sync above this threshold 139 conf.setInt(FSHLog.ROLL_ON_SYNC_TIME_MS, 5000); 140 141 // Slow sync executor. 142 EXECUTOR = Executors 143 .newSingleThreadScheduledExecutor(new ThreadFactoryBuilder().setNameFormat("Slow-sync-%d") 144 .setDaemon(true).setUncaughtExceptionHandler(Threads.LOGGING_EXCEPTION_HANDLER).build()); 145 } 146 147 @BeforeEach 148 public void initTestName(TestInfo testInfo) { 149 name = testInfo.getTestMethod().get().getName(); 150 } 151 152 @BeforeEach 153 public void setUp() throws Exception { 154 // Use 2 DataNodes and default values for other StartMiniCluster options. 155 TEST_UTIL.startMiniCluster(StartTestingClusterOption.builder().numDataNodes(2).build()); 156 157 cluster = TEST_UTIL.getHBaseCluster(); 158 dfsCluster = TEST_UTIL.getDFSCluster(); 159 fs = TEST_UTIL.getTestFileSystem(); 160 admin = TEST_UTIL.getAdmin(); 161 162 // disable region rebalancing (interferes with log watching) 163 cluster.getMaster().balanceSwitch(false); 164 } 165 166 @AfterEach 167 public void tearDown() throws Exception { 168 TEST_UTIL.shutdownMiniCluster(); 169 } 170 171 @AfterAll 172 public static void tearDownAfterClass() { 173 EXECUTOR.shutdownNow(); 174 } 175 176 private void startAndWriteData() throws IOException, InterruptedException { 177 this.server = cluster.getRegionServerThreads().get(0).getRegionServer(); 178 179 Table table = createTestTable(this.tableName); 180 181 server = TEST_UTIL.getRSForFirstRegionInTable(table.getName()); 182 for (int i = 1; i <= 256; i++) { // 256 writes should cause 8 log rolls 183 doPut(table, i); 184 if (i % 32 == 0) { 185 // After every 32 writes sleep to let the log roller run 186 try { 187 Thread.sleep(2000); 188 } catch (InterruptedException e) { 189 // continue 190 } 191 } 192 } 193 } 194 195 private static void setSyncLatencyMillis(int latency) { 196 syncLatencyMillis = latency; 197 } 198 199 protected final AbstractFSWAL<?> getWALAndRegisterSlowSyncHook(RegionInfo region) 200 throws IOException { 201 // Get a reference to the wal. 202 final AbstractFSWAL<?> log = (AbstractFSWAL<?>) server.getWAL(region); 203 204 // Register a WALActionsListener to observe if a SLOW_SYNC roll is requested 205 log.registerWALActionsListener(new WALActionsListener() { 206 @Override 207 public void logRollRequested(RollRequestReason reason) { 208 switch (reason) { 209 case SLOW_SYNC: 210 slowSyncHookCalled.lazySet(true); 211 break; 212 default: 213 break; 214 } 215 } 216 }); 217 return log; 218 } 219 220 protected final void checkSlowSync(AbstractFSWAL<?> log, Table table, int slowSyncLatency, 221 int writeCount, boolean slowSync) throws Exception { 222 if (slowSyncLatency > 0) { 223 setSyncLatencyMillis(slowSyncLatency); 224 setSlowLogWriter(log.conf); 225 } else { 226 setDefaultLogWriter(log.conf); 227 } 228 229 // Set up for test 230 log.rollWriter(true); 231 slowSyncHookCalled.set(false); 232 233 final WALProvider.WriterBase oldWriter = log.getWriter(); 234 235 // Write some data 236 for (int i = 0; i < writeCount; i++) { 237 writeData(table, rowNum++); 238 } 239 240 if (slowSync) { 241 TEST_UTIL.waitFor(10000, 100, new Waiter.ExplainingPredicate<Exception>() { 242 @Override 243 public boolean evaluate() throws Exception { 244 return log.getWriter() != oldWriter; 245 } 246 247 @Override 248 public String explainFailure() throws Exception { 249 return "Waited too long for our test writer to get rolled out"; 250 } 251 }); 252 253 assertTrue(slowSyncHookCalled.get(), "Should have triggered log roll due to SLOW_SYNC"); 254 } else { 255 assertFalse(slowSyncHookCalled.get(), "Should not have triggered log roll due to SLOW_SYNC"); 256 } 257 } 258 259 protected abstract void setSlowLogWriter(Configuration conf); 260 261 protected abstract void setDefaultLogWriter(Configuration conf); 262 263 /** 264 * Tests that log rolling doesn't hang when no data is written. 265 */ 266 @Test 267 public void testLogRollOnNothingWritten() throws Exception { 268 final Configuration conf = TEST_UTIL.getConfiguration(); 269 final WALFactory wals = 270 new WALFactory(conf, ServerName.valueOf("test.com", 8080, 1).toString()); 271 final WAL newLog = wals.getWAL(null); 272 try { 273 // Now roll the log before we write anything. 274 newLog.rollWriter(true); 275 } finally { 276 wals.close(); 277 } 278 } 279 280 /** 281 * Tests that logs are deleted 282 */ 283 @Test 284 public void testLogRolling() throws Exception { 285 this.tableName = getName(); 286 // TODO: Why does this write data take for ever? 287 startAndWriteData(); 288 RegionInfo region = server.getRegions(TableName.valueOf(tableName)).get(0).getRegionInfo(); 289 final WAL log = server.getWAL(region); 290 LOG.info( 291 "after writing there are " + AbstractFSWALProvider.getNumRolledLogFiles(log) + " log files"); 292 293 // roll the log, so we should have at least one rolled file and the log file size should be 294 // greater than 0, in case in the above method we rolled in the last round and then flushed so 295 // all the old wal files are deleted and cause the below assertion to fail 296 log.rollWriter(); 297 298 assertThat(AbstractFSWALProvider.getLogFileSize(log), greaterThan(0L)); 299 300 // flush all regions 301 for (HRegion r : server.getOnlineRegionsLocalContext()) { 302 r.flush(true); 303 } 304 305 // Now roll the log the again 306 log.rollWriter(); 307 308 // should have deleted all the rolled wal files 309 await().atMost(Duration.ofSeconds(15)).untilAsserted(() -> { 310 // we call archive log in a background thread but remove the log from wal file map in 311 // foreground, which means it is possible that when numRolledLogFiles reaches zero, the log 312 // file size is still greater than zero, so here we need to wait for them both. 313 assertEquals(0, AbstractFSWALProvider.getNumRolledLogFiles(log)); 314 assertEquals(0, AbstractFSWALProvider.getLogFileSize(log)); 315 }); 316 } 317 318 protected String getName() { 319 return "TestLogRolling-" + name; 320 } 321 322 void writeData(Table table, int rownum) throws IOException { 323 doPut(table, rownum); 324 325 // sleep to let the log roller run (if it needs to) 326 try { 327 Thread.sleep(2000); 328 } catch (InterruptedException e) { 329 // continue 330 } 331 } 332 333 void validateData(Table table, int rownum) throws IOException { 334 String row = "row" + String.format("%1$04d", rownum); 335 Get get = new Get(Bytes.toBytes(row)); 336 get.addFamily(HConstants.CATALOG_FAMILY); 337 Result result = table.get(get); 338 assertTrue(result.size() == 1); 339 assertTrue(Bytes.equals(value, result.getValue(HConstants.CATALOG_FAMILY, null))); 340 LOG.info("Validated row " + row); 341 } 342 343 /** 344 * Tests that logs are deleted when some region has a compaction record in WAL and no other 345 * records. See HBASE-8597. 346 */ 347 @Test 348 public void testCompactionRecordDoesntBlockRolling() throws Exception { 349 350 // When the hbase:meta table can be opened, the region servers are running 351 try (Table t = TEST_UTIL.getConnection().getTable(TableName.META_TABLE_NAME); 352 Table table = createTestTable(getName())) { 353 354 server = TEST_UTIL.getRSForFirstRegionInTable(table.getName()); 355 HRegion region = server.getRegions(table.getName()).get(0); 356 final WAL log = server.getWAL(region.getRegionInfo()); 357 Store s = region.getStore(HConstants.CATALOG_FAMILY); 358 359 // Put some stuff into table, to make sure we have some files to compact. 360 for (int i = 1; i <= 2; ++i) { 361 doPut(table, i); 362 admin.flush(table.getName()); 363 } 364 doPut(table, 3); // don't flush yet, or compaction might trigger before we roll WAL 365 assertEquals(0, AbstractFSWALProvider.getNumRolledLogFiles(log), 366 "Should have no WAL after initial writes"); 367 assertEquals(2, s.getStorefilesCount()); 368 369 // Roll the log and compact table, to have compaction record in the 2nd WAL. 370 log.rollWriter(); 371 assertEquals(1, AbstractFSWALProvider.getNumRolledLogFiles(log), 372 "Should have WAL; one table is not flushed"); 373 admin.flush(table.getName()); 374 region.compact(false); 375 // Wait for compaction in case if flush triggered it before us. 376 assertNotNull(s); 377 for (int waitTime = 3000; s.getStorefilesCount() > 1 && waitTime > 0; waitTime -= 200) { 378 Threads.sleepWithoutInterrupt(200); 379 } 380 assertEquals(1, s.getStorefilesCount(), "Compaction didn't happen"); 381 382 // Write some value to the table so the WAL cannot be deleted until table is flushed. 383 doPut(table, 0); // Now 2nd WAL will have both compaction and put record for table. 384 log.rollWriter(); // 1st WAL deleted, 2nd not deleted yet. 385 assertEquals(1, AbstractFSWALProvider.getNumRolledLogFiles(log), 386 "Should have WAL; one table is not flushed"); 387 388 // Flush table to make latest WAL obsolete; write another record, and roll again. 389 admin.flush(table.getName()); 390 doPut(table, 1); 391 log.rollWriter(); // Now 2nd WAL is deleted and 3rd is added. 392 assertEquals(1, AbstractFSWALProvider.getNumRolledLogFiles(log), 393 "Should have 1 WALs at the end"); 394 } 395 } 396 397 protected void doPut(Table table, int i) throws IOException { 398 Put put = new Put(Bytes.toBytes("row" + String.format("%1$04d", i))); 399 put.addColumn(HConstants.CATALOG_FAMILY, null, value); 400 table.put(put); 401 } 402 403 protected Table createTestTable(String tableName) throws IOException { 404 // Create the test table and open it 405 TableDescriptor desc = TableDescriptorBuilder.newBuilder(TableName.valueOf(getName())) 406 .setColumnFamily(ColumnFamilyDescriptorBuilder.of(HConstants.CATALOG_FAMILY)).build(); 407 admin.createTable(desc); 408 return TEST_UTIL.getConnection().getTable(desc.getTableName()); 409 } 410}