agrafix / Spock

Another Haskell web framework for rapid development
https://www.spock.li
679 stars 56 forks source link

Memory leak #186

Open soupi opened 1 year ago

soupi commented 1 year ago

I spotted what I believe is a memory leak trying to benchmark a very simple Spock app.

Reproduction steps in this repo.

You may need to use ulimit -n 4096 before running hello-spock, which is another indication that there's a problem.

Spock fairs rather poorly compared to twain and scotty. Here are some numbers:

Library Get (/) Params, query & header Post JSON
Spock 31,321.19 25,015.61 28,924.38
scotty 269,021.44 186,814.18 194,448.40
twain 306,501.25 230,075.55 227,636.17

When trying to figure out why that is I noticed very different behaviours between Spock and twain:

Screenshot from 2023-06-29 00-02-36

Screenshot from 2023-06-29 00-04-32

Here's a -s report of the two ``` > Spock is running on port 3000 149,218,795,624 bytes allocated in the heap 31,465,251,520 bytes copied during GC 505,829,376 bytes maximum residency (198 sample(s)) 67,873,264 bytes maximum slop 1557 MiB total memory in use (61 MiB lost due to fragmentation) Tot time (elapsed) Avg pause Max pause Gen 0 14970 colls, 14970 par 21.356s 6.710s 0.0004s 0.0044s Gen 1 198 colls, 197 par 39.219s 5.222s 0.0264s 0.0956s Parallel GC work balance: 87.24% (serial 0%, perfect 100%) TASKS: 123 (1 bound, 121 peak workers (122 total), using -N12) SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled) INIT time 0.003s ( 0.002s elapsed) MUT time 164.764s ( 23.123s elapsed) GC time 60.574s ( 11.932s elapsed) EXIT time 0.065s ( 0.003s elapsed) Total time 225.407s ( 35.060s elapsed) Alloc rate 905,650,467 bytes per MUT second Productivity 73.1% of total user, 66.0% of total elapsed ------ > Running twain app at http://localhost:3000 (ctrl-c to quit) 101,783,300,920 bytes allocated in the heap 2,880,638,200 bytes copied during GC 19,310,688 bytes maximum residency (23 sample(s)) 872,128 bytes maximum slop 104 MiB total memory in use (0 MiB lost due to fragmentation) Tot time (elapsed) Avg pause Max pause Gen 0 3931 colls, 3931 par 7.664s 2.089s 0.0005s 0.0017s Gen 1 23 colls, 22 par 0.128s 0.037s 0.0016s 0.0030s Parallel GC work balance: 72.41% (serial 0%, perfect 100%) TASKS: 26 (1 bound, 25 peak workers (25 total), using -N12) SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled) INIT time 0.003s ( 0.002s elapsed) MUT time 167.343s ( 32.921s elapsed) GC time 7.792s ( 2.126s elapsed) EXIT time 0.003s ( 0.001s elapsed) Total time 175.141s ( 35.051s elapsed) Alloc rate 608,230,568 bytes per MUT second Productivity 95.5% of total user, 93.9% of total elapsed ```

And a quick look at the hello-spock.prof reveals that Crypto.Random is doing quite a bit of work:

COST CENTRE                           MODULE                            SRC                                                      %time %alloc

supportedBackends                     Crypto.Random.Entropy.Backend     Crypto/Random/Entropy/Backend.hs:(31,1)-(41,5)            40.6   52.0
jberryman commented 1 year ago

@soupi I wasn't able to reproduce a space leak using a modified version of your repro. I used the following, which just depends on Spock-core:

