Performance degradation on M1 Max in release mode

[joshualex]

I came here from tokio-rs/axum#902, since the issue does not seem to be with Axum itself. I also managed to reproduce similar results with actix-web as well.

I'm using a MacBook Pro 16" (Apple Silicon M1 Max) and trying the following simple example:

use axum::{routing::post, Json, Router};
use serde::Deserialize;

#[tokio::main]
async fn main() {
    // build our application with a route
    let app = Router::new().route("/", post(compute));

    let addr = "127.0.0.1:8000".parse().unwrap();
    axum::Server::bind(&addr)
        .serve(app.into_make_service())
        .await
        .unwrap();
}

#[derive(Deserialize)]
struct Params {
    a: u32,
    b: u32,
}

async fn compute(params: Json<Params>) -> String {
    format!("Result is {}", params.a + params.b)
}

Running in debug, and then using hey to measure performance:

$ hey -n 100000 -T application/json -d '{"a": 2, "b": 3}' -m post http://127.0.0.1:8000

Under debug build, I get very decent results:

Summary:
  Total:	1.5304 secs
  Slowest:	0.0895 secs
  Fastest:	0.0001 secs
  Average:	0.0008 secs
  Requests/sec:	65342.6361

  Total data:	1100000 bytes
  Size/request:	11 bytes

Response time histogram:
  0.000 [1]	|
  0.009 [99872]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.018 [81]	|
  0.027 [21]	|
  0.036 [14]	|
  0.045 [4]	|
  0.054 [3]	|
  0.063 [1]	|
  0.072 [2]	|
  0.081 [0]	|
  0.089 [1]	|


Latency distribution:
  10% in 0.0003 secs
  25% in 0.0005 secs
  50% in 0.0007 secs
  75% in 0.0009 secs
  90% in 0.0012 secs
  95% in 0.0014 secs
  99% in 0.0021 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0001 secs, 0.0895 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0016 secs
  resp wait:	0.0007 secs, 0.0001 secs, 0.0895 secs
  resp read:	0.0000 secs, 0.0000 secs, 0.0014 secs

Status code distribution:
  [200]	100000 responses

However switching to release build causes performance to degrade considerably, at least as far as total run time goes:

Summary:
  Total:	2.7054 secs
  Slowest:	0.0129 secs
  Fastest:	0.0000 secs
  Average:	0.0013 secs
  Requests/sec:	36962.8461

  Total data:	1100000 bytes
  Size/request:	11 bytes

Response time histogram:
  0.000 [1]	|
  0.001 [60141]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.003 [22608]	|■■■■■■■■■■■■■■■
  0.004 [12366]	|■■■■■■■■
  0.005 [3914]	|■■■
  0.006 [813]	|■
  0.008 [121]	|
  0.009 [25]	|
  0.010 [8]	|
  0.012 [0]	|
  0.013 [3]	|


Latency distribution:
  10% in 0.0002 secs
  25% in 0.0003 secs
  50% in 0.0008 secs
  75% in 0.0021 secs
  90% in 0.0032 secs
  95% in 0.0039 secs
  99% in 0.0051 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0000 secs, 0.0129 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0057 secs
  resp wait:	0.0013 secs, 0.0000 secs, 0.0121 secs
  resp read:	0.0000 secs, 0.0000 secs, 0.0094 secs

Status code distribution:
  [200]	100000 responses

While the time spent in each request indeed became shorter (from 0.009 on average to 0.001-0.002s on average), the overall time is twice as long, and the number of requests per second drops as well.

Any ideas on why this behavior could be happening?

[Darksonn]

Sorry, nothing comes to mind.