Slow Initial HBase WAL Write After Ozone DataNode Restart During HBase–Ozone Integration

[zhangchao1171]

As the title suggests, when testing a standalone HBase instance integrated with Ozone (deployed using Docker Compose), I encountered an issue during a DataNode restart.

While one of the DataNodes was restarting, HBase Put operations experienced significant delays. According to the HBase logs, HBase was unable to obtain an available pipeline, causing WAL synchronization to exceed the default 10-second timeout and triggering a new WAL allocation.

How can this issue be avoided or mitigated?

here are hbase logs:
2026-11-04T10:55:15,983 INFO [AsyncFSWAL-0-ofs://172.19.0.3:9862/hbasevol/hbasebucket/hbase-prefix:pc-0,16020,1793760759237] wal.AbstractFSWAL: Slow sync cost: 11930 ms, current pipeline: []
2026-11-04T10:55:15,984 WARN [AsyncFSWAL-0-ofs://172.19.0.3:9862/hbasevol/hbasebucket/hbase-prefix:pc-0,16020,1793760759237] wal.AbstractFSWAL: Requesting log roll because we exceeded slow sync threshold; time=11930 ms, threshold=10000 ms, current pipeline: []
2026-11-04T10:55:15,990 WARN [RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020] ipc.RpcServer: (responseTooSlow): {"call":"Mutate(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$MutateRequest)","starttimems":"1793760904051","responsesize":"2","method":"Mutate","param":"region= test,aaaaaaaa,1793361733549.a451abfcaf617161a70528b3406c224d., row=y","processingtimems":11933,"blockbytesscanned":"0","fsreadtime":"0","client":"127.0.0.1:52202","queuetimems":0,"class":"HRegionServer"}
2026-11-04T10:55:19,126 INFO [regionserver/BJSK-A03594:16020.logRoller] wal.AbstractFSWAL: Rolled WAL /hbasevol/hbasebucket/hbase/WALs/pc-0,16020,1793760759237/pc-0%2C16020%2C1793760759237.1793760770951 with entries=11, filesize=2.82 KB; new WAL /hbasevol/hbasebucket/hbase/WALs/pc-0,16020,1793760759237/pc-0%2C16020%2C1793760759237.1793760915985

[Dv2Corn]

First, about current pipeline: []. That part of the log does not mean HBase failed to get an Ozone pipeline. On a non-HDFS filesystem, HBase wraps the output stream in WrapperAsyncFSOutput, and its getPipeline() always returns an empty array. You will see [] on every slow-sync line when the WAL is on Ozone, whether or not anything is wrong:

• https://github.com/apache/hbase/blob/d0066b0249e453caf9d2260a2c53aed7309355f4/hbase-asyncfs/src/main/java/org/apache/hadoop/hbase/io/asyncfs/AsyncFSOutputHelper.java#L53-L80
• https://github.com/apache/hbase/blob/d0066b0249e453caf9d2260a2c53aed7309355f4/hbase-asyncfs/src/main/java/org/apache/hadoop/hbase/io/asyncfs/WrapperAsyncFSOutput.java#L80-L93

The log only tells you that one hsync() on the Ozone output stream took about 11.9 s.

Why hsync waits while a datanode is restarting

On Ozone, a WAL sync goes through KeyOutputStream.hsync() and then RatisBlockOutputStream.hsync(). That call sends the pending data and a PutBlock, then waits for the Ratis watch() on that log index to finish:

• ozone/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/KeyOutputStream.java

  Lines 523 to 553 in e345940

  	public void hsync() throws IOException {
  	try {
  	getRequestSemaphore().acquire();
  	if (replication.getReplicationType() != ReplicationType.RATIS) {
  	throw new UnsupportedOperationException(
  	"Replication type is not " + ReplicationType.RATIS);
  	}
  	if (replication.getRequiredNodes() <= 1) {
  	throw new UnsupportedOperationException("The replication factor = "
  	+ replication.getRequiredNodes() + " <= 1");
  	}
  	if (!OzoneManagerVersion.HBASE_SUPPORT.isSupportedBy(ozoneManagerVersion)) {
  	throw new UnsupportedOperationException("Hsync API requires OM version "
  	+ OzoneManagerVersion.HBASE_SUPPORT + " or later. Current OM version "
  	+ ozoneManagerVersion);
  	}
  	checkNotClosed();
  	final long hsyncPos = writeOffset;
  	handleFlushOrClose(StreamAction.HSYNC);
  	doInWriteLock(() -> {
  	Preconditions.checkState(offset >= hsyncPos,
  	"offset = %s < hsyncPos = %s", offset, hsyncPos);
  	MetricUtil.captureLatencyNs(clientMetrics::addHsyncLatency,
  	() -> blockOutputStreamEntryPool.hsyncKey(hsyncPos));
  	});
  	} finally {
  	getRequestSemaphore().release();
  	}
  	}

• ozone/hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/storage/RatisBlockOutputStream.java

  Lines 127 to 136 in e345940

  	public void hflush() throws IOException {
  	hsync();
  	}
  	@Override
  	public void hsync() throws IOException {
  	if (!isClosed()) {
  	handleFlush(false);
  	}
  	}

• ozone/hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/storage/BlockOutputStream.java

  Lines 410 to 416 in e345940

  	private void recordWatchForCommitAsync(CompletableFuture<PutBlockResult> putBlockResultFuture) {
  	final CompletableFuture<Void> flushFuture = putBlockResultFuture.thenCompose(x -> watchForCommit(x.commitIndex));
  	Preconditions.checkState(Thread.holdsLock(this));
  	this.lastFlushFuture = flushFuture;
  	this.allPendingFlushFutures = allPendingFlushFutures.thenCombine(flushFuture, (last, curr) -> null);
  	}

By default, the client asks for ALL_COMMITTED, which means all 3 datanodes of the pipeline:

hdds.ratis.client.request.watch.type = ALL_COMMITTED   (default)

ozone/hadoop-hdds/common/src/main/java/org/apache/hadoop/hdds/ratis/conf/RatisClientConfig.java

Lines 37 to 45 in e345940

	@Config(key = "hdds.ratis.client.request.watch.type",
	defaultValue = "ALL_COMMITTED",
	type = ConfigType.STRING,
	tags = { OZONE, CLIENT, PERFORMANCE },
	description = "Desired replication level when Ozone client's Raft client calls watch(), " +
	"ALL_COMMITTED or MAJORITY_COMMITTED. MAJORITY_COMMITTED increases write performance by reducing watch() " +
	"latency when an Ozone datanode is slow in a pipeline, at the cost of potential read latency increasing " +
	"due to read retries to different datanodes.")
	private String watchType;

If one follower in the pipeline is down, the leader cannot satisfy an ALL_COMMITTED watch. The watch stays pending until one of these happens:

• the follower comes back and catches up, or
• the server-side watch timeout expires (hdds.ratis.raft.server.watch.timeout, default 30s). The leader then answers with NotReplicatedException.

In the second case, the client falls back to MAJORITY_COMMITTED and records the missing node as a failed server, so the next block allocation excludes it:

• ozone/hadoop-hdds/framework/src/main/java/org/apache/hadoop/hdds/conf/DatanodeRatisServerConfig.java

  Lines 46 to 56 in e345940

  	@Config(key = "hdds.ratis.raft.server.watch.timeout",
  	defaultValue = "30s",
  	type = ConfigType.TIME,
  	tags = {OZONE, DATANODE, RATIS},
  	description = "The timeout duration for watch request on Ratis Server. " +
  	"Timeout for the watch request in Ratis server to acknowledge a " +
  	"particular request is replayed to all servers. It is highly recommended " +
  	"for the timeout duration to be strictly shorter than Ratis client watch timeout " +
  	"(hdds.ratis.raft.client.rpc.watch.request.timeout)."
  	)
  	private long watchTimeOut = Duration.ofSeconds(30).toMillis();

• ozone/hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientRatis.java

  Lines 302 to 335 in e345940

  	public CompletableFuture<XceiverClientReply> watchForCommit(long index) {
  	final long replicatedMin = getReplicatedMinCommitIndex();
  	if (replicatedMin >= index) {
  	return CompletableFuture.completedFuture(newWatchReply(index, "replicatedMin", replicatedMin));
  	}
  	final CompletableFuture<XceiverClientReply> replyFuture = new CompletableFuture<>();
  	getClient().async().watch(index, watchType).thenAccept(reply -> {
  	final long updated = updateCommitInfosMap(reply, watchType);
  	Preconditions.checkState(updated >= index, "Returned index %s < expected %s", updated, index);
  	replyFuture.complete(newWatchReply(index, watchType, updated));
  	}).exceptionally(e -> {
  	LOG.warn("{} way commit failed on pipeline {}", watchType, pipeline, e);
  	final boolean isGroupMismatch = HddsClientUtils.containsException(e, GroupMismatchException.class) != null;
  	if (!isGroupMismatch && watchType == ReplicationLevel.ALL_COMMITTED) {
  	final Throwable nre = HddsClientUtils.containsException(e, NotReplicatedException.class);
  	if (nre instanceof NotReplicatedException) {
  	// If NotReplicatedException is thrown from the Datanode leader
  	// we can save one watch request round trip by using the CommitInfoProto
  	// in the NotReplicatedException
  	final Collection<CommitInfoProto> commitInfoProtoList = ((NotReplicatedException) nre).getCommitInfos();
  	replyFuture.complete(handleFailedAllCommit(index, commitInfoProtoList));
  	} else {
  	getClient().async().watch(index, ReplicationLevel.MAJORITY_COMMITTED)
  	.thenApply(reply -> handleFailedAllCommit(index, reply.getCommitInfos()))
  	.whenComplete(JavaUtils.asBiConsumer(replyFuture));
  	}
  	} else {
  	replyFuture.completeExceptionally(e);
  	}
  	return null;
  	});
  	return replyFuture;
  	}

• Ratis side (3.3.1, the version Ozone master uses): https://github.com/apache/ratis/blob/379c90a00291252beffa81c6d10d47ac0d015dce/ratis-server/src/main/java/org/apache/ratis/server/impl/WatchRequests.java#L120-L133

Either way, the WAL sync blocks for that time. 11.9 s is shorter than the 30 s timeout, so my guess is that the restarted datanode came back within about 12 s and the watch then completed. I have not reproduced this, so treat it as inferred from the code.

There is a second possibility: the restarted datanode was the Ratis leader of the pipeline. Then the remaining nodes need a leader election first. On datanodes, the election timeout is hdds.ratis.leader.election.minimum.timeout.duration (default 5s), and the maximum is set to that value plus 200 ms. The client also adds its retry backoff on top. That can also add up to roughly 10 s:

• ozone/hadoop-hdds/common/src/main/java/org/apache/hadoop/hdds/scm/ScmConfigKeys.java

  Lines 117 to 122 in e345940

  	public static final String
  	HDDS_RATIS_LEADER_ELECTION_MINIMUM_TIMEOUT_DURATION_KEY =
  	"hdds.ratis.leader.election.minimum.timeout.duration";
  	public static final TimeDuration
  	HDDS_RATIS_LEADER_ELECTION_MINIMUM_TIMEOUT_DURATION_DEFAULT =
  	TimeDuration.valueOf(5, TimeUnit.SECONDS);

• ozone/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/XceiverServerRatis.java

  Lines 368 to 388 in e345940

  	private void setRatisLeaderElectionTimeout(RaftProperties properties) {
  	TimeUnit leaderElectionMinTimeoutUnit =
  	OzoneConfigKeys.
  	HDDS_RATIS_LEADER_ELECTION_MINIMUM_TIMEOUT_DURATION_DEFAULT
  	.getUnit();
  	long duration = conf.getTimeDuration(
  	OzoneConfigKeys.HDDS_RATIS_LEADER_ELECTION_MINIMUM_TIMEOUT_DURATION_KEY,
  	OzoneConfigKeys.
  	HDDS_RATIS_LEADER_ELECTION_MINIMUM_TIMEOUT_DURATION_DEFAULT
  	.getDuration(), leaderElectionMinTimeoutUnit);
  	final TimeDuration leaderElectionMinTimeout =
  	TimeDuration.valueOf(duration, leaderElectionMinTimeoutUnit);
  	RaftServerConfigKeys.Rpc
  	.setTimeoutMin(properties, leaderElectionMinTimeout);
  	long leaderElectionMaxTimeout =
  	leaderElectionMinTimeout.toLong(TimeUnit.MILLISECONDS) + 200;
  	RaftServerConfigKeys.Rpc.setTimeoutMax(properties,
  	TimeDuration.valueOf(leaderElectionMaxTimeout, TimeUnit.MILLISECONDS));
  	RatisHelper.setFirstElectionTimeoutDuration(
  	conf, properties, HDDS_RATIS_LEADER_FIRST_ELECTION_MINIMUM_TIMEOUT_DURATION_KEY);

What you can change

1. Let hsync return once a majority has committed. Set this in the ozone-site.xml that the HBase RegionServer reads, because the Ozone client runs inside the RegionServer JVM. Then restart the RegionServer:

   <property>
     <name>hdds.ratis.client.request.watch.type</name>
     <value>MAJORITY_COMMITTED</value>
   </property>

   With 3 replicas, a sync then needs 2 of 3 datanodes, so a single restarting follower should no longer block it. The config description lists the trade-off: reads may need retries against a different datanode if they first hit the one that is behind. For a WAL, which is mostly read during recovery, that is usually acceptable. This key exists in 2.0.0 and later (HDDS-2887).

2. If you keep ALL_COMMITTED, the worst-case stall for a follower outage is bounded by hdds.ratis.raft.server.watch.timeout on the datanodes (default 30s). You can lower it. Keep it shorter than the client watch timeouts (hdds.ratis.client.request.watch.timeout and hdds.ratis.raft.client.rpc.watch.request.timeout, both default 30s), as their descriptions recommend. Option 1 is the more direct fix, though.

3. A leader restart cannot be fully hidden, because a new leader has to be elected. You can lower hdds.ratis.leader.election.minimum.timeout.duration. I would be careful with it: a value that is too low causes unnecessary elections when a node pauses briefly, for example during GC.

4. On the HBase side, hbase.regionserver.wal.roll.on.sync.ms (default 10000) only decides whether a slow sync also triggers a WAL roll. Raising it removes the roll, but not the delay of the Put itself:
   https://github.com/apache/hbase/blob/d0066b0249e453caf9d2260a2c53aed7309355f4/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/wal/AbstractFSWAL.java#L1362-L1376

The stale/dead node intervals (ozone.scm.stale.node.interval default 5m, ozone.scm.dead.node.interval default 10m) are not involved here. SCM does not close the pipeline during a restart this short, and lowering those values would not shorten the stall.

Also note that in a docker-compose cluster with exactly 3 datanodes, every RATIS/THREE pipeline includes the node you restart, so there is nothing for the client to route around. For planned restarts on a larger cluster, putting the datanode into maintenance first (ozone admin datanode maintenance <host>) makes SCM close its pipelines, so new blocks are allocated elsewhere. I have not measured how this affects an already-open WAL file.

To confirm which case you hit

Could you share:

• The RegionServer log around 10:55:04–10:55:16 at WARN/INFO for org.apache.hadoop.hdds.scm.XceiverClientRatis, org.apache.hadoop.hdds.scm.storage.BlockOutputStream and org.apache.hadoop.ozone.client.io.KeyOutputStream. Lines such as ALL_COMMITTED way commit failed on pipeline, Could not commit index ... to all the nodes, or Encountered exception ... on the pipeline show which path was taken.
• The log of the datanode you restarted, and of the other two datanodes, for the same window. Look especially for leader election and leader change messages for the pipeline's Ratis group.
• ozone admin pipeline list before the restart, to see whether the restarted node was the leader.
• Your Ozone and HBase versions, the number of datanodes, and any non-default hdds.ratis.* / ozone.client.* settings.

[zhangchao1171]

Regarding the 4 points you mentioned, my responses are as follows:

1. There are no relevant logs from the HBase RegionServer during the time window you mentioned because I was not performing continuous writes in real time. I only issued a single HBase put operation during the restart of datanode-1. Therefore, the logs I provided are the complete logs around that operation window.

2. Regarding your second point, the DataNode logs are as follows:
   datanode2-1:

2026-11-04 02:54:40,266 [ContainerMetadataScanner] INFO ozoneimpl.AbstractBackgroundContainerScanner: Completed an iteration in 0 minutes. Number of iterations (since the data-node restart) : 16, Number of containers scanned in this iteration : 4, Number of unhealthy containers found in this iteration : 0

2026-11-04 02:54:40,709 [DiskUsage-/data/hdds-0] INFO fs.DUOptimized: Disk metaPath du usages 163094528, container data usages 848140

2026-11-04 02:54:40,716 [DiskUsage-/data/metadata/dn.ratis-0] INFO fs.DUOptimized: Disk metaPath du usages 13225984, container data usages 0
2026-11-04 02:54:40,775 [526ac250-0be1-4836-899a-64c5e4e9c5b7-PeriodicHDDSVolumeChecker] INFO volume.ThrottledAsyncChecker: Scheduling a check for /data/hdds/hdds
2026-11-04 02:54:40,776 [526ac250-0be1-4836-899a-64c5e4e9c5b7-DataNodeDiskCheckerThread-45] WARN volume.HddsVolume: Volume /data/hdds/hdds reserved usages 103688187636 is higher than actual allocated reserved space 108110120. (Real usage: capacity=1081101176832, used=163942668, available=977249046528)
2026-11-04 02:54:40,776 [526ac250-0be1-4836-899a-64c5e4e9c5b7-PeriodicHDDSVolumeChecker] INFO volume.StorageVolumeChecker: Scheduled health check for volume /data/hdds/hdds
2026-11-04 02:54:40,785 [526ac250-0be1-4836-899a-64c5e4e9c5b7-PeriodicHDDSVolumeChecker] INFO volume.ThrottledAsyncChecker: Scheduling a check for /data/metadata/dn.ratis
2026-11-04 02:54:40,786 [526ac250-0be1-4836-899a-64c5e4e9c5b7-PeriodicHDDSVolumeChecker] INFO volume.StorageVolumeChecker: Scheduled health check for volume /data/metadata/dn.ratis
2026-11-04 02:55:00,812 [grpc-default-executor-675] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: RST_STREAM closed stream. HTTP/2 error code: CANCEL
2026-11-04 02:55:00,815 [grpc-default-executor-676] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=1); keep nextIndex (2011) unchanged and retry.
2026-11-04 02:55:05,845 [timer2] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=8); keep nextIndex (2011) unchanged and retry. (Repeated 8 times in the last 5.001s)
2026-11-04 02:55:05,845 [timer1] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries (Repeated 8 times in the last 5.002s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:06,500 [grpc-default-executor-675] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:06,501 [grpc-default-executor-674] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=9); keep nextIndex (2011) unchanged and retry.
2026-11-04 02:55:11,501 [timer2] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries (Repeated 8 times in the last 5.000s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:11,503 [timer3] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=16); keep nextIndex (2011) unchanged and retry. (Repeated 8 times in the last 5.001s)
2026-11-04 02:55:12,708 [grpc-default-executor-675] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:12,709 [grpc-default-executor-674] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=17); keep nextIndex (2011) unchanged and retry.
2026-11-04 02:55:17,709 [timer2] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries (Repeated 4 times in the last 5.000s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:17,710 [timer3] WARN server.GrpcLogAppender: 526ac250-0be1-4836-899a-64c5e4e9c5b7@group-11022ED39D36->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=20); keep nextIndex (2011) unchanged and retry. (Repeated 4 times in the last 5.000s)
root@BJSK-A03594:/opt/docker_image_start/ozone#

