Web-frameworks: Unverified 5xx or 4xx errors

[RicardoSette]

Hi @waghanza

See in this example below that there were 1048.14 requests per second, but 15791 responses is wrong.

# wrk -t8 -c64 -d15s --timeout 8s http://192.168.1.4:82/user/123
Running 15s test @ http://192.168.1.4:82/user/123
  8 threads and 64 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    53.39ms   30.83ms 371.49ms   76.14%
    Req/Sec   138.09     57.56   490.00     68.50%
  15791 requests in 15.07s, 4.52MB read
  Non-2xx or 3xx responses: 15791
Requests/sec:   1048.14
Transfer/sec:    307.03KB

See below that the script does not consider errors, so several frameworks may be with wrong scores.

https://github.com/the-benchmarker/web-frameworks/blob/03b28682a08a65ac0b563de70ec6f16b7a64815a/tools/src/client.cr#L84-L90

I came to this conclusion because Ubiquity (2.3) that runs with PHP-FPM had a high score compare other frameworks that run with PHP-SWOOLE. Not that Ubiquity is slow, but we know that the slowness is the PHP-FPM.

When investigating Ubiquity in Docker I noticed that he was not doing anything, as PHP-FPM was showing an error, there should be a configuration in /php/ubiquity/config.yaml referring to #slasheddocroot as it uses a php-fpm prefix different from the default. With that only NGINX was processing and returning error "502 Bad Gateway".

Here is a recommendation for correcting script web-frameworks/tools/src/client.cr and avoid erroneous scores:

 output = stdout.to_s 
 lines = output.split("\n") 
 requests_errors = lines.grep(/Non-2xx/)
 if requests_errors.length > 0 # wrk found errors
     requests_errors = requests_errors.first.split(":").pop.strip.to_f 
 else # wrk found no errors
     requests_errors = 0 
 end
 requests_per_seconds = lines.grep(/Requests/).first.split(":").pop.strip.to_f - (requests_errors/flags.duration)

 # insert(framework_id, "request_duration", result[0]) 
 # insert(framework_id, "request_total", result[1]) 
 insert(framework_id, "request_per_second", requests_per_seconds, concurrency_level_id) 

Lines is correct? :see_no_evil:

Now, if have 4xx or 5xx errors, they will be subtracted from the total number of requests.

@leocavalcante i found the reason why Ubiquity made many requests with PHP-FPM and probably other frameworks have the same false positive :nerd_face:

[waghanza]

you're right that can be non 2xx, even if the return in tested on CI. 👍

I'll take advantage of this and rewrite this tool in ruby

---

I appreciate your contributing efforts @RicardoSette

[waghanza]

@jcheron using wrk with ubiquity, I have

Running 15s test @ http://192.168.99.253:3000
  8 threads and 64 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.43ms    6.02ms 215.29ms   98.41%
    Req/Sec     1.13k    90.54     2.25k    97.18%
  135711 requests in 15.11s, 38.82MB read
  Non-2xx or 3xx responses: 135711
Requests/sec:   8982.92
Transfer/sec:      2.57MB

seems strange no ?

[jcheron]

yes, I'll take a closer look

[waghanza]

found before 😛

public directory does not exists

the bad news is : results are wrong, but I''ll fix and update next week

[jcheron]

Not soo bad,
I prefer poor results to erroneous results,
PHP-FPM is not the champion of the Hello world benchmark

[RicardoSette]

@waghanza I tested this code at https://www.tutorialspoint.com/execute_ruby_online.php and it presented the result successfully to requests_per_seconds.

 output = "Running 15s test @ http://192.168.99.253:3000
  8 threads and 64 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.43ms    6.02ms 215.29ms   98.41%
    Req/Sec     1.13k    90.54     2.25k    97.18%
  135711 requests in 15.11s, 38.82MB read
  Non-2xx or 3xx responses: 135711
