From f7f8964422e99072e5be72d1ff354e8d0fe5dcec Mon Sep 17 00:00:00 2001 From: Karl Knutsson Date: Wed, 2 Oct 2024 09:36:38 +0200 Subject: [PATCH] Tracing updates Improve DebugState tracing Add tracing for current ledgerStateJudgement and associationMode. Add TraceMempoolSynced support Add support for tracing TraceMempoolSynced along with a txsSyncDuration which tracks how long it took to sync the mempool after block adoption. Unit is ms. --- .../Cardano/Node/Tracing/Tracers/Consensus.hs | 20 ++++++++++++ .../Tracing/OrphanInstances/Consensus.hs | 5 +++ .../Tracing/OrphanInstances/Network.hs | 13 +++++++- cardano-node/src/Cardano/Tracing/Tracers.hs | 31 ++++++++++++------- 4 files changed, 56 insertions(+), 13 deletions(-) diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs index d63709d86d9..0ec5a5db4bc 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs @@ -1205,6 +1205,12 @@ instance , "mempoolSize" .= forMachine dtal mpSz ] + forMachine _dtal (TraceMempoolSynced et) = + mconcat + [ "kind" .= String "TraceMempoolSynced" + , "enclosingTime" .= et + ] + asMetrics (TraceMempoolAddedTx _tx _mpSzBefore mpSz) = [ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz) , IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz) @@ -1227,6 +1233,13 @@ instance , CounterM "txsProcessedNum" (Just (fromIntegral $ length txs)) ] + asMetrics (TraceMempoolSynced (FallingEdgeWith duration)) = + [ IntM "txsSyncDuration" (round $ 1000 * duration) + ] + + asMetrics (TraceMempoolSynced RisingEdge) = [] + + instance LogFormatting MempoolSize where forMachine _dtal MempoolSize{msNumTxs, msNumBytes} = mconcat @@ -1240,11 +1253,13 @@ instance MetaTrace (TraceEventMempool blk) where namespaceFor TraceMempoolRejectedTx {} = Namespace [] ["RejectedTx"] namespaceFor TraceMempoolRemoveTxs {} = Namespace [] ["RemoveTxs"] namespaceFor TraceMempoolManuallyRemovedTxs {} = Namespace [] ["ManuallyRemovedTxs"] + namespaceFor TraceMempoolSynced {} = Namespace [] ["Synced"] severityFor (Namespace _ ["AddedTx"]) _ = Just Info severityFor (Namespace _ ["RejectedTx"]) _ = Just Info severityFor (Namespace _ ["RemoveTxs"]) _ = Just Info severityFor (Namespace _ ["ManuallyRemovedTxs"]) _ = Just Info + severityFor (Namespace _ ["Synced"]) _ = Just Info severityFor _ _ = Nothing metricsDocFor (Namespace _ ["AddedTx"]) = @@ -1264,6 +1279,11 @@ instance MetaTrace (TraceEventMempool blk) where , ("mempoolBytes", "Byte size of the mempool") , ("txsProcessedNum", "") ] + + metricsDocFor (Namespace _ ["Synced"]) = + [ ("txsSyncDuration", "Time to sync the mempool in ms after block adoption") + ] + metricsDocFor _ = [] documentFor (Namespace _ ["AddedTx"]) = Just diff --git a/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs b/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs index 7ce83a99327..2a3c60f141b 100644 --- a/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs +++ b/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs @@ -1510,6 +1510,11 @@ instance ( ToObject (ApplyTxErr blk), ToObject (GenTx blk), , "txsInvalidated" .= map (toObject verb . txForgetValidated) txs1 , "mempoolSize" .= toObject verb mpSz ] + toObject _verb (TraceMempoolSynced et) = + mconcat + [ "kind" .= String "TraceMempoolSynced" + , "enclosingTime" .= et + ] instance ToObject MempoolSize where toObject _verb MempoolSize{msNumTxs, msNumBytes} = diff --git a/cardano-node/src/Cardano/Tracing/OrphanInstances/Network.hs b/cardano-node/src/Cardano/Tracing/OrphanInstances/Network.hs index 7cbb31073a8..5ca65ab077a 100644 --- a/cardano-node/src/Cardano/Tracing/OrphanInstances/Network.hs +++ b/cardano-node/src/Cardano/Tracing/OrphanInstances/Network.hs @@ -61,7 +61,7 @@ import Ouroboros.Network.NodeToNode (ErrorPolicyTrace (..), NodeToNode NodeToNodeVersionData (..), RemoteAddress, TraceSendRecv (..), WithAddr (..)) import qualified Ouroboros.Network.NodeToNode as NtN import Ouroboros.Network.PeerSelection.Bootstrap -import Ouroboros.Network.PeerSelection.Governor (DebugPeerSelection (..), +import Ouroboros.Network.PeerSelection.Governor (AssociationMode (..), DebugPeerSelection (..), DebugPeerSelectionState (..), PeerSelectionCounters, PeerSelectionState (..), PeerSelectionTargets (..), PeerSelectionView (..), TracePeerSelection (..), peerSelectionStateToCounters) @@ -1956,6 +1956,8 @@ instance ToObject (TracePeerSelection SockAddr) where , "inProgressDemoteToCold" .= dpssInProgressDemoteToCold ds , "upstreamyness" .= dpssUpstreamyness ds , "fetchynessBlocks" .= dpssFetchynessBlocks ds + , "ledgerStateJudgement" .= dpssLedgerStateJudgement ds + , "associationMode" .= dpssAssociationMode ds ] -- Connection manager abstract state. For explanation of each state see @@ -2625,6 +2627,15 @@ instance FromJSON LedgerStateJudgement where parseJSON (String "TooOld") = pure TooOld parseJSON _ = fail "Invalid JSON for LedgerStateJudgement" +instance ToJSON AssociationMode where + toJSON LocalRootsOnly = String "LocalRootsOnly" + toJSON Unrestricted = String "Unrestricted" + +instance FromJSON AssociationMode where + parseJSON (String "LocalRootsOnly") = pure LocalRootsOnly + parseJSON (String "Unrestricted") = pure Unrestricted + parseJSON _ = fail "Invalid JSON for AssociationMode" + instance ToJSON UseLedgerPeers where toJSON DontUseLedgerPeers = Number (-1) toJSON (UseLedgerPeers Always) = Number 0 diff --git a/cardano-node/src/Cardano/Tracing/Tracers.hs b/cardano-node/src/Cardano/Tracing/Tracers.hs index 45dbbd72bcc..78ea014e3e5 100644 --- a/cardano-node/src/Cardano/Tracing/Tracers.hs +++ b/cardano-node/src/Cardano/Tracing/Tracers.hs @@ -1249,6 +1249,9 @@ notifyTxsProcessed fStats tr = Tracer $ \case -- so we can treat them as completely processed. updatedTxProcessed <- mapForgingStatsTxsProcessed fStats (+ (length txs)) traceCounter "txsProcessedNum" tr (fromIntegral updatedTxProcessed) + TraceMempoolSynced (FallingEdgeWith duration) -> do + traceCounter "txsSyncDuration" tr (round $ 1000 * duration :: Int) + -- The rest of the constructors. _ -> return () @@ -1256,18 +1259,22 @@ notifyTxsProcessed fStats tr = Tracer $ \case mempoolMetricsTraceTransformer :: Trace IO a -> Tracer IO (TraceEventMempool blk) mempoolMetricsTraceTransformer tr = Tracer $ \mempoolEvent -> do let tr' = appendName "metrics" tr - (_n, tot) = case mempoolEvent of - TraceMempoolAddedTx _tx0 _ tot0 -> (1, tot0) - TraceMempoolRejectedTx _tx0 _ tot0 -> (1, tot0) - TraceMempoolRemoveTxs txs0 tot0 -> (length txs0, tot0) - TraceMempoolManuallyRemovedTxs txs0 txs1 tot0 -> ( length txs0 + length txs1, tot0) - logValue1 :: LOContent a - logValue1 = LogValue "txsInMempool" $ PureI $ fromIntegral (msNumTxs tot) - logValue2 :: LOContent a - logValue2 = LogValue "mempoolBytes" . PureI . fromIntegral . unByteSize32 . msNumBytes $ tot - meta <- mkLOMeta Critical Confidential - traceNamedObject tr' (meta, logValue1) - traceNamedObject tr' (meta, logValue2) + (_n, tot_m) = case mempoolEvent of + TraceMempoolAddedTx _tx0 _ tot0 -> (1, Just tot0) + TraceMempoolRejectedTx _tx0 _ tot0 -> (1, Just tot0) + TraceMempoolRemoveTxs txs0 tot0 -> (length txs0, Just tot0) + TraceMempoolManuallyRemovedTxs txs0 txs1 tot0 -> ( length txs0 + length txs1, Just tot0) + TraceMempoolSynced _ -> (0, Nothing) + case tot_m of + Just tot -> do + let logValue1 :: LOContent a + logValue1 = LogValue "txsInMempool" $ PureI $ fromIntegral (msNumTxs tot) + logValue2 :: LOContent a + logValue2 = LogValue "mempoolBytes" . PureI . fromIntegral . unByteSize32 . msNumBytes $ tot + meta <- mkLOMeta Critical Confidential + traceNamedObject tr' (meta, logValue1) + traceNamedObject tr' (meta, logValue2) + Nothing -> return () mempoolTracer :: ( ToJSON (GenTxId blk)