datanode3-1:

2026-11-04 02:55:00,811 [grpc-default-executor-1706] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: CANCELLED: RST_STREAM closed stream. HTTP/2 error code: CANCEL

2026-11-04 02:55:00,819 [grpc-default-executor-1706] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=1); keep nextIndex (2753) unchanged and retry.
2026-11-04 02:55:04,056 [grpc-default-executor-1702] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=9); keep nextIndex (2754) unchanged and retry.
2026-11-04 02:55:04,061 [grpc-default-executor-1704] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=11); keep nextIndex (2755) unchanged and retry.
2026-11-04 02:55:05,827 [timer5] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries (Repeated 14 times in the last 5.002s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:05,827 [timer6] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=8); keep nextIndex (2753) unchanged and retry. (Repeated 8 times in the last 5.001s)
2026-11-04 02:55:06,564 [grpc-default-executor-1704] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:09,057 [timer3] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=10); keep nextIndex (2754) unchanged and retry. (Repeated 2 times in the last 5.000s)
2026-11-04 02:55:09,062 [timer6] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=18); keep nextIndex (2755) unchanged and retry. (Repeated 8 times in the last 5.000s)
2026-11-04 02:55:10,032 [grpc-default-executor-1702] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=19); keep nextIndex (2755) unchanged and retry.
2026-11-04 02:55:11,565 [timer7] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries (Repeated 6 times in the last 5.001s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:12,090 [grpc-default-executor-1702] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries: org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
2026-11-04 02:55:15,032 [timer7] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-GrpcLogAppender: Follower failed (request=null, errorCount=24); keep nextIndex (2755) unchanged and retry. (Repeated 6 times in the last 5.000s)
2026-11-04 02:55:15,858 [grpc-default-executor-1704] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: received INCONSISTENCY reply with nextIndex 2753, errorCount=25, request=AppendEntriesRequest:cid=92744,entriesCount=0
2026-11-04 02:55:15,859 [grpc-default-executor-1704] INFO leader.FollowerInfo: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c: setNextIndex nextIndex: updateUnconditionally 2755 -> 2753
2026-11-04 02:55:17,091 [timer7] WARN server.GrpcLogAppender: 9f70b756-e326-4b68-a510-ee9a24c161b8@group-8A78A2F45648->30e4773d-b250-464a-83e1-919865369a9c-AppendLogResponseHandler: Failed appendEntries (Repeated 4 times in the last 5.001s): org.apache.ratis.thirdparty.io.grpc.StatusRuntimeException: UNAVAILABLE: io exception

3.Before and after the operation, I checked the DataNode-1 node in the RATIS/THREE pipeline, which was not the leader. As additional context, I am using a bucket configured with RATIS/THREE replication. The output of the pipeline list command is as follows:

Pipeline{ Id: 465d8c7b-579c-464c-a913-8a78a2f45648, Nodes: [ {30e4773d-b250-464a-83e1-919865369a9c(ozone-datanode-1-1.ozone_ozone-net/172.19.0.11), ReplicaIndex: 0}, {526ac250-0be1-4836-899a-64c5e4e9c5b7(ozone-datanode-2-1.ozone_ozone-net/172.19.0.12), ReplicaIndex: 0}, {9f70b756-e326-4b68-a510-ee9a24c161b8(ozone-datanode-3-1.ozone_ozone-net/172.19.0.13), ReplicaIndex: 0},], ReplicationConfig: RATIS/THREE, State:OPEN, leaderId:9f70b756-e326-4b68-a510-ee9a24c161b8, CreationTimestamp2026-10-30T12:12:29.147Z[Etc/UTC]}

Pipeline{ Id: 8077949a-7b56-4d60-b8b0-83154b0b1424, Nodes: [ {30e4773d-b250-464a-83e1-919865369a9c(ozone-datanode-1-1.ozone_ozone-net/172.19.0.11), ReplicaIndex: 0},], ReplicationConfig: RATIS/ONE, State:OPEN, leaderId:30e4773d-b250-464a-83e1-919865369a9c, CreationTimestamp2026-10-30T12:12:29.153Z[Etc/UTC]}
Pipeline{ Id: bb42a599-c7ac-4ab0-babc-b67ba60de1fc, Nodes: [ {526ac250-0be1-4836-899a-64c5e4e9c5b7(ozone-datanode-2-1.ozone_ozone-net/172.19.0.12), ReplicaIndex: 0},], ReplicationConfig: RATIS/ONE, State:OPEN, leaderId:526ac250-0be1-4836-899a-64c5e4e9c5b7, CreationTimestamp2026-10-30T12:12:29.155Z[Etc/UTC]}
Pipeline{ Id: ae431b51-cced-4764-a3f8-2955e4e43270, Nodes: [ {9f70b756-e326-4b68-a510-ee9a24c161b8(ozone-datanode-3-1.ozone_ozone-net/172.19.0.13), ReplicaIndex: 0},], ReplicationConfig: RATIS/ONE, State:OPEN, leaderId:9f70b756-e326-4b68-a510-ee9a24c161b8, CreationTimestamp2026-10-30T12:12:29.154Z[Etc/UTC]}
Pipeline{ Id: 4df7ce69-37eb-4f18-a59d-11022ed39d36, Nodes: [ {30e4773d-b250-464a-83e1-919865369a9c(ozone-datanode-1-1.ozone_ozone-net/172.19.0.11), ReplicaIndex: 0}, {526ac250-0be1-4836-899a-64c5e4e9c5b7(ozone-datanode-2-1.ozone_ozone-net/172.19.0.12), ReplicaIndex: 0}, {9f70b756-e326-4b68-a510-ee9a24c161b8(ozone-datanode-3-1.ozone_ozone-net/172.19.0.13), ReplicaIndex: 0},], ReplicationConfig: RATIS/THREE, State:OPEN, leaderId:526ac250-0be1-4836-899a-64c5e4e9c5b7, CreationTimestamp2026-10-30T12:12:29.150Z[Etc/UTC]}

4.ozone version 2.2.1, three datanodes use docker compose start, config as follows:

x-image: &image
image: ${OZONE_IMAGE:-apache/ozone}:${OZONE_IMAGE_VERSION:-2.2.1}${OZONE_IMAGE_FLAVOR:-}
restart: unless-stopped
networks:
- ozone-net

x-common-config: &common-config
OZONE-SITE.XML_ozone.replication: "3"
OZONE-SITE.XML_ozone.scm.names: "scm"
OZONE-SITE.XML_ozone.scm.client.address: "scm"
OZONE-SITE.XML_ozone.scm.block.client.address: "scm"
OZONE-SITE.XML_ozone.om.address: "om"
OZONE-SITE.XML_ozone.om.http-address: "om:9874"
OZONE-SITE.XML_ozone.recon.address: "recon:9891"
OZONE-SITE.XML_ozone.hbase.enhancements.allowed: "true"
OZONE-SITE.XML_ozone.fs.hsync.enabled: "true"
OZONE-SITE.XML_ozone.client.hbase.enhancements.allowed: "true"
OZONE-SITE.XML_ozone.client.stream.putblock.piggybacking: "true"
OZONE-SITE.XML_ozone.client.incremental.chunk.list: "true"
OZONE-SITE.XML_hdds.datanode.use.datanode.hostname: "false"
no_proxy: "om,recon,scm,s3g,httpfs,datanode-1,datanode-2,datanode-3,localhost,127.0.0.1"

services:
scm:
<<: *image
hostname: scm
command: ["ozone", "scm"]
ports:
- "9876:9876"
environment:
<<: *common-config
OZONE-SITE.XML_ozone.metadata.dirs: "/data/scm"
ENSURE_SCM_INITIALIZED: "/data/scm/scm/current/VERSION"
volumes:
- ./data/scm:/data/scm
networks:
ozone-net:
ipv4_address: 172.19.0.4

om:
<<: image
hostname: om
command: ["ozone", "om"]
depends_on:
- scm
ports:
- "9874:9874"
- "9862:9862"
environment:
<<: common-config
OZONE-SITE.XML_ozone.metadata.dirs: "/data/om"
CORE-SITE.XML_hadoop.proxyuser.hadoop.hosts: ""
CORE-SITE.XML_hadoop.proxyuser.hadoop.groups: ""
CORE-SITE.XML_fs.trash.interval: "360"
CORE-SITE.XML_fs.trash.classname: "org.apache.hadoop.fs.ozone.OzoneTrashPolicy"
CORE-SITE.XML_ozone.fs.trash.checkpoint.interval: "60"
ENSURE_OM_INITIALIZED: "/data/om/om/current/VERSION"
WAITFOR: "scm:9876"
volumes:
- ./data/om:/data/om
networks:
ozone-net:
ipv4_address: 172.19.0.3
datanode-1:
<<: *image
hostname: datanode-1
command: ["ozone", "datanode"]
depends_on:
- scm
- om
environment:
<<: *common-config
OZONE-SITE.XML_hdds.datanode.dir: "/data/hdds"
OZONE-SITE.XML_ozone.metadata.dirs: "/data/metadata"
OZONE-SITE.XML_ozone.scm.datanode.id.dir: "/data/metadata"
ports:
- "19856:9856"
- "19857:9857"
- "19858:9858"
- "19882:9882"
volumes:
- ./data/datanode-1/hdds:/data/hdds
- ./data/datanode-1/metadata:/data/metadata
networks:
ozone-net:
ipv4_address: 172.19.0.11
datanode-2:
<<: *image
hostname: datanode-2
command: ["ozone", "datanode"]
depends_on:
- scm
- om
environment:
<<: *common-config
OZONE-SITE.XML_hdds.datanode.dir: "/data/hdds"
OZONE-SITE.XML_ozone.metadata.dirs: "/data/metadata"
OZONE-SITE.XML_ozone.scm.datanode.id.dir: "/data/metadata"
ports:
- "29856:9856"
- "29857:9857"
- "29858:9858"
- "29882:9882"
volumes:
- ./data/datanode-2/hdds:/data/hdds
- ./data/datanode-2/metadata:/data/metadata
networks:
ozone-net:
ipv4_address: 172.19.0.12
datanode-3:
<<: *image
hostname: datanode-3
command: ["ozone", "datanode"]
depends_on:
- scm
- om
environment:
<<: *common-config
OZONE-SITE.XML_hdds.datanode.dir: "/data/hdds"
OZONE-SITE.XML_ozone.metadata.dirs: "/data/metadata"
OZONE-SITE.XML_ozone.scm.datanode.id.dir: "/data/metadata"
ports:
- "39856:9856"
- "39857:9857"
- "39858:9858"
- "39882:9882"
volumes:
- ./data/datanode-3/hdds:/data/hdds
- ./data/datanode-3/metadata:/data/metadata
networks:
ozone-net:
ipv4_address: 172.19.0.13
recon:
<<: *image
hostname: recon
command: ["ozone", "recon"]
depends_on:
- scm
- om
ports:
- "9888:9888"
environment:
<<: *common-config
OZONE-SITE.XML_ozone.metadata.dirs: "/data/recon"
OZONE-SITE.XML_ozone.recon.db.dir: "/data/recon/db"
volumes:
- ./data/recon:/data/recon
networks:
ozone-net:
ipv4_address: 172.19.0.21
s3g:
<<: *image
hostname: s3g
command: ["ozone", "s3g"]
depends_on:
- om
- scm
ports:
- "9878:9878"
environment:
<<: *common-config
networks:
ozone-net:
ipv4_address: 172.19.0.22
httpfs:
<<: *image
hostname: httpfs
command: ["ozone", "httpfs"]
depends_on:
- om
ports:
- "14000:14000"
environment:
<<: *common-config
CORE-SITE.XML_fs.defaultFS: "ofs://om"
networks:
ozone-net:
ipv4_address: 172.19.0.23
networks:
ozone-net:
driver: bridge
ipam:
config:
- subnet: 172.19.0.0/16
gateway: 172.19.0.1

hbase version is hbase-2.6.2-hadoop3 and config as follows :

ozone-site.xml

ozone.fs.hsync.enabled true ozone.hbase.enhancements.allowed true ozone.client.hbase.enhancements.allowed true ozone.client.stream.putblock.piggybacking true ozone.client.incremental.chunk.list true ozone.client.read.max.retries 3 ozone.client.read.retry.interval 1

hbase-site.xml

<!-- 单机运行：Master、RegionServer 同机 -->
<property>
    <name>hbase.cluster.distributed</name>
    <value>false</value>
</property>

<!-- HBase 数据存储到 Ozone -->
<property>
    <name>hbase.rootdir</name>
    <value>ofs://172.19.0.3:9862/hbasevol/hbasebucket/hbase</value>
</property>

<property>
    <name>ozone.fs.hsync.enabled</name>
    <value>true</value>
</property>
<property>
    <name>ozone.hbase.enhancements.allowed</name>
    <value>true</value>
</property>

<property>
    <name>ozone.client.hbase.enhancements.allowed</name>
    <value>true</value>
</property>
<property>
    <name>ozone.client.read.max.retries</name>
    <value>3</value>
</property>
<property>
    <name>ozone.client.read.retry.interval</name>
    <value>1</value>
</property>
<property>
    <name>ozone.client.stream.putblock.piggybacking</name>
    <value>true</value>
</property>

<property>
    <name>ozone.client.incremental.chunk.list</name>
    <value>true</value>
</property>
<!-- 内置 ZooKeeper -->
<property>
    <name>hbase.zookeeper.property.clientPort</name>
    <value>2181</value>
</property>
<property>
    <name>zookeeper.session.timeout</name>
    <value>120000</value>
</property>

<property>
    <name>hbase.zookeeper.property.tickTime</name>
    <value>6000</value>
</property>
<property>
    <name>hbase.zookeeper.property.dataDir</name>
    <value>/opt/hbase-2.6.2-hadoop3/zk_data/hbase/zookeeper</value>
</property>

<!-- Web UI -->
<property>
    <name>hbase.master.info.port</name>
    <value>16010</value>
</property>
<property>
    <name>hbase.superuser</name>
    <value>root,hadoop</value>
</property>
<!-- RPC 端口 -->
<property>
    <name>hbase.master.port</name>
    <value>16000</value>
</property>

<property>
    <name>hbase.regionserver.port</name>
    <value>16020</value>
</property>

<property>
    <name>hbase.security.authentication</name>
    <value>simple</value>
</property>
<property>
    <name>hbase.security.authorization</name>
    <value>true</value>
</property>

<property>
    <name>hbase.coprocessor.master.classes</name>
    <value>org.apache.hadoop.hbase.security.access.AccessController</value>
</property>

<property>
    <name>hbase.coprocessor.region.classes</name>
    <value>org.apache.hadoop.hbase.security.access.AccessController</value>
</property>

core-site.xml

<property>
    <name>fs.ofs.impl</name>
    <value>org.apache.hadoop.fs.ozone.RootedOzoneFileSystem</value>
</property>

<property>
    <name>fs.defaultFS</name>
    <value>ofs://om/</value>
</property>

[Dv2Corn]

Thanks, the timestamps are enough to place the delay. I checked the paths below against the ozone-2.2.1 tag and Ratis 3.2.1, the version that tag uses (pom.xml).

What the logs show

• The Put started at starttimems 1793760904051, which is 02:55:04.051 UTC, and the sync took 11930 ms, so it ended at about 02:55:15.98 UTC.
• datanode-1 dropped off at 02:55:00.81 (RST_STREAM). Until 02:55:15.86, both leaders only retry it (UNAVAILABLE, keep nextIndex unchanged and retry).
• In group 8A78A2F45648 (pipeline 465d8c7b, leader datanode-3), the nextIndex for datanode-1 moves 2753 → 2755 at 02:55:04.056–04.061. That is new log entries arriving at the moment of your Put. Group 11022ED39D36 stays at 2011. So the WAL block is on pipeline 465d8c7b.
• datanode-1 answers again at 02:55:15.858 (INCONSISTENCY reply with nextIndex 2753), and the sync returns about 120 ms later.

datanode-1 was a follower in both pipelines, so no leader election was involved. That rules out the second case from my earlier comment.

Why the sync waited for datanode-1

hsync() sends WriteChunk/PutBlock and then blocks on a Ratis watch() for that log index (BlockOutputStream L699-L712). The watch uses hdds.ratis.client.request.watch.type, default ALL_COMMITTED (RatisClientConfig L37-L45).

On the leader, an ALL_COMMITTED watch completes only when the lowest commit index across all followers reaches that index (LeaderStateImpl L574-L583). The write itself commits with 2 of 3 nodes, and the leader does not wait for the down follower. The watch does wait for it, until one of two things happens:

• the follower catches up, which is what happened here, or
• hdds.ratis.raft.server.watch.timeout expires (default 30s, DatanodeRatisServerConfig L46-L56). The leader then returns NotReplicatedException (WatchRequests L127-L134), and the client accepts majority and marks the node as failed (XceiverClientRatis L300-L335).

So the 11.9 s is the rest of datanode-1's restart time after the Put arrived. A restart longer than 30 s would cap the stall at about 30 s.

Correction to my earlier comment: in 2.2.1 the client watch timeouts are hdds.ratis.client.request.watch.timeout = 3m and hdds.ratis.raft.client.rpc.watch.request.timeout = 180s, not 30s (L54-L58, L217-L227). The 30s values I quoted are from master. The server timeout (30s) still fires first.

What to change

1. In the ozone-site.xml that the RegionServer reads (client side), set hdds.ratis.client.request.watch.type = MAJORITY_COMMITTED, then restart the RegionServer. A sync then needs 2 of 3 nodes. The cost, per the key's description, is possible read retries if a read first hits the lagging replica.
2. If you keep ALL_COMMITTED, lower hdds.ratis.raft.server.watch.timeout on the datanodes to cap the stall. Keep it below the two client timeouts above.
3. hbase.regionserver.wal.roll.on.sync.ms only avoids the WAL roll. It does not remove the wait.

Not verified

I have not reproduced this. One thing I inferred from the code but did not test: while a follower stays down, each new sync on the same open block sends another ALL_COMMITTED watch. So later syncs may also wait, not only the first one.

To confirm, repeat the same restart with option 1 alone. If the Put returns in milliseconds, that settles it. You can also enable DEBUG for org.apache.hadoop.hdds.scm.XceiverClientRatis on the RegionServer: the line watchForCommit(<index>) returns ALL_COMMITTED ... should appear at about 02:55:15.9.

[zhangchao1171]

Thank you， and I did a test with MAJORITY_COMMITTED, it works！！！