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.replication.regionserver;
019
020import static org.apache.hadoop.hbase.replication.ReplicationUtils.OFFSET_UPDATE_INTERVAL_MS_KEY;
021import static org.apache.hadoop.hbase.replication.ReplicationUtils.OFFSET_UPDATE_SIZE_THRESHOLD_KEY;
022import static org.apache.hadoop.hbase.replication.ReplicationUtils.getAdaptiveTimeout;
023import static org.apache.hadoop.hbase.replication.ReplicationUtils.sleepForRetries;
024
025import java.io.IOException;
026import java.util.List;
027import org.apache.hadoop.conf.Configuration;
028import org.apache.hadoop.fs.Path;
029import org.apache.hadoop.hbase.Cell;
030import org.apache.hadoop.hbase.CellUtil;
031import org.apache.hadoop.hbase.HConstants;
032import org.apache.hadoop.hbase.replication.ReplicationEndpoint;
033import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
034import org.apache.hadoop.hbase.util.Threads;
035import org.apache.hadoop.hbase.wal.WAL.Entry;
036import org.apache.hadoop.hbase.wal.WALEdit;
037import org.apache.yetus.audience.InterfaceAudience;
038import org.slf4j.Logger;
039import org.slf4j.LoggerFactory;
040
041import org.apache.hadoop.hbase.shaded.protobuf.generated.WALProtos.BulkLoadDescriptor;
042import org.apache.hadoop.hbase.shaded.protobuf.generated.WALProtos.StoreDescriptor;
043
044/**
045 * This thread reads entries from a queue and ships them. Entries are placed onto the queue by
046 * ReplicationSourceWALReaderThread
047 */
048@InterfaceAudience.Private
049public class ReplicationSourceShipper extends Thread {
050  private static final Logger LOG = LoggerFactory.getLogger(ReplicationSourceShipper.class);
051
052  // Hold the state of a replication worker thread
053  public enum WorkerState {
054    RUNNING,
055    STOPPED,
056    FINISHED, // The worker is done processing a queue
057  }
058
059  private final Configuration conf;
060  final String walGroupId;
061  private final ReplicationSource source;
062
063  // Last position in the log that we sent to ZooKeeper
064  // It will be accessed by the stats thread so make it volatile
065  private volatile long currentPosition = -1;
066  // Path of the current log
067  private Path currentPath;
068  // Current state of the worker thread
069  private volatile WorkerState state;
070  final ReplicationSourceWALReader entryReader;
071
072  // How long should we sleep for each retry
073  private final long sleepForRetries;
074  // Maximum number of retries before taking bold actions
075  private final int maxRetriesMultiplier;
076  private final int DEFAULT_TIMEOUT = 20000;
077  private final int getEntriesTimeout;
078  private final int shipEditsTimeout;
079  private long accumulatedSizeSinceLastUpdate = 0L;
080  private long lastOffsetUpdateTime = EnvironmentEdgeManager.currentTime();
081  private final long offsetUpdateIntervalMs;
082  private final long offsetUpdateSizeThresholdBytes;
083  private WALEntryBatch lastShippedBatch;
084
085  private static final long DEFAULT_OFFSET_UPDATE_INTERVAL_MS = Long.MAX_VALUE;
086  private static final long DEFAULT_OFFSET_UPDATE_SIZE_THRESHOLD = -1L;
087
088  public ReplicationSourceShipper(Configuration conf, String walGroupId, ReplicationSource source,
089    ReplicationSourceWALReader walReader) {
090    this.conf = conf;
091    this.walGroupId = walGroupId;
092    this.source = source;
093    this.entryReader = walReader;
094    // 1 second
095    this.sleepForRetries = this.conf.getLong("replication.source.sleepforretries", 1000);
096    // 5 minutes @ 1 sec per
097    this.maxRetriesMultiplier = this.conf.getInt("replication.source.maxretriesmultiplier", 300);
098    // 20 seconds
099    this.getEntriesTimeout =
100      this.conf.getInt("replication.source.getEntries.timeout", DEFAULT_TIMEOUT);
101    this.shipEditsTimeout = this.conf.getInt(HConstants.REPLICATION_SOURCE_SHIPEDITS_TIMEOUT,
102      HConstants.REPLICATION_SOURCE_SHIPEDITS_TIMEOUT_DFAULT);
103    this.offsetUpdateIntervalMs =
104      conf.getLong(OFFSET_UPDATE_INTERVAL_MS_KEY, DEFAULT_OFFSET_UPDATE_INTERVAL_MS);
105    this.offsetUpdateSizeThresholdBytes =
106      conf.getLong(OFFSET_UPDATE_SIZE_THRESHOLD_KEY, DEFAULT_OFFSET_UPDATE_SIZE_THRESHOLD);
107  }
108
109  @Override
110  public final void run() {
111    setWorkerState(WorkerState.RUNNING);
112    LOG.info("Running ReplicationSourceShipper Thread for wal group: {}", this.walGroupId);
113    // Loop until we close down
114    while (isActive()) {
115      // Sleep until replication is enabled again
116      if (!source.isPeerEnabled()) {
117        // The peer enabled check is in memory, not expensive, so do not need to increase the
118        // sleep interval as it may cause a long lag when we enable the peer.
119        sleepForRetries("Replication is disabled", sleepForRetries, 1, maxRetriesMultiplier);
120        continue;
121      }
122      try {
123        // check time-based offset persistence
124        if (shouldPersistLogPosition()) {
125          persistLogPosition();
126        }
127
128        long pollTimeout = getEntriesTimeout;
129        if (offsetUpdateIntervalMs != Long.MAX_VALUE) {
130          long elapsed = EnvironmentEdgeManager.currentTime() - lastOffsetUpdateTime;
131          long remaining = offsetUpdateIntervalMs - elapsed;
132          if (remaining > 0) {
133            pollTimeout = Math.min(getEntriesTimeout, remaining);
134          }
135        }
136        WALEntryBatch entryBatch = entryReader.poll(pollTimeout);
137        LOG.debug("Shipper from source {} got entry batch from reader: {}", source.getQueueId(),
138          entryBatch);
139
140        if (entryBatch == null) {
141          continue;
142        }
143        // the NO_MORE_DATA instance has no path so do not call shipEdits
144        if (entryBatch == WALEntryBatch.NO_MORE_DATA) {
145          noMoreData();
146        } else {
147          shipEdits(entryBatch);
148        }
149      } catch (InterruptedException | ReplicationRuntimeException e) {
150        LOG.warn("Interrupted while waiting for next replication entry batch", e);
151        Thread.currentThread().interrupt();
152      } catch (Exception e) {
153        // During source shutdown / peer removal we can see interrupted IOEs
154        // from replication queue updates. Do not restart in this case.
155        if (!source.isSourceActive() || isInterrupted() || !source.isPeerEnabled()) {
156          LOG.info("Ignoring persist failure during shutdown for walGroupId={}", walGroupId, e);
157          break;
158        }
159        LOG.error("Shipper {} failed to persist offset, restarting", walGroupId, e);
160        abortAndRestart(e);
161        return;
162      }
163    }
164
165    // If the worker exits run loop without finishing its task, mark it as stopped.
166    if (!isFinished()) {
167      try {
168        persistLogPosition();
169      } catch (Exception e) {
170        LOG.error("Failed persisting final offset for walGroupId={}", walGroupId, e);
171      }
172      setWorkerState(WorkerState.STOPPED);
173    } else {
174      source.removeWorker(this);
175      postFinish();
176    }
177  }
178
179  private void noMoreData() throws IOException {
180    // Flush any outstanding replication offset before marking the queue finished.
181    // Offset persistence may be delayed by size/time thresholds, so ensure the
182    // latest replicated position is stored before transitioning to FINISHED state.
183    persistLogPosition();
184
185    if (source.isRecovered()) {
186      LOG.debug("Finished recovering queue for group {} of peer {}", walGroupId,
187        source.getQueueId());
188      source.getSourceMetrics().incrCompletedRecoveryQueue();
189    } else {
190      LOG.debug("Finished queue for group {} of peer {}", walGroupId, source.getQueueId());
191    }
192    setWorkerState(WorkerState.FINISHED);
193  }
194
195  // To be implemented by recovered shipper
196  protected void postFinish() {
197  }
198
199  /**
200   * Do the shipping logic
201   */
202  void shipEdits(WALEntryBatch entryBatch) throws IOException {
203    List<Entry> entries = entryBatch.getWalEntries();
204    int sleepMultiplier = 0;
205    int currentSize = (int) entryBatch.getHeapSize();
206    MetricsSource metrics = source.getSourceMetrics();
207    if (metrics != null && !entries.isEmpty()) {
208      metrics.setTimeStampNextToReplicate(entries.get(entries.size() - 1).getKey().getWriteTime());
209    }
210    if (entries.isEmpty()) {
211      // empty batch may mean WAL boundary advancement
212      lastShippedBatch = entryBatch;
213      persistLogPosition();
214      return;
215    }
216    while (isActive()) {
217      try {
218        try {
219          source.tryThrottle(currentSize);
220        } catch (InterruptedException e) {
221          LOG.debug("Interrupted while sleeping for throttling control");
222          Thread.currentThread().interrupt();
223          // current thread might be interrupted to terminate
224          // directly go back to while() for confirm this
225          continue;
226        }
227        // create replicateContext here, so the entries can be GC'd upon return from this call
228        // stack
229        ReplicationEndpoint.ReplicateContext replicateContext =
230          new ReplicationEndpoint.ReplicateContext();
231        replicateContext.setEntries(entries).setSize(currentSize);
232        replicateContext.setWalGroupId(walGroupId);
233        replicateContext.setTimeout(getAdaptiveTimeout(this.shipEditsTimeout, sleepMultiplier));
234
235        long startTimeNs = System.nanoTime();
236        // send the edits to the endpoint. Will block until the edits are shipped and acknowledged
237        boolean replicated = source.getReplicationEndpoint().replicate(replicateContext);
238        long endTimeNs = System.nanoTime();
239
240        if (!replicated) {
241          continue;
242        } else {
243          sleepMultiplier = Math.max(sleepMultiplier - 1, 0);
244        }
245        // Clean up hfile references
246        for (Entry entry : entries) {
247          cleanUpHFileRefs(entry.getEdit());
248          LOG.trace("shipped entry {}: ", entry);
249        }
250
251        // offsets totalBufferUsed by deducting shipped batchSize (excludes bulk load size)
252        // this sizeExcludeBulkLoad has to use same calculation that when calling
253        // acquireBufferQuota() in ReplicationSourceWALReader because they maintain
254        // same variable: totalBufferUsed
255        source.postShipEdits(entries, entryBatch.getUsedBufferSize());
256        // FIXME check relationship between wal group and overall
257        source.getSourceMetrics().shipBatch(entryBatch.getNbOperations(), currentSize,
258          entryBatch.getNbHFiles());
259        source.getSourceMetrics().setAgeOfLastShippedOp(
260          entries.get(entries.size() - 1).getKey().getWriteTime(), walGroupId);
261        source.getSourceMetrics().updateTableLevelMetrics(entryBatch.getWalEntriesWithSize());
262
263        if (LOG.isTraceEnabled()) {
264          LOG.debug("Replicated {} entries or {} operations in {} ms", entries.size(),
265            entryBatch.getNbOperations(), (endTimeNs - startTimeNs) / 1000000);
266        }
267        break;
268      } catch (Exception ex) {
269        source.getSourceMetrics().incrementFailedBatches();
270        LOG.warn("{} threw unknown exception:",
271          source.getReplicationEndpoint().getClass().getName(), ex);
272        if (
273          sleepForRetries("ReplicationEndpoint threw exception", sleepForRetries, sleepMultiplier,
274            maxRetriesMultiplier)
275        ) {
276          sleepMultiplier++;
277        }
278      }
279    }
280
281    accumulatedSizeSinceLastUpdate += currentSize;
282    lastShippedBatch = entryBatch;
283    if (shouldPersistLogPosition()) {
284      persistLogPosition();
285    }
286  }
287
288  private boolean shouldPersistLogPosition() {
289    LOG.debug(
290      "Persist decision: accumulatedSizeSinceLastUpdate={} threshold={} elapsed={} interval={}",
291      accumulatedSizeSinceLastUpdate, offsetUpdateSizeThresholdBytes,
292      EnvironmentEdgeManager.currentTime() - lastOffsetUpdateTime, offsetUpdateIntervalMs);
293    if (lastShippedBatch == null) {
294      return false;
295    }
296    // Default behaviour to update offset immediately after replicate()
297    if (offsetUpdateSizeThresholdBytes == -1 && offsetUpdateIntervalMs == Long.MAX_VALUE) {
298      return true;
299    }
300
301    return (accumulatedSizeSinceLastUpdate >= offsetUpdateSizeThresholdBytes)
302      || (EnvironmentEdgeManager.currentTime() - lastOffsetUpdateTime >= offsetUpdateIntervalMs);
303  }
304
305  void persistLogPosition() throws IOException {
306    if (lastShippedBatch == null) {
307      return;
308    }
309
310    if (!source.isSourceActive() || isInterrupted() || !source.isPeerEnabled()) {
311      LOG.debug("Skip persistLogPosition for inactive/stopping source");
312      return;
313    }
314
315    ReplicationEndpoint endpoint = source.getReplicationEndpoint();
316    if (endpoint != null) {
317      endpoint.beforePersistingReplicationOffset();
318    }
319
320    // Log and clean up WAL logs
321    updateLogPosition(lastShippedBatch);
322    accumulatedSizeSinceLastUpdate = 0;
323    lastShippedBatch = null;
324    lastOffsetUpdateTime = EnvironmentEdgeManager.currentTime();
325  }
326
327  void cleanUpHFileRefs(WALEdit edit) throws IOException {
328    String peerId = source.getPeerId();
329    if (peerId.contains("-")) {
330      // peerClusterZnode will be in the form peerId + "-" + rsZNode.
331      // A peerId will not have "-" in its name, see HBASE-11394
332      peerId = peerId.split("-")[0];
333    }
334    List<Cell> cells = edit.getCells();
335    int totalCells = cells.size();
336    for (int i = 0; i < totalCells; i++) {
337      Cell cell = cells.get(i);
338      if (CellUtil.matchingQualifier(cell, WALEdit.BULK_LOAD)) {
339        BulkLoadDescriptor bld = WALEdit.getBulkLoadDescriptor(cell);
340        List<StoreDescriptor> stores = bld.getStoresList();
341        int totalStores = stores.size();
342        for (int j = 0; j < totalStores; j++) {
343          List<String> storeFileList = stores.get(j).getStoreFileList();
344          source.getSourceManager().cleanUpHFileRefs(peerId, storeFileList);
345          source.getSourceMetrics().decrSizeOfHFileRefsQueue(storeFileList.size());
346        }
347      }
348    }
349  }
350
351  private boolean updateLogPosition(WALEntryBatch batch) {
352    boolean updated = false;
353    // if end of file is true, then the logPositionAndCleanOldLogs method will remove the file
354    // record on zk, so let's call it. The last wal position maybe zero if end of file is true and
355    // there is no entry in the batch. It is OK because that the queue storage will ignore the zero
356    // position and the file will be removed soon in cleanOldLogs.
357    if (
358      batch.isEndOfFile() || !batch.getLastWalPath().equals(currentPath)
359        || batch.getLastWalPosition() != currentPosition
360    ) {
361      source.logPositionAndCleanOldLogs(batch);
362      updated = true;
363    }
364    // if end of file is true, then we can just skip to the next file in queue.
365    // the only exception is for recovered queue, if we reach the end of the queue, then there will
366    // no more files so here the currentPath may be null.
367    if (batch.isEndOfFile()) {
368      currentPath = entryReader.getCurrentPath();
369      currentPosition = 0L;
370    } else {
371      currentPath = batch.getLastWalPath();
372      currentPosition = batch.getLastWalPosition();
373    }
374    return updated;
375  }
376
377  public void startup(UncaughtExceptionHandler handler) {
378    String name = Thread.currentThread().getName();
379    Threads.setDaemonThreadRunning(this,
380      name + ".replicationSource.shipper" + walGroupId + "," + source.getQueueId(),
381      handler::uncaughtException);
382  }
383
384  Path getCurrentPath() {
385    return entryReader.getCurrentPath();
386  }
387
388  long getCurrentPosition() {
389    return currentPosition;
390  }
391
392  protected boolean isActive() {
393    return source.isSourceActive() && state == WorkerState.RUNNING && !isInterrupted();
394  }
395
396  protected final void setWorkerState(WorkerState state) {
397    this.state = state;
398  }
399
400  void stopWorker() {
401    setWorkerState(WorkerState.STOPPED);
402  }
403
404  public boolean isFinished() {
405    return state == WorkerState.FINISHED;
406  }
407
408  /**
409   * Attempts to properly update <code>ReplicationSourceManager.totalBufferUser</code>, in case
410   * there were unprocessed entries batched by the reader to the shipper, but the shipper didn't
411   * manage to ship those because the replication source is being terminated. In that case, it
412   * iterates through the batched entries and decrease the pending entries size from
413   * <code>ReplicationSourceManager.totalBufferUser</code>
414   * <p/>
415   * <b>NOTES</b> 1) This method should only be called upon replication source termination. It
416   * blocks waiting for both shipper and reader threads termination, to make sure no race conditions
417   * when updating <code>ReplicationSourceManager.totalBufferUser</code>. 2) It <b>does not</b>
418   * attempt to terminate reader and shipper threads. Those <b>must</b> have been triggered
419   * interruption/termination prior to calling this method.
420   */
421  void clearWALEntryBatch() {
422    long timeout = EnvironmentEdgeManager.currentTime() + this.shipEditsTimeout;
423    while (this.isAlive() || this.entryReader.isAlive()) {
424      try {
425        if (EnvironmentEdgeManager.currentTime() >= timeout) {
426          LOG.warn("Shipper clearWALEntryBatch method timed out while waiting reader/shipper "
427            + "thread to stop. Not cleaning buffer usage. PeerId: {}; Shipper alive: {}; Reader "
428            + "alive: {}", this.source.getPeerId(), this.isAlive(), this.entryReader.isAlive());
429          return;
430        } else {
431          // Wait both shipper and reader threads to stop
432          Thread.sleep(this.sleepForRetries);
433        }
434      } catch (InterruptedException e) {
435        LOG.warn("{} Interrupted while waiting {} to stop on clearWALEntryBatch. "
436          + "Not cleaning buffer usage: {}", this.source.getPeerId(), this.getName(), e);
437        return;
438      }
439    }
440    long totalReleasedBytes = 0;
441    while (true) {
442      WALEntryBatch batch = entryReader.entryBatchQueue.poll();
443      if (batch == null) {
444        break;
445      }
446      totalReleasedBytes += source.getSourceManager().releaseWALEntryBatchBufferQuota(batch);
447    }
448    if (LOG.isTraceEnabled()) {
449      LOG.trace("Decrementing totalBufferUsed by {}B while stopping Replication WAL Readers.",
450        totalReleasedBytes);
451    }
452  }
453
454  long getSleepForRetries() {
455    return sleepForRetries;
456  }
457
458  // Restart worker so replication resumes from last persisted offset.
459  void abortAndRestart(Throwable cause) {
460    LOG.warn("Restarting shipper for walGroupId={}", walGroupId, cause);
461    if (!source.isSourceActive() || !source.isPeerEnabled() || isInterrupted()) {
462      LOG.warn("abortAndRestart SKIPPED walGroupId={}, thread={}", walGroupId,
463        Thread.currentThread().getName());
464      return;
465    }
466    setWorkerState(WorkerState.STOPPED);
467    source.restartShipper(walGroupId, this);
468  }
469}