Consecutive requests are getting slower and slower

[Allsimon]

see reproduction repo

# copy pastable reproduction steps
git clone https://github.com/Allsimon/example-servant-minimal && cd example-servant-minimal
stack build && stack exec example-servant-minimal

# in another shell
./reproduce.sh

This is going to send batches of 1000 requests to a really simple endpoint: requests are taking more and more time.

➜  example-servant-minimal git:(master) ✗ ./reproduce.sh
Time per request:       0.281 [ms] (mean, across all concurrent requests)
Time per request:       0.504 [ms] (mean, across all concurrent requests)
Time per request:       0.886 [ms] (mean, across all concurrent requests)
Time per request:       1.034 [ms] (mean, across all concurrent requests)
Time per request:       1.416 [ms] (mean, across all concurrent requests)
Time per request:       2.144 [ms] (mean, across all concurrent requests)
Time per request:       2.041 [ms] (mean, across all concurrent requests)
Time per request:       2.306 [ms] (mean, across all concurrent requests)
Time per request:       2.663 [ms] (mean, across all concurrent requests)
Time per request:       2.905 [ms] (mean, across all concurrent requests)
Time per request:       3.134 [ms] (mean, across all concurrent requests)

[phadej]

On my machine:

% bash reproduce.sh
Time per request:       0.083 [ms] (mean, across all concurrent requests)
Time per request:       0.083 [ms] (mean, across all concurrent requests)
Time per request:       0.088 [ms] (mean, across all concurrent requests)
Time per request:       0.081 [ms] (mean, across all concurrent requests)
Time per request:       0.082 [ms] (mean, across all concurrent requests)
Time per request:       0.083 [ms] (mean, across all concurrent requests)
Time per request:       0.084 [ms] (mean, across all concurrent requests)
Time per request:       0.089 [ms] (mean, across all concurrent requests)
Time per request:       0.083 [ms] (mean, across all concurrent requests)
Time per request:       0.082 [ms] (mean, across all concurrent requests)

And I didn't even add -threaded or anything.

