Add setScheduledExecutorService() to NettyChannelBuilder

[danfaer]

Is your feature request related to a problem?

The NettyTransportFactory.getScheduledExecutorService() method returns the EventLoopGroup used for scheduling timeout tasks and other operations. However, the current implementation of EventLoopGroup.schedule() calls EventLoopGroup.next(), which moves the index of the current event loop to the next position. This behavior leads to unpredictable event loop selection for NettyClientTransport, potentially causing multiple Netty channels to share the same event loop, even if the number of event loops in the group is greater than the number of channels.

Describe the solution you'd like

I propose adding a setter for the ScheduledExecutorService in the NettyChannelBuilder. If a user-defined ScheduledExecutorService is set, it will be returned by NettyTransportFactory.getScheduledExecutorService() and used for scheduling tasks. As a result, the call to EventLoopGroup.next() will exclusively occur from NettyClientTransport.start().

Describe alternatives you've considered

An alternative solution would be to use a Composite EventLoopGroup that handles EventLoopGroup.schedule() differently. However, implementing this solution is not straightforward due to the EpollEventLoopGroup being a final class.

[sanjaypujare]

Background discussion https://groups.google.com/g/grpc-io/c/xR82L6dNhfk/m/8ry1e9pLAwAJ

CC @ejona86 something we should consider in the next API meeting?

[sanjaypujare]

@danfaer are you interested in contributing a PR for this?

[ejona86]

potentially causing multiple Netty channels to share the same event loop

Is that a problem? We generally expect and assume this will happen.

even if the number of event loops in the group is greater than the number of channels

This is possible a limited amount of connection churn as well.

The deadline task may end up in the same slow EventLoop, which subsequently requires its cancellation.

Overall, I'm not seeing something we'd call a problem. But I do expect there was a problem and it just wasn't fully shared. This quote from the mailing list may be a hint though because of the word "slow." Did you experience a latency issue on one connection because it was shared with another? Can you share how severe the issue was?

[danfaer]

here is the original problem - https://stackoverflow.com/questions/76106267/grpc-java-call-takes-much-longer-than-deadline
I can't prove that the reason for slowness is sharing EventLoopGroups; it's just a hunch. However, in any case, using EventLoopGroups only for the Netty transport is beneficial because the probability of equal event loop to Netty transport distribution is much higher compared to when EventLoopGroups are used for scheduling tasks.

[ejona86]

Two seconds is really long. If the network threads are seeing 2s of latency, lots of things will be bad. We would want to look into that and address that, independent of deadlines.

I have seen a synthetic test that could maybe do that by starting a ton of RPCs on a single connection, but it is hard to reproduce without running out of memory. I'd normally expect that to be caused by someone "blocking on the network thread." That'd be some user that did blocking in a NameResolver or StreamTracer, or tried to eek out more performance by using managedChannel.directExecutor(). But the only way to fix those is to find the offending code and fix it.

If this is actually a general problem and not "someone doing something wrong," it'd probably be better to change our default, because it would be far too deep for users to diagnose why they are getting weird latencies. We'd swap to our shared scheduledExecutorService (and provide the override in the builder). But we'd want something more to be confident this is the problem.

If the problem is just next() mutating the counter, it might not be horrible to use iterator() to make a copy of the executor list and keep our own counter. That'd keep things mostly the same as they are now. It does assume that the group won't change size.

I saw you posted a reproduction, but then removed it. The timing difference you saw was just the JVM warming up. If you alternate more times between "today" and "using scheduledExecutorService" the latency difference disappears (for that specific attempt to reproduce).

[danfaer]

Eric, you are correct that the time difference in my reproducer is mainly due to JVM warmup. I removed my comment because I switched the order and observed the opposite result. However, in any case, I was able to consistently reproduce delays, although I can't prove that an external scheduled executor is better. The reproducer setup is as follows: - One shared channel with a connection to one local server. - The client's EventLoopGroup with 20 threads. - 100 threads start sending requests at the same time with a DeadlineAfter of 200 ms. - The server takes 500 ms to respond. - Time is measured outside the call. The minimum time observed was 250 ms, and the maximum time was 400 ms.

…

