I'm looking at porting a simple logger I wrote a while back in Python to a language which would result in less runtime overhead from logging.
As an informal benchmark, I try to log a message, including the current time, 10,000,000 times to a given file, and to record the time.
The original Python version, under CPython 3.6.0 clocks in at about 2m06s on an Intel Core i7-3615QM CPU @ 2.30GHz, with logging to a file as well as STDOUT, but with STDOUT redirected to
/dev/null (constant refreshing of my terminal emulator window with new output causes noticeable overhead).
Run under PyPy 2.7.12, that time is nearly halved to 1m10s.
A trivial C port does the same thing in about half a second with
-O3 and a near-identical algorithm (which IMO is a pretty spectacular improvement, and realistically, not the type of performance I can aim for in most other languages AFAIK)
What I'm concerned about is a Haskell port I've been trying to get to run faster than Python:
module Main where import Control.Monad.Writer import Data.List hiding (repeat) import Data.Time (getCurrentTime) import Data.Time.Format (formatTime) import System.IO hiding (putStrLn) import System.Locale (defaultTimeLocale) data Color = GREEN | BLUE | YELLOW | RED | PURPLE | RESET instance Show Color where show GREEN = "\x1b[32m" show BLUE = "\x1b[34m" show YELLOW = "\x1b[33m" show RED = "\x1b[31m" show PURPLE = "\x1b[35m" show RESET = "\x1b[0m" data MessageLevel = OK | INFO | WARN | FAIL | CRIT instance Show MessageLevel where show OK = " OK " show INFO = " INFO " show WARN = " WARN " show FAIL = " FAIL " show CRIT = " CRIT " splotch :: MessageLevel -> String splotch OK = (show GREEN) ++ " ⬢ " ++ (show RESET) splotch INFO = (show BLUE) ++ " ⬢ " ++ (show RESET) splotch WARN = (show YELLOW) ++ " ⬢ " ++ (show RESET) splotch FAIL = (show RED) ++ " ⬢ " ++ (show RESET) splotch CRIT = (show PURPLE) ++ " ⬢ " ++ (show RESET) buildMessage :: MessageLevel -> String -> IO String buildMessage lvl msg = do now <- getCurrentTime return $ (show now) ++ " || [" ++ (show lvl) ++ "]" ++ (splotch lvl) ++ msg slog :: MessageLevel -> String -> Handle -> IO () slog lvl msg f = (buildMessage lvl msg) >>= (hPutStrLn f) bench1 = do f <- openFile "log.txt" AppendMode replicateM_ 10000000 $ slog OK "Hello, world!" f hClose f main = bench1
Long story, short, this generates output which includes:
- Picosecond-precise time (which isn't a requirement; second-precise is enough);
- The log level;
- A colored icon making it easier to recognize the log level at a glance; and
- The log message.
After implementing some revision suggestions from the comments, this code can match Python's performance, but doesn't surpass it.
My primary concerns with my code are:
That picosecond-precise time is reducing how often memoization is performed
- I've tried using second-resolution time, which would make this a true port of the basic Python functionality, but Haskell's datetime facilities seem fairly contrived to me
That I'm using a non-optimal way of sharing the file
That the benchmarking function itself could be inducing overhead
That I'm missing some places where pure and impure computations can be separated
I'm trying to avoid using the
Writer monad because in the use cases for this logger, the output of computations inducing a logger call wouldn't need to be passed down the pipeline.
What changes can I introduce into this code to improve its performance in the benchmark I described?