Skip to content

Commit 2363a53

Browse files
nfrisbynfrisby
committed
Add txsMempoolTimeoutSoft and txsMempoolTimeoutHard counters
1 parent e866317 commit 2363a53

File tree

9 files changed

+187
-16
lines changed

9 files changed

+187
-16
lines changed

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

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,8 @@ module Cardano.Node.Tracing.Tracers.Consensus
1818
, calculateBlockFetchClientMetrics
1919
, servedBlockLatest
2020
, ClientMetrics
21+
, txsMempoolTimeoutSoftCounterName
22+
, impliesMempoolTimeoutSoft
2123
) where
2224

2325

@@ -1241,6 +1243,17 @@ instance MetaTrace (TraceLocalTxSubmissionServerEvent blk) where
12411243
-- Mempool Tracer
12421244
--------------------------------------------------------------------------------
12431245

1246+
txsMempoolTimeoutSoftCounterName :: Text.Text
1247+
txsMempoolTimeoutSoftCounterName = "txsMempoolTimeoutSoft"
1248+
1249+
impliesMempoolTimeoutSoft ::
1250+
LedgerSupportsMempool blk => TraceEventMempool blk -> Bool
1251+
impliesMempoolTimeoutSoft = \case
1252+
TraceMempoolRejectedTx _tx txApplyErr _mpSz ->
1253+
-- TODO export a proper predicate from Consensus
1254+
"ApplyTxError (ConwayMempoolFailure" `List.isPrefixOf` show txApplyErr
1255+
_ -> False
1256+
12441257
instance
12451258
( LogFormatting (ApplyTxErr blk)
12461259
, LogFormatting (GenTx blk)
@@ -1311,10 +1324,14 @@ instance
13111324
[ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz)
13121325
, IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz)
13131326
]
1314-
asMetrics (TraceMempoolRejectedTx _tx _txApplyErr mpSz) =
1327+
asMetrics ev@(TraceMempoolRejectedTx _tx _txApplyErr mpSz) =
13151328
[ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz)
13161329
, IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz)
13171330
]
1331+
++
1332+
[ CounterM txsMempoolTimeoutSoftCounterName Nothing
1333+
| impliesMempoolTimeoutSoft ev
1334+
]
13181335
asMetrics (TraceMempoolRemoveTxs txs mpSz) =
13191336
[ IntM "txsInMempool" (fromIntegral $ msNumTxs mpSz)
13201337
, IntM "mempoolBytes" (fromIntegral . unByteSize32 . msNumBytes $ mpSz)
@@ -1370,6 +1387,7 @@ instance MetaTrace (TraceEventMempool blk) where
13701387
metricsDocFor (Namespace _ ["RejectedTx"]) =
13711388
[ ("txsInMempool","Transactions in mempool")
13721389
, ("mempoolBytes", "Byte size of the mempool")
1390+
, (txsMempoolTimeoutSoftCounterName, "Transactions that soft timed out in mempool")
13731391
]
13741392
metricsDocFor (Namespace _ ["RemoveTxs"]) =
13751393
[ ("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/Metrics.hs‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,8 @@
1414
module Cardano.Tracing.Metrics
1515
( ForgingStats (..)
1616
, ForgeThreadStats (..)
17+
, incrForgingStatsTxsMempoolTimeoutHard
18+
, incrForgingStatsTxsMempoolTimeoutSoft
1719
, mapForgingCurrentThreadStats
1820
, mapForgingCurrentThreadStats_
1921
, mapForgingStatsTxsProcessed
@@ -41,6 +43,10 @@ data ForgingStats
4143
, fsState :: !(TVar (Map ThreadId (TVar ForgeThreadStats)))
4244
, fsBlocksUncoupled :: !(TVar Int64)
4345
-- ^ Blocks forged since last restart not on the current chain
46+
, fsTxsMempoolTimeoutSoft :: !(IORef Int)
47+
-- ^ Transactions that soft timed out in the mempool.
48+
, fsTxsMempoolTimeoutHard :: !(IORef Int)
49+
-- ^ Transactions that hard timed out in the mempool.
4450
}
4551

4652
-- | Per-forging-thread statistics.
@@ -65,6 +71,18 @@ mkForgingStats =
6571
<$> newIORef 0
6672
<*> newTVarIO mempty
6773
<*> newTVarIO 0
74+
<*> newIORef 0
75+
<*> newIORef 0
76+
77+
incrForgingStatsTxsMempoolTimeoutSoft :: ForgingStats -> IO Int
78+
incrForgingStatsTxsMempoolTimeoutSoft fs =
79+
atomicModifyIORef' (fsTxsMempoolTimeoutSoft fs) $
80+
\txCount -> join (,) $ txCount + 1
81+
82+
incrForgingStatsTxsMempoolTimeoutHard :: ForgingStats -> IO Int
83+
incrForgingStatsTxsMempoolTimeoutHard fs =
84+
atomicModifyIORef' (fsTxsMempoolTimeoutHard fs) $
85+
\txCount -> join (,) $ txCount + 1
6886

6987
mapForgingStatsTxsProcessed ::
7088
ForgingStats

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

Lines changed: 69 additions & 11 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

@@ -345,7 +349,7 @@ mkTracers blockConfig tOpts@(TracingOnLegacy trSel) tr nodeKern ekgDirect = do
345349
, consensusTracers = consensusTracers
346350
, nodeToClientTracers = nodeToClientTracers' trSel verb tr
347351
, nodeToNodeTracers = nodeToNodeTracers' trSel verb tr
348-
, diffusionTracers
352+
, diffusionTracers = diffusionTracers fStats
349353
, churnModeTracer
350354
-- TODO: startupTracer should ignore severity level (i.e. it should always
351355
-- be printed)!
@@ -386,9 +390,9 @@ mkTracers blockConfig tOpts@(TracingOnLegacy trSel) tr nodeKern ekgDirect = do
386390
(getCardanoBuildInfo ev)
387391
Nothing -> pure ()
388392

389-
diffusionTracers :: Cardano.Diffusion.CardanoTracers IO
390-
diffusionTracers = Cardano.Diffusion.Tracers
391-
{ Diffusion.dtMuxTracer = muxTracer
393+
diffusionTracers :: ForgingStats -> Cardano.Diffusion.CardanoTracers IO
394+
diffusionTracers fStats = Cardano.Diffusion.Tracers
395+
{ Diffusion.dtMuxTracer = muxTracer ekgDirect trSel tr fStats
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,26 @@ mkTracers _ _ _ _ _ =
537539
, ledgerMetricsTracer = nullTracer
538540
}
539541

542+
--------------------------------------------------------------------------------
543+
-- Diffusion Layer Tracers
544+
--------------------------------------------------------------------------------
545+
546+
muxTracer
547+
:: Maybe EKGDirect
548+
-> TraceSelection
549+
-> Trace IO Text
550+
-> ForgingStats
551+
-> Tracer IO (Mux.WithBearer (ConnectionId RemoteAddress) Mux.Trace)
552+
muxTracer mbEKGDirect trSel tracer fStats = Tracer $ \ev -> do
553+
-- Update the EKG tracer even when this tracer is turned off.
554+
flip traceWith (Mux.wbEvent ev) $
555+
notifyTxsMempoolTimeoutHard mbEKGDirect fStats tracer
556+
whenOn (traceMux trSel) $ do
557+
flip traceWith ev $
558+
annotateSeverity $
559+
toLogObject' (traceVerbosity trSel) $
560+
appendName "Mux" tracer
561+
540562
--------------------------------------------------------------------------------
541563
-- Chain DB Tracers
542564
--------------------------------------------------------------------------------
@@ -796,7 +818,7 @@ mkConsensusTracers mbEKGDirect trSel verb tr nodeKern fStats = do
796818

797819
, Consensus.txOutboundTracer = tracerOnOff (traceTxOutbound trSel) verb "TxOutbound" tr
798820
, Consensus.localTxSubmissionServerTracer = tracerOnOff (traceLocalTxSubmissionServer trSel) verb "LocalTxSubmissionServer" tr
799-
, Consensus.mempoolTracer = tracerOnOff' (traceMempool trSel) $ mempoolTracer trSel tr fStats
821+
, Consensus.mempoolTracer = mempoolTracer mbEKGDirect trSel tr fStats
800822
, Consensus.forgeTracer = tracerOnOff' (traceForge trSel) $
801823
Tracer $ \tlcev@Consensus.TraceLabelCreds{} -> do
802824
traceWith (annotateSeverity
@@ -1243,6 +1265,35 @@ notifyBlockForging fStats tr = Tracer $ \case
12431265
-- Mempool Tracers
12441266
--------------------------------------------------------------------------------
12451267

1268+
notifyTxsMempoolTimeoutSoft ::
1269+
LedgerSupportsMempool blk
1270+
=> Maybe EKGDirect
1271+
-> ForgingStats
1272+
-> Trace IO Text
1273+
-> Tracer IO (TraceEventMempool blk)
1274+
notifyTxsMempoolTimeoutSoft mbEKGDirect fStats tr = case mbEKGDirect of
1275+
Nothing -> nullTracer
1276+
Just ekgDirect -> Tracer $ \ev -> do
1277+
when (ConsensusTracers.impliesMempoolTimeoutSoft ev) $ do
1278+
n <- incrForgingStatsTxsMempoolTimeoutSoft fStats
1279+
let nm = ConsensusTracers.txsMempoolTimeoutSoftCounterName
1280+
sendEKGDirectCounter ekgDirect nm
1281+
traceCounter nm tr (fromIntegral n)
1282+
1283+
notifyTxsMempoolTimeoutHard ::
1284+
Maybe EKGDirect
1285+
-> ForgingStats
1286+
-> Trace IO Text
1287+
-> Tracer IO Mux.Trace
1288+
notifyTxsMempoolTimeoutHard mbEKGDirect fStats tr = case mbEKGDirect of
1289+
Nothing -> nullTracer
1290+
Just ekgDirect -> Tracer $ \ev -> do
1291+
when (DiffusionTracers.impliesMempoolTimeoutHard ev) $ do
1292+
n <- incrForgingStatsTxsMempoolTimeoutHard fStats
1293+
let nm = DiffusionTracers.txsMempoolTimeoutHardCounterName
1294+
sendEKGDirectCounter ekgDirect nm
1295+
traceCounter nm tr (fromIntegral n)
1296+
12461297
notifyTxsProcessed :: ForgingStats -> Trace IO Text -> Tracer IO (TraceEventMempool blk)
12471298
notifyTxsProcessed fStats tr = Tracer $ \case
12481299
TraceMempoolRemoveTxs [] _ -> return ()
@@ -1287,13 +1338,17 @@ mempoolTracer
12871338
, LedgerSupportsMempool blk
12881339
, ConvertRawHash blk
12891340
)
1290-
=> TraceSelection
1341+
=> Maybe EKGDirect
1342+
-> TraceSelection
12911343
-> Trace IO Text
12921344
-> ForgingStats
12931345
-> Tracer IO (TraceEventMempool blk)
1294-
mempoolTracer tc tracer fStats = Tracer $ \ev -> do
1295-
traceWith (mempoolMetricsTraceTransformer tracer) ev
1296-
traceWith (notifyTxsProcessed fStats tracer) ev
1346+
mempoolTracer mbEKGDirect tc tracer fStats = Tracer $ \ev -> do
1347+
-- Update the EKG tracer even when this tracer is turned off.
1348+
traceWith (notifyTxsMempoolTimeoutSoft mbEKGDirect fStats tracer) ev
1349+
whenOn (traceMempool tc) $ do
1350+
traceWith (mempoolMetricsTraceTransformer tracer) ev
1351+
traceWith (notifyTxsProcessed fStats tracer) ev
12971352
let tr = appendName "Mempool" tracer
12981353
traceWith (mpTracer tc tr) ev
12991354

@@ -1788,6 +1843,9 @@ tracerOnOff'
17881843
tracerOnOff' (OnOff False) _ = nullTracer
17891844
tracerOnOff' (OnOff True) tr = tr
17901845

1846+
whenOn :: Monad m => OnOff b -> m () -> m ()
1847+
whenOn (OnOff b) = when b
1848+
17911849
instance Show a => Show (WithSeverity a) where
17921850
show (WithSeverity _sev a) = show a
17931851

‎cardano-tracer/src/Cardano/Tracer/Handlers/RTView/State/Historical.hs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -124,6 +124,8 @@ data DataName
124124
| TxsProcessedNumData
125125
| MempoolBytesData
126126
| TxsInMempoolData
127+
| TxsMempoolTimeoutSoftData
128+
| TxsMempoolTimeoutHardData
127129
deriving (Eq, Ord, Read, Show)
128130

129131
type HistoricalData = Map DataName HistoricalPoints

‎cardano-tracer/src/Cardano/Tracer/Handlers/RTView/UI/Charts.hs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -320,6 +320,8 @@ dataNameToChartId dataName =
320320
TxsProcessedNumData -> TxsProcessedNumChart
321321
MempoolBytesData -> MempoolBytesChart
322322
TxsInMempoolData -> TxsInMempoolChart
323+
TxsMempoolTimeoutSoftData -> TxsMempoolTimeoutSoftChart
324+
TxsMempoolTimeoutHardData -> TxsMempoolTimeoutHardChart
323325

324326
getSavedColorForNode
325327
:: TracerEnv

0 commit comments

Comments
 (0)