Add async logger by default

[JoshCap20]

Sync logger decreased performance dramatically.

Running stress test with no logger:

joshcaponigro@Joshs-MBP benchmark % wrk -t12 -c400 -d30s http://127.0.0.1:8001/json
Running 30s test @ http://127.0.0.1:8001/json
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     8.00ms  706.71us  30.54ms   97.72%
    Req/Sec     4.14k   202.35     6.88k    95.03%
  1485845 requests in 30.04s, 136.03MB read
  Socket errors: connect 0, read 534, write 0, timeout 0
Requests/sec:  49464.57
Transfer/sec:      4.53MB

Running same test with logger:

joshcaponigro@Joshs-MBP benchmark % wrk -t12 -c400 -d30s http://127.0.0.1:8001/json
Running 30s test @ http://127.0.0.1:8001/json
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    22.79ms    9.12ms 114.26ms   91.00%
    Req/Sec     1.49k   350.93     2.14k    82.06%
  534960 requests in 30.05s, 48.98MB read
  Socket errors: connect 0, read 551, write 0, timeout 0
Requests/sec:  17801.11
Transfer/sec:      1.63MB

[MihirKohli]

Should I replace the default logger with an async/await logger?

[JoshCap20]

Should I replace the default logger with an async/await logger?

Yes, I think the performance speedup compared to logging vs sync makes it worth it to be the default.

[JoshCap20]

Write some tests for it too and I'll take care of end-to-end testing and load testing it

[MihirKohli]

can you please provide a little guidance on getting started with understanding the codebase?

[JoshCap20]

@MihirKohli, sure:

From a high level, the AreionServer is made up of a bunch of separate components that it manages to provide fuctionality. Some of these components are defined by an interface in areion/base/ and can be easily extended or completely changed but still work with the AreionServer if they implement the interface methods. The default implementations of these are in areion/default/: the engine (provides a HTML template renderer), the logger (provides logging capabilities), the orchestrator ('orchestrates' tasks in the background and can also schedule tasks), and the router (provides routes and their handlers). These defaults provide a quick start (e.g. the DefaultRouter() which uses a trie based routing system with dynamic paths). They are exported in the root __init__.py file prefixed with Default (I'll prob just rename them to avoid future confusion). The other components (server, response, request) are the core of the HTTP protocol and this whole framework so they are managed under the hood. The response object is injected into all route handlers and includes methods to access the other components and includes all the parsed headers, body, params, etc. It can be transformed via middleware as described in the README before it is passed to a route handler. Reversely, I'll add in a new component called an Interceptor that will act on a response after a route handler but before it is sent. So there's control over the response coming in and the request going out. You can also just create and modify the Response object and return it directly, but some types are automatically handled (dict conversion to json, using the request.render() calls the html parser engine and returns html), etc.

areion/source/ provides the core elements of the HTTP server. server.py provides a classHttpServer that handles incoming requests, parses them into a HttpRequest object, and eventually sends a HttpResponse object.

areion/base/ provides Java-like interfaces that extensible or swappable components should implement.

areion/default/ provides the default implementation of useful server components.

The whole point is you can use as many or as little components as you want for your server based on your needs. Lots of examples of these usages and references of the objects are available in the root README.md.

You'll want to look at areion/default/logger.py and replace these synchronous logging methods with asynchronous ones. While currently the defaultlogger is just a wrapper around the logging package, you'll want to look into how to asynchronously log in Python and then add that implementation here.

[MihirKohli]

Using default logger

❯ wrk -t12 -c400 -d30s http://127.0.0.1:8001/json

Running 30s test @ http://127.0.0.1:8001/json 12 threads and 400 connections Thread Stats Avg Stdev Max +/- Stdev Latency 136.09ms 70.18ms 2.00s 97.48% Req/Sec 148.85 77.16 350.00 63.29% 45290 requests in 30.10s, 8.08MB read Socket errors: connect 155, read 265, write 7, timeout 195 Requests/sec: 1504.79 Transfer/sec: 274.80KB

Using aiologger

❯ wrk -t12 -c400 -d30s http://127.0.0.1:8001/json

Running 30s test @ http://127.0.0.1:8001/json 12 threads and 400 connections Thread Stats Avg Stdev Max +/- Stdev Latency 98.34ms 72.15ms 1.98s 98.73% Req/Sec 184.24 89.27 656.00 70.23% 62167 requests in 30.10s, 11.09MB read Socket errors: connect 155, read 210, write 3, timeout 177 Requests/sec: 2065.41 Transfer/sec: 377.18KB

[JoshCap20]

@MihirKohli can you include the new logger implementation used and the application tested with? Confused by the amount of socket errors and slight improvement using async logger.

[MihirKohli]

Currently i am testing default logger with following code, trying to better understand working of it. Please correct me if something is wrong with this implementation.

`from areion import DefaultRouter, HttpResponse, DefaultLogger, AreionServerBuilder

logger = DefaultLogger() router = DefaultRouter()

@router.route("/log", methods=["GET"]) async def some_handler(request): logger.info("Processing request")

Create an HTTP response

return HttpResponse(body="Response", status_code=200, headers={"Content-Type": "text/plain"})

server = AreionServerBuilder().with_router(router).with_logger(logger).build() server.run() `

Test results for above

`❯ wrk -t12 -c400 -d30s http://127.0.0.1:8080/log

Running 30s test @ http://127.0.0.1:8080/log 12 threads and 400 connections Thread Stats Avg Stdev Max +/- Stdev Latency 61.69ms 73.45ms 1.96s 98.25% Req/Sec 292.65 164.22 0.93k 67.86% 98928 requests in 30.10s, 8.30MB read Socket errors: connect 155, read 266, write 0, timeout 173 Requests/sec: 3286.69 Transfer/sec: 282.45KB`

[JoshCap20]

Ok interesting, 100k total requests in 30 seconds is acceptable (still beats FastAPI by a fuck ton lol).

That is exactly how the framework is used! I think it's interesting you stressed test with an async route because I hadn't tried that yet. It seems the read errors are greatly reduced but there is now connect and timeout errors, but still these errors are such a tiny fraction of the total requests.

I think using the sync logger with an async function is what causes the performance to still be extremely good, good to know. Am very interested in this async logger with an async function now

@MihirKohli

[JoshCap20]

So basically this task is just replacing DefaultLogger() with the same methods but an async implementation if that makes it more clear

[MihirKohli]

thank you currently there are two ways to implement async logger using asyncio converting default to async or using aiologger. Will test them both and post comparison here based on which you can decide which one to move forward with.

[JoshCap20]

Awesome man, glad you like the project.

[MihirKohli]

https://github.com/JoshCap20/areion/pull/111

[MihirKohli]

Awesome man, glad you like the project.

This is an interesting project actually.