Block propagation metrics. #2476

karknu · 2021-03-11T07:59:40Z

Depends on IntersectMBO/ouroboros-network#2979

This PR implements 6 gauges and counters with data from the Blockfetch client.
All these gauges are derived from the first time we download a block for a given slot. Other blocks for that slot, or even the same block for that slot is ignored.

cardano_node_metrics_blockfetchclient_blockdelay_cdfOne, cardano_node_metrics_blockfetchclient_blockdelay_cdfThree, cardano_node_metrics_blockfetchclient_blockdelay_cdfFive
The gauges attempts to estimate the probability that we manage to download a block within 1s, 3s or 5s. 95% of blocks within 3s is a soft limit for a well operating node. 95% of all blocks within 5s is a hard limit for praos security.

cardano_node_metrics_blockfetchclient_blockdelay_s
This gauge estimated delay from when the block should have been forged until it was received by the local blockfetch client. This metric does not include the time it took for consensus/ledger to adopt the block (and it is possible that they never will adopt it).

cardano_node_metrics_blockfetchclient_blocksize
This gauge tracks the block size. This is the block size of the first time we downloaded a block for a given slot. due to forks it may not be the size of the block that ended up on the stable part of the chain. For that you need db-sync.

cardano_node_metrics_blockfetchclient_lateblocks
This counter tracks blocks that arrived more than 5s after they where supposed to have been forged.

njd42 · 2021-03-11T11:44:26Z

I see the calculation of 'success counts' here (i.e <1, <2, <5s) - but not 'failure' counts - should we also capture the count of those that are >5s? That would be a measure (or at least could become one) of the "data diffusion not timely enough" hazard being armed.

njd42

This is great as a tracking mechanism to track the data-diffusion-timeliness hazard; if we were to also track the >=5s arrival times that would potentially give deeper insight into outlier issues (e.g. misconfigured block producers with excessive clock skew, etc);

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

karknu · 2021-03-11T12:59:22Z

I've added a counter for tracking the number of blocks that arrive more than 5s late.

njd42

Looks good to me - accepting that the duration is a bit arbitrary and should be derived from chain details eventually; that's not critical at this point.

njd42 · 2021-03-15T12:08:59Z

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

+      cdf2s <- STM.readTVar cdf2sVar
+      cdf5s <- STM.readTVar cdf5sVar
+      return (fromIntegral cdf1s / fromIntegral size, fromIntegral cdf2s / fromIntegral size,
+              fromIntegral cdf5s / fromIntegral size)


I am assuming that the overall fraction of blocks received is tracked elsewhere - i.e. here it is a fraction, somewhere else we know the total population size...

That is tracked in slotMapVar which contains the k/2 latest blocks.

dcoutts

Mmm. Grumble. This seems quite expensive.

At minimum I think we should pull the CDF tracking out into a trace transformer so it's not all open-coded within the block fetch tracer.

We should stick TODOs on it to revisit this for efficiency once we have the improved metrics route.

The use of a finite map for a rolling buffer is overkill. At most it needs a FIFO queue. There are cheap implementations of that with O(1) amortised insert and delete.

dcoutts · 2021-03-18T10:11:22Z

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

+                 return True
+             else return False
+      when fresh $
+        sendEKGDirectDouble ekgDirect "cardano.node.metrics.blockfetchclient.blockdelay.s"


Why is this an EKG label metric rather than a guage metric (e.g. measured in microseconds or something)?

And do we really have to do an EKG store string lookup every time? 😬 Maybe that's just the way it is until we replace the EKG metrics reporting scheme.

Doubles can't be represented directly, so we have to dumb them down to strings -- gauges would be nicer, as they are integral.

dcoutts · 2021-03-18T10:14:10Z

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

+            sendEKGDirectDouble ekgDirect "cardano.node.metrics.blockfetchclient.blockdelay.s"
+                $ realToFrac delay
+            sendEKGDirectDouble ekgDirect "cardano.node.metrics.blockfetchclient.blockdelay.cdf1s"
+               cdf1s
+            sendEKGDirectDouble ekgDirect "cardano.node.metrics.blockfetchclient.blockdelay.cdf2s"
+               cdf2s
+            sendEKGDirectDouble ekgDirect "cardano.node.metrics.blockfetchclient.blockdelay.cdf5s"
+               cdf5s
+            when (delay > 5) $
+              sendEKGDirectCounter ekgDirect "cardano.node.metrics.blockfetchclient.lateblocks"


It's painful that this is so slow.

TODO added for when there is a faster way.

