Using await in handlers appears to have a substantial performance penalty

[guzba]

Hello, I noticed some unexpected performance behavior when benchmarking HttpBeast and wanted to open an issue here in the hope of finding the cause or seeing if perhaps I'm misunderstanding something.

Here is the very simple HTTP server running on an Ubuntu 22.04 Linux server.

import httpbeast, std/asyncdispatch, std/options

proc onRequest(req: Request): Future[void] {.async.} =
  if req.httpMethod == some(HttpGet):
    case req.path.get()
    of "/":
      await sleepAsync(10)
      req.send(Http200, "abcdefghijklmnopqrstuvwxyz")
    else:
      req.send(Http404)

run(onRequest)

And the benchmarking command is wrk -t10 -c100 -d10s http://localhost:8080

No matter how I build this server, I always end up with a result of around Requests/sec: 99.82

This includes, -d:release,danger --threads:on,off

If I comment out the await sleepAsync(10) which is there to simulate the request taking a little time before responding (like talking to Redis or Posgres or RPC or whatever) the performance goes way way up, Requests/sec: 375,486.11

This is a pretty sizeable performance drop from using await, which is a normal thing to do in an async handler.

This issue appears to affect HttpBest, Jester, and Prologue that I have tested.

It appears what I have noticed may be related to https://github.com/dom96/httpbeast/issues/20 but I've not dug into that very deeply.

One more note:

The following simple AsyncHttpServer:

import std/asyncdispatch, std/asynchttpserver, std/strutils

proc main {.async.} =
  let server = newAsyncHttpServer()

  proc cb(request: Request) {.async.} =
    if request.url.path == "/":
      if request.reqMethod == HttpGet:
        {.gcsafe.}:
          await sleepAsync(10)
          await request.respond(Http200, "abcdefghijklmnopqrstuvwxyz")

  server.listen(Port(8080))

  while true:
    if server.shouldAcceptRequest():
      await server.acceptRequest(cb)
    else:
      await sleepAsync(500)

waitFor main()

Does not have this unexpected performance penalty, getting Requests/sec: 8,040.98

This result has been reproduced on two different Linux servers by two different people.

Compiler:

Nim Compiler Version 1.6.10 [Linux: amd64]
Compiled at 2022-11-21
Copyright (c) 2006-2021 by Andreas Rumpf

git hash: f1519259f85cbdf2d5ff617c6a5534fcd2ff6942
active boot switches: -d:release

[dom96]

I believe the issue here is that sleepAsync uses non-fd-based timers (i.e. ones that are tracked and polled completely by asyncdispatch) so the event loop blocks even though timers are pending. Can you try replacing await sleepAsync(10) with https://nim-lang.org/docs/asyncdispatch.html#addTimer%2Cint%2Cbool%2CCallback and see if that makes a difference?

[guzba]

Yeah of course, here's what I have put together:

import httpbeast, std/asyncdispatch, std/options

proc onRequest(req: Request): Future[void] {.async.} =
  if req.httpMethod == some(HttpGet):
    case req.path.get()
    of "/":
      addTimer(10, true, proc(fd: AsyncFD): bool =
        req.send(Http200, "abcdefghijklmnopqrstuvwxyz")
        return true
      )
    else:
      req.send(Http404)

run(onRequest)

However, when I run it and start making requests to the server I get:

Starting 8 threads
Listening on port 8080
fatal.nim(54)            sysFatal
Error: unhandled exception: httpbeast.nim(427, 12) `requestData.headersFinished` Selector for 47 not ready to send. [AssertionDefect]

I am hopefully not missing something obvious. Let me know if I've misunderstood the suggestion.

Your idea that perhaps sleepAsync is the cause is worth investigating. I'm going to try setting up a dummy AsyncHttpServer server that takes 10ms to respond and await on requests to that. Just to use a different simulated delay and see what happens.

[guzba]

As another experiment I just tried using the simple AsyncHttpServer I posted source for above running on port 8081 as an alternative for sleepAsync:

import httpbeast, std/asyncdispatch, std/options, std/httpclient

proc onRequest(req: Request): Future[void] {.async.} =
  if req.httpMethod == some(HttpGet):
    case req.path.get()
    of "/":
      let client = newAsyncHttpClient()
      discard await client.get("http://localhost:8081/")
      req.send(Http200, "abcdefghijklmnopqrstuvwxyz")
    else:
      req.send(Http404)

run(onRequest)

Then started running the wrk command, however after a bit it stops due to:

Starting 8 threads
Listening on port 8080
asyncfutures.nim(389)    read
asyncfutures.nim(389)    read
asyncfutures.nim(389)    read
asyncfutures.nim(389)    read
asyncfutures.nim(389)    read
asyncfutures.nim(389)    read
httpbeast.nim(150)       onRequestFutureComplete
Error: unhandled exception: Cannot assign requested address [OSError]

If I turn --threads:off, this error does not occur and the performance is much better than the stuck-at-100 I was seeing so I do think your sleepAsync thought is a good one. I still haven't gotten await + threads + HttpBeast working though.

[dom96]

Try something like this (untested):

import httpbeast, std/asyncdispatch, std/options

proc fdSleep(): Future[void] =
  var res = newFuture[void]()
  addTimer(10, true, proc (fd: AsyncFD): bool = res.complete(); return true)
  return res

proc onRequest(req: Request): Future[void] {.async.} =
  if req.httpMethod == some(HttpGet):
    case req.path.get()
    of "/":
      await fdSleep()
      req.send(Http200, "abcdefghijklmnopqrstuvwxyz")
    else:
      req.send(Http404)

run(onRequest)

[guzba]

Ah got it, thanks! That works perfect and fully fixes the unexpected performance drop.

While the sleepAsync issue remains a thing, to me that is not on the same level at all as what this appeared to be before knowing that.

It seems the sleepAsync issue may be in Nim's async code not in HttpBeast? If that is the case this issue can be closed I would say and a new one for that could be opened, which is much less of an issue than this appeared to be.

[dom96]

Cool. Glad to hear it works and that my guess was correct :) What does the performance look like now?

The sleepAsync thing is still a HttpBeast issue. It's a bit bleh this timing code: the async dispatcher goes through all timers and finds the nearest one, then changes the poll timeout to match when the next nearest timer finishes. HttpBeast needs to do the same (and it might actually not be possible without a patch to Nim's async to expose these timers, dunno, maybe it's already public). Alternatively Nim's async could use fd-based timers for all sleepAsync calls but the you risk running out of fds if you have too many sleeps :D

[guzba]

When using await sleepFd() I'm seeing Requests/sec: 9,862.00 on my server, which is excellent given the theoretical max of 10,000 (100 connections, 10 ms response time, for 10 seconds).

As for sleepAsync, yeah I can see the trade-offs. I'd say its not a burning issue given production code probably doesn't make much use of it, I just didn't realize it was a trap for benchmarking is all.