Merge #445

445: CAD-391 eliding messages r=CodiePP a=CodiePP

prints first and last message of range of equivalent 'TraceLedgerReplayEvent'.
```
[nixos19:cardano.node.ChainDB:Info:64] [2019-12-24 23:26:57.00 UTC] {"event":{"kind":"TraceOpenEvent.OpenedVolDB"},"kind":"TraceEvent","tip":"genesis(origin)"}
[nixos19:cardano.node.ChainDB:Info:64] [2019-12-24 23:26:57.31 UTC] {"event":{"snapshot":{"snapshot":"DiskSnapshot 9","kind":"snapshot"},"kind":"TraceLedgerReplayEvent.ReplayFromSnapshot","tip":"Tip (At (Block {blockPointSlot = SlotNo {unSlotNo = 3549092}, blockPointHash = ByronHash {unByronHash = AbstractHash 2cfa35fe9617a9c41ef5ec19bed50742e587ab10d18ce6ac80c09bf71308fc3e}}))"},"kind":"TraceEvent","tip":"genesis(origin)"}
[nixos19:cardano.node.ChainDB:Info:64] [2019-12-24 23:26:57.39 UTC] {"event":{"snapshot":{"snapshot":"DiskSnapshot 9","kind":"snapshot"},"kind":"TraceLedgerReplayEvent.ReplayFromSnapshot","tip":"Tip (At (Block {blockPointSlot = SlotNo {unSlotNo = 3549092}, blockPointHash = ByronHash {unByronHash = AbstractHash 2cfa35fe9617a9c41ef5ec19bed50742e587ab10d18ce6ac80c09bf71308fc3e}}))"},"kind":"TraceEvent","tip":"genesis(origin)"}
[nixos19:cardano.node.ChainDB:Info:64] [2019-12-24 23:26:57.39 UTC] messages elided in total = 70
[nixos19:cardano.node.ChainDB:Info:64] [2019-12-24 23:26:57.39 UTC] {"event":{"kind":"TraceOpenEvent.OpenedLgrDB"},"kind":"TraceEvent","tip":"genesis(origin)"}
```

Co-authored-by: Alexander Diemand <[email protected]>

benchmarking/chain-sync/benchmark-chain-sync-mainnet.sh

@@ -9,9 +9,12 @@ DATADIR=state-node-mainnet
 mkdir -p $DATADIR
 cd $DATADIR
 
+# remove blockchain
 if [ -d db-mainnet-0 ]; then
   rm -rf db-mainnet-0
 fi
+
+# remove old log files
 rm node-0*
 
 #set -euo pipefail
@@ -21,6 +24,7 @@ ulimit -t $CPU_TIME_LIMIT
 date --iso-8601=seconds > STARTTIME
 
 NODE="cabal v2-run exe:cardano-node -- "
+NODE="stack --nix exec cardano-node -- "
 
 exec ${NODE} \
   --genesis-file ${BASEDIR}/../../configuration/mainnet-genesis.json \
@@ -32,7 +36,9 @@ exec ${NODE} \
   --host-addr 127.0.0.1 \
   --port 7778 \
   --tracing-verbosity-maximal \
+  --trace-block-fetch-decisions \
   --trace-mempool \
+  --trace-chain-db \
   --trace-forge \
    \
  $@

benchmarking/chain-sync/configuration/log-config-byron-proxy.yaml

@@ -17,7 +17,9 @@ defaultBackends:
 hasEKG: 12789
 
 # if wanted, the Prometheus interface is using this port:
-hasPrometheus: 12799
+hasPrometheus:
+  - "localhost"
+  - 12799
 
 # here we set up outputs of logging in 'katip':
 setupScribes:

benchmarking/chain-sync/configuration/log-configuration.yaml

@@ -1,5 +1,5 @@
 # global filter; messages must have at least this severity to pass:
-minSeverity: Notice
+minSeverity: Debug
 
 # global file rotation settings:
 rotation:
@@ -68,6 +68,8 @@ options:
       # Change the `subtrace` value to `Neutral` in order to log
       # `UTxO`-related messages during epoch validation.
       subtrace: NoTrace
+    'cardano.#messagecounters':
+      subtrace: NoTrace
     '#messagecounters.aggregation':
       subtrace: NoTrace
     '#messagecounters.monitoring':
@@ -84,17 +86,15 @@ options:
     cardano.epoch-validation.benchmark:
       - AggregationBK
     'cardano.node.peers.BlockFetchDecision':