@dcoutts, @karknu, would you expect the new APIs to provide you with a way to acquire the EKG object once, and then repeatedly post updates to it?

We only currently consider ways to improve the performance without paying the (synchronisation) cost of modifyMVar (or equivalents) -- but we're not exposing EKG objects directly. We still expect to be performing a namespace map lookup per post.

The reason we didn't go for direct EKG exposure is for two reasons:

it would make for a less abstract, less uniform API

we don't expect a single map lookup (which is what the new version should boil down to) to be expensive -- the CPU sync/RTS cost of modifyMVar won't be there

Would you consider such a design unacceptable and would you like, instead, to (as mentioned above) operate on an once-acquired EKG object directly?

dcoutts · 2021-03-18T10:14:44Z

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

+              slotMap <- STM.readTVar slotMapVar
+              case SMap.lookup slotNo slotMap of
+                   Nothing -> do
+                     let slotMap' = SMap.insert slotNo delay slotMap


Note that SMap here is the non-strict Data.Map. We probably want the Data.Map.Strict

I've switched the SMap import to use Data.Map.Strict.

karknu · 2021-03-18T10:58:11Z

The use of a finite map for a rolling buffer is overkill. At most it needs a FIFO queue. There are cheap implementations of that with O(1) amortised insert and delete.

A finite size map is what is needed. Blocks don't arrive in order and we may attempt to fetch the same block more than once and in that case we only want to track the first to finish.

dcoutts · 2021-03-18T19:26:52Z

A finite size map is what is needed. Blocks don't arrive in order and we may attempt to fetch the same block more than once and in that case we only want to track the first to finish.

Fair enough. Then we'd want a priority queue.

karknu · 2021-03-18T20:55:01Z

Fair enough. Then we'd want a priority queue.

Agreed, a priority queue would work.

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

coot · 2021-04-06T08:40:41Z

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

+              case SMap.lookup slotNo slotMap of
+                   Nothing -> do
+                     let slotMap' = SMap.insert slotNo delay slotMap
+                     if SMap.size slotMap' > 1080 -- TODO k/2, should come from config file


Please open an issue for it, and add the issue number here.

coot

Just a few minor comments from me, other than that LGTM.

Do we have an issue (I'd prefer that over a TODO comment) that tracks:

We should stick TODOs on it to revisit this for efficiency once we have the improved metrics route.

@deepfire is metrics performance be improved by the new logging system?

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

coot · 2021-09-06T08:24:15Z

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

+
+    decCdfs :: NominalDiffTime -> Int -> STM ()
+    decCdfs delay size =
+      decCdfCounter delay size cdf1sVar


nicer indentation:

Suggested change

decCdfCounter delay size cdf1sVar

decCdfCounter delay size cdf1sVar

Rest of the file uses two space indentation.

deepfire · 2021-09-07T19:56:16Z

@deepfire is metrics performance be improved by the new logging system?

Yes, in two respects:

We're only doing namespace manipulations once per reconfiguration, not per trace call
We will either (depending on how our ongoing investigation concludes):
2.1 Avoid using a lock to get the EKG object, as done currently
2.2 Provide direct EKG object access, so you can post to it directly

In any case, we're currently working on benchmarking of the logging system -- and both systems will be directly comparable for some time (for as long as we don't remove the legacy one -- the transition period).

dcoutts

LGTM!

Calculate the CDF for 1s, 3s and 5s for the last 1080 blocks which corresponds to about 6h for mainnet.

A gauge for block sizes seen over the blockfetch protocol.

karknu · 2021-10-15T12:55:06Z

bors r+

iohk-bors · 2021-10-15T13:13:41Z

Build succeeded:

karknu force-pushed the karknu/blockdelay branch from bdf52d6 to 96c1e10 Compare March 11, 2021 11:14

njd42 requested changes Mar 11, 2021

View reviewed changes

cardano-node/src/Cardano/Tracing/Tracers.hs Outdated Show resolved Hide resolved

karknu force-pushed the karknu/blockdelay branch from 96c1e10 to 3d1b885 Compare March 11, 2021 12:57

karknu force-pushed the karknu/blockdelay branch from 3d1b885 to 4040614 Compare March 15, 2021 11:02

njd42 approved these changes Mar 15, 2021

View reviewed changes

karknu force-pushed the karknu/blockdelay branch 4 times, most recently from 91d432d to 4500594 Compare March 16, 2021 14:54

karknu marked this pull request as ready for review March 16, 2021 15:20

