# [Haskell-cafe] attempt creating alternative logging lib which is actually much slower (?)

Marc Weber marco-oweber at gmx.de
Thu Feb 12 08:47:01 EST 2009

> > without removing all all setLevel calls to subloggers?
> > Is this desirable?
>
> I don't understand the problem.  If you told hslogger that you didn't
> want to hear about stuff about "A", why do you not like that it is

Because taht >>don't want to hear abuot "A"<< could have been set
without my knowledge. When trouble shooting a problem it could be handy
to just get all messages. But when such a use case arrives I can still
patch hslogger.

mlog (attempt to create a minimal alternative)
====

I've tried writing another minimal logging system.
The idea was driven by adding the possibility to add a handler logging
everything not matter what levels are set to different loggers or
handlers.

The design is simple: keep a list of log handlers and a list of filters.
you can add a filter telling that a log message of "A.B" should not be
logged. The actual handler function then looks like this

log shouldbeLogged logmessage loggername prio = ....

So you can still ignore shouldbeLogged easily.
However I couldn't even come close to the speed of hslogger even when
caching the list of handlers which are supposed to log the message.

[some code snippets see end of mail]

without any attached handlers:

hslogger*[1] : 4ms
mlog[2]: 12ms

with one default stderr logger (./test 2> /dev/null)

hslogger*[1] : 109ms
mlog[2]:   150ms

[1]: my modified version of hslogger (git://mawercer.de/hslogger)
[2]: (git://mawercer.de/mlog)

I've tried doing some investigation figuring out why my lib is that much
slower but I failed. I noticed that -O2 had an impact on how often the
list of generated test cases is run. But that has been all. I don't even
use existential types!

So I'll shut up and keep using hslogger. Thanks to you John Goerzen

I've learned that I'm very bad at troubleshooting performance.
I really thought I could make mlog faster than hslogger*.
Using profiling (-P) didn't reveal the source wasting CPU cycles to me.

Sincerly
Marc Weber

[ some code snippets of mlog]

the global logger data looks like this:

data GlobalLoggerData = GlobalLoggerData {

handlers :: M.Map Int LogHandler
-- assign a key so that this logger can be removed easily again

,filters :: M.Map Int GlobalFilter -- allow to add global filters

-- cache information about which logger accepts what logging data
-- String = Priority : loggername
, cached :: M.Map String (Bool, [ LogMessageAction ])

}

{-# NOINLINE globalLoggerData #-}
globalLoggerData :: MVar GlobalLoggerData
globalLoggerData = unsafePerformIO $newMVar$ GlobalLoggerData M.empty M.empty M.empty

accept = \ln p -> True -- which logging events does this log handler accept?
,logAction = \ln p msg doLog -> hPutStrLn stderr msg
,close = return ()
}