Skip to content

Commit 4f02648

Browse files
palaspalas
authored
Merge pull request #6420 from IntersectMBO/nfrisby/defensive-mempool-counters
Add EKG metrics for soft and hard timeouts and include defensive mempool
2 parents eb084f5 + a1a8d89 commit 4f02648

6 files changed

Lines changed: 138 additions & 21 deletions

File tree

‎cardano-node/ChangeLog.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@
22

33
## Next version
44

5+
* Added EKG metrics for soft and hard timeouts and included defensive mempool
6+
57
* Improved `cardano-node --help` output by making it the same as the one shown when calling `cardano-node` without arguments.
68

79
* Removed `cardano-node' as a dependency from `cardano-tracer'. This necessitated moving `NodeInfo`

‎cardano-node/src/Cardano/Node/TraceConstraints.hs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import Cardano.Ledger.Keys
1313
import Cardano.Logging (LogFormatting)
1414
import Cardano.Node.Queries (ConvertTxId, GetKESInfo (..), HasKESInfo (..),
1515
HasKESMetricsData (..), LedgerQueries)
16+
import qualified Cardano.Node.Tracing.Tracers.Consensus as ConsensusTracers
1617
import Cardano.Protocol.Crypto (StandardCrypto)
1718
import Cardano.Tracing.HasIssuer (HasIssuer)
1819
import Ouroboros.Consensus.Block (BlockProtocol, CannotForge, ForgeStateUpdateError,

‎cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs‎

Lines changed: 25 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
{-# LANGUAGE DataKinds #-}
12
{-# LANGUAGE FlexibleContexts #-}
23
{-# LANGUAGE FlexibleInstances #-}
34
{-# LANGUAGE LambdaCase #-}
@@ -18,6 +19,8 @@ module Cardano.Node.Tracing.Tracers.Consensus
1819
, calculateBlockFetchClientMetrics
1920
, servedBlockLatest
2021
, ClientMetrics
22+
, txsMempoolTimeoutSoftCounterName
23+
, impliesMempoolTimeoutSoft
2124
) where
2225

2326

@@ -43,7 +46,8 @@ import Ouroboros.Consensus.Ledger.Inspect (LedgerEvent (..), LedgerUpd
4346
import Ouroboros.Consensus.Ledger.SupportsMempool (ApplyTxErr, ByteSize32 (..), GenTxId,
4447
HasTxId, LedgerSupportsMempool, txForgetValidated, txId)
4548
import Ouroboros.Consensus.Ledger.SupportsProtocol
46-
import Ouroboros.Consensus.Mempool (MempoolSize (..), TraceEventMempool (..))
49+
import Ouroboros.Consensus.Mempool (MempoolRejectionDetails (..), MempoolSize (..),
50+
TraceEventMempool (..), jsonMempoolRejectionDetails)
4751
import Ouroboros.Consensus.MiniProtocol.BlockFetch.Server
4852
(TraceBlockFetchServerEvent (..))
4953
import Ouroboros.Consensus.MiniProtocol.ChainSync.Client
@@ -83,7 +87,6 @@ import Data.Time (NominalDiffTime)
8387
import Data.Word (Word32, Word64)
8488
import Network.TypedProtocol.Core
8589

86-
8790
instance (LogFormatting adr, Show adr) => LogFormatting (ConnectionId adr) where
8891
forMachine _dtal (ConnectionId local' remote) =
8992
mconcat [ "connectionId" .= String (showT local'
@@ -1241,6 +1244,17 @@ instance MetaTrace (TraceLocalTxSubmissionServerEvent blk) where
12411244
-- Mempool Tracer
12421245
--------------------------------------------------------------------------------
12431246

1247+
txsMempoolTimeoutSoftCounterName :: Text.Text
1248+
txsMempoolTimeoutSoftCounterName = "txsMempoolTimeoutSoft"
1249+
1250+
impliesMempoolTimeoutSoft :: TraceEventMempool blk -> Bool
1251+
impliesMempoolTimeoutSoft = \case
1252+
TraceMempoolRejectedTx _tx _txApplyErr details _mpSz ->
1253+
case details of
1254+
MempoolRejectedByTimeoutSoft{} -> True
1255+
MempoolRejectedByLedger -> False
1256+
_ -> False
1257+
12441258
instance
12451259
( LogFormatting (ApplyTxErr blk)
12461260
, LogFormatting (GenTx blk)
@@ -1254,14 +1268,15 @@ instance
12541268
, "tx" .= forMachine dtal (txForgetValidated tx)
12551269
, "mempoolSize" .= forMachine dtal mpSzAfter
12561270
]
1257-
forMachine dtal (TraceMempoolRejectedTx tx txApplyErr _ mpSz) =
1271+
forMachine dtal (TraceMempoolRejectedTx tx txApplyErr details mpSz) =
12581272
mconcat $
12591273
[ "kind" .= String "TraceMempoolRejectedTx"
12601274
, "tx" .= forMachine dtal tx
12611275
, "mempoolSize" .= forMachine dtal mpSz
12621276
] <>
1277+
if dtal < DDetailed then [] else
12631278
[ "err" .= forMachine dtal txApplyErr
1264-
| dtal >= DDetailed
1279+
, "errdetails" .= jsonMempoolRejectionDetails details
12651280
]
12661281
forMachine dtal (TraceMempoolRemoveTxs txs mpSz) =
12671282
mconcat
@@ -1311,10 +1326,14 @@ instance
13111326
[ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz)
13121327
, IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz)
13131328
]
1314-
asMetrics (TraceMempoolRejectedTx _tx _txApplyErr _ mpSz) =
1329+
asMetrics ev@(TraceMempoolRejectedTx _tx _txApplyErr _details mpSz) =
13151330
[ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz)
13161331
, IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz)
13171332
]
1333+
++
1334+
[ CounterM txsMempoolTimeoutSoftCounterName Nothing
1335+
| impliesMempoolTimeoutSoft ev
1336+
]
13181337
asMetrics (TraceMempoolRemoveTxs txs mpSz) =
13191338
[ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz)
13201339
, IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz)
@@ -1370,6 +1389,7 @@ instance MetaTrace (TraceEventMempool blk) where
13701389
metricsDocFor (Namespace _ ["RejectedTx"]) =
13711390
[ ("txsInMempool","Transactions in mempool")
13721391
, ("mempoolBytes", "Byte size of the mempool")
1392+
, (txsMempoolTimeoutSoftCounterName, "Transactions that soft timed out in mempool")
13731393
]
13741394
metricsDocFor (Namespace _ ["RemoveTxs"]) =
13751395
[ ("txsInMempool","Transactions in mempool")

‎cardano-node/src/Cardano/Node/Tracing/Tracers/Diffusion.hs‎

Lines changed: 49 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,20 +3,26 @@
33
{-# LANGUAGE FlexibleContexts #-}
44
{-# LANGUAGE FlexibleInstances #-}
55
{-# LANGUAGE GADTs #-}
6+
{-# LANGUAGE LambdaCase #-}
67
{-# LANGUAGE NamedFieldPuns #-}
78
{-# LANGUAGE OverloadedStrings #-}
89
{-# LANGUAGE ScopedTypeVariables #-}
10+
{-# LANGUAGE TypeApplications #-}
911

1012

1113

1214
{-# OPTIONS_GHC -Wno-orphans #-}
1315

1416
module Cardano.Node.Tracing.Tracers.Diffusion
15-
() where
17+
( txsMempoolTimeoutHardCounterName
18+
, impliesMempoolTimeoutHard
19+
) where
1620

1721

1822
import Cardano.Logging
1923
import Cardano.Node.Configuration.TopologyP2P ()
24+
import Control.Exception (fromException)
25+
import Ouroboros.Consensus.Mempool.API (ExnMempoolTimeout)
2026
import qualified Ouroboros.Network.Diffusion.Types as Diff
2127
import Ouroboros.Network.PeerSelection.LedgerPeers (NumberOfPeers (..), PoolStake (..),
2228
TraceLedgerPeers (..))
@@ -356,6 +362,16 @@ instance MetaTrace Mux.ChannelTrace where
356362
, Namespace [] ["ChannelSendEnd"]
357363
]
358364

365+
txsMempoolTimeoutHardCounterName :: Text
366+
txsMempoolTimeoutHardCounterName = "txsMempoolTimeoutHard"
367+
368+
impliesMempoolTimeoutHard :: Mux.Trace -> Bool
369+
impliesMempoolTimeoutHard = \case
370+
Mux.TraceExceptionExit _mid _dir e
371+
| Just _ <- fromException @ExnMempoolTimeout e
372+
-> True
373+
_ -> False
374+
359375
instance LogFormatting Mux.Trace where
360376
forMachine _dtal (Mux.TraceState new) = mconcat
361377
[ "kind" .= String "Mux.TraceState"
@@ -435,6 +451,24 @@ instance LogFormatting Mux.Trace where
435451
forHuman Mux.TraceStopping = "Mux stopping"
436452
forHuman Mux.TraceStopped = "Mux stoppped"
437453

454+
asMetrics = \case
455+
Mux.TraceState{} -> []
456+
Mux.TraceCleanExit{} -> []
457+
ev@Mux.TraceExceptionExit{} ->
458+
-- Somewhat awkward to "catch" this Consensus exception here, but
459+
-- Diffusion Layer is indeed the ultimate manager of the per-peer
460+
-- threads.
461+
[ CounterM txsMempoolTimeoutHardCounterName Nothing
462+
| impliesMempoolTimeoutHard ev
463+
]
464+
Mux.TraceStartEagerly{} -> []
465+
Mux.TraceStartOnDemand{} -> []
466+
Mux.TraceStartOnDemandAny{} -> []
467+
Mux.TraceStartedOnDemand{} -> []
468+
Mux.TraceTerminating{} -> []
469+
Mux.TraceStopping{} -> []
470+
Mux.TraceStopped{} -> []
471+
438472
instance MetaTrace Mux.Trace where
439473
namespaceFor Mux.TraceState {} =
440474
Namespace [] ["State"]
@@ -491,6 +525,20 @@ instance MetaTrace Mux.Trace where
491525
"Mux shutdown."
492526
documentFor _ = Nothing
493527

528+
metricsDocFor (Namespace _ ["State"]) = []
529+
metricsDocFor (Namespace _ ["CleanExit"]) = []
530+
metricsDocFor (Namespace _ ["ExceptionExit"]) =
531+
[ (txsMempoolTimeoutHardCounterName, "Transactions that hard timed out in mempool")
532+
]
533+
metricsDocFor (Namespace _ ["StartEagerly"]) = []
534+
metricsDocFor (Namespace _ ["StartOnDemand"]) = []
535+
metricsDocFor (Namespace _ ["StartedOnDemand"]) = []
536+
metricsDocFor (Namespace _ ["StartOnDemandAny"]) = []
537+
metricsDocFor (Namespace _ ["Terminating"]) = []
538+
metricsDocFor (Namespace _ ["Stopping"]) = []
539+
metricsDocFor (Namespace _ ["Stopped"]) = []
540+
metricsDocFor _ = []
541+
494542
allNamespaces = [
495543
Namespace [] ["State"]
496544
, Namespace [] ["CleanExit"]

‎cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,8 @@ import Ouroboros.Consensus.Ledger.Inspect (InspectLedger, LedgerEvent
4444
import Ouroboros.Consensus.Ledger.SupportsMempool (ApplyTxErr, ByteSize32 (..), GenTx,
4545
GenTxId, HasTxId, LedgerSupportsMempool, TxId, txForgetValidated, txId)
4646
import Ouroboros.Consensus.Ledger.SupportsProtocol (LedgerSupportsProtocol)
47-
import Ouroboros.Consensus.Mempool (MempoolSize (..), TraceEventMempool (..))
47+
import Ouroboros.Consensus.Mempool (MempoolSize (..), TraceEventMempool (..),
48+
jsonMempoolRejectionDetails)
4849
import Ouroboros.Consensus.MiniProtocol.BlockFetch.Server
4950
(TraceBlockFetchServerEvent (..))
5051
import Ouroboros.Consensus.MiniProtocol.ChainSync.Client (TraceChainSyncClientEvent (..))
@@ -1543,14 +1544,15 @@ instance ( ToObject (ApplyTxErr blk), ToObject (GenTx blk),
15431544
, "tx" .= toObject verb (txForgetValidated tx)
15441545
, "mempoolSize" .= toObject verb mpSzAfter
15451546
]
1546-
toObject verb (TraceMempoolRejectedTx tx txApplyErr _ mpSz) =
1547+
toObject verb (TraceMempoolRejectedTx tx txApplyErr details mpSz) =
15471548
mconcat $
15481549
[ "kind" .= String "TraceMempoolRejectedTx"
15491550
, "tx" .= toObject verb tx
15501551
, "mempoolSize" .= toObject verb mpSz
15511552
] <>
1553+
if verb /= MaximalVerbosity then [] else
15521554
[ "err" .= toObject verb txApplyErr
1553-
| verb == MaximalVerbosity
1555+
, "errdetails" .= jsonMempoolRejectionDetails details
15541556
]
15551557
toObject verb (TraceMempoolRemoveTxs txs mpSz) =
15561558
mconcat

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

Lines changed: 56 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,8 @@ import Cardano.Node.Startup
4343
import qualified Cardano.Node.STM as STM
4444
import Cardano.Node.TraceConstraints
4545
import Cardano.Node.Tracing
46+
import qualified Cardano.Node.Tracing.Tracers.Consensus as ConsensusTracers
47+
import qualified Cardano.Node.Tracing.Tracers.Diffusion as DiffusionTracers
4648
import Cardano.Node.Tracing.Tracers.NodeVersion
4749
import Cardano.Network.Diffusion (CardanoPeerSelectionCounters)
4850
import Cardano.Protocol.TPraos.OCert (KESPeriod (..))
@@ -80,6 +82,8 @@ import qualified Ouroboros.Consensus.Storage.ChainDB as ChainDB
8082
import qualified Ouroboros.Consensus.Storage.LedgerDB as LedgerDB
8183
import Ouroboros.Consensus.Util.Enclose
8284

85+
import qualified Network.Mux as Mux
86+
8387
import qualified Cardano.Network.Diffusion.Types as Cardano.Diffusion
8488
import qualified Cardano.Network.PeerSelection.Governor.Types as Cardano
8589

@@ -388,7 +392,7 @@ mkTracers blockConfig tOpts@(TracingOnLegacy trSel) tr nodeKern ekgDirect = do
388392

389393
diffusionTracers :: Cardano.Diffusion.CardanoTracers IO
390394
diffusionTracers = Cardano.Diffusion.Tracers
391-
{ Diffusion.dtMuxTracer = muxTracer
395+
{ Diffusion.dtMuxTracer = muxTracer ekgDirect trSel tr
392396
, Diffusion.dtChannelTracer = channelTracer
393397
, Diffusion.dtBearerTracer = bearerTracer
394398
, Diffusion.dtHandshakeTracer = handshakeTracer
@@ -464,8 +468,6 @@ mkTracers blockConfig tOpts@(TracingOnLegacy trSel) tr nodeKern ekgDirect = do
464468
}
465469
verb :: TracingVerbosity
466470
verb = traceVerbosity trSel
467-
muxTracer =
468-
tracerOnOff (traceMux trSel) verb "Mux" tr
469471
channelTracer =
470472
tracerOnOff (traceMux trSel) verb "MuxChannel" tr
471473
bearerTracer =
@@ -537,6 +539,32 @@ mkTracers _ _ _ _ _ =
537539
, ledgerMetricsTracer = nullTracer
538540
}
539541

542+
--------------------------------------------------------------------------------
543+
-- Diffusion Layer Tracers
544+
--------------------------------------------------------------------------------
545+
546+
notifyTxsMempoolTimeoutHard :: Maybe EKGDirect -> Tracer IO Mux.Trace
547+
notifyTxsMempoolTimeoutHard mbEKGDirect = case mbEKGDirect of
548+
Nothing -> nullTracer
549+
Just ekgDirect -> Tracer $ \ev -> do
550+
when (DiffusionTracers.impliesMempoolTimeoutHard ev) $ do
551+
sendEKGDirectCounter ekgDirect DiffusionTracers.txsMempoolTimeoutHardCounterName
552+
553+
muxTracer
554+
:: Maybe EKGDirect
555+
-> TraceSelection
556+
-> Trace IO Text
557+
-> Tracer IO (Mux.WithBearer (ConnectionId RemoteAddress) Mux.Trace)
558+
muxTracer mbEKGDirect trSel tracer = Tracer $ \ev -> do
559+
-- Update the EKG metric even when this tracer is turned off.
560+
flip traceWith (Mux.wbEvent ev) $
561+
notifyTxsMempoolTimeoutHard mbEKGDirect
562+
whenOn (traceMux trSel) $ do
563+
flip traceWith ev $
564+
annotateSeverity $
565+
toLogObject' (traceVerbosity trSel) $
566+
appendName "Mux" tracer
567+
540568
--------------------------------------------------------------------------------
541569
-- Chain DB Tracers
542570
--------------------------------------------------------------------------------
@@ -796,7 +824,7 @@ mkConsensusTracers mbEKGDirect trSel verb tr nodeKern fStats = do
796824

797825
, Consensus.txOutboundTracer = tracerOnOff (traceTxOutbound trSel) verb "TxOutbound" tr
798826
, Consensus.localTxSubmissionServerTracer = tracerOnOff (traceLocalTxSubmissionServer trSel) verb "LocalTxSubmissionServer" tr
799-
, Consensus.mempoolTracer = tracerOnOff' (traceMempool trSel) $ mempoolTracer trSel tr fStats
827+
, Consensus.mempoolTracer = mempoolTracer mbEKGDirect trSel tr fStats
800828
, Consensus.forgeTracer = tracerOnOff' (traceForge trSel) $
801829
Tracer $ \tlcev@Consensus.TraceLabelCreds{} -> do
802830
traceWith (annotateSeverity
@@ -1243,6 +1271,15 @@ notifyBlockForging fStats tr = Tracer $ \case
12431271
-- Mempool Tracers
12441272
--------------------------------------------------------------------------------
12451273

1274+
notifyTxsMempoolTimeoutSoft ::
1275+
Maybe EKGDirect
1276+
-> Tracer IO (TraceEventMempool blk)
1277+
notifyTxsMempoolTimeoutSoft mbEKGDirect = case mbEKGDirect of
1278+
Nothing -> nullTracer
1279+
Just ekgDirect -> Tracer $ \ev -> do
1280+
when (ConsensusTracers.impliesMempoolTimeoutSoft ev) $ do
1281+
sendEKGDirectCounter ekgDirect ConsensusTracers.txsMempoolTimeoutSoftCounterName
1282+
12461283
notifyTxsProcessed :: ForgingStats -> Trace IO Text -> Tracer IO (TraceEventMempool blk)
12471284
notifyTxsProcessed fStats tr = Tracer $ \case
12481285
TraceMempoolRemoveTxs [] _ -> return ()
@@ -1263,9 +1300,9 @@ mempoolMetricsTraceTransformer :: Trace IO a -> Tracer IO (TraceEventMempool blk
12631300
mempoolMetricsTraceTransformer tr = Tracer $ \mempoolEvent -> do
12641301
let tr' = appendName "metrics" tr
12651302
(_n, tot_m) = case mempoolEvent of
1266-
TraceMempoolAddedTx _tx0 _ tot0 -> (1, Just tot0)
1303+
TraceMempoolAddedTx _tx0 _ tot0 -> (1, Just tot0)
12671304
TraceMempoolRejectedTx _tx0 _ _ tot0 -> (1, Just tot0)
1268-
TraceMempoolRemoveTxs txs0 tot0 -> (length txs0, Just tot0)
1305+
TraceMempoolRemoveTxs txs0 tot0 -> (length txs0, Just tot0)
12691306
TraceMempoolManuallyRemovedTxs txs0 txs1 tot0 -> ( length txs0 + length txs1, Just tot0)
12701307
TraceMempoolSynced _ -> (0, Nothing)
12711308
_ -> (0, Nothing)
@@ -1287,15 +1324,19 @@ mempoolTracer
12871324
, LedgerSupportsMempool blk
12881325
, ConvertRawHash blk
12891326
)
1290-
=> TraceSelection
1327+
=> Maybe EKGDirect
1328+
-> TraceSelection
12911329
-> Trace IO Text
12921330
-> ForgingStats
12931331
-> Tracer IO (TraceEventMempool blk)
1294-
mempoolTracer tc tracer fStats = Tracer $ \ev -> do
1295-
traceWith (mempoolMetricsTraceTransformer tracer) ev
1296-
traceWith (notifyTxsProcessed fStats tracer) ev
1297-
let tr = appendName "Mempool" tracer
1298-
traceWith (mpTracer tc tr) ev
1332+
mempoolTracer mbEKGDirect tc tracer fStats = Tracer $ \ev -> do
1333+
-- Update the EKG metric even when this tracer is turned off.
1334+
traceWith (notifyTxsMempoolTimeoutSoft mbEKGDirect) ev
1335+
whenOn (traceMempool tc) $ do
1336+
traceWith (mempoolMetricsTraceTransformer tracer) ev
1337+
traceWith (notifyTxsProcessed fStats tracer) ev
1338+
let tr = appendName "Mempool" tracer
1339+
traceWith (mpTracer tc tr) ev
12991340

13001341
mpTracer :: ( ToJSON (GenTxId blk)
13011342
, ToObject (ApplyTxErr blk)
@@ -1788,6 +1829,9 @@ tracerOnOff'
17881829
tracerOnOff' (OnOff False) _ = nullTracer
17891830
tracerOnOff' (OnOff True) tr = tr
17901831

1832+
whenOn :: Monad m => OnOff b -> m () -> m ()
1833+
whenOn (OnOff b) = when b
1834+
17911835
instance Show a => Show (WithSeverity a) where
17921836
show (WithSeverity _sev a) = show a
17931837

0 commit comments

Comments
 (0)