Improving Haskell performance for small GET requests

Question

In an effort to become better with Haskell, I'm rewriting a small CLI that I developed originally in Python. The CLI mostly makes GET requests to an API and allows for filtering/formatting the JSON result.

I'm finding my Haskell version to be a lot slower than my Python one.

To help narrow down the problem, I excluded all parts of my Haskell code except the fetching of data - essentially, it's this:

import           Data.Aeson
import qualified Data.ByteString.Char8 as BC
import           Data.List (intercalate)
import           Network.HTTP.Simple

...

-- For testing purposes
getUsers :: [Handle] -> IO ()
getUsers hs = do
    let handles = BC.pack $ intercalate ";" hs

    req <- parseRequest (baseUrl ++ "/user.info")
    let request = setRequestQueryString [("handles", Just handles)] $ req

    response <- httpJSON request

    let (usrs :: Maybe (MyApiResponseType [User])) = getResponseBody response
    print usrs

And I'm using the following dependencies:

dependencies:
  - base >= 4.7 && < 5
  - aeson
  - bytestring
  - http-conduit

To test this, I timed how long it takes for my Haskell program to retrieve data for a particular user (without any particular formatting). I compared it with my Python version (which formats the data), and Curl (which I piped into jq to format the data):

I ran each 5 times and took the average of the 3 middle values, excluding the highest and lowest times:

        Haskell   Python    Curl
real:   1017 ms   568 ms    214 ms
user:   1062 ms   367 ms    26 ms
sys:    210 ms    45 ms     10 ms

Ok, so the Haskell version is definitely slower. Next I tried profiling tools to narrow down the cause of the problem.

I profiled the code using an SCC annotation for the function above:

> stack build --profile
...
> stack exec --profile -- my-cli-exe +RTS -p -sstderr
...

     244,904,040 bytes allocated in the heap
      27,759,640 bytes copied during GC
       5,771,840 bytes maximum residency (6 sample(s))
         245,912 bytes maximum slop
              28 MiB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0       228 colls,   228 par    0.849s   0.212s     0.0009s    0.0185s
  Gen  1         6 colls,     5 par    0.090s   0.023s     0.0038s    0.0078s

  Parallel GC work balance: 30.54% (serial 0%, perfect 100%)

  TASKS: 21 (1 bound, 20 peak workers (20 total), using -N8)

  SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)

  INIT    time    0.004s  (  0.003s elapsed)
  MUT     time    0.881s  (  0.534s elapsed)
  GC      time    0.939s  (  0.235s elapsed)
  RP      time    0.000s  (  0.000s elapsed)
  PROF    time    0.000s  (  0.000s elapsed)
  EXIT    time    0.010s  (  0.001s elapsed)
  Total   time    1.833s  (  0.773s elapsed)

  Alloc rate    277,931,867 bytes per MUT second

  Productivity  48.1% of total user, 69.1% of total elapsed

Seems like a lot of time is being spent in garbage collection.

I looked at the generated .prof file, which gave this:

COST CENTRE                        MODULE                         SRC                                                  %time %alloc