{-# LANGUAGE OverloadedStrings #-}
{-# language ScopedTypeVariables #-}

import Data.Aeson (Value)
import Data.String (fromString)
import Data.Text (Text)
import qualified Web.Spock.Core as Spock

import System.Mem
import Control.Concurrent
import GHC.Stats
import Control.Monad (forever, void)

main :: IO ()
main = do
  void $ forkIO $ forever $ do
      threadDelay $ 30*1000*1000
      performMajorGC
      getRTSStats >>= \stats -> do
          print $ gcdetails_live_bytes $ gc stats
  Spock.runSpock 3000 $
    Spock.spockT id routes

routes :: Spock.SpockCtxT () IO ()
routes = do
  Spock.get "/" $
    Spock.text "hi"

  Spock.get ("/id/" Spock.<//> Spock.var) $ \(id' :: Int) -> do
    (name :: Text) <- Spock.param' "name"
    Spock.setHeader "x-powered-by" "benchmark"
    Spock.text (fromString (show id') <> " " <> name)

  Spock.post "/json" $ do
    (value :: Value) <- Spock.jsonBody'
    Spock.json value

I just tested it using curl, and observing the reported live bytes that get logged every 30 seconds, e.g.:

for _ in {1..1000000}; do   curl -X GET http://localhost:3000/id/3\?name\=bun  &> /dev/null; done

I tested both w ghc 9.2.7 and 9.4.5

So wrt any space leaks, it might be:

Here’s my freeze file for 9.4

Click me ``` active-repositories: hackage.haskell.org:merge constraints: any.Cabal ==3.8.1.0, any.Cabal-syntax ==3.8.1.0, any.HUnit ==1.6.2.0, any.OneTuple ==0.4.1.1, any.QuickCheck ==2.14.3, QuickCheck -old-random +templatehaskell, any.Spock-core ==0.14.0.1, any.StateVar ==1.2.2, any.aeson ==2.1.2.1, aeson -cffi +ordered-keymap, any.ansi-terminal ==1.0, ansi-terminal -example, any.ansi-terminal-types ==0.11.5, any.appar ==0.1.8, any.array ==0.5.4.0, any.asn1-encoding ==0.9.6, any.asn1-parse ==0.9.5, any.asn1-types ==0.3.4, any.assoc ==1.1, assoc +tagged, any.async ==2.2.4, async -bench, any.attoparsec ==0.14.4, attoparsec -developer, any.attoparsec-iso8601 ==1.1.0.0, any.auto-update ==0.1.6, any.base ==4.17.1.0, any.base-compat ==0.13.0, any.base-compat-batteries ==0.13.0, any.base-orphans ==0.9.0, any.base64-bytestring ==1.2.1.0, any.basement ==0.0.16, any.bifunctors ==5.6.1, bifunctors +tagged, any.binary ==0.8.9.1, any.bsb-http-chunked ==0.0.0.4, any.byteorder ==1.0.4, any.bytestring ==0.11.4.0, any.cabal-doctest ==1.0.9, any.call-stack ==0.4.0, any.case-insensitive ==1.2.1.0, any.colour ==2.3.6, any.comonad ==5.0.8, comonad +containers +distributive +indexed-traversable, any.containers ==0.6.7, any.contravariant ==1.5.5, contravariant +semigroups +statevar +tagged, any.cookie ==0.4.6, any.crypton ==0.31, crypton -check_alignment +integer-gmp -old_toolchain_inliner +support_aesni +support_deepseq +support_pclmuldq +support_rdrand -support_sse +use_target_attributes, any.crypton-x509 ==1.7.6, any.data-default-class ==0.1.2.0, any.data-fix ==0.3.2, any.deepseq ==1.4.8.0, any.directory ==1.3.7.1, any.distributive ==0.6.2.1, distributive +semigroups +tagged, any.dlist ==1.0, dlist -werror, any.easy-file ==0.2.5, any.exceptions ==0.10.5, any.fast-logger ==3.2.1, any.filepath ==1.4.2.2, any.foldable1-classes-compat ==0.1, foldable1-classes-compat +tagged, any.generically ==0.1.1, any.ghc-bignum ==1.3, any.ghc-boot-th ==9.4.5, any.ghc-prim ==0.9.0, any.hashable ==1.4.2.0, hashable +integer-gmp -random-initial-seed, any.hourglass ==0.2.12, any.hsc2hs ==0.68.9, hsc2hs -in-ghc-tree, any.http-api-data ==0.5.1, http-api-data -use-text-show, any.http-date ==0.0.11, any.http-types ==0.12.3, any.http2 ==4.1.4, http2 -devel -h2spec, any.hvect ==0.4.0.1, any.indexed-traversable ==0.1.2.1, any.indexed-traversable-instances ==0.1.1.2, any.integer-gmp ==1.1, any.integer-logarithms ==1.0.3.1, integer-logarithms -check-bounds +integer-gmp, any.iproute ==1.7.12, any.memory ==0.18.0, memory +support_bytestring +support_deepseq, any.mmorph ==1.2.0, any.monad-control ==1.0.3.1, any.mtl ==2.2.2, any.network ==3.1.4.0, network -devel, any.network-byte-order ==0.1.6, any.old-locale ==1.0.0.7, any.old-time ==1.1.0.3, any.parsec ==3.1.16.1, any.pem ==0.2.4, any.pretty ==1.1.3.6, any.primitive ==0.8.0.0, any.process ==1.6.16.0, any.psqueues ==0.2.7.3, any.random ==1.2.1.1, any.recv ==0.1.0, any.reroute ==0.7.0.0, any.resourcet ==1.3.0, any.rts ==1.0.2, any.safe-exceptions ==0.1.7.3, any.scientific ==0.3.7.0, scientific -bytestring-builder -integer-simple, any.semialign ==1.3, semialign +semigroupoids, any.semigroupoids ==6.0.0.1, semigroupoids +comonad +containers +contravariant +distributive +tagged +unordered-containers, any.simple-sendfile ==0.2.31, simple-sendfile +allow-bsd -fallback, any.splitmix ==0.1.0.4, splitmix -optimised-mixer, any.stm ==2.5.1.0, any.streaming-commons ==0.2.2.6, streaming-commons -use-bytestring-builder, any.strict ==0.5, any.superbuffer ==0.3.1.2, any.tagged ==0.8.7, tagged +deepseq +transformers, any.template-haskell ==2.19.0.0, any.text ==2.0.2, any.text-short ==0.1.5, text-short -asserts, any.th-abstraction ==0.5.0.0, any.these ==1.2, any.time ==1.12.2, any.time-compat ==1.9.6.1, time-compat -old-locale, any.time-manager ==0.0.0, any.transformers ==0.5.6.2, any.transformers-base ==0.4.6, transformers-base +orphaninstances, any.transformers-compat ==0.7.2, transformers-compat -five +five-three -four +generic-deriving +mtl -three -two, any.unix ==2.7.3, any.unix-compat ==0.7, unix-compat -old-time, any.unix-time ==0.4.9, any.unliftio ==0.2.24.0, any.unliftio-core ==0.2.1.0, any.unordered-containers ==0.2.19.1, unordered-containers -debug, any.uuid-types ==1.0.5, any.vault ==0.3.1.5, vault +useghc, any.vector ==0.13.0.0, vector +boundschecks -internalchecks -unsafechecks -wall, any.vector-stream ==0.1.0.0, any.wai ==3.2.3, any.wai-extra ==3.1.13.0, wai-extra -build-example, any.wai-logger ==2.4.0, any.warp ==3.3.27, warp +allow-sendfilefd -network-bytestring -warp-debug +x509, any.witherable ==0.4.2, any.word8 ==0.1.3, any.zlib ==0.6.3.0, zlib -bundled-c-zlib -non-blocking-ffi -pkg-config index-state: hackage.haskell.org 2023-06-14T18:19:34Z ```
soupi commented 1 year ago

@jberryman oh nice catch. This seems to be a problem with the full Spock version and not Spock-core. I've ran your example (without the forkIO) and indeed it runs quite fast while the full Spock version does not. This is the diff that will make it run fast:

 {-# LANGUAGE OverloadedStrings #-}
 {-# language ScopedTypeVariables #-}

 import Data.Aeson (Value)
 import Data.String (fromString)
 import Data.Text (Text)
-import qualified Web.Spock as Spock
-import qualified Web.Spock.Config as Spock
+import qualified Web.Spock.Core as Spock

 main :: IO ()
 main = do
-  config <- mkConfig
   Spock.runSpock 3000 $
-    Spock.spock config routes
+    Spock.spockT id routes

-mkConfig :: IO (Spock.SpockCfg () () ())
-mkConfig = Spock.defaultSpockCfg () Spock.PCNoDatabase ()

-routes :: Spock.SpockM () () () ()
+routes :: Spock.SpockCtxT () IO ()
 routes = do
   Spock.get "/" $
     Spock.text "hi"

   Spock.get ("/id/" Spock.<//> Spock.var) $ \(id' :: Int) -> do
     (name :: Text) <- Spock.param' "name"
     Spock.setHeader "x-powered-by" "benchmark"
     Spock.text (fromString (show id') <> " " <> name)

   Spock.post "/json" $ do
     (value :: Value) <- Spock.jsonBody'
     Spock.json value

And the profile looks fine as well:

Screenshot from 2023-07-27 22-42-22