GRPC C++ request spent > 2s from client to server

[Frank Yu]

Hi GRPC team,

I tried to use grpc C++ with the package version Pkggrpc_cpp_1_29_1377_125. It is a simple "sayhello" implementation, and both the grpc client and grpc server are running on different services of the same node. 

The problem is that I found the sayhello request spent more than 2 seconds to complete. Which is far more than what I expected according to the benchmarking.

Here's part of my code.
Client:

HRESULT

SayHello(__in REQUEST* helloRequest, __inout RESPONSE* helloResponse)

{

    std::shared_ptr<grpc::Channel> channel =

        grpc::CreateChannel("localhost:53002", grpc::InsecureChannelCredentials());

    std::unique_ptr<App_QADDisk::Stub> stub_(App_QADDisk::NewStub(channel));

...

    // The actual RPC.

    RD_TRACE_LOG((RD_TRACE_INFO, L"Calling gRPC request"));

    Status status = stub_->SayHello(&context, request, &reply);

    RD_TRACE_LOG((RD_TRACE_INFO, L"Returned gRPC request"));

...

}

Server:

class AppSayHelloImpl final : public App_SayHello::Service

    {

        grpc::Status

        SayHello(ServerContext* context, const Request* request, Response* response) override

        {

            RDOS_INFO << L"Received request: " << request->testmessage();

            std::string message = request->testmessage();

            response->set_message(message);

            RDOS_INFO << L"returned.";

            return Status::OK;

        }

    };

Logs:
Client:

[2023/12/14, 06:02:46.536,  INFO, 00019432] Calling gRPC request

[2023/12/14, 06:02:48.567,  INFO, 00019432] Returned gRPC request

Server:

[2023/12/14, 06:02:48.567, INFO, 00027292] Received request: test

[2023/12/14, 06:02:48.567, INFO, 00027292] returned.

Further logging shows that the flow from the client calling SayHello() to the Server trigger the SayHello() function took the 2 seconds.  

Questions:

1. Does GRPC client and server write internal logs? If it does, where I can find it on Windows? If not, how can I trace it.

2. Any idea about why it take so long sending the request from client to server? Is it expected? If not, how can I debugging/tracing it?

Any response will be appreciated! 

Best regards,

Frank

[veb...@google.com]

You can use environment variables to get more gRPC logging; See https://github.com/grpc/grpc/blob/master/doc/environment_variables.md

I don't think spending 2 seconds to complete a simple RPC look good.

[Craig Tiller]

Also worth checking how long the second RPC takes -- gRPC will lazily connect the channel by default on the first RPC, so you'll be measuring all of the connection establishment latency (for which 2 seconds is probably still too high)

--
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/8bb77cc7-fc3d-4363-b34a-540966139e9en%40googlegroups.com.

[Frank Yu]

Hi Craig,

Thanks for your responding! The Grpc Client will be on a proxy service so logically we could maintain a single Channel/Stub for all the communication between the client and server. Once we start the proxy service, we could send a request to lazily initiate the connection. But here's my 2 concerns:

1. Will the channel always stays connected unless we manually close it? Is there a timeout for the connection? Per my testing, after 3 hours idle seems the connection still alive.

2. If the channel connection drops by accident, will it try to reconnect automatically, or we need to handle it ourselves? 

Our case is time sensitive. We can accept the first request take longer time to lazily initiate the channel connection. But we don't want the rest of the requests take long time by any chance.

Thanks,

Frank Yu

[Frank Yu]

Hi Veb,

Will it get logged into a log file or on the console? I tried  to set the environment variables but could not find the log.

Thanks