wisp icon indicating copy to clipboard operation
wisp copied to clipboard

Detecting temp directory performed on every request

Open makindotcc opened this issue 1 year ago • 6 comments

Hello. I was benchmarking wisp and mist, I saw that wisp is significantly slower. Found that applying following diff to make_connection and wisp_mist.handler is making wisp 20x faster on linux (wsl).

pub fn make_connection(
  body_reader: Reader,
  secret_key_base: String,
) -> Connection {
  // Fallback to current working directory when no valid tmp directory exists
-  let prefix = case directories.tmp_dir() {
-    Ok(tmp_dir) -> tmp_dir <> "/gleam-wisp/"
-    Error(_) -> "./tmp/"
-  }
-  let temporary_directory = join_path(prefix, random_slug())
+  let temporary_directory = "test"
  Connection(
    reader: body_reader,
    max_body_size: 8_000_000,
    max_files_size: 32_000_000,
    read_chunk_size: 1_000_000,
    temporary_directory: temporary_directory,
    secret_key_base: secret_key_base,
  )
}
pub fn handler(
  handler: fn(wisp.Request) -> wisp.Response,
  secret_key_base: String,
) -> fn(HttpRequest(mist.Connection)) -> HttpResponse(mist.ResponseData) {
  fn(request: HttpRequest(_)) {
    let connection =
      internal.make_connection(mist_body_reader(request), secret_key_base)
    let request = request.set_body(request, connection)
+    // todo: try to delete temporary files only if they have been allocated for this request?
-    use <- exception.defer(fn() {
-      let assert Ok(_) = wisp.delete_temporary_files(request)
-    })

    let response =
      request
      |> handler
      |> mist_response

    response
  }
}

Current wisp version:

Running 1s test @ http://127.0.0.1:8000
  6 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.95ms  404.93us   5.37ms   72.56%
    Req/Sec     4.05k   295.12     4.69k    73.33%
  24198 requests in 1.00s, 2.61MB read
Requests/sec:  24165.91
Transfer/sec:      2.60MB

With following path:

wrk -c 100 -d 1 -t 6 http://127.0.0.1:8000
Running 1s test @ http://127.0.0.1:8000
  6 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   274.09us  507.14us   9.34ms   93.26%
    Req/Sec    83.83k    15.16k  105.48k    63.08%
  541738 requests in 1.10s, 58.38MB read
Requests/sec: 492452.83
Transfer/sec:     53.07MB

I think it would be better to do it lazily (only when needed) since looking up temp directory (directories.tmp_dir()) to check if file exists to never use that in handler is too expensive. I would be happy to PR laziness, but I don't know really how to make that yet, I'm a new gleamer...

makindotcc avatar Oct 06 '24 03:10 makindotcc

Was the the finding of the temp directory or the generation of the slug that was source of the problem?

What does your handler do your benchmark?

What was the time cost per request?

lpil avatar Oct 07 '24 08:10 lpil

Was the the finding of the temp directory or the generation of the slug that was source of the problem?

directories.tmp_dir() is source of the problem, because it asks OS for file information to make sure given temp path is a directory. The same applies to wisp.delete_temporary_files, which always makes an expensive syscall.

What does your handler do your benchmark?

    wisp_mist.handler(
      fn(_req) {
        wisp.response(200)
        |> wisp.set_body(wisp.Text(string_builder.from_string("Hello, world")))
      },
      "secret",
    )
    |> mist.new
    |> mist.port(8000)
    |> mist.start_http

What was the time cost per request?

current version

user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000643s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000671s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000611s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000744s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000763s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000622s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000675s

without temp directories:

user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000509s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000448s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000465s
user@desktop:~$ curl -o /dev/null -s -w 'Total: %{time_total}s\n' http://localhost:8000
Total: 0.000396s

It's more impactful on high load.

Is there recommended way to profile gleam program?

makindotcc avatar Oct 07 '24 10:10 makindotcc

So it is about a cost of ~0.2ms per request?

If that's the case it may be that this would not be measurable with a real application that doesn't return immediately with a fixed value in the handler. In this benchmark it's only work being performed, so removing it has a large proportional impact on the results.

Moving the tmp directory discovery to the application initialiser rather than per request sounds sensible.

lpil avatar Oct 07 '24 10:10 lpil

So it is about a cost of ~0.2ms per request?

For single request, it looks like. Latency increases a lot under high pressure (as results from wrk results from original post shows). I'm running this bench on a beefy pc (with fast m2 990 pro ssd) so the results may not be that critical in my case. Additional layers between gleam program and OS like virtualization (running on a vps) and containerization (docker) can also impact that.

Moving the tmp directory discovery to the application initialiser rather than per request sounds sensible.

Will it solve unnecessary wisp.delete_temporary_files(request) call?

makindotcc avatar Oct 07 '24 11:10 makindotcc

A useful test would be to write a more realistic application that uses all of Wisp's middleware, decodes and encodes a handful of kb of JSON, and reads and writes to a database or some files. That would give a better understanding of the impact. The current data suggests it is not a good area to try and optimise.

Moving the tmp directory detection to the initialiser would not remove the need for cleanup, no.

lpil avatar Oct 07 '24 12:10 lpil

Yeah, but 25k requests per second on latest gen cpu with 32 threads is in my "real application" total no go. I understand most real world applications are frontends for database, but unfortunately not in my case. I think using raw mist would be fine for me, but I'm scared that any day it will end up as solution only for cruds. https://github.com/gleam-wisp/wisp/issues/60 is misleading

makindotcc avatar Oct 07 '24 12:10 makindotcc