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}