+      - EKGViewBK
       - kind: UserDefinedBK
         name: LiveViewBackend
     'cardano.node.ChainDB':
       - KatipBK
       - kind: UserDefinedBK
         name: LiveViewBackend
-    'cardano.node.metrics.ChainDB':
-      - EKGViewBK
-      - kind: UserDefinedBK
-        name: LiveViewBackend
     cardano.node.metrics:
+      - EKGViewBK
       - kind: UserDefinedBK
         name: LiveViewBackend
 ##########################################################

benchmarking/chain-sync/launch_mainnet_proxy.sh

@@ -11,7 +11,10 @@ set -euo pipefail
 
 cd ${TARGETDIR}
 
-cabal v2-run exe:cardano-byron-proxy -- \
+RUNNER="cabal v2-run exe:cardano-byron-proxy --"
+RUNNER="stack --nix exec cardano-byron-proxy --"
+
+${RUNNER} \
   +RTS -T -RTS \
   --database-path state-proxy-mainnet/db \
   --index-path state-proxy-mainnet/index \

cardano-node/src/Cardano/Tracing/ToObjectOrphans.hs

@@ -61,6 +61,7 @@ import           Ouroboros.Network.TxSubmission.Outbound
                    (TraceTxSubmissionOutbound)
 
 import qualified Ouroboros.Storage.ChainDB as ChainDB
