Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,6 @@ public abstract class AbstractNettyRemotingClient extends AbstractNettyRemoting
private static final String MSG_ID_PREFIX = "msgId:";
private static final String FUTURES_PREFIX = "futures:";
private static final String SINGLE_LOG_POSTFIX = ";";
private static final int MAX_MERGE_SEND_MILLS = 1;
private static final String THREAD_PREFIX_SPLIT_CHAR = "_";
private static final int MAX_MERGE_SEND_THREAD = 1;
private static final long KEEP_ALIVE_TIME = Integer.MAX_VALUE;
Expand Down Expand Up @@ -587,7 +586,15 @@ public void run() {
while (true) {
mergeLock.lock();
try {
mergeCondition.await(MAX_MERGE_SEND_MILLS, TimeUnit.MILLISECONDS);
// Park until there are pending messages, so the merge thread no longer
// burns CPU with a 1ms polling cycle when idle. The check-and-wait is
// atomic under mergeLock and producers offer to the basket before
// signalling (see sendSyncRequest), so no wake-up can be lost.
while (isBasketEmpty()) {
isSending = false;
mergeCondition.await();

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With this approach, whenever a message arrives, the processing thread waits for up to another 1 ms. Why is this additional delay necessary?

With the implementation you’re currently using, consider the case where only a single message arrives: it wakes up the thread, but the thread then waits for another 1 ms before sending the message. This effectively adds about 1 ms to the request latency.

I don’t think an await of 1 ms alone should cause such high CPU usage. Could the high CPU utilization be related to Arthas being enabled? Given the performance of modern CPUs, 1,000 wake-ups per second that do essentially no work should not normally be enough to consume around 30% CPU.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the review — both points were spot on. I've removed the post-wakeup await(1ms) entirely: the thread now drains immediately after being signalled. Measured locally: first-message drain latency drops from ~1.4-15.3ms (with the 1ms await) to ~0.09-0.21ms, and batching does not regress — avg batch size is 50 vs 21.3 on the original under a 4x25 concurrent burst. The full measurement table is in the PR description.

On the 30% CPU number — fair point that Arthas sampling and container CPU quota matter. What the issue confirms is the thread dump: the rpcMergeMessageSend_*_1 threads sit in TIMED_WAITING while burning CPU. Locally (ThreadMXBean, 10s window) the original implementation consumes a steady 31ms of thread CPU time per 10s at idle; this PR takes it to 0. The absolute ratio is environment-dependent, but the idle wake-up cost is real and now gone.

}
isSending = true;
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
LOGGER.warn("MergedSendRunnable wait interrupted", e);
Expand Down Expand Up @@ -639,6 +646,21 @@ public void run() {
}
}

/**
* Checks whether all baskets are empty. The merge thread parks itself
* when this returns true, avoiding the idle 1ms polling busy loop.
*
* @return true if every basket in basketMap is empty
*/
private boolean isBasketEmpty() {
for (BlockingQueue<RpcMessage> basket : basketMap.values()) {
if (!basket.isEmpty()) {
return false;
}
}
return true;
}

private void printMergeMessageLog(MergedWarpMessage mergeMessage) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("merge msg size:{}", mergeMessage.msgIds.size());
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@
import org.slf4j.LoggerFactory;

import java.net.InetSocketAddress;
import java.util.Map;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.ThreadPoolExecutor;
Expand Down Expand Up @@ -1479,6 +1480,52 @@ public void testMergedSendRunnableWithEmptyBasket() throws Exception {
}
}

@Test
public void testMergedSendRunnableIdleWaitState() throws Exception {
TestNettyRemotingClientWithMergeRunnable mergeClient =
new TestNettyRemotingClientWithMergeRunnable(clientConfig, messageExecutor);

try {
mergeClient.init();

// Wait for the merge send thread to start and park itself
Thread.sleep(300);

// The merge thread must be parked on Condition.await (WAITING) instead of
// spinning on a 1ms timed wait (TIMED_WAITING) when idle
for (Map.Entry<Thread, StackTraceElement[]> entry :
Thread.getAllStackTraces().entrySet()) {
Thread thread = entry.getKey();
if (thread.getName().startsWith("rpcMergeMessageSend")) {
assertFalse(
Thread.State.TIMED_WAITING == thread.getState(),
"merge send thread should not spin on a 1ms timed wait when idle: " + thread.getName());
}
}

// A message must wake the thread and get drained from the basket
GlobalBeginRequest request = new GlobalBeginRequest();
request.setTransactionName("test-tx-idle-wake");
try {
mergeClient.sendSyncRequest(request);
} catch (Exception e) {
// Expected: no real server at 127.0.0.1:8080, the merge thread
// drains the basket and fast-fails the future
}

Thread.sleep(300);
assertTrue(
mergeClient.basketMap.values().stream().allMatch(BlockingQueue::isEmpty),
"basket should be drained by the merge send thread after wake-up");
} finally {
try {
mergeClient.destroy();
} catch (Exception e) {
// Ignore
}
}
}

/**
* Test implementation that simulates reconnect exception
*/
Expand Down