search

the-benchmarker / web-frameworks

Which is the fastest web framework?
MIT License
6.9k stars 642 forks source link

[D] Serverino debug/test #7409

Closed cyrusmsk closed 5 days ago

cyrusmsk commented 1 week ago

Can you try to run this code for full test please?

cyrusmsk commented 1 week ago

@waghanza it seems some error in running script..

waghanza commented 1 week ago

@cyrusmsk 

object.Exception@/root/.dub/packages/serverino/0.7.2/serverino/source/serverino/config.d(231): Configuration error. Must be minWorkers <= maxWorkers
cyrusmsk commented 1 week ago

Oh it seems it was this error. Now probably it should work

waghanza commented 1 week ago

Unfortunately no @cyrusmsk . Could you enqble logging / debug mode ?

@trikko server hang I mean I built the container, and run ito in. on an other terminal with curl http://172.17.0.2:3000 -v, I have


*   Trying 172.17.0.2:3000...
* Connected to 172.17.0.2 (172.17.0.2) port 3000 (#0)
> GET / HTTP/1.1
> Host: 172.17.0.2:3000
> User-Agent: curl/8.0.1
> Accept: */*
>
* Recv failure: Connexion ré-initialisée par le correspondant
* Closing connection 0
curl: (56) Recv failure: Connexion ré-initialisée par le correspondant
cyrusmsk commented 1 week ago

In my local test I received this: curl http://localhost:3000 -v

trikko commented 1 week ago

Is 172.17.0.2 the right ip of docker?

trikko commented 1 week ago

@waghanza if you start docker with -p 3000:3000 and then you execute curl -v localhost:3000, what happens?

trikko commented 1 week ago

What is serverino log saying? That could help a lot!

waghanza commented 1 week ago

where are logs produced by serverino ?

trikko commented 1 week ago

On stderr, of course. Redirect with ./your_serverino_exe 2>log.txt

waghanza commented 1 week ago

when using curl http://172.17.0.2:3000 -v

I have

*   Trying 172.17.0.2:3000...
* Connected to 172.17.0.2 (172.17.0.2) port 3000 (#0)
> GET / HTTP/1.1
> Host: 172.17.0.2:3000
> User-Agent: curl/8.0.1
> Accept: */*
>

on server side, I have


nobody@493a850a94bd:/opt/web$ ./server
* [000008] [i] 2024-04-22 21:37 [daemon.d:0259] Daemon started.
* [000008] [i] 2024-04-22 21:37 [daemon.d:0283] Listening on http://0.0.0.0:3000/
  [000010] [l] 2024-04-22 21:38 [worker.d:0123] Worker started. (user=nobody group=nogroup)

I tried with -p @trikko

trikko commented 1 week ago

Is that the complete log? It seems there's only one worker running.

If you use -p, try localhost:3000 (or the ip of the machine where it is running)

waghanza commented 1 week ago

It is what I do. Using docker inspect for that

trikko commented 1 week ago

-p 3000:3000 map the docker port 3000 on the server port 3000. So if you're running docker on your pc you can try curl localhost:3000 rather than curl 172.x.x.x:3000.

waghanza commented 1 week ago

Same @trikko

waghanza commented 1 week ago

Workers starts after a long time on server side.

Maybe we can activate some verbose level

trikko commented 1 week ago

Workers starts after a long time on server side.

What?! Is it the log lagging or the timestamps confirm that they start slowly? They should start in a fraction of second!

trikko commented 1 week ago

This is serverino running on a raspberry pi (not a really powerful machine). Check the startup times!

Video del 22-04-2024 22:32:15.webm

trikko commented 1 week ago

@waghanza where are you running the whole thing? On your computer? On a server? (aws? digitalocean? which kind of instance)

waghanza commented 1 week ago

On a local machine (fedora Linux) with docker, will investigate on that

waghanza commented 1 week ago

I see @trikko . I have compiled on the docker container, copied it to my local machine and execute the binary, and the results are

[waghanza@localhost:~] $ wrk -H 'Connection: keep-alive' --connections 64 --threads 8 --duration 15 --timeout 1 --script /home/waghanza/workspace/benchmark/web/pipeline_post.lua http://127.0.0.1:3000/user
Running 15s test @ http://127.0.0.1:3000/user
  8 threads and 64 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.70ms   31.07ms 904.99ms   98.20%
    Req/Sec     8.61k     4.18k   18.13k    75.88%
  461928 requests in 15.10s, 44.49MB read
  Socket errors: connect 0, read 10, write 0, timeout 12
Requests/sec:  30591.29
Transfer/sec:      2.95MB
waghanza commented 1 week ago

but I have a lot of errors

[waghanza@localhost:~/workspace … eb/d/serverino] serverino_test+* 12m48s ± /tmp/server 
* [018379] [i] 2024-04-23 21:36 [daemon.d:0259] Daemon started.
* [018379] [i] 2024-04-23 21:36 [daemon.d:0283] Listening on http://0.0.0.0:3000/
  [018381] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018384] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018387] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018390] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018393] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018396] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018399] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
  [018402] [l] 2024-04-23 21:36 [worker.d:0123] Worker started. (user=waghanza group=waghanza)
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
* [018379] [l] 2024-04-23 21:36 [communicator.d:0375] Socket error on read. Connection reset by peer
trikko commented 1 week ago

Slow computer! rpi get 15k req/s :)

How many times did you run the test?

Typically those are not errors, but warnings. In fact wrk does not bother to close the connection at the end of the timeout but turns off the program suddenly and serverino detects an interrupted communication. So normally at the end of each test with wrk you will find a message like this for each worker.

If you try other programs (for example: bombardier) that smoothly and correctly close the connection when they are finished, you will not see any errors.

