Advice for debugging long round trip time in multilingual deployment

[C-Loftus]

Thank you very much for your excellent work on this library.

Question

• I have a gRPC client in Go and a server in tonic.
• Although the backend function that is ran in tonic only takes 200ms, the round trip is significantly more and can sometimes take up to 1 second.
• Are there any debugging tips I can use to find where the roundtrip latency is coming from?
  • I am finding it a bit tricky to determine if this is due to go-grpc, tonic, tokio, or some other part of the stack
  • I am new to gRPC so I may be missing something fundamental about server multiplexing

My guess is that there is a limit on concurrent requests somehow and thus the client is blocking on either send or recieve but I am unclear where / why

Background

• I have a CLI written in Go using the typical go-grpc lib
• My go client is reusing the same connection with the same client for each request

	conn, err := grpc.NewClient("unix:///tmp/shacl_validator.sock",
		grpc.WithTransportCredentials(insecure.NewCredentials()),
	)
	if err != nil {
		return SitemapCrawlStats{}, fmt.Errorf("failed to connect to gRPC server: %w", err)
	}
	defer conn.Close()
	grpcClient := protoBuild.NewShaclValidatorClient(conn)

• it is communicating to a tonic gRPC server via a unix socket

- My Tonic Server Code

• I only have one simple service on my grpc server.
• I am using multithreading in tokio so I assumed there is no blocking serverside and can handle 100+ connections to the socket without issue

#[tokio::main(flavor = "multi_thread")] // defaults to number of cpus on the system
async fn main() -> Result<(), Box<dyn std::error::Error>> {

    let path = "/tmp/shacl_validator.sock";

    // Remove the socket file if it already exists
    if Path::new(path).exists() {
        fs::remove_file(path)?;
    }

    std::fs::create_dir_all(Path::new(path).parent().unwrap())?;

    let uds = UnixListener::bind(path)?;
    let uds_stream = UnixListenerStream::new(uds);

    // the validator just runs one CPU intensive function to validate a payload then returns
    let validator = Validator::default();

    println!("Starting gRPC server on {}", path);

    // Run the server and listen for Ctrl+C
    let server = Server::builder()
        .add_service(ShaclValidatorServer::new(validator))
        .serve_with_incoming_shutdown(
            uds_stream,
            async {
                signal::ctrl_c().await.expect("failed to install Ctrl+C handler");
            }
        );

    let result = server.await;

    // Clean up the socket file on shutdown
    if Path::new(path).exists() {
        println!("Cleaning up socket file at {}", path);
        fs::remove_file(path)?;
    }
    result?;
    Ok(())
}

• My tonic service has potentially a few hundred inbound requests at once and is executing a CPU bound function (essentially a web crawler utility function)
  • Despite this, the validation part that is CPU bound pretty much never takes above 300ms

Timing Background

• Each validation function takes < 200ms to complete but I find that the total round trip is >500ms
• I assumed performance would be better since I am using a local socket
• My payload and protobuf schema are both very small and simple (no nesting, nothing over a few thousand bytes in total, i.e. serialized json payload size)
  • Here is an example of a payload I am sending to tonic, https://reference.geoconnex.us/collections/dams/items/1022598?f=jsonld (it is fairly small when serialized)
• Here are some timing spans from otel
  

Thank you very much

[kvc0]

Nearly all of my experience with tonic is via http2. For reference, at my day job, we have a go sdk customers use (on their own servers) that connects via normal tls http2 to remote servers (that I own) running tonic. P999 latency for payloads of this size is on the order of 1-3 milliseconds, assuming they're in the same cloud and depending on whether or not they're in the same AZ. I'm not saying this to brag, but to reassure you that multilingual grpc with < 1s latency is a very reasonable ask 😆 ❤️

---

First and easiest, a tokio trivia: Your main is fine, except that it runs your server "off the runtime." This can cause delays mostly for new connections (possibly more). Try changing one line in your server to:

let result = tokio::spawn(server).await;

This makes your server run on a runtime thread, so any task it spawns will be from within the runtime - and that makes the tasks start much more quickly. I don't think this is costing you a second though.

---

Second and probably a wild goose chase, is your go client making only 1 connection for all the concurrency? I've had to go to great lengths to make high concurrency on 1 h2 connection work well. If your client library allows it, you might try a load balancing connection pool or something with 10 connections to spread the concurrent stream synchronization. I also don't think this is costing you a second.

---

Third and probably the root, is that 200 milliseconds is too long to hold a cooperative multitasking thread. Tokio doesn't know which task you want to execute first, so in the abstract, they run in unordered fashion, and your complete work items delay other work items.

In Rust, tasks don't have any way to implicitly, preemptively yield in the middle of their work. They will occupy their thread unconditionally until they reach an await (or complete) just like a 2+2 expression or thread::sleep(). For your tasks that run tonic requests, you want to stay within 50µs of an await at all times, as much as possible. Broadly, I know of 2 convenient patterns to do this with what you describe:

Make your cpu work async: You make that 200-300ms "validation" code asynchronous, and assuming you're doing a bunch of computation in some loop, you would put an await in there every thousand iterations or something to that effect, like this:

tokio::task::consume_budget().await;

Run your cpu work off the runtime: Not all thread-bound work is created equal. Consider how easily a cpu accomplishes thread::sleep() or reading bytes from a drive, versus a hard loop computing the nth digit of pi. I am not sure what kind of work your validation work is, so if I had to give you a silver bullet recommendation, I'd ask you to move that 200-300ms to a different thread pool.

You can do that by:

let validation_result = tokio::task::spawn_blocking(async move {
    run_200ms_validation(the_request)
});

or by creating a rayon thread pool and doing some channel plumbing, e.g., with tokio::sync::oneshot::channel(). A 200-300 millisecond cpu-bound work is enough to legitimize an "off-runtime task wake" via a mechanism like this.

---

Lastly, some obligatory engineering theory because I can't help myself: If you have 100 computations that each take 0.2 seconds, that's 20 seconds of CPU time that has come from somewhere. By Little's Law, a 16 core CPU can only retire a CPU-bound 200ms task at a rate of:

r * 0.2 = 16
r = 80

80 requests per second. If you make requests at a higher rate than that, you are queueing and your latency will increase - irrespective of libraries, tech stacks, architectures, or anything else.