Merge pull request #96 from channable/dd/journaling-log

Add logging on duration of journaling operations

Author: diegodiv

server/src/Persistence.hs

@@ -25,6 +25,7 @@ import qualified Data.ByteString.Char8      as SBS8
 import qualified Data.ByteString.Lazy       as LBS
 import qualified Data.ByteString.Lazy.Char8 as LBS8
 import           Data.Foldable
+import           Data.Maybe                 (isJust)
 import           Data.Text                  (Text)
 import qualified Data.Text                  as Text
 import           Data.Traversable
@@ -43,12 +44,25 @@ import qualified Store
 import Config (StorageBackend (..))
 
 data PersistentValue = PersistentValue
-  { pvConfig  :: PersistenceConfig
-  , pvValue   :: TVar Store.Value
+  { pvConfig       :: PersistenceConfig
+  , pvValue        :: TVar Store.Value
     -- ^ contains the state of the whole database
-  , pvIsDirty :: TVar Bool
+  , pvIsDirty      :: TVar Bool
     -- ^ flag indicating whether the current value of 'pvValue' has not yet been persisted to disk
-  , pvJournal :: Maybe Handle
+  , pvJournal      :: Maybe Handle
+  , pvJournalStats :: TVar JournalStatistics
+    -- ^ Structure keeping track of the duration of journaling operations.
+  }
+
+data JournalStatistics = JournalStatistics
+  { journalCount :: !Int
+    -- ^ The number of times a command has been journaled.
+  , journalTimeTotalMicros  :: !Int
+    -- ^ The total (sum) time journaling took.
+  , journalTimeMaxMicros   :: !Int
+    -- ^ The maximum time a journaling operation took.
+  , journalTimeMinMicros   :: !Int
+    -- ^ The minimum time a journaling operation took.
   }
 
 data PersistenceConfig = PersistenceConfig
@@ -59,6 +73,14 @@ data PersistenceConfig = PersistenceConfig
   , pcLogSync     :: Bool
   }
 
+emptyJournalStatistics :: JournalStatistics
+emptyJournalStatistics = JournalStatistics
+  { journalCount           = 0
+  , journalTimeTotalMicros = 0
+  , journalTimeMaxMicros   = 0
+  , journalTimeMinMicros   = maxBound
+  }
+
 -- | Get the actual value
 getValue :: PersistentValue -> STM Store.Value
 getValue = readTVar . pvValue
@@ -68,8 +90,19 @@ apply :: Store.Modification -> PersistentValue -> IO ()
 apply op val = do
   -- append to journal if enabled
   for_ (pvJournal val) $ \journalHandle -> do
+    start <- Clock.getTime Clock.Monotonic
     let entry = Aeson.encode op
     LBS8.hPutStrLn journalHandle entry
+    end <- Clock.getTime Clock.Monotonic
+    let time = fromInteger $ Clock.toNanoSecs (Clock.diffTimeSpec end start) `div` 1000
+    -- Update the structure containing the statistics on journaling.
+    atomically $ do
+      modifyTVar' (pvJournalStats val) $
+        \s -> s { journalCount           = journalCount s + 1
+                , journalTimeTotalMicros = journalTimeTotalMicros s + time
+                , journalTimeMaxMicros   = max (journalTimeMaxMicros s) time
+                , journalTimeMinMicros   = min (journalTimeMinMicros s) time
+                }
     for_ (pcMetrics . pvConfig $ val) $ \metrics -> do
       journalPos <- hTell journalHandle
       _ <- Metrics.incrementJournalWritten (LBS8.length entry) metrics
@@ -143,28 +176,45 @@ loadFromBackend backend config = runExceptT $ do
     File -> readData dataFilePath
     Sqlite -> readSqliteData dataFilePath
 
-  valueVar <- lift $ newTVarIO value
-  dirtyVar <- lift $ newTVarIO False
-  journal <- for (pcJournalFile config) openJournal
+  valueVar     <- lift $ newTVarIO value
+  dirtyVar     <- lift $ newTVarIO False
+  journalStats <- lift $ newTVarIO emptyJournalStatistics
+  journal      <- for (pcJournalFile config) openJournal
 
   let val = PersistentValue
-        { pvConfig  = config
-        , pvValue   = valueVar
-        , pvIsDirty = dirtyVar
-        , pvJournal = journal
+        { pvConfig       = config
+        , pvValue        = valueVar
+        , pvIsDirty      = dirtyVar
+        , pvJournal      = journal
+        , pvJournalStats = journalStats
         }
   recoverJournal val
   return val
 
+logJournalStats :: PersistentValue -> IO ()
+logJournalStats pv = do
+  jStats <- atomically $ do
+    stats <- readTVar (pvJournalStats pv)
+    writeTVar (pvJournalStats pv) emptyJournalStatistics
+    return stats
+  let jCount = journalCount jStats
+  when (jCount /= 0) $ do
+    let jAvg   = journalTimeTotalMicros jStats `div` jCount
+        jMin   = journalTimeMinMicros jStats
+        jMax   = journalTimeMaxMicros jStats
+        jLog   = Text.concat ["Journaling duration (avg/min/max/count) in microseconds since last Sync: "
+                             , Text.intercalate "/" $ map (Text.pack . show) [jAvg, jMin, jMax, jCount]]
+    logMessage pv jLog
+
 syncToBackend :: StorageBackend -> PersistentValue -> IO ()
 syncToBackend File pv = do
     start <- Clock.getTime Clock.Monotonic
     syncFile pv
     end <- Clock.getTime Clock.Monotonic
     let time = Clock.toNanoSecs (Clock.diffTimeSpec end start) `div` 1000000
-    if pcLogSync $ pvConfig pv then
-      logMessage pv $ Text.concat ["It took ", Text.pack $ show time, " ms to synchronize Icepeak on disk."]
-    else return ()
+    when (pcLogSync $ pvConfig pv) $ do
+      logMessage pv $ Text.concat ["It took ", Text.pack $ show time, " ms to synchronize Icepeak on disk."] 
+      when (isJust $ pcJournalFile $ pvConfig pv) $ logJournalStats pv
 syncToBackend Sqlite pv = syncSqliteFile pv
 
 -- * SQLite loading and syncing