waghanza commented 1 week ago

8 core (AMD FX-8320E Eight-Core Processor) qnd 16G of RAM

and quit the same with bombardier

Bombarding http://127.0.0.1:3000 for 10s using 125 connection(s)
[========================================================================================================================================================================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec     30196.52    1558.81   33198.69
  Latency        4.13ms    83.49ms      4.00s
  HTTP codes:
    1xx - 0, 2xx - 301968, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:     4.70MB/s
trikko commented 1 week ago

Nice, no errors with bombardier, right? It seems too slow, anyway.

I tested the version 0.7.2 on rpi4, right now:

Running 10s test @ http://localhost:8080
  8 threads and 64 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     9.82ms   75.85ms   1.64s    97.93%
    Req/Sec     5.05k     4.66k   20.77k    58.20%
  224159 requests in 10.10s, 21.59MB read
  Socket errors: connect 0, read 5, write 0, timeout 28
Requests/sec:  22197.15
Transfer/sec:      2.14MB

On my laptop (i7-12700H) I get 140-150k with both bombardier and wrk (without scripts).

trikko commented 1 week ago

I'm not joking!

pibench.webm

waghanza commented 1 week ago

weird on the same workstation, some nim frameworks are aroun 200K rps ;-)

but anyway, still not understand the docker layer troubles, because the problem here is not about performances, is about running or not, and why CI is OK ;-)

trikko commented 1 week ago

There's a good chance all this things are related in some way, isn't it?

cyrusmsk commented 1 week ago

weird on the same workstation, some nim frameworks are aroun 200K rps ;-)

some frameworks are cheating :)

waghanza commented 1 week ago

Yes, I'm sure this is located to my machine, on github action the container is up and running, https://github.com/the-benchmarker/web-frameworks/actions/runs/8790164134/job/24121594878?pr=7409#step:7:2091

I plan to run all thos benchmark on a brand new workstation, this server is old

trikko commented 1 week ago

weird on the same workstation, some nim frameworks are aroun 200K rps ;-)

Yeah I know, but at least some of them I've tried are not real server. They are made just for win benchmarks, they don't even parse headers or request correctly. Not the point anyway.

cyrusmsk commented 1 week ago

don't even parse headers or request correctly.

Btw maybe worth to add such tests and requests into benchmark. To make it more "real testing", rather than absolutely synthetic and our of the real business cases.

Not the point anyway.

Agree.

But I don't understand why Docker could be the problem..

trikko commented 1 week ago

A simple test you can try is uploading a file with curl, it's not handled correctly by many server including httpbeast, the fastest one.

Uploading a big file (150MB!) on serverino:

andrea ~ > time curl -X POST -H "content-type: octet/stream" --data-binary @sdserverino.mp4  http://localhost:8080 -v
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> POST / HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.81.0
> Accept: */*
> content-type: octet/stream
> Content-Length: 157915974
> Expect: 100-continue
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 100 continue
* We are completely uploaded and fine
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< connection: keep-alive
< content-length: 0
< content-type: text/html;charset=utf-8
< 
* Connection #0 to host localhost left intact

real    0m0,178s
user    0m0,020s
sys    0m0,090s

Same request, on httpbeast:


andrea ~ > time curl -X POST -H "content-type: octet/stream" --data-binary @sdserverino.mp4  http://localhost:8080 -v
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> POST / HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.81.0
> Accept: */*
> content-type: octet/stream
> Content-Length: 157915974
> Expect: 100-continue
> 
* Done waiting for 100-continue
* We are completely uploaded and fine
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Content-Length: 10
< Server: HttpBeast
< Date: Tue, 23 Apr 2024 20:39:43 GMT
< 
* Connection #0 to host localhost left intact
HELLO POST
real    0m11,152s
user    0m0,054s
sys    0m0,116s```
trikko commented 1 week ago

don't even parse headers or request correctly.

Btw maybe worth to add such tests and requests into benchmark. To make it more "real testing", rather than absolutely synthetic and our of the real business cases.

Not the point anyway.

Agree.

But I don't understand why Docker could be the problem..

Please notice that we use regulary serverino with docker in production without any performance issue!

waghanza commented 1 week ago

So there is 3 concerns here :

  1. Why serverino hang on the setup here ?
  2. Are all servers implementation correct in here (parsing headers things) ?
  3. Add tests for point number 2
trikko commented 1 week ago

I have a lot of tests if you need them :)

waghanza commented 1 week ago

Be my guest @trikko. Maybe you could start a discussion on that.

Having more tests could reduce heterogeneity of implementations here

trikko commented 1 week ago

Workers starts after a long time on server side.

Maybe we can activate some verbose level

Could you please make a test? If they are slow to start on docker, try launch docker with an extra param --ulimit nofile=4096

Do you see any speedup?

waghanza commented 1 week ago

Workers starts instantely but still not reacheable

PS : Not understood, since the default of open files is 1073741816

trikko commented 1 week ago

Workers starts instantely but still not reacheable

PS : Not understood, since the default of open files is 1073741816

It's a bad default value. It's way too high, It degrades CPU performances. Now I set it to 4096 on Serverino startup if it's too high, if not set by user.

About reachability: from last release I set a custom name for processes, does it mess your config scripts?

waghanza commented 1 week ago

I can run it now, but server seems to crash at some point

PS : With number of open file to 4096

trikko commented 1 week ago

I can run it now, but server seems to crash at some point

PS : With number of open file to 4096

Pump up that number, it counts every fd

waghanza commented 1 week ago

I have use 10240 for next run

trikko commented 1 week ago

In the meanwhile I've added a workaround to serverino (that set 16384 as value) and send a pull request (already accepted) to dlang to fix the problem that is in the standard library.