+import           Ouroboros.Storage.Common (EpochNo (..))
 import qualified Ouroboros.Storage.LedgerDB.OnDisk as LedgerDB
 
 -- | Tracing wrapper which includes current tip in the logs (thus it requires
@@ -233,7 +234,8 @@ instance DefineSeverity (ChainDB.TraceEvent blk) where
   defineSeverity (ChainDB.TraceLedgerReplayEvent ev) = case ev of
     LedgerDB.ReplayFromGenesis {} -> Info
     LedgerDB.ReplayFromSnapshot {} -> Info
-    _ -> Debug
+    LedgerDB.ReplayedBlock {} -> Info
+
   defineSeverity (ChainDB.TraceLedgerEvent ev) = case ev of
     LedgerDB.TookSnapshot {} -> Info
     LedgerDB.DeletedSnapshot {} -> Debug
@@ -251,9 +253,9 @@ instance DefineSeverity (ChainDB.TraceEvent blk) where
     ChainDB.OpenedDB {} -> Info
     ChainDB.ClosedDB {} -> Info
     ChainDB.ReopenedDB {} -> Debug
-    ChainDB.OpenedImmDB {} -> Debug
-    ChainDB.OpenedVolDB -> Debug
-    ChainDB.OpenedLgrDB -> Debug
+    ChainDB.OpenedImmDB {} -> Info
+    ChainDB.OpenedVolDB -> Info
+    ChainDB.OpenedLgrDB -> Info
 
   defineSeverity (ChainDB.TraceReaderEvent ev) = case ev of
     ChainDB.NewReader {} -> Info
@@ -473,7 +475,8 @@ readableChainDBTracer tracer = Tracer $ \case
     LedgerDB.ReplayFromSnapshot snap tip' _replayTo -> tr $ WithTip tip $
       "Replaying ledger from snapshot " <> show snap <> " at " <>
         condense tip'
-    LedgerDB.ReplayedBlock {} -> pure ()
+    LedgerDB.ReplayedBlock _r (epochno, slotno) _replayTo -> tr $ WithTip tip $
+      "Replayed block: " <> show (unSlotNo slotno) <> " in epoch: " <> show (unEpochNo epochno)
   WithTip tip (ChainDB.TraceLedgerEvent ev) -> case ev of
     LedgerDB.TookSnapshot snap pt -> tr $ WithTip tip $
       "Took ledger snapshot " <> show snap <> " at " <> condense pt
@@ -656,7 +659,10 @@ instance (Condense (HeaderHash blk), ProtocolLedgerView blk)
       mkObject [ "kind" .= String "TraceLedgerReplayEvent.ReplayFromSnapshot"
                , "snapshot" .= toObject verb snap
                , "tip" .= show tip' ]
-    _ -> emptyObject
+    LedgerDB.ReplayedBlock _ (epochno, slotno) _replayTo ->
+      mkObject [ "kind" .= String "TraceLedgerReplayEvent.ReplayedBlock"
+               , "epoch" .= show (unEpochNo epochno)
+               , "slot" .= show (unSlotNo slotno) ]
 
   toObject MinimalVerbosity (ChainDB.TraceLedgerEvent _ev) = emptyObject -- no output
   toObject verb (ChainDB.TraceLedgerEvent ev) = case ev of

cardano-node/src/Cardano/Tracing/Tracers.hs

@@ -36,6 +36,7 @@ import           Cardano.BM.Data.Aggregated (Measurable (..))
 import           Cardano.BM.Data.LogItem (LOContent (..), LogObject (..),
                                           PrivacyAnnotation (Confidential),
                                           mkLOMeta)
+import           Cardano.BM.ElidingTracer
 import           Cardano.BM.Tracing
 import           Cardano.BM.Trace (traceNamedObject)
 import           Cardano.BM.Data.Tracer (WithSeverity (..), addName,
@@ -118,6 +119,26 @@ nullTracers = Tracers {
       muxTracer = nullTracer
     }
 
+
+instance ElidingTracer
+  (WithSeverity (WithTip blk (ChainDB.TraceEvent blk))) where
+  -- equivalent by type and severity
+  isEquivalent (WithSeverity s1 (WithTip _tip1 (ChainDB.TraceLedgerReplayEvent _ev1)))
+                (WithSeverity s2 (WithTip _tip2 (ChainDB.TraceLedgerReplayEvent _ev2))) = s1 == s2
+  isEquivalent (WithSeverity s1 (WithTip _tip1 (ChainDB.TraceGCEvent _ev1)))
+                (WithSeverity s2 (WithTip _tip2 (ChainDB.TraceGCEvent _ev2))) = s1 == s2
+  isEquivalent _ _ = False
+  -- the types to be elided
+  doelide (WithSeverity _ (WithTip _ (ChainDB.TraceLedgerReplayEvent _))) = True
+  doelide (WithSeverity _ (WithTip _ (ChainDB.TraceGCEvent _))) = True
+  doelide _ = False
+  conteliding _tform _tverb _tr _ (Nothing, _count) = return (Nothing, 0)
+  conteliding _tform _tverb tr ev (_old, count) = do
+      when (count > 0 && count `mod` 100 == 0) $ do  -- report every 100th elided message
+          meta <- mkLOMeta (defineSeverity ev) (definePrivacyAnnotation ev)
+          traceNamedObject tr (meta, LogValue "messages elided so far" (PureI $ toInteger count))
+      return (Just ev, count + 1)
+
 -- | Smart constructor of 'NodeTraces'.
 --
 mkTracers :: forall peer blk.
@@ -145,11 +166,13 @@ mkTracers traceOptions tracer = do
   -- a block.
   -- txsOutcomeExtractor <- mkOutcomeExtractor
 
+  elided <- newstate  -- for eliding messages in ChainDB tracer
+
   pure Tracers
     { chainDBTracer
         = tracerOnOff (traceChainDB traceOptions)
           $ annotateSeverity
-          $ teeTraceChainTip StructuredLogging tracingVerbosity
+          $ teeTraceChainTip StructuredLogging tracingVerbosity elided
           $ addName "ChainDB" tracer
     , consensusTracers
         = mkConsensusTracers forgeTracers traceOptions
@@ -191,11 +214,19 @@ mkTracers traceOptions tracer = do
 
     teeTraceChainTip :: TracingFormatting
                      -> TracingVerbosity
+                     -> MVar (Maybe (WithSeverity (WithTip blk (ChainDB.TraceEvent blk))), Int)
                      -> Tracer IO (LogObject Text)
                      -> Tracer IO (WithSeverity (WithTip blk (ChainDB.TraceEvent blk)))
-    teeTraceChainTip tform tverb tr = Tracer $ \ev -> do
+    teeTraceChainTip tform tverb elided tr = Tracer $ \ev -> do
         traceWith (teeTraceChainTip' tr) ev
-        traceWith (toLogObject' tform tverb tr) ev
+        traceWith (teeTraceChainTipElide tform tverb elided tr) ev
+    teeTraceChainTipElide :: TracingFormatting
+                          -> TracingVerbosity
+                          -> MVar (Maybe (WithSeverity (WithTip blk (ChainDB.TraceEvent blk))), Int)
+                          -> Tracer IO (LogObject Text)
+                          -> Tracer IO (WithSeverity (WithTip blk (ChainDB.TraceEvent blk)))
+    teeTraceChainTipElide = elideToLogObject
+
     teeTraceChainTip' :: Tracer IO (LogObject Text)
                       -> Tracer IO (WithSeverity (WithTip blk (ChainDB.TraceEvent blk)))
     teeTraceChainTip' tr =