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}