Requests/sec:   8982.92
Transfer/sec:      2.57MB"
 lines = output.split("\n") 
 seconds_all_requests = lines.grep(/requests in/).first.match /.*requests in (?<seconds>[0-9\.]*)s\, .*/
 requests_errors = lines.grep(/Non-2xx/)
 if requests_errors.length > 0 # wrk found errors
     requests_errors = requests_errors.first.split(":").pop.strip.to_f 
 else # wrk found no errors
     requests_errors = 0 
 end
 requests_per_seconds = lines.grep(/Requests/).first.split(":").pop.strip.to_f - (requests_errors/seconds_all_requests[:seconds].to_f )
 puts requests_per_seconds;

Note that it is necessary to calculate with the number of real seconds(seconds_all_requests), as it usually has some decimal places beyond 15s.

Just go back line "output = stdout.to_s" and remove the last line referring to the put.

I confess that I am curious to know how many projects were showing 4xx and 5xx errors, I could even have an additional column(requests_errors) to show the number of errors to facilitate and promote visibility to the developers of the reason for the low score.

[leocavalcante]

Nice one @RicardoSette !!

[waghanza]

Working on it @RicardoSette. Having a lua script to output wrk data seems more accurate, it will be compted next week.

---

and to_f could lead to imprecision : 0.1+0.1+0.1 is not strictly equal to 0.3 (I prefer use to_d)

[waghanza]

wrk return number of completed requests, but indeed we need to substract socket errors, timeouts and http errors to compute a req/s based on successful requests

/cc @OvermindDL1

[RicardoSette]

Hi @waghanza

More detailed statistics in WRK can be done with LUA script. I use this LUA script(done_resume.lua) in my projects to detail the results:

done = function(summary, latency, requests)
   io.write("------------------------------------------\n")
   io.write("----------------  SUMMARY  ---------------\n")
   io.write("------------------------------------------\n")
   local msg = 
        "run duration in microseconds: %d \n" ..
        "    total completed requests: %d \n" ..
        "        total bytes received: %d"
   print(msg:format(summary.duration,summary.requests,summary.bytes))
   io.write("------------------------------------------\n")
   io.write("----------------  ERRORS  ----------------\n")
   io.write("------------------------------------------\n")
   local msgErros = 
        "socket connection errors: %d \n" ..
        "      socket read errors: %d \n" ..
                "     socket write errors: %d \n" ..
                " HTTP status codes > 399: %d \n" ..
                "        request timeouts: %d \n" ..
                "            ------------------------\n" ..
                "            TOTAL ERRORS: %d"
   local totalErrors =  
            summary.errors.connect + 
            summary.errors.read + 
            summary.errors.write + 
            summary.errors.status + summary.errors.timeout
   print(msgErros:format(summary.errors.connect, summary.errors.read, 
            summary.errors.write, summary.errors.status,
            summary.errors.timeout, totalErrors))
   io.write("------------------------------------------\n")
   io.write("----------------  RESUME  ----------------\n")
   io.write("------------------------------------------\n")
   local msgResume =
                "             all requests: %d \n" ..
                "               all errors: %d \n" ..
                "           valid requests: %d \n" ..
                "valid requests for second: %.2f "
   local validRequests = summary.requests - totalErrors
   local validRequestsSeconds = validRequests / summary.duration * 1000000
   print(msgResume:format(summary.requests, totalErrors, 
            validRequests, validRequestsSeconds))
   io.write("------------------------------------------\n")
   io.write("by RicardoSette\n")
end

See the result when I momentarily force the service to stop while running the WRK:

# wrk --script done_resume.lua -t1 -c1 -d10s --timeout 1s http://127.0.0.1:9503/api/status
Running 10s test @ http://127.0.0.1:9503/api/status
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.79ms   14.08ms 163.36ms   92.50%
    Req/Sec     2.44k     0.92k    3.80k    85.71%
  5456 requests in 10.11s, 3.35MB read
  Socket errors: connect 1, read 1, write 0, timeout 0