On Tue, Jun 6, 2023 at 9:37 AM Eric Anderson ***@***.***> wrote: Two seconds is really long. If the network threads are seeing 2s of latency, lots of things will be bad. We would want to look into that and address that, independent of deadlines. I have seen a synthetic test that could maybe do that by starting a *ton* of RPCs on a single connection, but it is hard to reproduce without running out of memory. I'd normally expect that to be caused by someone "blocking on the network thread." That'd be some user that did blocking in a NameResolver or StreamTracer, or tried to eek out more performance by using managedChannel.directExecutor(). But the only way to fix those is to find the offending code and fix it. If this is actually a general problem and not "someone doing something wrong," it'd probably be better to change our default, because it would be far too deep for users to diagnose why they are getting weird latencies. We'd swap to our shared scheduledExecutorService (and provide the override in the builder). But we'd want something more to be confident this is the problem. If the problem is just next() mutating the counter, it might not be horrible to use iterator() to make a copy of the executor list and keep our own counter. That'd keep things mostly the same as they are now. It does assume that the group won't change size. I saw you posted a reproduction, but then removed it. The timing difference you saw was just the JVM warming up. If you alternate more times between "today" and "using scheduledExecutorService" the latency difference disappears (for that specific attempt to reproduce). — Reply to this email directly, view it on GitHub <#10246 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA4YKX3UGOTNKSADWUUEZ4LXJ5MEFANCNFSM6AAAAAAYYRPGM4> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[ejona86]

When I ran that reproducer (with 50 tasks, and 1 eventloop in the group) it didn't show any serious latency. My service implementation threw away the request, so it was guaranteed to timeout without me needing to schedule anything on server-side or have more threads.

I wouldn't expect a burst-send-with-later-timeout to show much issue. The creation of the RPCs is bursty, but the timeout is scheduled on the calling thread and when the timeout fires the system is close to idle. The timeout causes a small RST_STREAM and a callback to the application, which couldn't contribute ms.

A simple noop RPC takes ~200 µs, so doing half of it serially would only be 20 ms. I would have expected a larger RPC (metadata or message size) to be necessary to trigger this.

It's possible something is wrong with Netty's KQueue channel. I am testing on my i7-8650U Linux laptop with epoll. It might be worth checking if Nio behaves the same way on Mac.

Alternating the tests back-and-forth:

withScheduledService=false, testNum=0, maxTime=61, minTime=52, totalTime=2,771
withScheduledService=false, testNum=1, maxTime=56, minTime=50, totalTime=2,706
withScheduledService=false, testNum=2, maxTime=51, minTime=50, totalTime=2,505
withScheduledService=false, testNum=3, maxTime=72, minTime=51, totalTime=3,176
withScheduledService=false, testNum=4, maxTime=124, minTime=67, totalTime=3,731
withScheduledService=false, totalTimePerExperiments=14,889
withScheduledService=true, testNum=0, maxTime=51, minTime=50, totalTime=2,503
withScheduledService=true, testNum=1, maxTime=58, minTime=51, totalTime=2,751
withScheduledService=true, testNum=2, maxTime=56, minTime=51, totalTime=2,705
withScheduledService=true, testNum=3, maxTime=57, minTime=51, totalTime=2,736
withScheduledService=true, testNum=4, maxTime=53, minTime=51, totalTime=2,588
withScheduledService=true, totalTimePerExperiments=13,283
withScheduledService=false, testNum=0, maxTime=51, minTime=50, totalTime=2,510
withScheduledService=false, testNum=1, maxTime=53, minTime=50, totalTime=2,601
withScheduledService=false, testNum=2, maxTime=51, minTime=50, totalTime=2,502
withScheduledService=false, testNum=3, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=4, maxTime=58, minTime=50, totalTime=2,737
withScheduledService=false, totalTimePerExperiments=12,850
withScheduledService=true, testNum=0, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=true, testNum=1, maxTime=56, minTime=50, totalTime=2,637
withScheduledService=true, testNum=2, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=true, testNum=3, maxTime=54, minTime=51, totalTime=2,618
withScheduledService=true, testNum=4, maxTime=52, minTime=50, totalTime=2,546
withScheduledService=true, totalTimePerExperiments=12,801
withScheduledService=false, testNum=0, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=1, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=2, maxTime=51, minTime=50, totalTime=2,504
withScheduledService=false, testNum=3, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=4, maxTime=52, minTime=50, totalTime=2,567
withScheduledService=false, totalTimePerExperiments=12,571
withScheduledService=true, testNum=0, maxTime=51, minTime=50, totalTime=2,513
withScheduledService=true, testNum=1, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=true, testNum=2, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=true, testNum=3, maxTime=51, minTime=50, totalTime=2,501
withScheduledService=true, testNum=4, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=true, totalTimePerExperiments=12,514
withScheduledService=false, testNum=0, maxTime=52, minTime=50, totalTime=2,566
withScheduledService=false, testNum=1, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=2, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=3, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, testNum=4, maxTime=50, minTime=50, totalTime=2,500
withScheduledService=false, totalTimePerExperiments=12,566

[danfaer]

I tested it with Nio also - same results as with KQueue

[danfaer]

Replicating your experiment with back and forth 8 times, service throwing away request. Running on my Apple M1 Max, 64g laptop.
posting here 4 last results:

KQueue

