large performance hit from (i think?) using yesod-websocket

[geoff]

This is my first foray into profiling a haskell app, so I apologize for my clumsiness.

I mentioned the other day I was playing with yesod-websocket, and my method was taking some existing Handler functions and adding websocket "commands" that map to those requests, and updating the Angular app talking to Haskell backend to use websockets for those specific requests.

I was surprised to see >100% increase in request time for a GET request vs a websocket message.

It's not a perfect comparison since I am passing slightly different json and parsing it differently.

That being said, here is my attempt to succintly describe what is going on:

I have a function

processImage :: SessionId -> String -> Value -> Int -> Handler String

Both my GET /session/#SessionId and equivalent websocket.send() Handlers use this main function

The JSON for the websocket looks 

{process_image: {session_id : "theid", <process_image_fields>}  

while the JSON for the GET request (since the session_id and command are in the URL/Verb) is simply

 {<process_image_fields>}

The requests were *much* slower when being called against the websocket, so I set out to profile to find out why.  

When using fprof-auto  and NOT using websocket, the profile looks something like:

MAIN            MAIN                        59.7   79.8

unstream/resize Data.Text.Fusion            19.6   14.0

jstring_        Data.Aeson.Parser.Internal   7.5    2.1

break           Data.Aeson.Encode            5.8    0.0

main            Main                         3.0    2.4

encode          Data.Aeson.Encode            1.9    0.5

However, when I am using websockets (and also adding some custom SSC's to try and figure out what is going on)

parseFromStreamInternal.go.\ System.IO.Streams.Internal.Attoparsec  34.1   48.0

MAIN                         MAIN                                   24.1   15.4

unstream/resize              Data.Text.Fusion                       16.1    9.3

parse_vmxcommand             Handler.WebSocket                       8.8   22.1

jstring_                     Data.Aeson.Parser.Internal              6.0    1.1

main                         Main                                    3.1    2.5

break                        Data.Aeson.Encode                       2.7    0.0

encode                       Data.Aeson.Encode                       2.6    0.3

You'll notice that parseFromStreamInternal is absolutely dominating here.

The relevant part of the profile is which is a direct child of MAIN.

 parseFromStreamInternal                     System.IO.Streams.Internal.Attoparsec       1610           1    0.2    0.0    35.2   48.4

  parseFromStreamInternal.go                 System.IO.Streams.Internal.Attoparsec       1757           0    0.0    0.0     0.0    0.0

   _read                                     System.IO.Streams.Internal                  1758          34    0.0    0.0     0.0    0.0

  parseFromStreamInternal.\                  System.IO.Streams.Internal.Attoparsec       1738          35    0.0    0.0    35.0   48.4

   parseFromStreamInternal.go                System.IO.Streams.Internal.Attoparsec       1739         603    0.9    0.4    35.0   48.4

    parseFromStreamInternal.go.\             System.IO.Streams.Internal.Attoparsec       1759         568   34.1   48.0    34.1   48.0

    parseFromStreamInternal.leftover         System.IO.Streams.Internal.Attoparsec       1740          35    0.0    0.0     0.0    0.0

  _read                                      System.IO.Streams.Internal                  1611          35    0.0    0.0     0.0    0.0

 _read        

Relevant code:

-- routes:

/session/#SessionId ProcessImageR POST OPTIONS

/websocket WebSocketR GET

data ProcessImageCommand =  ProcessImageCommand {

    picImage :: String,

    processImageParams   :: Value,

    picTime :: Int

}

instance FromJSON ProcessImageCommand where

    parseJSON (Object o) = do

        ProcessImageCommand <$> (o .: "image") <*> (o .: "params") <*> (o .: "time")

    parseJSON _ = mzero

postProcessImageR :: SessionId -> Handler String

postProcessImageR sid = do

   addHeader "Access-Control-Allow-Origin" "*"

   addHeader "Content-Type" "application/json"

   (pic :: ProcessImageCommand) <- requireJsonBody

   processImage sid (picImage pic) (processImageParams pic) (picTime pic) >>= return

data VMXCommand = CreateSession (Maybe String)

                | GetSessions

                | ProcessImage SessionId String Value Int

instance FromJSON VMXCommand where

  parseJSON j = do

      o <- {-# SCC "parse_vmxcommand" #-} parseJSON  j

      case H.toList (o :: Object) of

          [("new_connection", Object o')]  -> CreateSession <$> o' .: "model_name"

          [("process_image",   Object o')] -> ProcessImage <$> (o' .: "session_id") <*> (o' .: "image") <*> (o' .: "params") <*> (o' .: "time")

          [("list_sessions",   Object o')] -> return GetSessions

          _                      -> fail "Rule: unexpected format"

vmxWebSocket :: WebSocketsT Handler ()

vmxWebSocket = (forever $ do

                (d :: L.ByteString) <-                  {-# SCC "receiveData" #-}      receiveData

                let (wsc :: Either String VMXCommand) = {-# SCC "decode_websocket" #-} eitherDecode d

                case  wsc of

                    Left error' -> sendTextData $ pack error'

                    Right command' ->

                        case command' of

                            CreateSession model_name -> do

                                (out :: String) <- lift $ createSession model_name

                                sendTextData $ object ["new_connection" .= makeJson out]

                            ProcessImage sid image params time -> do

                                liftIO $ print "inside process image"

                                (out :: String) <- lift $ processImage sid image params time

                                liftIO $ print out

                                sendTextData $ pack $"{\"process_image\" : " <> out <> "}"

                )

getWebSocketR :: Handler ()

getWebSocketR =  do

                              webSockets {- # SCC "the_websockets" #-} vmxWebSocket

                              return ()

[Greg Weber]

Thanks for digging into this. How are you getting the requests times?

--
You received this message because you are subscribed to the Google Groups "Yesod Web Framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to yesodweb+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[geoff]

nothing fancy, in the angular code:

start_time = new Date().getTime();

if(vmxwebsockets.useSocket){

          vmxwebsocket.send("process_image", {session_id: this.connection.id, image: cropped_image.dataURL, params:params, time:current_time});

          vmxwebsocket.listen("process_image", function(response)){

              request_time = (new Date().getTime() - start_time)/1000;

              ...update ui..

          }

} else {

 $http.post(_url("process_image", this.connection.id),{image:cropped_image.dataURL, params:params, time:current_time})

           .success(function( respond ) {

      request_time = (new Date().getTime() - start_time)/1000;

      ...update ui..

}

I can compare on more "regular" input and give some structured data if it would be useful.. as well as run a few different Handlers.  I haven't even bench marked the others i've ported already, I just noticed this since process_image is running continuously and updating the UI so it became immediately apparent.

[Michael Snoyman]

Thanks for the very thorough report Geoff, this situation is pretty troubling. I don't have anything to say yet, but I just wanted to let you know that I'm looking at this.

[Michael Snoyman]

OK, just to be certain that the bottleneck really is in websockets or io-streams...

I've just pushed a commit to a new native-ws branch of yesod[1]. This is an incomplete WebSockets implementation, but should be sufficient for basic performance/sanity checking, and provides an almost identical API to the current yesod-websockets.

Geoff: can you try installing yesod-websockets from that branch and letting me know if it addresses your performance issues?

[1] https://github.com/yesodweb/yesod/tree/native-ws

[Greg Weber]

Can you perform the timings on the Haskell side since that is where we are concerned?

[geoff]

Thanks Michael!

Okay, so I did a silly thing and kind of nuked my whole cabal for the build that was not using the native-ws branch of yesod-websockets.

Performance is still worse than GETs, and unfortunately I didn't save the data to show here.. but for my application this branch is ~50% longer per request than just using a GET.. whereas it was ~100% before.

Most strikingly, the 

parseFromStreamInternal.go.\ System.IO.Streams.Internal.Attoparsec  34.1   48.0

Is no longer in the profile dominating clock time.

I'm currently rebuilding with the standard yesod-websockets so I can give real comparisons.

I will do some in-haskell timings as well.. if there is any particular way this would be most helpful I'm open to suggestions.

[Michael Snoyman]

I'm not terribly surprised that this is slower than a simple GET, since:

1. The code I just wrote isn't nearly as optimized as Warp itself.

2. Unless I'm mistaken, you're incurring a double overhead in this test: first establishing the normal connection with Warp, and then upgrading to WebSockets. You should only start to see improved performance once you start sending multiple requests over an existing connection. And on a local system, the latency is so low that you may *never* see that improved performance.

I'm not sure of the best approach to in-Haskell timings, but I *can* tell you that the profiling information you provided previously was extremely helpful.

[geoff]

I'm just getting up and will get together some more info this morning.

However, I /am/ testing multiple requests per connection vs seperate GET requests.  Thanks again for being so attentive and pro-active; hopefully some more insight will be forthcoming.

[geoff]

I just wanted to give some status.  I was not able to get any good/relevant in-haskell timings using the 'getCPUTime' splattered all about; as the reported times were ~10% of the actual request time i was seeing when interacting, and essentially the same between the HTTP and websocket requests.  I was doiing all the timings within the various Handlers though and wasn't sure how to test at the request level.

I still get consistently worse results using a websocket as opposed to multiple HTTP requests; but the difference is significantly reduced.  The profile i get with +RTS -p now consistently shows MAIN as the dominating cost center.

I'm going to leave well-enough alone; but I do have things set up for testing and eagerly await any future updates to yesod-websockets.

Thanks