>>=.\.ks'                          Data.ASN1.Get                  Data/ASN1/Get.hs:104:13-61                            10.2    9.8
fromBase64.decode4                 Data.Memory.Encoding.Base64    Data/Memory/Encoding/Base64.hs:(299,9)-(309,37)        9.0   12.3
>>=.\                              Data.ASN1.Parse                Data/ASN1/Parse.hs:(54,9)-(56,43)                      5.4    0.7
fromBase64.loop                    Data.Memory.Encoding.Base64    Data/Memory/Encoding/Base64.hs:(264,9)-(296,45)        4.2    7.4
>>=.\                              Data.ASN1.Get                  Data/ASN1/Get.hs:(104,9)-(105,38)                      4.2    3.5
decodeSignedObject.onContainer     Data.X509.Signed               Data/X509/Signed.hs:(167,9)-(171,30)                   3.6    2.9
runParseState.go                   Data.ASN1.BinaryEncoding.Parse Data/ASN1/BinaryEncoding/Parse.hs:(98,12)-(129,127)    3.0    3.2
getConstructedEndRepr.getEnd       Data.ASN1.Stream               Data/ASN1/Stream.hs:(37,11)-(41,82)                    3.0   12.7
getConstructedEnd                  Data.ASN1.Stream               Data/ASN1/Stream.hs:(23,1)-(28,93)                     3.0    7.8
readCertificates                   Data.X509.CertificateStore     Data/X509/CertificateStore.hs:(92,1)-(96,33)           3.0    2.2
fmap.\.ks'                         Data.ASN1.Get                  Data/ASN1/Get.hs:88:13-52                              1.8    2.2
decodeConstruction                 Data.ASN1.BinaryEncoding       Data/ASN1/BinaryEncoding.hs:(48,1)-(50,66)             1.8    0.0
fmap                               Data.ASN1.Parse                Data/ASN1/Parse.hs:41:5-57                             1.8    1.0
concat.loopCopy                    Data.ByteArray.Methods         Data/ByteArray/Methods.hs:(210,5)-(215,28)             1.2    0.4
fromBase64.rset                    Data.Memory.Encoding.Base64    Data/Memory/Encoding/Base64.hs:(312,9)-(314,53)        1.2    0.0
localTimeParseE.allDigits          Data.Hourglass.Format          Data/Hourglass/Format.hs:358:9-37                      1.2    0.3
getWord8                           Data.ASN1.Get                  Data/ASN1/Get.hs:(200,1)-(204,43)                      1.2    0.0
fmap.\                             Data.ASN1.Get                  Data/ASN1/Get.hs:(88,9)-(89,38)                        1.2    0.6
runParseState.runGetHeader.\       Data.ASN1.BinaryEncoding.Parse Data/ASN1/BinaryEncoding/Parse.hs:131:44-66            1.2    0.0
mplusEither                        Data.ASN1.BinaryEncoding.Parse Data/ASN1/BinaryEncoding/Parse.hs:(67,1)-(70,45)       1.2    4.9
getOID.groupOID                    Data.ASN1.Prim                 Data/ASN1/Prim.hs:299:9-92                             1.2    0.3
getConstructedEndRepr.getEnd.zs    Data.ASN1.Stream               Data/ASN1/Stream.hs:40:48-73                           1.2    0.0
getConstructedEndRepr.getEnd.(...) Data.ASN1.Stream               Data/ASN1/Stream.hs:40:48-73                           1.2    0.4
getConstructedEnd.(...)            Data.ASN1.Stream               Data/ASN1/Stream.hs:28:48-80                           1.2    0.3
decodeEventASN1Repr.loop           Data.ASN1.BinaryEncoding       Data/ASN1/BinaryEncoding.hs:(54,11)-(67,69)            1.2    2.5
put                                Data.ASN1.Parse                Data/ASN1/Parse.hs:(72,1)-(74,24)                      1.2    0.0
fromASN1                           Data.X509.ExtensionRaw         Data/X509/ExtensionRaw.hs:(55,5)-(61,71)               1.2    0.0
compare                            Data.X509.DistinguishedName    Data/X509/DistinguishedName.hs:31:23-25                1.2    0.0
putBinaryVersion                   Network.TLS.Packet             Network/TLS/Packet.hs:(109,1)-(110,41)                 1.2    0.0
parseLBS.onSuccess                 Data.ASN1.BinaryEncoding.Parse Data/ASN1/BinaryEncoding/Parse.hs:(147,11)-(149,64)    0.6    1.7
pemParseLBS                        Data.PEM.Parser                Data/PEM/Parser.hs:(92,1)-(97,41)                      0.6    1.0
runParseState.terminateAugment     Data.ASN1.BinaryEncoding.Parse Data/ASN1/BinaryEncoding/Parse.hs:(87,12)-(93,53)      0.0    1.7
parseOnePEM.getPemContent          Data.PEM.Parser                Data/PEM/Parser.hs:(56,9)-(64,93)                      0.0    1.8

This doesn't seem too bad, and when I scrolled down to functions I had defined and they didn't seem to be taking much time either.

This leads me to believe it's a memory leak problem(?), so I profiled the heap:

stack exec --profile -- my-cli-exe +RTS -h
hp2ps my-cli-exe.hp
open my-cli.exe.ps

So it seems as though lots of space is being allocated on the heap, and then suddenly cleared.

The main issue is, I'm not sure where to go from here. My function is relatively small and is only getting a small JSON response of around 500 bytes. So where could the issue be coming from?

That graph doesn't say much of use. It looks like it only took 1 sample while your program was actually running, which is not enough to get any idea what's going on. Especially since 3.5 megabytes (or 6, whichever) really isn't an interesting amount of heap space. — Carl
From your profiling, at least half the time and half the memory is spent on SSL stuff. I wouldn't be surprised if perusing the ... in your .prof file would bump that number up even higher. I'd look into that code for next optimizations. — Daniel Wagner
@DanielWagner thanks - I've edited my answer to include the remaining rows of the .prof file, if that helps. Could you clarify what you mean by SSL stuff - Data.ASN1? I'm using http-conduit too, so does this suggest most of the "slower" code is from the library? — Farbod Salamat-Zadeh
Yes, all the ASN1, PEM, and X509 stuff are related to TLS (sorry, said SSL but meant TLS). Probably all the rest of the things you included are also in support of the TLS implementation, though I'm slightly less confident of that claim -- say, 30% of the time that I feel this confident, at least one module will not be TLS-related. I don't know whether the library code is slower than its Python/curl counterparts, but if I had any actual stake in finding out what was slow I'd definitely start there. — Daniel Wagner

Farbod Salamat-Zadeh Farbod Salamat-Zadeh · Accepted Answer · 2021-05-02T00:04:23

It seemed odd that the performance of a common Haskell library was so slow for me, but somehow this approach solved my concerns:

I found that the performance of my executable was faster when I used stack install to copy the binaries:

stack install
my-cli-exe

instead of using build and run.

Here are the running times again for comparison:

        HS (stack install)  HS (stack run)   Python    Curl
real:   373 ms              1017 ms          568 ms    214 ms
user:   222 ms              1062 ms          367 ms    26 ms
sys:    141 ms              210 ms           45 ms     10 ms

Improving Haskell performance for small GET requests

1 Answers