on master help sign in
Merge pull request #48 from adinapoli/increment-handle-scribe-performance

(Breaking change) Faster Handle Scribe

commit79e21e382ccc09666010e8840283b40a0fb453e9 authorMichael Xavier <michael@michaelxavier.net> dateMon 20 Feb 2017, 10:19 (10 years ago) parent5297ae458d3181
11 files changed+68−29
katip/bench/Main.hs+10−5 katip/examples/example.hs+2−2 katip/examples/example_lens.hs+2−1 katip/katip.cabal+2 katip/src/Katip/Scribes/Handle.hs+38−14 katip/test/Katip/Tests/Scribes/Handle.hs+7−6 stack-lts-2.yaml+2 stack-lts-3.yaml+1 stack-lts-4.yaml+1 stack-lts-5.yaml+1 stack.yaml+2−1
katip/bench/Main.hs+10−5
@@ -31,14 +31,14 @@ main = defaultMain [
3131-------------------------------------------------------------------------------
3232handleScribeBench :: Benchmark
3333handleScribeBench = bgroup "Katip.Scribes.Handle" [
34− env setupHandleEnv $ \ ~(Scribe push, tid) ->
34+ env setupHandleEnv $ \ ~((Scribe push, _), tid) ->
3535 bench "Bytestring Builder" $
36− whnfIO $ push $ exItem tid
36+ whnfIO $ (push (exItem tid))
3737 ]
3838
3939
4040-------------------------------------------------------------------------------
41−setupHandleEnv :: IO (Scribe, ThreadIdText)
41+setupHandleEnv :: IO ((Scribe, Finaliser), ThreadIdText)
4242setupHandleEnv = do
4343 scribe <- setup
4444 tid <- myThreadId
@@ -83,15 +83,20 @@ mkUTCTime y mt d h mn s = UTCTime day dt
8383
8484
8585-------------------------------------------------------------------------------
86−setup :: IO Scribe
86+setup :: IO (Scribe, Finaliser)
8787setup = do
8888 h <- openFile "/dev/null" WriteMode
89− mkHandleScribe ColorIfTerminal h DebugS V0
89+ (s, f) <- mkHandleScribe ColorIfTerminal h DebugS V0
90+ return (s, F f)
9091
9192
9293-------------------------------------------------------------------------------
9394deriving instance NFData ThreadIdText
9495
96+newtype Finaliser = F (IO ())
9597
9698instance NFData Scribe where
9799 rnf (Scribe _) = ()
100+
101+instance NFData Finaliser where
102+ rnf (F _) = ()
katip/examples/example.hs+2−2
@@ -34,7 +34,7 @@ main = do
3434 -- messages entirely. Note that katip provides facilities like
3535 -- 'unregisterScribe' and 'registerScribe' to make it possible to
3636 -- hot-swap scribes at runtime if you need to.
37− handleScribe <- mkHandleScribe ColorIfTerminal stdout InfoS V2
37+ (handleScribe, finaliser) <- mkHandleScribe ColorIfTerminal stdout InfoS V2
3838 let le' = registerScribe "stdout" handleScribe le
3939 let s = MyState M.mempty mempty le'
4040 runStack s $ do
@@ -52,7 +52,7 @@ main = do
5252 $(logTM) InfoS "Namespace and context are back to normal"
5353 noLogging $
5454 $(logTM) DebugS "You'll never see this log message!"
55−
55+ finaliser
5656
5757-------------------------------------------------------------------------------
5858newtype ConfrabLogCTX = ConfrabLogCTX Int
katip/examples/example_lens.hs+2−1
@@ -50,7 +50,7 @@ main = do
5050 -- messages entirely. Note that katip provides facilities like
5151 -- 'unregisterScribe' and 'registerScribe' to make it possible to
5252 -- hot-swap scribes at runtime if you need to.
53− handleScribe <- mkHandleScribe ColorIfTerminal stdout InfoS V2
53+ (handleScribe, finaliser) <- mkHandleScribe ColorIfTerminal stdout InfoS V2
5454 let le' = registerScribe "stdout" handleScribe le
5555 let s = MyState M.mempty mempty le'
5656 runStack s $ do
@@ -68,6 +68,7 @@ main = do
6868 $(logTM) InfoS "Namespace and context are back to normal"
6969 noLogging $
7070 $(logTM) DebugS "You'll never see this log message!"
71+ finaliser
7172
7273
7374-------------------------------------------------------------------------------
katip/katip.cabal+2
@@ -55,6 +55,7 @@ library
5555
5656 build-depends: base >=4.5 && <5
5757 , aeson >=0.6 && <1.2
58+ , async < 3.0.0.0
5859 , auto-update >= 0.1 && < 0.2
5960 , bytestring >= 0.9 && < 0.11
6061 , containers >=0.4 && <0.6
@@ -76,6 +77,7 @@ library
7677 , microlens >= 0.2.0.0 && < 0.5
7778 , microlens-th >= 0.1.0.0 && < 0.5
7879 , semigroups
80+ , unagi-chan < 0.5.0.0
7981
8082 hs-source-dirs: src
8183 default-language: Haskell2010
katip/src/Katip/Scribes/Handle.hs+38−14
@@ -3,21 +3,22 @@
33module Katip.Scribes.Handle where
44
55-------------------------------------------------------------------------------
6−import Control.Applicative as A
7−import Control.Concurrent
8−import Control.Exception (bracket_)
6+import Control.Applicative as A
97import Control.Monad
8+import Control.Exception (onException)
109import Data.Aeson
11−import qualified Data.HashMap.Strict as HM
10+import qualified Data.HashMap.Strict as HM
1211import Data.Monoid
13−import Data.Text (Text)
12+import Data.Text (Text)
1413import Data.Text.Lazy.Builder
15−import Data.Text.Lazy.IO as T
14+import Data.Text.Lazy.IO as T
1615import System.IO
17−import System.IO.Unsafe (unsafePerformIO)
16+import System.IO.Unsafe (unsafePerformIO)
17+import qualified Control.Concurrent.Chan.Unagi.Bounded as U
18+import Control.Concurrent.Async
1819-------------------------------------------------------------------------------
1920import Katip.Core
20−import Katip.Format.Time (formatAsLogTime)
21+import Katip.Format.Time (formatAsLogTime)
2122-------------------------------------------------------------------------------
2223
2324
@@ -48,6 +49,10 @@ data ColorStrategy
4849 | ColorIfTerminal
4950 -- ^ Color if output is a terminal
5051
52+-------------------------------------------------------------------------------
53+data WorkerCmd =
54+ NewItem Builder
55+ | PoisonPill
5156
5257-------------------------------------------------------------------------------
5358-- | Logs to a file handle such as stdout, stderr, or a file. Contexts
@@ -57,17 +62,35 @@ data ColorStrategy
5762-- > [2016-05-11 21:01:15][MyApp][Info][myhost.example.com][1724][ThreadId 1154][main:Helpers.Logging Helpers/Logging.hs:32:7] Started
5863-- > [2016-05-11 21:01:15][MyApp.confrabulation][Debug][myhost.example.com][1724][ThreadId 1154][confrab_factor:42.0][main:Helpers.Logging Helpers/Logging.hs:41:9] Confrabulating widgets, with extra namespace and context
5964-- > [2016-05-11 21:01:15][MyApp][Info][myhost.example.com][1724][ThreadId 1154][main:Helpers.Logging Helpers/Logging.hs:43:7] Namespace and context are back to normal
60−mkHandleScribe :: ColorStrategy -> Handle -> Severity -> Verbosity -> IO Scribe
65+--
66+-- Returns the newly-created `Scribe` together with a finaliser the user needs to run to perform resource cleanup.
67+mkHandleScribe :: ColorStrategy -> Handle -> Severity -> Verbosity -> IO (Scribe, IO ())
6168mkHandleScribe cs h sev verb = do
69+ (inChan, outChan) <- U.newChan 4096
70+ worker <- async $ workerLoop outChan
71+ flip onException (stopWorker worker inChan) $ do
6272 hSetBuffering h LineBuffering
6373 colorize <- case cs of
6474 ColorIfTerminal -> hIsTerminalDevice h
6575 ColorLog b -> return b
66− lock <- newMVar ()
67− return $ Scribe $ \ i@Item{..} -> do
68− when (permitItem sev i) $ bracket_ (takeMVar lock) (putMVar lock ()) $
69− T.hPutStrLn h $ toLazyText $ formatItem colorize verb i
76+ let scribe = Scribe $ \i ->
77+ when (permitItem sev i) $ void (U.tryWriteChan inChan (NewItem (formatItem colorize verb i)))
78+ return (scribe, stopWorker worker inChan)
7079
80+ where
81+ stopWorker :: Async () -> U.InChan WorkerCmd -> IO ()
82+ stopWorker worker inChan = do
83+ U.writeChan inChan PoisonPill
84+ void $ waitCatch worker
85+
86+ workerLoop :: U.OutChan WorkerCmd -> IO ()
87+ workerLoop outChan = do
88+ newCmd <- U.readChan outChan
89+ case newCmd of
90+ NewItem b -> do
91+ T.hPutStrLn h $ toLazyText b
92+ workerLoop outChan
93+ PoisonPill -> return ()
7194
7295-------------------------------------------------------------------------------
7396formatItem :: LogItem a => Bool -> Verbosity -> Item a -> Builder
@@ -100,10 +123,11 @@ formatItem withColor verb Item{..} =
100123
101124-------------------------------------------------------------------------------
102125-- | An implicit environment to enable logging directly ouf of the IO monad.
126+-- Be careful as this LogEnv won't perform any resource cleanup for you.
103127_ioLogEnv :: LogEnv
104128_ioLogEnv = unsafePerformIO $ do
105129 le <- initLogEnv "io" "io"
106− lh <- mkHandleScribe ColorIfTerminal stdout DebugS V3
130+ (lh, _) <- mkHandleScribe ColorIfTerminal stdout DebugS V3
107131 return $ registerScribe "stdout" lh le
108132{-# NOINLINE _ioLogEnv #-}
109133
katip/test/Katip/Tests/Scribes/Handle.hs+7−6
@@ -33,8 +33,9 @@ tests :: TestTree
3333tests = testGroup "Katip.Scribes.Handle"
3434 [
3535 withResource setup teardown $ \setupScribe -> testCase "logs the correct data" $ do
36− (path, h, le) <- setupScribe
36+ (path, h, fin, le) <- setupScribe
3737 runKatipT le $ logItem dummyLogItem "test" Nothing InfoS "test message"
38+ fin
3839 hClose h
3940 res <- readFile path
4041 let pat = "\\[[[:digit:]]{4}-[[:digit:]]{2}-[[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\\]\\[katip-test.test\\]\\[Info\\]\\[.+\\]\\[[[:digit:]]+\\]\\[ThreadId [[:digit:]]+\\]\\[note.deep:some note\\] test message" :: String
@@ -73,18 +74,18 @@ dummyLogItem = DummyLogItem "some note"
7374
7475
7576-------------------------------------------------------------------------------
76−setup :: IO (FilePath, Handle, LogEnv)
77+setup :: IO (FilePath, Handle, IO (), LogEnv)
7778setup = do
7879 tempDir <- getTemporaryDirectory
7980 (fp, h) <- openTempFile tempDir "katip.log"
80− s <- mkHandleScribe (ColorLog False) h DebugS V3
81+ (s, finaliser) <- mkHandleScribe (ColorLog False) h DebugS V3
8182 le <- initLogEnv "katip-test" "test"
82− return (fp, h, registerScribe "handle" s le)
83+ return (fp, h, finaliser, registerScribe "handle" s le)
8384
8485
8586-------------------------------------------------------------------------------
86−teardown :: (FilePath, Handle, LogEnv) -> IO ()
87−teardown (_, h, _) = do
87+teardown :: (FilePath, Handle, IO (), LogEnv) -> IO ()
88+teardown (_, h, _, _) = do
8889 chk <- hIsOpen h
8990 when chk $ hClose h
9091
stack-lts-2.yaml+2
@@ -21,6 +21,8 @@ extra-deps:
2121 - memory-0.13
2222 - rng-utils-0.2.1
2323 - lens-aeson-1.0.0.5
24+ - unagi-chan-0.4.0.0
25+ - atomic-primops-0.8.0.4
2426flags:
2527 katip:
2628 lib-Werror: true
stack-lts-3.yaml+1
@@ -14,6 +14,7 @@ extra-deps:
1414 - retry-0.7.4.2
1515 - tasty-0.11.0.4
1616 - rng-utils-0.2.1
17+ - unagi-chan-0.4.0.0
1718flags:
1819 katip:
1920 lib-Werror: true
stack-lts-4.yaml+1
@@ -11,6 +11,7 @@ extra-deps:
1111 - tagged-0.8.3
1212 - uuid-1.3.12
1313 - rng-utils-0.2.1
14+ - unagi-chan-0.4.0.0
1415flags:
1516 katip:
1617 lib-Werror: true
stack-lts-5.yaml+1
@@ -8,6 +8,7 @@ extra-deps:
88 - aeson-0.11.1.0
99 - http-client-0.5.4
1010 - rng-utils-0.2.1
11+ - unagi-chan-0.4.0.0
1112flags:
1213 katip:
1314 lib-Werror: true
stack.yaml+2−1
@@ -2,7 +2,8 @@ resolver: lts-7.9
22packages:
33 - katip
44 - katip-elasticsearch
5−extra-deps: []
5+extra-deps:
6+ - unagi-chan-0.4.0.0
67flags:
78 katip:
89 lib-Werror: true