on master help sign in
Faster time encoding for Handle Scribe

This implements time encoding functions using low-level Data.Text interface. Encoding functions do not allocate anything except the result, and work really fast. The Handle Scribe benchmark improved almost 4x times. From 24us to 6.1 us. This should probably be used in JSON encoding, at least in the toJSON part. The toEncoding part should use efficient implementation in Data.Aeson to avoid allocating Text or ByteString outside of Builder.

commitc5954514c5fca4ef9533047285cdb8d2a21d3a3e authorLeonid Onokhov <sopvop@gmail.com> dateWed 26 Oct 2016, 23:08 (10 years ago) parentf7dd153
5 files changed+292−4
katip/katip.cabal+2−1 katip/src/Katip/Format/Time.hs+213 katip/src/Katip/Scribes/Handle.hs+2−3 katip/test/Katip/Tests/Format/Time.hs+73 katip/test/Main.hs+2
katip/katip.cabal+2−1
@@ -37,6 +37,7 @@ library
3737 exposed-modules:
3838 Katip
3939 Katip.Core
40+ Katip.Format.Time
4041 Katip.Monadic
4142 Katip.Scribes.Handle
4243
@@ -63,7 +64,6 @@ library
6364 , template-haskell >= 2.8 && < 2.12
6465 , text >= 0.11 && <1.3
6566 , time >= 1 && < 1.7
66− , time-locale-compat >= 0.1.0.1 && < 0.2
6767 , transformers >= 0.3 && < 0.6
6868 , transformers-compat
6969 , unix >= 2.5 && < 2.8
@@ -97,6 +97,7 @@ test-suite test
9797 , template-haskell
9898 , text
9999 , time
100+ , time-locale-compat >= 0.1.0.1 && < 0.2
100101 , temporary
101102 , directory
102103 , regex-tdfa
katip/src/Katip/Format/Time.hsnew file+213
@@ -0,0 +1,213 @@
1+-- | Time and memory efficient time encoding helper functions.
2+--
3+module Katip.Format.Time
4+ ( formatAsLogTime
5+ , formatAsIso8601
6+ ) where
7+
8+import Control.Monad.ST (ST)
9+
10+import Data.Int (Int64)
11+import qualified Data.Text.Array as TA
12+import Data.Text (Text)
13+import Data.Text.Internal (Text(..))
14+import Data.Time (UTCTime(..), toGregorian, Day, DiffTime)
15+import Data.Word (Word16)
16+import Unsafe.Coerce (unsafeCoerce)
17+
18+-- Note: All functions here are optimized to never allocate anything
19+-- on heap. At least on ghc 8.0.1 no extra strictness annotations are
20+-- seem to be needed.
21+--
22+-- Exported functions are INLINEABLE
23+
24+
25+-- | Format 'UTCTime' into a short human readable format.
26+--
27+-- >>> formatAsLogTime $ UTCTime (fromGregorian 2016 1 23) 5025.123456789012
28+-- "2016-01-23 01:23:45"
29+--
30+formatAsLogTime :: UTCTime -> Text
31+formatAsLogTime (UTCTime day time) = toText $ TA.run2 $ do
32+ buf <- TA.new 19 -- length "2016-10-20 12:34:56"
33+ _ <- writeDay buf 0 day
34+ TA.unsafeWrite buf 10 0x20 -- space
35+ _ <- writeTimeOfDay False buf 11 (diffTimeOfDay64 time)
36+ pure (buf, 19)
37+ where
38+ toText (arr, len) = Text arr 0 len
39+
40+{-# INLINEABLE formatAsLogTime #-}
41+
42+-- | Format 'UTCTime' into a Iso8601 format.
43+--
44+-- Note that this function may overcommit up to 12*2 bytes, depending
45+-- on sub-second precision. If this is an issue, make a copy with a
46+-- 'Data.Text.copy'.
47+--
48+-- >>> formatAsIso8601 $ UTCTime (fromGregorian 2016 1 23) 5025.123456789012
49+-- "2016-11-23T01:23:45.123456789012Z"
50+-- >>> formatAsIso8601 $ UTCTime (fromGregorian 2016 1 23) 5025.123
51+-- "2016-01-23T01:23:45.123Z"
52+-- >>> formatAsIso8601 $ UTCTime (fromGregorian 2016 1 23) 5025
53+-- "2016-01-23T01:23:45Z"
54+
55+--
56+formatAsIso8601 :: UTCTime -> Text
57+formatAsIso8601 (UTCTime day time) = toText $ TA.run2 $ do
58+ buf <- TA.new 33 -- length "2016-10-20 12:34:56.123456789012Z"
59+ _ <- writeDay buf 0 day
60+ TA.unsafeWrite buf 10 0x54 -- T
61+ next <- writeTimeOfDay True buf 11 (diffTimeOfDay64 time)
62+ TA.unsafeWrite buf next 0x5A -- Z
63+ pure (buf, next+1)
64+ where
65+ toText (arr, len) = Text arr 0 len
66+
67+{-# INLINEABLE formatAsIso8601 #-}
68+
69+-- | Writes the @YYYY-MM-DD@ part of timestamp
70+writeDay :: TA.MArray s -> Int -> Day -> ST s Int
71+writeDay buf off day =
72+ do
73+ TA.unsafeWrite buf (off + 0) (digit y1)
74+ TA.unsafeWrite buf (off + 1) (digit y2)
75+ TA.unsafeWrite buf (off + 2) (digit y3)
76+ TA.unsafeWrite buf (off + 3) (digit y4)
77+ TA.unsafeWrite buf (off + 4) 0x2d -- dash
78+ TA.unsafeWrite buf (off + 5) m1
79+ TA.unsafeWrite buf (off + 6) m2
80+ TA.unsafeWrite buf (off + 7) 0x2d -- dash
81+ TA.unsafeWrite buf (off + 8) d1
82+ TA.unsafeWrite buf (off + 9) d2
83+ pure (off + 10)
84+ where
85+ (yr,m,d) = toGregorian day
86+ (y1, ya) = fromIntegral (abs yr) `quotRem` 1000
87+ (y2, yb) = ya `quotRem` 100
88+ (y3, y4) = yb `quotRem` 10
89+ T m1 m2 = twoDigits m
90+ T d1 d2 = twoDigits d
91+{-# INLINE writeDay #-}
92+
93+-- | Write time of day, optionally with sub seconds
94+writeTimeOfDay :: Bool -> TA.MArray s -> Int -> TimeOfDay64 -> ST s Int
95+writeTimeOfDay doSubSeconds buf off (TOD hh mm ss) =
96+ do
97+
98+ TA.unsafeWrite buf off h1
99+ TA.unsafeWrite buf (off + 1) h2
100+ TA.unsafeWrite buf (off + 2) 0x3A -- colon
101+ TA.unsafeWrite buf (off + 3) m1
102+ TA.unsafeWrite buf (off + 4) m2
103+ TA.unsafeWrite buf (off + 5) 0x3A -- colon
104+ TA.unsafeWrite buf (off + 6) s1
105+ TA.unsafeWrite buf (off + 7) s2
106+ if doSubSeconds && frac /= 0
107+ then writeFracSeconds buf (off + 8) frac
108+ else pure (off + 8)
109+ where
110+ T h1 h2 = twoDigits hh
111+ T m1 m2 = twoDigits mm
112+ T s1 s2 = twoDigits (fromIntegral real)
113+ (real,frac) = ss `quotRem` pico
114+ pico = 1000000000000 -- number of picoseconds in 1 second
115+
116+
117+writeFracSeconds :: TA.MArray s -> Int -> Int64 -> ST s Int
118+writeFracSeconds buf off frac =
119+ do
120+ TA.unsafeWrite buf off 0x2e -- period
121+ if mills == 0
122+ then do
123+ writeTrunc6 buf (off + 1) (fromIntegral mics)
124+ else do
125+ writeDigit6 buf (off + 1) (fromIntegral mics)
126+ writeTrunc6 buf (off + 7) (fromIntegral mills)
127+
128+ where
129+ (mics, mills) = frac `quotRem` micro
130+ micro = 1000000 -- number of microseconds in 1 second
131+
132+
133+writeDigit6 :: TA.MArray s -> Int -> Int -> ST s ()
134+writeDigit6 buf off i =
135+ do
136+ writeDigit3 buf off f1
137+ writeDigit3 buf (off+3) f2
138+ where
139+ (f1, f2) = i `quotRem` 1000
140+
141+{-# INLINE writeDigit6 #-}
142+
143+writeDigit3 :: TA.MArray s -> Int -> Int -> ST s ()
144+writeDigit3 buf off i =
145+ do
146+ TA.unsafeWrite buf off (digit d1)
147+ TA.unsafeWrite buf (off+1) (digit d2)
148+ TA.unsafeWrite buf (off+2) (digit d3)
149+ where
150+ (d1, d) = i `quotRem` 100
151+ (d2, d3) = d `quotRem` 10
152+
153+{-# INLINE writeDigit3 #-}
154+
155+writeTrunc6 :: TA.MArray s -> Int -> Int -> ST s Int
156+writeTrunc6 buf off i =
157+ if f2 == 0
158+ then writeTrunc3 buf off f1
159+ else do
160+ writeDigit3 buf off f1
161+ writeTrunc3 buf (off+3) f2
162+ where
163+ (f1, f2) = i `quotRem` 1000
164+
165+{-# INLINE writeTrunc6 #-}
166+
167+
168+writeTrunc3 :: TA.MArray s -> Int -> Int -> ST s Int
169+writeTrunc3 buf off i
170+ | d == 0 = do
171+ TA.unsafeWrite buf off (digit d1)
172+ pure (off+1)
173+ | d3 == 0 = do
174+ TA.unsafeWrite buf off (digit d1)
175+ TA.unsafeWrite buf (off+1) (digit d2)
176+ pure (off+2)
177+
178+ | otherwise = do
179+ TA.unsafeWrite buf off (digit d1)
180+ TA.unsafeWrite buf (off+1) (digit d2)
181+ TA.unsafeWrite buf (off+2) (digit d3)
182+ pure (off+3)
183+ where
184+ (d1, d) = i `quotRem` 100
185+ (d2, d3) = d `quotRem` 10
186+
187+{-# INLINE writeTrunc3 #-}
188+
189+
190+-- Following code was adapted from aeson package.
191+--
192+-- Copyright: (c) 2015-2016 Bryan O'Sullivan
193+-- License: BSD3
194+
195+data T = T {-# UNPACK #-} !Word16 {-# UNPACK #-} !Word16
196+
197+twoDigits :: Int -> T
198+twoDigits a = T (digit hi) (digit lo)
199+ where (hi,lo) = a `quotRem` 10
200+
201+digit :: Int -> Word16
202+digit x = fromIntegral (x + 48)
203+
204+
205+data TimeOfDay64 = TOD {-# UNPACK #-} !Int
206+ {-# UNPACK #-} !Int
207+ {-# UNPACK #-} !Int64
208+
209+diffTimeOfDay64 :: DiffTime -> TimeOfDay64
210+diffTimeOfDay64 t = TOD (fromIntegral h) (fromIntegral m) s
211+ where (h,mp) = fromIntegral pico `quotRem` 3600000000000000
212+ (m,s) = mp `quotRem` 60000000000000
213+ pico = unsafeCoerce t :: Integer
katip/src/Katip/Scribes/Handle.hs+2−3
@@ -13,12 +13,11 @@ import Data.Monoid
1313import Data.Text (Text)
1414import Data.Text.Lazy.Builder
1515import Data.Text.Lazy.IO as T
16−import Data.Time
17−import qualified Data.Time.Locale.Compat as LC
1816import System.IO
1917import System.IO.Unsafe (unsafePerformIO)
2018-------------------------------------------------------------------------------
2119import Katip.Core
20+import Katip.Format.Time (formatAsLogTime)
2221-------------------------------------------------------------------------------
2322
2423
@@ -83,7 +82,7 @@ formatItem withColor verb Item{..} =
8382 maybe mempty (brackets . fromString . locationToString) _itemLoc <>
8483 fromText " " <> (unLogStr _itemMessage)
8584 where
86− nowStr = fromString $ formatTime LC.defaultTimeLocale "%Y-%m-%d %H:%M:%S" _itemTime
85+ nowStr = fromText (formatAsLogTime _itemTime)
8786 ks = map brackets $ getKeys verb _itemPayload
8887 renderSeverity' s = case s of
8988 EmergencyS -> red $ renderSeverity s
katip/test/Katip/Tests/Format/Time.hsnew file+73
@@ -0,0 +1,73 @@
1+
2+module Katip.Tests.Format.Time
3+ ( tests
4+ ) where
5+
6+import Data.Aeson (toJSON)
7+import qualified Data.Text as Text
8+import Data.Time
9+import Data.Time.Clock.POSIX
10+import qualified Data.Time.Locale.Compat as LC
11+
12+import Test.Tasty
13+import Test.Tasty.HUnit
14+import Test.Tasty.QuickCheck
15+
16+import Katip.Format.Time
17+
18+tests :: TestTree
19+tests = testGroup "Katip.Format.Time"
20+ [ testCase "formatAsLogTime" $ do
21+ assertEqual "time 1" (formatDT t1) (formatAsLogTime t1)
22+ assertEqual "time 2" (formatDT t2) (formatAsLogTime t2)
23+ assertEqual "time 3" (formatDT t3) (formatAsLogTime t3)
24+
25+ , testCase "formatAsIso8601" $ do
26+ assertEqual "time 1" (formatDTISO t1) (formatAsIso8601 t1)
27+ assertEqual "time 2" (formatDTISO t2) (formatAsIso8601 t2)
28+ assertEqual "time 3" (formatDTISO t3) (formatAsIso8601 t3)
29+
30+ , testCase "formatAsIso8601 Aeson" $ do
31+ assertEqual "time 1" (toJSON t1) (toJSON $ formatAsIso8601 t1)
32+ assertEqual "time 2" (toJSON t2) (toJSON $ formatAsIso8601 t2)
33+ assertEqual "time 3" (toJSON t3) (toJSON $ formatAsIso8601 t3)
34+
35+
36+ , testProperty "LogTime same as Date.Time" $ \(ArbUTCTime t) ->
37+ prop_format_log t
38+
39+ , testProperty "ISO 8601 same as Date.Time" $ \(ArbUTCTime t) ->
40+ prop_format_iso t
41+
42+ , testProperty "ISO 8601 same as Aeson" $ \(ArbUTCTime t) ->
43+ prop_format_aeson t
44+
45+ ]
46+ where
47+ t1 = UTCTime (fromGregorian 2016 12 34) 5025.123456789012
48+ t2 = UTCTime (fromGregorian 2016 1 23) 5025.123
49+ t3 = UTCTime (fromGregorian 16 12 1) 025
50+
51+formatDT :: UTCTime -> Text.Text
52+formatDT = Text.pack . formatTime LC.defaultTimeLocale "%0Y-%m-%d %H:%M:%S"
53+
54+formatDTISO :: UTCTime -> Text.Text
55+formatDTISO = Text.pack . formatTime LC.defaultTimeLocale "%0Y-%m-%dT%H:%M:%S%QZ"
56+
57+prop_format_log :: UTCTime -> Property
58+prop_format_log a = formatDT a === formatAsLogTime a
59+
60+prop_format_iso :: UTCTime -> Property
61+prop_format_iso a = formatDTISO a === formatAsIso8601 a
62+
63+prop_format_aeson :: UTCTime -> Property
64+prop_format_aeson a = toJSON a === toJSON (formatAsIso8601 a)
65+
66+
67+newtype ArbUTCTime = ArbUTCTime {
68+ unArbUTCTime :: UTCTime
69+ } deriving (Show)
70+
71+instance Arbitrary ArbUTCTime where
72+ arbitrary = ArbUTCTime . posixSecondsToUTCTime . fromInteger
73+ <$> arbitrary
katip/test/Main.hs+2
@@ -4,6 +4,7 @@ module Main (main) where
44import Test.Tasty
55-------------------------------------------------------------------------------
66import qualified Katip.Tests
7+import qualified Katip.Tests.Format.Time
78import qualified Katip.Tests.Scribes.Handle
89-------------------------------------------------------------------------------
910
@@ -15,5 +16,6 @@ testSuite :: TestTree
1516testSuite = testGroup "katip"
1617 [
1718 Katip.Tests.tests
19+ , Katip.Tests.Format.Time.tests
1820 , Katip.Tests.Scribes.Handle.tests
1921 ]