withScheduledService=false, testNum=0, maxTime=66, minTime=57, totalTime=3098
withScheduledService=false, testNum=1, maxTime=56, minTime=54, totalTime=2716
withScheduledService=false, testNum=2, maxTime=59, minTime=51, totalTime=2768
withScheduledService=false, testNum=3, maxTime=55, minTime=54, totalTime=2720
withScheduledService=false, testNum=4, maxTime=60, minTime=52, totalTime=2800
withScheduledService=false, totalTimePerExperiment=14102
withScheduledService=true, testNum=0, maxTime=55, minTime=53, totalTime=2685
withScheduledService=true, testNum=1, maxTime=63, minTime=54, totalTime=3040
withScheduledService=true, testNum=2, maxTime=62, minTime=57, totalTime=2954
withScheduledService=true, testNum=3, maxTime=58, minTime=54, totalTime=2761
withScheduledService=true, testNum=4, maxTime=61, minTime=56, totalTime=2987
withScheduledService=true, totalTimePerExperiment=14427
withScheduledService=false, testNum=0, maxTime=54, minTime=50, totalTime=2566
withScheduledService=false, testNum=1, maxTime=52, minTime=51, totalTime=2599
withScheduledService=false, testNum=2, maxTime=51, minTime=51, totalTime=2550
withScheduledService=false, testNum=3, maxTime=53, minTime=51, totalTime=2589
withScheduledService=false, testNum=4, maxTime=59, minTime=52, totalTime=2721
withScheduledService=false, totalTimePerExperiment=13025
withScheduledService=true, testNum=0, maxTime=97, minTime=80, totalTime=4354
withScheduledService=true, testNum=1, maxTime=122, minTime=78, totalTime=4968
withScheduledService=true, testNum=2, maxTime=95, minTime=88, totalTime=4576
withScheduledService=true, testNum=3, maxTime=57, minTime=55, totalTime=2790
withScheduledService=true, testNum=4, maxTime=56, minTime=53, totalTime=2749
withScheduledService=true, totalTimePerExperiment=19437

Nio

withScheduledService=false, testNum=0, maxTime=69, minTime=51, totalTime=2959
withScheduledService=false, testNum=1, maxTime=57, minTime=52, totalTime=2666
withScheduledService=false, testNum=2, maxTime=52, minTime=52, totalTime=2600
withScheduledService=false, testNum=3, maxTime=58, minTime=55, totalTime=2896
withScheduledService=false, testNum=4, maxTime=57, minTime=52, totalTime=2721
withScheduledService=false, totalTimePerExperiment=13842
withScheduledService=true, testNum=0, maxTime=61, minTime=58, totalTime=2984
withScheduledService=true, testNum=1, maxTime=53, minTime=52, totalTime=2633
withScheduledService=true, testNum=2, maxTime=62, minTime=58, totalTime=3057
withScheduledService=true, testNum=3, maxTime=65, minTime=55, totalTime=3117
withScheduledService=true, testNum=4, maxTime=65, minTime=60, totalTime=3116
withScheduledService=true, totalTimePerExperiment=14907
withScheduledService=false, testNum=0, maxTime=55, minTime=51, totalTime=2655
withScheduledService=false, testNum=1, maxTime=55, minTime=52, totalTime=2747
withScheduledService=false, testNum=2, maxTime=66, minTime=53, totalTime=3007
withScheduledService=false, testNum=3, maxTime=65, minTime=60, totalTime=3131
withScheduledService=false, testNum=4, maxTime=60, minTime=50, totalTime=2624
withScheduledService=false, totalTimePerExperiment=14164
withScheduledService=true, testNum=0, maxTime=76, minTime=53, totalTime=3025
withScheduledService=true, testNum=1, maxTime=80, minTime=51, totalTime=3212
withScheduledService=true, testNum=2, maxTime=56, minTime=55, totalTime=2799
withScheduledService=true, testNum=3, maxTime=59, minTime=54, totalTime=2837
withScheduledService=true, testNum=4, maxTime=56, minTime=55, totalTime=2774
withScheduledService=true, totalTimePerExperiment=14647

[ejona86]

Those are really weak results... I even ran while doing a video chat where chrome was using 150% CPU (of 4 cores total) and didn't see much difference to what I posted before. You aren't running on battery during the test, right?

I've dumped the code at:
https://github.com/ejona86/grpc-java-10246

@sanjaypujare, would you mind running the code in that repository on your M1 and see if you also see poor deadline latency? You'll need to check out #10250 (git fetch https://github.com/danfaer/grpc-java.git ncb-scheduled-executor; git checkout FETCH_HEAD).

[sanjaypujare]

...
@sanjaypujare, would you mind running the code in that repository on your M1 and see if you also see poor deadline latency? You'll need to check out #10250 (git fetch https://github.com/danfaer/grpc-java.git ncb-scheduled-executor; git checkout FETCH_HEAD).

Sure, will try and let you know