Interleaved log output when messages are larger than buffer size

[snoyberg]

The following reproduces the problem (also available as a Gist):

-- Compiled with:
--
-- stack --resolver lts-6.17 ghc --package async --package fast-logger -- -threaded -rtsopts -with-rtsopts -N large-fast-logger.hs

{-# LANGUAGE OverloadedStrings #-}
import Control.Concurrent.Async (Concurrently (..))
import Control.Monad            (unless, zipWithM_)
import Data.Foldable            (traverse_)
import Data.Monoid              ((<>))
import Data.String              (fromString)
import System.Log.FastLogger    (LoggerSet, newFileLoggerSet, pushLogStr,
                                 rmLoggerSet)

main :: IO ()
main = do
    loggerSet <- newFileLoggerSet 16 "log.txt" -- really small on purpose
    runConcurrently $ traverse_ (Concurrently . run loggerSet) ['A'..'Z']
    rmLoggerSet loggerSet
    output <- readFile "log.txt"
    zipWithM_ checkLine [1..] (lines output)

run :: LoggerSet -> Char -> IO ()
run loggerSet c =
    pushLogStr loggerSet str
  where
    str = fromString (replicate 99 c) <> "\n"

checkLine :: Int -> String -> IO ()
checkLine lineNumber chars = do
    unless (length chars == 99)
        $ putStrLn $ "Does not have 99 characters: " ++ show lineNumber
    case chars of
        [] -> return () -- already mentioned above
        x:xs
            | any (/= x) xs ->
                putStrLn $ "Mismatched characters: " ++ show lineNumber
            | otherwise -> return ()

The issue appears to be that each thread's individual buffer fills up, and then the chunks are sent interleaved to the Handle.

[snoyberg]

Making this (obviously terribly inefficient) replacement seems to fix the problem:

toBufIOWith :: Buffer -> BufSize -> (Buffer -> Int -> IO ()) -> Builder -> IO ()
toBufIOWith buf !size io builder =
    let (PS fptr off siz) = L.toStrict $ toLazyByteString builder
     in withForeignPtr fptr $ \ptr -> io (ptr `plusPtr` off) siz

The proper way to do this would be, when nlen is greater than the buffer size, allocate a new buffer of the right size and pass it in.

However, I think we're still left open for an interleaved output race condition. Specifically, if the write system call doesn't write all bytes, another thread could take a stab at sending some bytes before our buffer is emptied. The three solutions I can think of for this are:

1. Implement some MVar-based blocking whenever writing to the FD, which will likely kill performance
2. Have a dedicated worker thread which writes chunks to the FD
3. Perhaps there's some way we can use atomicModifyIORef' to let multiple threads all put data into a single ref, but I haven't figured out the right mechanisms to make sure that we don't get interleaved I/O. Perhaps some kind of tricks like we use in auto-update could be employed.

[lehins]

I was curious about how solving this issue outside fast-logger with STM and MVar would work, here is some benchmarks: https://rawgit.com/lehins/practice/master/haskell/fast-logger/results.html Code is here: https://github.com/lehins/practice/blob/master/haskell/fast-logger/how-fast-logger.hs It seems that for entries larger than the buffer size and with many threads STM approach does outperform even native (buggy) log writing. Thought it might be useful here.

[kazu-yamamoto]

I would close this issue thanks to #103. Please reopen if necessary.