Dependencies I used (most importantly servant-0.16, and latest warp-3.2.26

adjunctions-4.4
aeson-1.4.2.0
ansi-terminal-0.9
ansi-wl-pprint-0.6.8.2
appar-0.1.7
array-0.5.3.0
async-2.2.1
attoparsec-0.13.2.2
attoparsec-iso8601-1.0.1.0
auto-update-0.1.4.1
base-4.12.0.0
base64-bytestring-1.0.0.2
base-compat-0.10.5
basement-0.0.10
base-orphans-0.8.1
bifunctors-5.5.3
binary-0.8.6.0
blaze-builder-0.4.1.0
blaze-html-0.9.1.1
blaze-markup-0.8.2.2
bsb-http-chunked-0.0.0.4
byteorder-1.0.4
bytestring-0.10.8.2
Cabal-2.4.0.1
cabal-doctest-1.0.6
call-stack-0.1.0
case-insensitive-1.2.0.11
clock-0.7.2
colour-2.3.4
comonad-5.0.4 lib:comonad setup
containers-0.6.0.1
contravariant-1.5
cookie-0.4.4
cryptonite-0.25
data-default-class-0.1.2.0
deepseq-1.4.4.0
directory-1.3.3.0
distributive-0.6 lib:distributive setup
dlist-0.8.0.6
easy-file-0.2.2
erf-2.0.0.0
example-servant-minimal-0.0.0
example-servant-minimal-0.0.0 exe:example-servant-minimal
example-servant-minimal-0.0.0 test:spec
exceptions-0.10.1
fast-logger-2.4.13
file-embed-0.0.11
filepath-1.4.2.1
free-5.1
ghc-boot-th-8.6.4
ghc-prim-0.5.3
hashable-1.2.7.0
hsc2hs-0.68.4 exe:hsc2hs
hspec-2.7.0
hspec-core-2.7.0
hspec-discover-2.7.0
hspec-discover-2.7.0 exe:hspec-discover
hspec-expectations-0.8.2
http2-1.6.4
http-api-data-0.4 lib:http-api-data setup
http-client-0.6.3
http-date-0.0.8
http-media-0.7.1.3
http-types-0.12.3
HUnit-1.6.0.0
integer-gmp-1.0.2.0
integer-logarithms-1.0.2.2
invariant-0.5.1
iproute-1.7.7
kan-extensions-5.2
memory-0.14.18
mime-types-0.1.0.9
mmorph-1.1.2
monad-control-1.0.2.3
mtl-2.2.2
network-3.0.1.1
network-byte-order-0.0.0.0
network-uri-2.6.1.0
old-locale-1.0.0.7
old-time-1.1.0.3
optparse-applicative-0.14.3.0
parsec-3.1.13.0
pretty-1.1.3.6
primitive-0.6.4.0
process-1.6.5.0
profunctors-5.3
psqueues-0.2.7.1
QuickCheck-2.12.6.1
quickcheck-io-0.2.0
random-1.1
resourcet-1.2.2
rts-1.0
safe-0.3.17
scientific-0.3.6.2
semigroupoids-5.3.2 lib:semigroupoids setup
semigroups-0.18.5
servant-0.16 lib:servant setup
servant-client-0.16
servant-client-core-0.16
servant-server-0.16 lib:servant-server exe:greet setup
setenv-0.1.1.3
simple-sendfile-0.2.28
singleton-bool-0.1.4
StateVar-1.1.1.1
stm-2.5.0.0
streaming-commons-0.2.1.0
string-conversions-0.4.0.1
tagged-0.8.6
template-haskell-2.14.0.0
text-1.2.3.1
tf-random-0.5
th-abstraction-0.2.11.0
time-1.8.0.2
time-locale-compat-0.1.1.5
transformers-0.5.6.2
transformers-base-0.4.5.2
transformers-compat-0.6.4
unix-2.7.2.2
unix-compat-0.5.1
unix-time-0.4.5
unliftio-core-0.1.2.0
unordered-containers-0.2.10.0
utf8-string-1.0.1.1
uuid-types-1.0.3
vault-0.3.1.2
vector-0.12.0.2
void-0.7.2
wai-3.2.2
wai-app-static-3.1.6.3
wai-app-static-3.1.6.3 exe:warp
wai-extra-3.0.25
wai-logger-2.3.4 lib:wai-logger setup
warp-3.2.26
word8-0.1.3
zlib-0.6.2

[Allsimon]

I cannot reproduce this issue on Linux, but a colleague reproduce it on Mac too.

It might me Mac specific :/

[saurabhnanda]

This is going to send batches of 1000 requests to a really simple endpoint: requests are taking more and more time.

I'm trying to reproduce this as well. In the meantime, how much does this grow? Does it constantly keep increasing, or does this "reset" at some point? What about memory usage?

[saurabhnanda]

@Allsimon can you please paste your output for 100 runs, i.e.

for i in {1..100}
do
ab -T 'application/json' -H 'accept: application/json' -n 1000 -c 1  -p test.json http://127.0.0.1:3000/echo 2>&1 | grep "across"
done

[saurabhnanda]

@Allsimon you closed this issue? Did you figure this out?

[saurabhnanda]

Btw, notice the strange timings that I'm getting in a 100 run - https://gist.github.com/saurabhnanda/a381709fc33c44d55827524c2bb70257

[Allsimon]

(Sorry misclicked and closed the issue)

If I keep throwing requests at it, the timing grows from 0.2ms to ~5ms per requests. Then I have a plateau and oscillate between 3 and 5ms.

Whats really weird is that waiting ~20s, "resets" the response time back to 0.2ms (it then regrows)

Server on Mac launched directly (stack run)
Server in Ubuntu via Docker for Mac

[saurabhnanda]

@Allsimon do you want to try replicating this with wrk instead of ab?

Here's what I am trying and getting wildly varying results (probably due to GC pauses) and am unable to replicate your observations:

post.lua

wrk.method = "POST"
wrk.body   = "1"
wrk.headers["Content-Type"] = "application/json"

reproduce.sh

for i in {1..100}
do

## remember to change the path to wrk
~/projects/wrk/wrk -c 1 -d 5 -t 1 -s post.lua http://127.0.0.1:3000/echo | grep -i "requests"

done

[Allsimon]

With wrk

We can't see the """warm up""" phase where the endpoints is getting progressively slower and slower with wrk.