After the channel is created, it takes 1000+ms to transition from IDEL state to CONNECTING state.How can i reduce the time required to change state?

[邹会江]

### JAVA Code

```
            channel = ManagedChannelBuilder.forTarget(param.getTarget()).build();
            long channelStart = System.currentTimeMillis();
            asyncStub = ASRRouteGrpc.newStub(channel);
            asrResponseStreamObserver = new ASRResponseStreamObserver(speechTranscriberListener);
            requestObserver = asyncStub.route(asrResponseStreamObserver);
            RouteRequest requestConf = newRequestHead(param);
            traceId = requestConf.getAsrConfig().getTraceId();
            ConnectivityState currentChannelState = channel.getState(true);
            while (currentChannelState != ConnectivityState.READY) {
                CountDownLatch latchUntilChannelReady = new CountDownLatch(1);
                channel.notifyWhenStateChanged(currentChannelState, latchUntilChannelReady::countDown);
                latchUntilChannelReady.await();
                currentChannelState = channel.getState(true);
                if (currentChannelState == ConnectivityState.CONNECTING) {
                    long channelConnecting = System.currentTimeMillis();
                    LOGGER.info("The transition from idle state to connecting takes: {} ms", channelConnecting - channelStart);
                }
            }
            long channelReady = System.currentTimeMillis();
            if (LOGGER.isInfoEnabled()) {
                LOGGER.info("Trace id: {}, channel start time: {}, channel ready time: {}, creating channel takes: {} ms", traceId, channelStart, channelReady,
                        channelReady - channelStart);
            }
```
### LOGGER

```
2023-08-22 14:12:34,816 INFO  client.ASRClient - The transition from idle state to connecting takes: 1009 ms
2023-08-22 14:12:34,841 INFO  client.ASRClient - Trace id: 6afd2c67-e8c5-4cea-bd5c-4b82591a52aa, channel start time: 1692684753807, channel ready time: 1692684754841, creating channel takes: 1034 ms
```
### Description
#### code logic
1. first create channel
2. mark a time stamp(channelStart) after the channel is created
3. get the state of channel ,the state is IDEL
4. when the state of channel changes from IDEL to CONNECTING,mark a time stamp(channelConnecting)
5. when the state of channel changes from CONNECTING to READY, mark a time stamp(channelReady)

#### Log info
1. It takes 1009ms for channel from IDLE state to CONNECTING state.
2. It takes 25ms for channel from CONNECTIONG state to READY state.
### What's i supposed
1. Does it take too long for a channel to change from IDLE to CONNECTING?
2. I want to reduce the time it takes for a channel to go from IDLE to CONNECTING.

[Yuri Golobokov]

Hello,

What is the round-trip time? How much time does DNS resolution take?

[Larry Safran]

Another question is whether this is the same the second time you create a channel.  The first time, the JVM may be taking time doing class loading.

--
You received this message because you are subscribed to the Google Groups "grpc.io" group.
To unsubscribe from this group and stop receiving emails from it, send an email to grpc-io+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/8f2a15b8-1541-422e-ad66-9a5778e53882n%40googlegroups.com.

[邹会江]

Thank you for your reply!
1. The first time:
The transition from idle state to connecting takes: 3377 ms,
The transition from idle state to ready takes: 3679 ms
2. The second time:
The transition from idle state to connecting takes: 1643 ms,
The transition from idle state to ready takes: 1797 ms
3.The third time:
The transition from idle state to connecting takes: 1019 ms,
The transition from idle state to ready takes: 1049 ms
4. What is my enviroment?
MacBook Pro (16-inch, 2019)
2.6 GHz 6 core Intel Core i7
16 GB 2667 MHz DDR4

[Sanjay Pujare]

Most of the time is spent in IDLE -> CONNECTING transition. From this doc https://github.com/grpc/grpc/blob/master/doc/connectivity-semantics-and-api.md which says for CONNECTING

CONNECTING: The channel is trying to establish a connection and is waiting to make progress on one of the steps involved in name resolution, TCP connection establishment or TLS handshake. This may be used as the initial state for channels upon creation.

DNS resolution and TLS handshake (since you are not calling usePlaintext() on the builder) are possible culprits. Even TCP connection establishment is a possibility depending on where the target is. If you enable trace logging you might be able to figure out.  

To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/8901e7bd-b684-462f-bf88-3607b6b01713n%40googlegroups.com.

[邹会江]

Sanjay Pujare：

Thank you for your reply!

1. How do  i enable trace logging?
2. DNS resolution,TLS hanshake and TCP connection.In this case,the state of channel should be CONNECTING?Therefore,the TCP connectio only affects the CONNECTING time, but not the IDLE time.

[Sanjay Pujare]

On Wed, Aug 23, 2023 at 1:37 AM '邹会江' via grpc.io <grp...@googlegroups.com> wrote:

Sanjay Pujare：
Thank you for your reply!
1. How do  i enable trace logging?

It uses java util logging so to enable using JAVA_OPTS:

export JAVA_OPTS="-Djava.util.logging.config.file=/logging.properties"

And in /logging.properties have this:

handlers=java.util.logging.ConsoleHandler
io.grpc.ChannelLogger.level=FINEST
io.grpc.level=FINEST
io.netty.level=FINEST
java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

Or you can tweak it to your liking.

 

2. DNS resolution,TLS hanshake and TCP connection.In this case,the state of channel should be CONNECTING?

Yes.

 

Therefore,the TCP connectio only affects the CONNECTING time, but not the IDLE time.

Not sure I understand this comment/question. But when it is trying to establish the TCP connection, yes the status is CONNECTING

 

To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/76f2be33-959a-4bf3-9405-1b1748ba3ec0n%40googlegroups.com.

[邹会江]

1. I modified the logging.properties file under jre/lib:

handlers=java.util.logging.ConsoleHandler
io.grpc.ChannelLogger.level=FINEST
io.grpc.level=FINEST
io.netty.level=FINEST
java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

but grpc doesn't have any log output to the console.

[sanjay...@google.com]

Instead of modifying and using the jre/lib logging.properties file can you try using one for your application alone as described in my previous message (use Java property java.util.logging.config.file and so on)? 

[邹会江]

Thanks！

I upgrade the grpc-java version from 1.3.3 to 1.51.0, and the IDLE time is reduced from 1000ms to 300ms.

[Sanjay Pujare]

Oh, I didn't realize your grpc java version was so old. Good to know your issue is resolved.

To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/421ab865-34bd-4753-99e9-01286cc513dbn%40googlegroups.com.

[Eric Anderson]

This was also discussed on Stack Overflow. I filed https://github.com/grpc/grpc-java/issues/10517 for the delayed transition to CONNECTING. It won't change performance any, though.

To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/CA%2BPad6igrZcg4PO8gCjZSiDhaNxgwJ7EY8a4uU_vNSXTx3B7KQ%40mail.gmail.com.