Requests/sec:    539.41
Transfer/sec:    339.04KB
------------------------------------------
----------------  SUMMARY  ---------------
------------------------------------------
run duration in microseconds: 10114763 
    total completed requests: 5456 
        total bytes received: 3511595
------------------------------------------
----------------  ERRORS  ----------------
------------------------------------------
socket connection errors: 1 
      socket read errors: 1 
     socket write errors: 0 
 HTTP status codes > 399: 0 
        request timeouts: 0 
            ------------------------
            TOTAL ERRORS: 3
------------------------------------------
----------------  RESUME  ----------------
------------------------------------------
             all requests: 5456 
               all errors: 3 
           valid requests: 5453 
valid requests for second: 539.11 
------------------------------------------
by RicardoSette

See result to Ubiquity project with failed:

# wrk --script done_resume.lua -t1 -c1 -d10s --timeout 1s http://192.168.1.4:82/user/123
Running 10s test @ http://192.168.1.4:82/user/123
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    30.37ms  101.59ms 764.51ms   94.96%
    Req/Sec   194.93     47.85   313.00     81.11%
  1818 requests in 10.13s, 532.53KB read
  Non-2xx or 3xx responses: 1818
Requests/sec:    179.47
Transfer/sec:     52.57KB
------------------------------------------
----------------  SUMMARY  ---------------
------------------------------------------
run duration in microseconds: 10129992 
    total completed requests: 1818 
        total bytes received: 545310
------------------------------------------
----------------  ERRORS  ----------------
------------------------------------------
socket connection errors: 0 
      socket read errors: 0 
     socket write errors: 0 
 HTTP status codes > 399: 1818 
        request timeouts: 0 
            ------------------------
            TOTAL ERRORS: 1818
------------------------------------------
----------------  RESUME  ----------------
------------------------------------------
             all requests: 1818 
               all errors: 1818 
           valid requests: 0 
valid requests for second: 0.00 
------------------------------------------
by RicardoSette

See result to Ubiquity project corrected:

# wrk --script done_resume.lua -t1 -c1 -d10s --timeout 1s http://192.168.1.4:82/user/123
Running 10s test @ http://192.168.1.4:82/user/123
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    11.35ms   11.50ms  60.21ms   82.52%
    Req/Sec   126.16     23.49   171.00     63.54%
  1246 requests in 10.03s, 244.52KB read
Requests/sec:    124.20
Transfer/sec:     24.37KB
------------------------------------------
----------------  SUMMARY  ---------------
------------------------------------------
run duration in microseconds: 10032482 
    total completed requests: 1246 
        total bytes received: 250386
------------------------------------------
----------------  ERRORS  ----------------
------------------------------------------
socket connection errors: 0 
      socket read errors: 0 
     socket write errors: 0 
 HTTP status codes > 399: 0 
        request timeouts: 0 
            ------------------------
            TOTAL ERRORS: 0
------------------------------------------
----------------  RESUME  ----------------
------------------------------------------
             all requests: 1246 
               all errors: 0 
           valid requests: 1246 
valid requests for second: 124.20 
------------------------------------------
by RicardoSette

I believe that line valid requests for second will be sufficient for the statistics presented today in the project.

Remember that I previously recommended presenting an additional column indicating the total number of errors, this will assist those responsible for the framework in investigating the cause of low performance.

[waghanza]

Are you sure about @RicardoSette

local totalErrors =     summary.errors.connect + 
            summary.errors.connect + 
            summary.errors.read + 
            summary.errors.write + 
            summary.errors.status + summary.errors.timeout

I mean a request in socket error (summary.errors.connect) is either a read (summary.errors.read) or a write error (summary.errors.write).

I think totalErrors are socket errors (summary.errors.connect) + http errors (summary.errors.status) + server timeout (summary.errors.timeout)

PS : I prefer presenting (but will be collected) a minimum of information for now (the plan is to have a GraphQL API to explore the data collected and help framework authors)