Efficient logging of string data in Haskell's ST Monad

Question

I have a Haskell program that generates ~280M of logging text data during a run inside the ST monad. This is where virtually all memory consumption goes (with logging disabled the program allocates a grand total of 3MB real memory).

Problem is, I run out of memory. While the program runs memory consumption exceeds 1.5GB, and it finally runs out when it tries to write the log string to a file.

The log function takes a String and accumulates the log data into a string builder stored in an STRef in the environment:

import qualified Data.ByteString.Lazy.Builder as BB
...
myLogFunction s = do
    ...
    lift $ modifySTRef myStringBuilderRef (<> BB.stringUtf8 s)

I tried introducing strictness using bang patterns and modifySTRef', but this made memory consumption even worse.

I write the log string as recommended by the hPutBuilder documentation, like this:

    hSetBinaryMode h True
    hSetBuffering  h $ BlockBuffering Nothing
    BB.hPutBuilder h trace

This consumes several additional GBs of memory. I tried different buffering settings and converting to a lazy ByteString first (slightly better).

Qs:

• How can I minimize memory consumption while the program runs? I'd expect given a tight ByteString representation and the appropriate amount of strictness I'd need little more memory than the ~280M of actual log data I'm storing.

• How can I write the result to a file without allocating memory? I don't understand why Haskell needs GBs of memory to just stream some resident data into a file.

Edit:

Here's the memory profile for a small run (~42MB of log data). The total memory use is 3MB with logging disabled.

    15,632,058,700 bytes allocated in the heap
     4,168,127,708 bytes copied during GC
       343,530,916 bytes maximum residency (42 sample(s))
         7,149,352 bytes maximum slop
               931 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max pause
    Gen  0     29975 colls,     0 par    5.96s    6.15s     0.0002s    0.0104s
    Gen  1        42 colls,     0 par    6.01s    7.16s     0.1705s    1.5604s

    TASKS: 3 (1 bound, 2 peak workers (2 total), using -N1)

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

    INIT    time    0.00s  (  0.00s elapsed)
    MUT     time   32.38s  ( 33.87s elapsed)
    GC      time   11.97s  ( 13.31s elapsed)
    RP      time    0.00s  (  0.00s elapsed)
    PROF    time    0.00s  (  0.00s elapsed)
    EXIT    time    0.00s  (  0.00s elapsed)
    Total   time   44.35s  ( 47.18s elapsed)

    Alloc rate    482,749,347 bytes per MUT second

    Productivity  73.0% of total user, 68.6% of total elapsed

Edit:

I ran a memory profile with a small log run as asked:

profile http://imageshack.us/a/img14/9778/6a5o.png

I tried adding bang patterns, $!, deepseq/$!!, force and such in the relevant places, but it doesn't seem to make any difference. How do I force Haskell to actually take my string / printf expression etc. and put it in a tight ByteString instead of keeping all those [Char] lists and unevaluated thunks around?

Edit:

Here's the actual full trace function

trace s = do
     enable <- asks envTraceEnable
     when (enable) $ do
        envtrace <- asks envTrace
        let b = B8.pack s
        lift $ b `seq` modifySTRef' envtrace (<> BB.byteString b)

Is this 'strict' enough? Do I need to watch out for anything if I call this typeclass function inside my ReaderT/ST monad? Just so that it is actually called and not deferred in any way.

do
    trace $ printf "%i" myint

is fine?

Thanks!

Answer 1

Since the log messages take that much memory, it would be more efficient to write them to file as soon as they are produced. This seems impossible because we are inside the ST monad, and you can't perform IO while in the ST monad.

But there is a way out: use some kind of coroutine monad transformer like those of the "pipes" package. Here is an example using pipes-3.3.0:

{-# LANGUAGE ExplicitForAll #-}
{-# LANGUAGE RankNTypes #-}
{-# LANGUAGE LiberalTypeSynonyms #-}

import Control.Monad
import Control.Monad.ST
import Control.Monad.ST (stToIO) -- Transforms ST computations into IO computations
import Control.Monad.Trans
import Control.Monad.Morph (hoist) -- Changes the base monad of a monad transformer
import Control.Proxy.Prelude (stdoutD) -- Consumer that prints to stdout
import Control.Proxy.Core
import Control.Proxy.Core.Correct

import Data.STRef

simpleST :: ST s Bool
simpleST= do
    ref <- newSTRef True
    writeSTRef ref False
    readSTRef ref

-- Like simpleST, but emits log messages during the computation
loggingST :: Producer ProxyCorrect String (ST s) Bool
loggingST = do
    ref <- lift $ newSTRef True
    respond "Before writing"
    lift $ writeSTRef ref False
    respond "After writing"
    lift $ readSTRef ref

adapt :: (forall s . Producer ProxyCorrect String (ST s) a) ->
         Producer ProxyCorrect String IO a
adapt x = hoist stToIO x

main :: IO ()
main = do
    result <- runProxy $ (\_ -> adapt loggingST) >-> stdoutD
    putStrLn . show $ result

It prints the log to stdout. When run, it outputs the following:

Before writing
After writing
False

It works as follows: you emit the log messages in the producer using respond while still residing in the ST monad. That way you can log and still be sure that your computation doesn't perform some weird IO stuff. It forces you to pepper your code with lifts, though.

Once you have constructed your ST computation, you transform the base monad of the producer from ST to IO using hoist. hoist is a useful function that lets you change the tablecloth while the dishes are still on the table.

Now we are in IO-land! The only thing left to do is to connect the producer with a consumer that actually writes the messages (here they are printed to stdout, but you can just as easily connect to a consumer which writes to file.)