karknu requested review from DavidEichmann, dcoutts, erikd, Jimbo4350 and newhoggy as code owners March 16, 2021 15:20

karknu force-pushed the karknu/blockdelay branch from 4500594 to e546ad2 Compare March 18, 2021 07:02

dcoutts requested changes Mar 18, 2021

View reviewed changes

karknu force-pushed the karknu/blockdelay branch 2 times, most recently from 5894b89 to 60997d5 Compare March 25, 2021 12:40

karknu requested a review from dcoutts March 25, 2021 13:01

karknu force-pushed the karknu/blockdelay branch 2 times, most recently from 1b2ae57 to f6b0f00 Compare March 30, 2021 08:36

coot reviewed Apr 6, 2021

View reviewed changes

karknu force-pushed the karknu/blockdelay branch from f6b0f00 to 1c756ca Compare April 26, 2021 11:11

karknu mentioned this pull request May 10, 2021

Rebase onto 1.26.2 & review #2687

Merged

karknu force-pushed the karknu/blockdelay branch from 1c756ca to 60aa834 Compare September 6, 2021 07:01

karknu requested review from JaredCorduan and nc6 as code owners September 6, 2021 07:01

coot approved these changes Sep 6, 2021

View reviewed changes

karknu force-pushed the karknu/blockdelay branch 2 times, most recently from a66659b to 1a8d6c9 Compare September 20, 2021 19:14

karknu force-pushed the karknu/blockdelay branch from 1a8d6c9 to 6806104 Compare October 14, 2021 08:23

dcoutts approved these changes Oct 15, 2021

View reviewed changes

karknu added 3 commits October 15, 2021 13:02

Add a counter block propagation delay

142d0be

Calculate the CDF for 1s, 3s and 5s for block delay

27b9585

Calculate the CDF for 1s, 3s and 5s for the last 1080 blocks which corresponds to about 6h for mainnet.

Implement block size gauge

ea8a8f1

A gauge for block sizes seen over the blockfetch protocol.

karknu force-pushed the karknu/blockdelay branch from 6806104 to ea8a8f1 Compare October 15, 2021 11:14

iohk-bors bot merged commit 6405d71 into master Oct 15, 2021

iohk-bors bot deleted the karknu/blockdelay branch October 15, 2021 13:13

btbf mentioned this pull request Aug 8, 2022

Grafanaダッシュボード改善およびSJGWebサイトへ掲載希望 btbf/spojapanguild#203

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Block propagation metrics. #2476

Block propagation metrics. #2476

karknu commented Mar 11, 2021 •

edited

Loading

njd42 commented Mar 11, 2021

njd42 left a comment

karknu commented Mar 11, 2021

njd42 left a comment

njd42 Mar 15, 2021

karknu Mar 15, 2021

dcoutts left a comment

dcoutts Mar 18, 2021

deepfire Sep 7, 2021

dcoutts Mar 18, 2021

karknu Mar 25, 2021

deepfire Sep 7, 2021 •

edited

Loading

dcoutts Mar 18, 2021

karknu Mar 25, 2021

karknu commented Mar 18, 2021 •

edited

Loading

dcoutts commented Mar 18, 2021

karknu commented Mar 18, 2021

coot Apr 6, 2021

coot left a comment

coot Sep 6, 2021

karknu Sep 6, 2021

deepfire commented Sep 7, 2021 •

edited

Loading

dcoutts left a comment

karknu commented Oct 15, 2021

iohk-bors bot commented Oct 15, 2021

	decCdfCounter delay size cdf1sVar
	decCdfCounter delay size cdf1sVar

Block propagation metrics. #2476

Block propagation metrics. #2476

Conversation

karknu commented Mar 11, 2021 • edited Loading

njd42 commented Mar 11, 2021

njd42 left a comment

Choose a reason for hiding this comment

karknu commented Mar 11, 2021

njd42 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dcoutts left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

deepfire Sep 7, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

karknu commented Mar 18, 2021 • edited Loading

dcoutts commented Mar 18, 2021

karknu commented Mar 18, 2021

Choose a reason for hiding this comment

coot left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

deepfire commented Sep 7, 2021 • edited Loading

dcoutts left a comment

Choose a reason for hiding this comment

karknu commented Oct 15, 2021

iohk-bors bot commented Oct 15, 2021

karknu commented Mar 11, 2021 •

edited

Loading

deepfire Sep 7, 2021 •

edited

Loading

karknu commented Mar 18, 2021 •

edited

Loading

deepfire commented Sep 7, 2021 •

edited

Loading