diff --git a/CODEOWNERS b/CODEOWNERS index b1a42ae7dca..d6886d94163 100644 --- a/CODEOWNERS +++ b/CODEOWNERS @@ -20,13 +20,12 @@ doc @docs-access README.* @docs-access bench/tx-generator @deepfire @MarcFontaine -bench @deepfire @denisshevchenko @jutaro @MarcFontaine @cleverca22 +bench @deepfire @denisshevchenko @jutaro @MarcFontaine @mgmeier @cleverca22 cardano-tracer @deepfire @denisshevchenko -nix/workbench @deepfire @denisshevchenko @jutaro @MarcFontaine -nix/supervisord-cluster @deepfire @denisshevchenko @jutaro @MarcFontaine -trace-dispatcher @deepfire @denisshevchenko @jutaro -trace-forward @deepfire @denisshevchenko @jutaro -trace-resources @deepfire @denisshevchenko @jutaro +nix/workbench @deepfire @denisshevchenko @jutaro @MarcFontaine @mgmeier +trace-dispatcher @deepfire @denisshevchenko @jutaro @mgmeier +trace-forward @deepfire @denisshevchenko @jutaro @mgmeier +trace-resources @deepfire @denisshevchenko @jutaro @mgmeier Makefile @deepfire .buildkite @devops diff --git a/Makefile b/Makefile index 970c4887bb4..29964da17e8 100644 --- a/Makefile +++ b/Makefile @@ -1,118 +1,74 @@ +help: ## Print documentation + @{ grep -hE '^[a-zA-Z0-9_-]+:.*?## .*$$' $(MAKEFILE_LIST); echo -e '$(EXTRA_HELP)'; } | sed 's/^ //' | sort | awk 'BEGIN {FS = ":.*?## "}; {printf "\033[36m%-30s\033[0m %s\n", $$1, $$2}' + +include lib.mk +include nix.mk +include legacy.mk + PROJECT_NAME = cardano-node NUM_PROC = $(nproc --all) ## One of: shey alra mary alzo -ERA ?= alzo +ERA ?= alzo -CLUSTER_PROFILE ?= default-${ERA} -ifneq "${CLUSTER_PROFILE}" "default-${ERA}" -$(warning DEPRECATED: CLUSTER_PROFILE is deprecated, please use PROFILE) -endif - -PROFILE ?= ${CLUSTER_PROFILE} +PROFILE ?= default-${ERA} REV ?= master ARGS ?= +CMD ?= - -help: ## Print documentation - @grep -E '^[a-zA-Z0-9_-]+:.*?## .*$$' $(MAKEFILE_LIST) | sort | awk 'BEGIN {FS = ":.*?## "}; {printf "\033[36m%-30s\033[0m %s\n", $$1, $$2}' +lint hlint: + hlint . stylish-haskell: ## Apply stylish-haskell on all *.hs files - @find . -type f -name "*.hs" -not -path '.git' -not -path '*.stack-work*' -print0 | xargs -0 stylish-haskell -i + @find . -type f -name "*.hs" -not -path '.git' -print0 | xargs -0 stylish-haskell -i cabal-hashes: nix run .#checkCabalProject -ghci: ## Run repl - @stack ghci $(PROJECT_NAME):lib --haddock-deps --ghci-options=-fobject-code --nix - -ghcid: ## Run ghcid - @ghcid --command "stack ghci $(PROJECT_NAME):lib --nix -j12 --ghci-options=-fobject-code" - -run-test: ## Build & run test - @stack build --fast --nix && \ - stack test --fast --nix - -test-ghci: ## Run repl on test suites - @stack ghci $(PROJECT_NAME):lib $(PROJECT_NAME):test:$(PROJECT_NAME)-test --ghci-options=-fobject-code --nix - -test-ghcid: ## Run ghcid on test suites - @ghcid --command "stack ghci --nix $(PROJECT_NAME):lib $(PROJECT_NAME):test:$(PROJECT_NAME)-test --ghci-options=-fobject-code" - -test-ghcid-nix: ## Run ghcid on test suites with Nix - @ghcid --command="stack ghci --test --main-is $(PROJECT_NAME):test:$(PROJECT_NAME)-test --nix -j$(NUM_PROC)" - -bench-chainsync: PROFILE=chainsync-${ERA} -bench-chainsync: cluster-shell-dev ## Enter Nix shell and start the chainsync benchmark - -## TODO: migrate to `nix develop` -cluster-shell: ## Enter Nix shell and start the workbench cluster - nix-shell --max-jobs 8 --cores 0 --show-trace --argstr profileName ${PROFILE} --arg 'autoStartCluster' true - -shell-dev: ARGS += --arg 'workbenchDevMode' true ## Enter Nix shell, dev mode (workbench run from checkout) -cluster-shell: ARGS += --arg 'autoStartCluster' true ## Enter Nix shell, and start workbench cluster -cluster-shell-dev: ARGS += --arg 'autoStartCluster' true --arg 'workbenchDevMode' true ## Enter Nix shell, dev mode, and start workbench cluster -cluster-shell-trace: ARGS += --arg 'autoStartCluster' true --argstr 'autoStartClusterArgs' '--trace --trace-workbench' ## Enter Nix shell, start workbench cluster, with shell tracing -cluster-shell-dev-trace: ARGS += --arg 'autoStartCluster' true --arg 'workbenchDevMode' true --argstr 'autoStartClusterArgs' '--trace --trace-workbench' ## Enter Nix shell, dev mode, start workbench cluster, with shell tracing -fixed: PROFILE = fixed-${ERA} -fixed: ARGS += --arg 'autoStartCluster' true -forge-stress: PROFILE = forge-stress-${ERA} -forge-stress: ARGS += --arg 'workbenchDevMode' true -quick: PROFILE = quick-${ERA} -quick: ARGS += --arg 'workbenchDevMode' true -shell-dev cluster-shell-dev cluster-shell-trace cluster-shell-dev-trace fixed forge-stress quick: shell - -test-smoke: smoke ## Build the 'workbench-smoke-test', same as the Hydra job -smoke: - nix build -f 'default.nix' 'workbench-smoke-test' --out-link result-smoke-run --cores 0 -test-analysis: smoke-analysis ## Build the 'workbench-smoke-analysis', same as the Hydra job -smoke-analysis: - nix build -f 'default.nix' 'workbench-smoke-analysis' --out-link result-smoke-analysis --cores 0 --show-trace -ci-analysis: - nix build -f 'default.nix' 'workbench-ci-analysis' --out-link result-ci-analysis --cores 0 --show-trace - -list-profiles: ## List workbench profiles - nix build .#workbench.profile-names-json --json | jq '.[0].outputs.out' -r | xargs jq . -show-profile: ## NAME=profile-name - @test -n "${NAME}" || { echo 'HELP: to specify profile to show, add NAME=profle-name' && exit 1; } - nix build .#all-profiles-json --json --option substitute false | jq '.[0].outputs.out' -r | xargs jq ".\"${NAME}\" | if . == null then error(\"\n###\n### Error: unknown profile: ${NAME} Please consult: make list-profiles\n###\") else . end" -ps: list-profiles - -bump-cardano-node-workbench: ## Update the cardano-node-workbench flake input - nix flake lock --update-input cardano-node-workbench -bump-node-measured: ## Update the node-measured flake input - nix flake lock --update-input node-measured -bump-cardano-deployment: ## Sync the flake.lock to the CI check - nix run nixpkgs#nixUnstable -- build .#hydraJobs.cardano-deployment -membench-1: ## Membench: one iteration, current commit - nix build .#membench-node-this-1.batch-report --out-link result-batch-1-report -membench-1-at: ## Membench: one iteration, set commit by: make membench-1-at REV=[master] - nix build .#membench-node-measured-1.batch-report --out-link result-batch-1-report --override-input node-measured github:input-output-hk/cardano-node/${REV} -membench-5: ## Membench: 5 iterations, current commit - nix build .#membench-node-this-5.batch-report --out-link result-batch-5-report -membench-5-at: ## Membench: 5 iterations, set commit by: make membench-5-at REV=[master] - nix build .#membench-node-this-5.batch-report --out-link result-batch-5-report --override-input node-measured github:input-output-hk/cardano-node/${REV} - -shell: ## Enter Nix shell, CI mode (workbench run from Nix store) - nix-shell --max-jobs 8 --cores 0 --show-trace --argstr profileName ${PROFILE} ${ARGS} - cli node: cabal --ghc-options="+RTS -qn8 -A32M -RTS" build cardano-$@ trace-documentation: cabal run -- exe:cardano-node trace-documentation --config 'configuration/cardano/mainnet-config-new-tracing.yaml' --output-file 'doc/new-tracing/tracers_doc_generated.md' -BENCH_REPEATS ?= 3 -BENCH_CONFIG ?= both -BENCH_TAG ?= HEAD -BENCH_XARGS ?= +### +### Workbench +### +## +## Base targets: +## +shell: ## Nix shell, CI mode (from Nix store), vars: PROFILE, CMD + nix-shell --max-jobs 8 --cores 0 --show-trace --argstr profileName ${PROFILE} ${ARGS} ${if ${CMD},--run "${CMD}"} +shell-dev: shell +shell-dev: ARGS += --arg 'workbenchDevMode' true ## Nix shell, dev mode (from checkout), vars: PROFILE, CMD + +list-profiles: ## List workbench profiles + nix build .#workbench.profile-names-json --json | jq '.[0].outputs.out' -r | xargs jq . +show-profile: ## NAME=profile-name + @test -n "${NAME}" || { echo 'HELP: to specify profile to show, add NAME=profle-name' && exit 1; } + nix build .#all-profiles-json --json --option substitute false | jq '.[0].outputs.out' -r | xargs jq ".\"${NAME}\" | if . == null then error(\"\n###\n### Error: unknown profile: ${NAME} Please consult: make list-profiles\n###\") else . end" +ps: ## Plain-text list of profiles + @nix build .#workbench.profile-names-json --json | jq '.[0].outputs.out' -r | xargs jq '.[]' --raw-output + +## +## Profile-based cluster shells (autogenerated targets) +## +SHELL_PROFILES += fixed +SHELL_PROFILES += quick quick-oldtracing + +SHELL_PROFILES += forge-stress forge-stress-plutus forge-stress-oldtracing + +SHELL_PROFILES += chainsync-early-byron chainsync-early-byron-oldtracing +SHELL_PROFILES += chainsync-early-alonzo chainsync-early-alonzo-oldtracing + +## Note: to enable a shell for a profile, just add its name (one of names from 'make ps') to SHELL_PROFILES -profile-chainsync: - scripts/mainnet-via-fetcher.sh ${BENCH_XARGS} --node-config-${BENCH_CONFIG} --repeats ${BENCH_REPEATS} --nix --profile time --tag ${BENCH_TAG} +$(eval $(call define_profile_targets,$(SHELL_PROFILES))) -profile-chainsync-fast: BENCH_XARGS=--skip-prefetch -profile-chainsync-fast: profile-chainsync +### +### Misc +### clean-profile proclean: rm -f *.html *.prof *.hp *.stats *.eventlog @@ -120,9 +76,9 @@ clean: clean-profile rm -rf logs/ socket/ cluster.* full-clean: clean - rm -rf db dist-newstyle .stack-work $(shell find . -name '*~' -or -name '*.swp') + rm -rf db dist-newstyle $(shell find . -name '*~' -or -name '*.swp') cls: echo -en "\ec" -.PHONY: bench-chainsync cabal-hashes clean cli cls cluster-profiles cluster-shell cluster-shell-dev cluster-shell-dev-trace cluster-shell-trace ghci ghcid help node run-test shell shell-dev stylish-haskell test-ghci test-ghcid test-ghcid-nix +.PHONY: cabal-hashes clean cli cls cluster-profiles cluster-shell help node run-test shell shell-dev stylish-haskell diff --git a/bench/locli/locli.cabal b/bench/locli/locli.cabal index 9e2ef8ebbe5..89f2cedd9f9 100644 --- a/bench/locli/locli.cabal +++ b/bench/locli/locli.cabal @@ -47,6 +47,7 @@ library , bytestring , cardano-git-rev , cardano-prelude + , cardano-ledger-core , iohk-monitoring , cardano-slotting , containers diff --git a/bench/locli/src/Cardano/Analysis/API.hs b/bench/locli/src/Cardano/Analysis/API.hs index 512d3469f21..2397b096341 100644 --- a/bench/locli/src/Cardano/Analysis/API.hs +++ b/bench/locli/src/Cardano/Analysis/API.hs @@ -2,7 +2,10 @@ {-# LANGUAGE DeriveGeneric #-} {-# OPTIONS_GHC -Wno-name-shadowing #-} {- HLINT ignore "Use head" -} -module Cardano.Analysis.API (module Cardano.Analysis.API) where +module Cardano.Analysis.API + ( module Cardano.Analysis.API + , module Cardano.Util) +where import Prelude ((!!), error) import Cardano.Prelude hiding (head) @@ -11,8 +14,7 @@ import Data.Aeson (ToJSON(..), FromJSON(..)) import Data.Text qualified as T import Data.Text.Short (toText) import Data.Time.Clock (NominalDiffTime) -import Data.Time (UTCTime) -import Text.Printf (PrintfArg, printf) +import Text.Printf (PrintfArg) import Cardano.Analysis.Chain import Cardano.Analysis.ChainFilter @@ -22,6 +24,7 @@ import Cardano.Analysis.Version import Cardano.Logging.Resources.Types import Cardano.Unlog.LogObject hiding (Text) import Cardano.Unlog.Render +import Cardano.Util import Data.Distribution @@ -60,7 +63,7 @@ data BlockEvents , beBlockNo :: !BlockNo , beSlotNo :: !SlotNo , beEpochNo :: !EpochNo - , beEpochSafeInt :: !EpochSafeInt + , beEpochSafeInt :: !EpochSafeInt , beForge :: !BlockForge , beObservations :: [BlockObservation] , bePropagation :: !(Distribution Float NominalDiffTime) @@ -195,12 +198,11 @@ data SlotStats , slRejectedTx :: !Word64 , slBlockNo :: !Word64 , slBlockless :: !Word64 - , slEarliest :: !UTCTime - , slSpanCheck :: !NominalDiffTime - , slSpanLead :: !NominalDiffTime - , slSpanForge :: !NominalDiffTime + , slSpanCheck :: !(StrictMaybe NominalDiffTime) + , slSpanLead :: !(StrictMaybe NominalDiffTime) + , slSpanForge :: !(StrictMaybe NominalDiffTime) , slMempoolTxs :: !Word64 - , slTxsMemSpan :: !(Maybe NominalDiffTime) + , slSpanTxsMem :: !(StrictMaybe NominalDiffTime) , slTxsCollected :: !Word64 , slTxsAccepted :: !Word64 , slTxsRejected :: !Word64 @@ -420,10 +422,10 @@ instance RenderTimeline SlotStats where , Field 3 0 "forges" "For" "ge" $ IWord64 slCountForges , Field 4 0 "CDBSnap" "CDB" "snap" $ IWord64 slChainDBSnap , Field 3 0 "rejTxs" "rej" "txs" $ IWord64 slRejectedTx - , Field 7 0 "checkSpan" "check" "span" $ IDeltaT slSpanCheck - , Field 5 0 "leadSpan" "lead" "span" $ IDeltaT slSpanLead - , Field 5 0 "forgeSpan" "forg" "span" $ IDeltaT slSpanForge - , Field 4 0 "mempoolTxSpan" (t 4!!0) "span" $ IText (maybe "" show.slTxsMemSpan) + , Field 7 0 "checkSpan" "check" "span" $ IText (smaybe "" show.slSpanCheck) + , Field 5 0 "leadSpan" "lead" "span" $ IText (smaybe "" show.slSpanLead) + , Field 5 0 "forgeSpan" "forg" "span" $ IText (smaybe "" show.slSpanForge) + , Field 4 0 "mempoolTxSpan" (t 4!!0) "span" $ IText (smaybe "" show.slSpanTxsMem) , Field 4 0 "txsColl" (t 4!!1) "cold" $ IWord64 slTxsCollected , Field 4 0 "txsAcc" (t 4!!2) "accd" $ IWord64 slTxsAccepted , Field 4 0 "txsRej" (t 4!!3) "rejd" $ IWord64 slTxsRejected diff --git a/bench/locli/src/Cardano/Analysis/Chain.hs b/bench/locli/src/Cardano/Analysis/Chain.hs index 10d0f2b18cb..c7e260168c6 100644 --- a/bench/locli/src/Cardano/Analysis/Chain.hs +++ b/bench/locli/src/Cardano/Analysis/Chain.hs @@ -42,6 +42,13 @@ slotStart Genesis{..} = . fromIntegral . unSlotNo +impliedSlot :: Genesis -> UTCTime -> SlotNo +impliedSlot Genesis{..} = + SlotNo + . floor + . (/ slotLength) + . (`Time.diffUTCTime` systemStart) + sinceSlot :: UTCTime -> SlotStart -> NominalDiffTime sinceSlot t (SlotStart start) = Time.diffUTCTime t start diff --git a/bench/locli/src/Cardano/Analysis/ChainFilter.hs b/bench/locli/src/Cardano/Analysis/ChainFilter.hs index 4bb21922f06..bf67edad9ff 100644 --- a/bench/locli/src/Cardano/Analysis/ChainFilter.hs +++ b/bench/locli/src/Cardano/Analysis/ChainFilter.hs @@ -5,7 +5,6 @@ {- HLINT ignore "Use head" -} module Cardano.Analysis.ChainFilter (module Cardano.Analysis.ChainFilter) where -import Prelude (String) import Cardano.Prelude hiding (head) import Data.Aeson diff --git a/bench/locli/src/Cardano/Analysis/MachTimeline.hs b/bench/locli/src/Cardano/Analysis/MachTimeline.hs index 98fc29b3ad6..60f486734b0 100644 --- a/bench/locli/src/Cardano/Analysis/MachTimeline.hs +++ b/bench/locli/src/Cardano/Analysis/MachTimeline.hs @@ -5,30 +5,30 @@ {- HLINT ignore "Use head" -} module Cardano.Analysis.MachTimeline (module Cardano.Analysis.MachTimeline) where -import Prelude (String, error, head, last) +import Prelude (error, head, last) import Cardano.Prelude hiding (head) import Cardano.Prelude qualified as CP import Data.List ((!!)) import Data.Map.Strict qualified as Map +import Data.Text (pack) import Data.Vector (Vector) import Data.Vector qualified as Vec import Data.Time.Clock (NominalDiffTime, UTCTime) import Data.Time.Clock qualified as Time -import Data.Accum import Data.Distribution import Cardano.Analysis.API import Cardano.Analysis.Chain import Cardano.Analysis.ChainFilter +import Cardano.Analysis.Context import Cardano.Analysis.Ground import Cardano.Analysis.Run import Cardano.Analysis.Version import Cardano.Unlog.LogObject hiding (Text) import Cardano.Unlog.Resources -import Cardano.Util -- | A side-effect of analysis @@ -41,8 +41,9 @@ data RunScalars deriving stock Generic deriving anyclass NFData -collectSlotStats :: Run -> [(JsonLogfile, [LogObject])] -> IO [(JsonLogfile, (RunScalars, [SlotStats]))] -collectSlotStats run = mapConcurrentlyPure (fmap $ timelineFromLogObjects run) +collectSlotStats :: Run -> [(JsonLogfile, [LogObject])] + -> IO (Either Text [(JsonLogfile, (RunScalars, [SlotStats]))]) +collectSlotStats run = fmap sequence <$> mapConcurrentlyPure (timelineFromLogObjects run) runSlotFilters :: Run @@ -70,9 +71,11 @@ runSlotFilters Run{genesis} (flts, _fltNames) slots = do slotFilters :: [SlotCond] slotFilters = catSlotFilters filters -slotStatsSummary :: Run -> [SlotStats] -> MachTimeline -slotStatsSummary _ slots = - MachTimeline +slotStatsSummary :: Run -> (JsonLogfile, [SlotStats]) -> Either Text (JsonLogfile, MachTimeline) +slotStatsSummary _ (JsonLogfile f, []) = + Left $ "slotStatsSummary: zero filtered slots from " <> pack f +slotStatsSummary _ (f, slots) = + Right . (f,) $ MachTimeline { sMaxChecks = maxChecks , sSlotMisses = misses , sSpanLensCPU85 = spanLensCPU85 @@ -86,9 +89,9 @@ slotStatsSummary _ slots = , sLeadsDistrib = dist (slCountLeads <$> slots) , sUtxoDistrib = dist (slUtxoSize <$> slots) , sDensityDistrib = dist (slDensity <$> slots) - , sSpanCheckDistrib = dist (slSpanCheck <$> slots) - , sSpanLeadDistrib = dist (slSpanLead <$> slots) - , sSpanForgeDistrib = dist (filter (/= 0) $ slSpanForge <$> slots) + , sSpanCheckDistrib = dist (slSpanCheck `mapSMaybe` slots) + , sSpanLeadDistrib = dist (slSpanLead `mapSMaybe` slots) + , sSpanForgeDistrib = dist (filter (/= 0) $ slSpanForge `mapSMaybe` slots) , sBlocklessDistrib = dist (slBlockless <$> slots) , sSpanLensCPU85Distrib = dist spanLensCPU85 , sSpanLensCPU85EBndDistrib = dist sSpanLensCPU85EBnd @@ -165,16 +168,25 @@ forTANth xs@TimelineAccum{aSlotStats=ss} n f = (pre, x:post) -> pre <> (f x : post) _ -> error $ "mapNth: couldn't go " <> show n <> "-deep into the timeline" -timelineFromLogObjects :: Run -> [LogObject] -> (RunScalars, [SlotStats]) -timelineFromLogObjects run = - (aRunScalars &&& reverse . aSlotStats) - . foldl' (timelineStep run) zeroTimelineAccum +timelineFromLogObjects :: Run -> (JsonLogfile, [LogObject]) + -> Either Text (JsonLogfile, (RunScalars, [SlotStats])) +timelineFromLogObjects _ (JsonLogfile f, []) = + Left $ "timelineFromLogObjects: zero logobjects from " <> pack f +timelineFromLogObjects run@Run{genesis} (f, xs) = + Right . (f,) + $ foldl' (timelineStep run) + zeroTimelineAccum + xs + & (aRunScalars &&& reverse . aSlotStats) where + firstLogObjectTime :: UTCTime + firstLogObjectTime = loAt (head xs) + zeroTimelineAccum :: TimelineAccum zeroTimelineAccum = TimelineAccum { aResAccums = mkResAccums - , aResTimestamp = zeroUTCTime + , aResTimestamp = firstLogObjectTime , aMempoolTxs = 0 , aBlockNo = 0 , aLastBlockSlot = 0 @@ -187,20 +199,19 @@ timelineFromLogObjects run = zeroSlotStats :: SlotStats zeroSlotStats = SlotStats - { slSlot = 0 + { slSlot = impliedSlot genesis firstLogObjectTime , slEpoch = 0 , slEpochSlot = 0 , slEpochSafeInt = 0 - , slStart = SlotStart zeroUTCTime + , slStart = SlotStart firstLogObjectTime , slCountChecks = 0 , slCountLeads = 0 , slCountForges = 0 - , slEarliest = zeroUTCTime - , slSpanCheck = realToFrac (0 :: Int) - , slSpanLead = realToFrac (0 :: Int) - , slSpanForge = realToFrac (0 :: Int) + , slSpanCheck = SNothing + , slSpanLead = SNothing + , slSpanForge = SNothing + , slSpanTxsMem = SNothing , slMempoolTxs = 0 - , slTxsMemSpan = Nothing , slTxsCollected = 0 , slTxsAccepted = 0 , slTxsRejected = 0 @@ -214,90 +225,57 @@ timelineFromLogObjects run = } timelineStep :: Run -> TimelineAccum -> LogObject -> TimelineAccum -timelineStep run@Run{genesis} a@TimelineAccum{aSlotStats=cur:_, ..} = \case - LogObject{loAt, loBody=LOTraceStartLeadershipCheck slot utxo density} -> - if slot == slSlot cur -- L-shipCheck for the current slot. - then forTAHead a - (registerLeadCheck loAt) - else if slot - slSlot cur == 1 -- L-shipCheck for the next slot. - then forTAHead (addTimelineSlot run slot loAt 0 utxo density a) - (registerLeadCheck loAt) - else if slot < slSlot cur -- L-shipCheck for a slot we've gone by already. - then forTANth a (fromIntegral . unSlotNo $ slSlot cur - slot) - (registerLeadCheck loAt) - -- L-shipCheck for a further-than-immediate future slot - else let gap = unSlotNo $ slot - slSlot cur - 1 - gapStartSlot = slSlot cur + 1 in - patchSlotCheckGap gap gapStartSlot a - & addTimelineSlot run slot loAt 1 utxo density - where - registerLeadCheck :: UTCTime -> SlotStats -> SlotStats - registerLeadCheck now sl@SlotStats{..} = - sl { slCountChecks = slCountChecks + 1 - , slSpanCheck = now `sinceSlot` slStart -- XXX: used to "max 0" this - } - - patchSlotCheckGap :: Word64 -> SlotNo -> TimelineAccum -> TimelineAccum - patchSlotCheckGap 0 _ a' = a' - patchSlotCheckGap gapLen slot a'@TimelineAccum{aSlotStats=cur':_} = - patchSlotCheckGap (gapLen - 1) (slot + 1) $ - addTimelineSlot run slot - (unSlotStart $ genesis `slotStart` slot) - 0 (slUtxoSize cur') (slDensity cur') a' - LogObject{loAt, loBody=LOTraceLeadershipDecided slot yesNo} -> - if slot /= slSlot cur - then error $ "LeadDecided for noncurrent slot=" <> show slot <> " cur=" <> show (slSlot cur) - else forTAHead a (onLeadershipCertainty loAt yesNo) - where - onLeadershipCertainty :: UTCTime -> Bool -> SlotStats -> SlotStats - onLeadershipCertainty now lead sl@SlotStats{..} = - sl { slCountLeads = slCountLeads + if lead then 1 else 0 - , slSpanLead = checkToCertainty - } - where - checkAbsTime = slSpanCheck `Time.addUTCTime` unSlotStart slStart - checkToCertainty = now `Time.diffUTCTime` checkAbsTime - LogObject{loAt, loBody=LOBlockForged _ _ _ slot} -> - if slot /= slSlot cur - then error $ "BlockForged for noncurrent slot=" <> show slot <> " cur=" <> show (slSlot cur) - else forTAHead a (onBlockForge loAt) - where - onBlockForge :: UTCTime -> SlotStats -> SlotStats - onBlockForge now sl@SlotStats{..} = - sl { slCountForges = slCountForges + 1 - , slSpanForge = certaintyToForge - } - where - certaintyAbsTime = slSpanLead `Time.addUTCTime` (slSpanCheck `Time.addUTCTime` unSlotStart slStart) - certaintyToForge = now `Time.diffUTCTime` certaintyAbsTime +timelineStep Run{genesis} a@TimelineAccum{aSlotStats=cur:_, ..} = + let continue :: SlotNo -> UTCTime -> TimelineAccum + continue slot loAt = + if slot < slSlot cur then a + else a + & (if slot - slSlot cur <= 1 + then identity -- for the next slot, no gap to patch + else patchSlotGap genesis slot) -- for a future slot, patch the gap just until + & if slot == slSlot cur + then identity -- for the current slot, nothing to add + else addTimelineSlot genesis slot loAt + mapExistingSlot :: SlotNo -> (SlotStats -> SlotStats) -> TimelineAccum -> TimelineAccum + mapExistingSlot slot fSlot a'@TimelineAccum{aSlotStats=last:_} = + (if slot < slSlot last -- for a slot gone by + then forTANth a' (fromIntegral . unSlotNo $ slSlot last - slot) fSlot + else forTAHead a' fSlot) + in \case + -- First, events that can extend the timeline: + -- LogObject{loAt, loBody=LOResources rs} -> - -- Update resource stats accumulators & record values current slot. - (forTAHead a - \s-> s { slResources = Just <$> extractResAccums accs }) - { aResAccums = accs, aResTimestamp = loAt } - where accs = updateResAccums loAt rs aResAccums + continue slot loAt + & mapExistingSlot slot + (\sl -> sl { slResources = Just <$> extractResAccums accs }) + & \a' -> a' { aResAccums = accs + , aResTimestamp = loAt + } + where + slot = impliedSlot genesis loAt + accs = updateResAccums loAt rs aResAccums + LogObject{loAt, loBody=LOTraceStartLeadershipCheck slot utxo density} -> + continue slot loAt + & mapExistingSlot slot + (\sl@SlotStats{..} -> + sl { slCountChecks = slCountChecks + 1 + , slSpanCheck = SJust $ loAt `sinceSlot` slStart + , slUtxoSize = utxo + , slDensity = density + }) + -- Next, events that technically should extend the timeline, + -- but we don't really care for their misattribution to incur the overhead: + -- LogObject{loBody=LOMempoolTxs txCount} -> (forTAHead a \s-> s { slMempoolTxs = txCount }) { aMempoolTxs = txCount } - LogObject{loBody=LOBlockContext blockNo} -> - (forTAHead a - \s-> s { slBlockNo = blockNo - , slBlockless = if newBlock then 0 else slBlockless cur - }) - { aBlockNo = blockNo - , aLastBlockSlot = if newBlock - then slSlot cur - else aLastBlockSlot - } - where - newBlock = aBlockNo /= blockNo - LogObject{loBody=LOLedgerTookSnapshot} -> - forTAHead a - \s-> s { slChainDBSnap = slChainDBSnap cur + 1 } LogObject{loBody=LOMempoolRejectedTx} -> forTAHead a \s-> s { slRejectedTx = slRejectedTx cur + 1 } + LogObject{loBody=LOLedgerTookSnapshot} -> + forTAHead a + \s-> s { slChainDBSnap = slChainDBSnap cur + 1 } LogObject{loBody=LOGeneratorSummary _noFails sent elapsed threadwiseTps} -> a { aRunScalars = aRunScalars { rsThreadwiseTps = Just threadwiseTps @@ -320,33 +298,120 @@ timelineStep run@Run{genesis} a@TimelineAccum{aSlotStats=cur:_, ..} = \case LogObject{loBody=LOTxsProcessed acc rej, loTid, loAt} -> (forTAHead a \s@SlotStats{..}-> s - { slTxsMemSpan = + { slSpanTxsMem = case loTid `Map.lookup` aTxsCollectedAt of Nothing -> -- error $ mconcat -- ["LOTxsProcessed missing LOTxsCollected for tid", show tid, " at ", show loAt] - Just $ + SJust $ 1.0 + - fromMaybe 0 slTxsMemSpan + fromSMaybe 0 slSpanTxsMem Just base -> - Just $ + SJust $ (loAt `Time.diffUTCTime` base) + - fromMaybe 0 slTxsMemSpan + fromSMaybe 0 slSpanTxsMem , slTxsAccepted = slTxsAccepted + acc , slTxsRejected = slTxsRejected + max 0 (fromIntegral rej) }) { aTxsCollectedAt = loTid `Map.delete` aTxsCollectedAt } + -- Next, events that rely on their slotstats to pre-exist: + -- + LogObject{loAt, loBody=LOTraceLeadershipDecided slot yesNo} -> + if slot /= slSlot cur + then error $ "LeadDecided for noncurrent slot=" <> show slot <> " cur=" <> show (slSlot cur) + else forTAHead a (onLeadershipCertainty loAt yesNo) + where + onLeadershipCertainty :: UTCTime -> Bool -> SlotStats -> SlotStats + onLeadershipCertainty now lead sl@SlotStats{..} = + sl { slCountLeads = slCountLeads + if lead then 1 else 0 + , slSpanLead = checkToCertainty + } + where + checkAbsTime = slSpanCheck <&> (`Time.addUTCTime` unSlotStart slStart) + checkToCertainty = (now `Time.diffUTCTime`) <$> checkAbsTime + LogObject{loBody=LOBlockContext blockNo} -> + (forTAHead a + \s-> s { slBlockNo = blockNo + , slBlockless = if newBlock then 0 else slBlockless cur + }) + { aBlockNo = blockNo + , aLastBlockSlot = if newBlock + then slSlot cur + else aLastBlockSlot + } + where + newBlock = aBlockNo /= blockNo + LogObject{loAt, loBody=LOBlockForged _ _ _ slot} -> + if slot /= slSlot cur + then error $ "BlockForged for noncurrent slot=" <> show slot <> " cur=" <> show (slSlot cur) + else forTAHead a (onBlockForge loAt) + where + onBlockForge :: UTCTime -> SlotStats -> SlotStats + onBlockForge now sl@SlotStats{..} = + sl { slCountForges = slCountForges + 1 + , slSpanForge = certaintyToForge + } + where + certaintyAbsTime = Time.addUTCTime + <$> slSpanLead + <*> (slSpanCheck <&> (`Time.addUTCTime` unSlotStart slStart)) + certaintyToForge = (now `Time.diffUTCTime`) <$> certaintyAbsTime _ -> a timelineStep _ a = const a -addTimelineSlot :: - Run - -> SlotNo -> UTCTime -> Word64 -> Word64 -> Float - -> TimelineAccum -> TimelineAccum -addTimelineSlot Run{genesis} slot time checks utxo density a@TimelineAccum{..} = +patchSlotGap :: Genesis -> SlotNo -> TimelineAccum -> TimelineAccum +patchSlotGap genesis curSlot a@TimelineAccum{aSlotStats=last:_, ..} = + a & go (unSlotNo $ curSlot - gapStartSlot) gapStartSlot + where + gapStartSlot = slSlot last + 1 + + go :: Word64 -> SlotNo -> TimelineAccum -> TimelineAccum + go 0 _ acc = acc + go gapLen patchSlot acc = + go (gapLen - 1) (patchSlot + 1) (acc & addGapSlot patchSlot) + + addGapSlot :: SlotNo -> TimelineAccum -> TimelineAccum + addGapSlot slot acc = + let (epoch, epochSlot) = genesis `unsafeParseSlot` slot in + acc { aSlotStats = SlotStats + { slSlot = slot + , slEpoch = epoch + , slEpochSlot = epochSlot + , slEpochSafeInt= slotEpochSafeInt genesis epochSlot + , slStart = slStart + -- Updated as we see repeats: + , slCountChecks = 0 + , slCountLeads = 0 + , slCountForges = 0 + , slSpanCheck = SNothing + , slSpanLead = SNothing + , slSpanForge = SNothing + , slSpanTxsMem = SNothing + , slTxsCollected= 0 + , slTxsAccepted = 0 + , slTxsRejected = 0 + , slMempoolTxs = aMempoolTxs + , slUtxoSize = slUtxoSize last + , slDensity = slDensity last + , slChainDBSnap = 0 + , slRejectedTx = 0 + , slBlockNo = aBlockNo + , slBlockless = unSlotNo $ slot - aLastBlockSlot + , slResources = maybeDiscard + <$> discardObsoleteValues + <*> extractResAccums aResAccums} + : aSlotStats acc + } + where maybeDiscard :: (Word64 -> Maybe Word64) -> Word64 -> Maybe Word64 + maybeDiscard f = f + + slStart = slotStart genesis slot + +addTimelineSlot :: Genesis -> SlotNo -> UTCTime -> TimelineAccum -> TimelineAccum +addTimelineSlot genesis slot time a@TimelineAccum{..} = let (epoch, epochSlot) = genesis `unsafeParseSlot` slot in a { aSlotStats = SlotStats { slSlot = slot @@ -354,21 +419,20 @@ addTimelineSlot Run{genesis} slot time checks utxo density a@TimelineAccum{..} = , slEpochSlot = epochSlot , slEpochSafeInt= slotEpochSafeInt genesis epochSlot , slStart = slStart - , slEarliest = time -- Updated as we see repeats: - , slCountChecks = checks + , slCountChecks = 0 , slCountLeads = 0 , slCountForges = 0 - , slSpanCheck = time `sinceSlot` slStart - , slSpanLead = 0 - , slSpanForge = 0 - , slTxsMemSpan = Nothing + , slSpanCheck = SJust $ time `sinceSlot` slStart + , slSpanLead = SNothing + , slSpanForge = SNothing + , slSpanTxsMem = SNothing , slTxsCollected= 0 , slTxsAccepted = 0 , slTxsRejected = 0 , slMempoolTxs = aMempoolTxs - , slUtxoSize = utxo - , slDensity = density + , slUtxoSize = 0 + , slDensity = 0 , slChainDBSnap = 0 , slRejectedTx = 0 , slBlockNo = aBlockNo diff --git a/bench/locli/src/Cardano/Command.hs b/bench/locli/src/Cardano/Command.hs index acf5b4ba930..148f997950e 100644 --- a/bench/locli/src/Cardano/Command.hs +++ b/bench/locli/src/Cardano/Command.hs @@ -1,7 +1,6 @@ {-# OPTIONS_GHC -fmax-pmcheck-models=300 #-} module Cardano.Command (module Cardano.Command) where -import Prelude (String) import Cardano.Prelude hiding (State) import Data.Aeson qualified as Aeson @@ -21,7 +20,6 @@ import Cardano.Analysis.Run import Cardano.Analysis.Version import Cardano.Unlog.LogObject hiding (Text) import Cardano.Unlog.Render -import Cardano.Util import Data.Distribution data CommandError @@ -43,7 +41,10 @@ parseChainCommand = subparser (mconcat [ commandGroup "Common data: logobject keys, run metafile & genesis" , op "list-logobject-keys" "List logobject keys that analyses care about" (ListLogobjectKeys - <$> optTextOutputFile "keys" "Text file to write logobject keys to") + <$> optTextOutputFile "keys" "Text file to write logobject keys to") + , op "list-logobject-keys-legacy" "List legacy logobject keys that analyses care about" + (ListLogobjectKeysLegacy + <$> optTextOutputFile "keys-legacy" "Text file to write logobject keys to") , op "meta-genesis" "Machine performance timeline" (MetaGenesis <$> optJsonRunMetafile "run-metafile" "The meta.json file from the benchmark run" @@ -167,6 +168,8 @@ parseChainCommand = data ChainCommand = ListLogobjectKeys TextOutputFile + | ListLogobjectKeysLegacy + TextOutputFile | MetaGenesis -- () -> Run JsonRunMetafile @@ -252,6 +255,11 @@ runChainCommand s dumpText "logobject-keys" (toText <$> logObjectStreamInterpreterKeys) f & firstExceptT (CommandError c) pure s +runChainCommand s + c@(ListLogobjectKeysLegacy f) = do + dumpText "logobject-keys-legacy" (toText <$> logObjectStreamInterpreterKeysLegacy) f + & firstExceptT (CommandError c) + pure s runChainCommand s c@(MetaGenesis runMeta shelleyGenesis) = do @@ -301,8 +309,7 @@ runChainCommand _ c@RebuildChain = missingCommandData c runChainCommand s c@(ReadChain f) = do - chainRaw <- sequence - . fmap (Aeson.eitherDecode @BlockEvents) + chainRaw <- mapM (Aeson.eitherDecode @BlockEvents) . filter ((> 5) . LBS.length) . LBS.split '\n' <$> LBS.readFile (unJsonInputFile f) @@ -331,6 +338,9 @@ runChainCommand s@State{sRun=Just run, sChainRaw=Just chainRaw} & firstExceptT (CommandError c) (domSlot, domBlock, chain) <- filterChain run flts chainRaw & liftIO & firstExceptT (CommandError c) + when (ddFilteredCount domBlock == 0) $ + throwE $ CommandError c $ mconcat + [ "All ", show (ddRawCount domBlock), " blocks filtered out." ] pure s { sChain = Just chain, sDomSlots = Just domSlot, sDomBlocks = Just domBlock } runChainCommand _ c@FilterChain{} = missingCommandData c ["run metadata & genesis", "slot filters", "unfiltered slot stats"] @@ -353,8 +363,8 @@ runChainCommand _ c@TimelineChain{} = missingCommandData c runChainCommand s@State{sRun=Just run, sObjLists=Just objs} c@CollectSlots = do (scalars, slotsRaw) <- - mapAndUnzip redistribute <$> collectSlotStats run objs - & liftIO + fmap (mapAndUnzip redistribute) <$> collectSlotStats run objs + & newExceptT & firstExceptT (CommandError c) pure s { sScalars = Just scalars, sSlotsRaw = Just slotsRaw } runChainCommand _ c@CollectSlots = missingCommandData c @@ -374,6 +384,9 @@ runChainCommand s@State{sRun=Just run, sSlotsRaw=Just slotsRaw} (domSlots, fltrd) <- runSlotFilters run flts slotsRaw & liftIO & firstExceptT (CommandError c) + when (maximum (length . snd <$> fltrd) == 0) $ + throwE $ CommandError c $ mconcat + [ "All ", show $ maximum (length . snd <$> slotsRaw), " slots filtered out." ] pure s { sSlots = Just fltrd, sDomSlots = Just domSlots } runChainCommand _ c@FilterSlots{} = missingCommandData c ["run metadata & genesis", "slot filters", "unfiltered slot stats"] @@ -410,8 +423,9 @@ runChainCommand _ c@DumpPropagation{} = missingCommandData c runChainCommand s@State{sRun=Just run, sSlots=Just slots} c@PerfAnalysis = do - perfAnalysis <- mapConcurrentlyPure (fmap $ slotStatsSummary run) slots - & liftIO + perfAnalysis <- mapConcurrentlyPure (slotStatsSummary run) slots + & fmap sequence + & newExceptT & firstExceptT (CommandError c) pure s { sPerfAnalysis = Just perfAnalysis } runChainCommand _ c@PerfAnalysis{} = missingCommandData c diff --git a/bench/locli/src/Cardano/Unlog/LogObject.hs b/bench/locli/src/Cardano/Unlog/LogObject.hs index 821b15b4b21..2c35d484855 100644 --- a/bench/locli/src/Cardano/Unlog/LogObject.hs +++ b/bench/locli/src/Cardano/Unlog/LogObject.hs @@ -10,7 +10,7 @@ module Cardano.Unlog.LogObject (module Cardano.Unlog.LogObject) where -import Prelude (String, error, head, id, show) +import Prelude (error, head, id, show) import Cardano.Prelude hiding (Text, head, show) import Control.Monad (fail) @@ -26,6 +26,7 @@ import Data.Text.Short (ShortText, fromText, toText) import Data.Time.Clock (NominalDiffTime, UTCTime) import Data.Map qualified as Map import Data.Vector (Vector) +import Data.Vector qualified as V import Cardano.Logging.Resources.Types @@ -54,7 +55,7 @@ readLogObjectStream :: FilePath -> IO [LogObject] readLogObjectStream f = LBS.readFile f <&> - fmap (either (LogObject zeroUTCTime "DecodeError" "" (TId "0") . LODecodeError) + fmap (either (LogObject zeroUTCTime "Cardano.Analysis.DecodeError" "DecodeError" "" (TId "0") . LODecodeError) id . AE.eitherDecode) . LBS.split (fromIntegral $ fromEnum '\n') @@ -62,6 +63,7 @@ readLogObjectStream f = data LogObject = LogObject { loAt :: !UTCTime + , loNS :: !Text , loKind :: !Text , loHost :: !Host , loTid :: !TId @@ -82,45 +84,47 @@ deriving instance NFData a => NFData (Resources a) -- LogObject stream interpretation -- -interpreters :: Map Text (Object -> Parser LOBody) -interpreters = Map.fromList - [ (,) "TraceStartLeadershipCheck" $ +type ACouple t = (t, t) + +interpreters :: ACouple (Map Text (Object -> Parser LOBody)) +interpreters = (Map.fromList *** Map.fromList) . unzip . fmap ent $ + [ (,,) "TraceStartLeadershipCheck" "Cardano.Node.Forge.StartLeadershipCheck" $ \v -> LOTraceStartLeadershipCheck <$> v .: "slot" <*> (v .:? "utxoSize" <&> fromMaybe 0) <*> (v .:? "chainDensity" <&> fromMaybe 0) - , (,) "TraceBlockContext" $ + , (,,) "TraceBlockContext" "Cardano.Node.Forge.BlockContext" $ \v -> LOBlockContext <$> v .: "tipBlockNo" - , (,) "TraceNodeIsLeader" $ + , (,,) "TraceNodeIsLeader" "Cardano.Node.Forge.NodeIsLeader" $ \v -> LOTraceLeadershipDecided <$> v .: "slot" <*> pure True - , (,) "TraceNodeNotLeader" $ + , (,,) "TraceNodeNotLeader" "Cardano.Node.Forge.NodeNotLeader" $ \v -> LOTraceLeadershipDecided <$> v .: "slot" <*> pure False - , (,) "TraceMempoolAddedTx" $ + , (,,) "TraceMempoolAddedTx" "Cardano.Node.Mempool.AddedTx" $ \v -> do x :: Object <- v .: "mempoolSize" LOMempoolTxs <$> x .: "numTxs" - , (,) "TraceMempoolRemoveTxs" $ + , (,,) "TraceMempoolRemoveTxs" "Cardano.Node.Mempool.RemoveTxs" $ \v -> do x :: Object <- v .: "mempoolSize" LOMempoolTxs <$> x .: "numTxs" - , (,) "TraceMempoolRejectedTx" $ + , (,,) "TraceMempoolRejectedTx" "Cardano.Node.Mempool.RejectedTx" $ \_ -> pure LOMempoolRejectedTx - , (,) "TraceLedgerEvent.TookSnapshot" $ + , (,,) "TraceLedgerEvent.TookSnapshot" "Cardano.Node.LedgerEvent.TookSnapshot" $ \_ -> pure LOLedgerTookSnapshot - , (,) "TraceBenchTxSubSummary" $ + , (,,) "TraceBenchTxSubSummary" "TraceBenchTxSubSummary" $ \v -> do x :: Object <- v .: "summary" LOGeneratorSummary @@ -130,28 +134,28 @@ interpreters = Map.fromList <*> x .: "ssElapsed" <*> x .: "ssThreadwiseTps" - , (,) "TraceBenchTxSubServAck" $ + , (,,) "TraceBenchTxSubServAck" "TraceBenchTxSubServAck" $ \v -> LOTxsAcked <$> v .: "txIds" - , (,) "Resources" $ + , (,,) "Resources" "Cardano.Node.Resources" $ \v -> LOResources <$> parsePartialResourceStates (Object v) - , (,) "TraceTxSubmissionCollected" $ + , (,,) "TraceTxSubmissionCollected" "TraceTxSubmissionCollected" $ \v -> LOTxsCollected <$> v .: "count" - , (,) "TraceTxSubmissionProcessed" $ + , (,,) "TraceTxSubmissionProcessed" "TraceTxSubmissionProcessed" $ \v -> LOTxsProcessed <$> v .: "accepted" <*> v .: "rejected" - , (,) "TraceForgedBlock" $ + , (,,) "TraceForgedBlock" "Cardano.Node.Forge.ForgedBlock" $ \v -> LOBlockForged <$> v .: "block" <*> v .: "blockPrev" <*> v .: "blockNo" <*> v .: "slot" - , (,) "TraceAddBlockEvent.AddedToCurrentChain" $ + , (,,) "TraceAddBlockEvent.AddedToCurrentChain" "Cardano.Node.ChainDB.AddBlockEvent.AddedToCurrentChain" $ \v -> LOBlockAddedToCurrentChain <$> ((v .: "newtip") <&> hashFromPoint) <*> pure Nothing @@ -159,35 +163,35 @@ interpreters = Map.fromList -- Compat for node versions 1.27 and older: <&> fromMaybe 1) -- TODO: we should clarify the distinction between the two cases (^ and v). - , (,) "TraceAdoptedBlock" $ + , (,,) "TraceAdoptedBlock" "Cardano.Node.Forge.AdoptedBlock" $ \v -> LOBlockAddedToCurrentChain <$> v .: "blockHash" <*> ((v .: "blockSize") <&> Just) <*> pure 1 - , (,) "ChainSyncServerEvent.TraceChainSyncServerRead.AddBlock" $ + , (,,) "ChainSyncServerEvent.TraceChainSyncServerRead.AddBlock" "Cardano.Node.ChainSyncServerHeader.ChainSyncServerEvent.ServerRead.AddBlock" $ \v -> LOChainSyncServerSendHeader <$> v .: "block" <*> v .: "blockNo" <*> v .: "slot" - , (,) "ChainSyncServerEvent.TraceChainSyncServerReadBlocked.AddBlock" $ + , (,,) "ChainSyncServerEvent.TraceChainSyncServerReadBlocked.AddBlock" "Cardano.Node.ChainSyncServerHeader.ChainSyncServerEvent.ServerReadBlocked.AddBlock" $ \v -> LOChainSyncServerSendHeader <$> v .: "block" <*> v .: "blockNo" <*> v .: "slot" -- v, but not ^ -- how is that possible? - , (,) "TraceBlockFetchServerSendBlock" $ + , (,,) "TraceBlockFetchServerSendBlock" "Cardano.Node.BlockFetchServer.SendBlock" $ \v -> LOBlockFetchServerSending <$> v .: "block" - , (,) "SendFetchRequest" $ + , (,,) "SendFetchRequest" "Cardano.Node.BlockFetchClient.SendFetchRequest" $ \v -> LOBlockFetchClientRequested <$> v .: "head" <*> v .: "length" - , (,) "ChainSyncClientEvent.TraceDownloadedHeader" $ + , (,,) "ChainSyncClientEvent.TraceDownloadedHeader" "Cardano.Node.ChainSyncClient.ChainSyncClientEvent.DownloadedHeader" $ \v -> LOChainSyncClientSeenHeader <$> v .: "block" <*> v .: "blockNo" <*> v .: "slot" - , (,) "CompletedBlockFetch" $ + , (,,) "CompletedBlockFetch" "Cardano.Node.BlockFetchClient.CompletedBlockFetch" $ \v -> LOBlockFetchClientCompletedFetch <$> v .: "block" ] @@ -195,8 +199,12 @@ interpreters = Map.fromList hashFromPoint :: LText.Text -> Hash hashFromPoint = Hash . fromText . Prelude.head . LText.splitOn "@" -logObjectStreamInterpreterKeys :: [Text] -logObjectStreamInterpreterKeys = Map.keys interpreters + ent :: (a,b,c) -> ((a,c), (b,c)) + ent (a,b,c) = ((a,c), (b,c)) + +logObjectStreamInterpreterKeysLegacy, logObjectStreamInterpreterKeys :: [Text] +logObjectStreamInterpreterKeysLegacy = Map.keys (fst interpreters) +logObjectStreamInterpreterKeys = Map.keys (snd interpreters) data LOBody = LOTraceStartLeadershipCheck !SlotNo !Word64 !Float @@ -253,12 +261,20 @@ instance FromJSON LogObject where body :: Object <- v .: "data" -- XXX: fix node causing the need for this workaround (,) unwrapped kind <- unwrap "credentials" "val" body + nsVorNs :: Value <- v .: "ns" + let ns = case nsVorNs of + Array (V.toList -> [String ns']) -> fromText ns' + String ns' -> fromText ns' + x -> error $ + "The 'ns' field must be either a string, or a singleton-String vector, was: " <> show x LogObject <$> v .: "at" + <*> pure ns <*> pure kind <*> v .: "host" <*> v .: "thread" - <*> case Map.lookup kind interpreters of + <*> case Map.lookup ns (snd interpreters) <|> + Map.lookup kind (fst interpreters) of Just interp -> interp unwrapped Nothing -> pure $ LOAny unwrapped where diff --git a/bench/locli/src/Cardano/Util.hs b/bench/locli/src/Cardano/Util.hs index 2e74cc700ef..2527b7fcab8 100644 --- a/bench/locli/src/Cardano/Util.hs +++ b/bench/locli/src/Cardano/Util.hs @@ -1,5 +1,7 @@ module Cardano.Util - ( module Cardano.Util + ( module Prelude + , module Cardano.Util + , module Cardano.Ledger.BaseTypes , module Control.Arrow , module Control.Applicative , module Control.Concurrent.Async @@ -20,12 +22,38 @@ import Data.Aeson (FromJSON, ToJSON, encode, eitherDecode) import Data.ByteString.Lazy.Char8 qualified as LBS import Data.Text qualified as T import Data.Text.Short (fromText) +import GHC.Base (build) import Text.Printf (printf) import System.FilePath qualified as F import Cardano.Analysis.Ground - +import Cardano.Ledger.BaseTypes (StrictMaybe (..), fromSMaybe) + + +smaybe :: b -> (a -> b) -> StrictMaybe a -> b +smaybe x _ SNothing = x +smaybe _ f (SJust x) = f x + +mapSMaybe :: (a -> StrictMaybe b) -> [a] -> [b] +mapSMaybe _ [] = [] +mapSMaybe f (x:xs) = + let rs = mapSMaybe f xs in + case f x of + SNothing -> rs + SJust r -> r:rs +{-# NOINLINE [1] mapSMaybe #-} + +{-# RULES +"mapSMaybe" [~1] forall f xs. mapSMaybe f xs + = build (\c n -> foldr (mapSMaybeFB c f) n xs) + #-} + +{-# INLINE [0] mapSMaybeFB #-} -- See Note [Inline FB functions] in GHC.List +mapSMaybeFB :: (b -> r -> r) -> (a -> StrictMaybe b) -> a -> r -> r +mapSMaybeFB cons f x next = case f x of + SNothing -> next + SJust r -> cons r next mapConcurrentlyPure :: NFData b => (a -> b) -> [a] -> IO [b] mapConcurrentlyPure f = diff --git a/cardano-node/src/Cardano/Node/Run.hs b/cardano-node/src/Cardano/Node/Run.hs index 3311d3a511e..733929727eb 100644 --- a/cardano-node/src/Cardano/Node/Run.hs +++ b/cardano-node/src/Cardano/Node/Run.hs @@ -63,6 +63,7 @@ import Cardano.Node.Configuration.POM (NodeConfiguration (..), defaultPartialNodeConfiguration, makeNodeConfiguration, parseNodeConfigurationFP) import Cardano.Node.Startup import Cardano.Node.Tracing.API +import Cardano.Node.Tracing.StateRep (NodeState(NodeKernelOnline)) import Cardano.Node.Tracing.Tracers.Startup (getStartupInfo) import Cardano.Node.Types import Cardano.Tracing.Config (TraceOptions (..), TraceSelection (..)) @@ -238,7 +239,9 @@ handleNodeWithTracers cmdPc nc p networkMagic runP = do -- We ignore peer logging thread if it dies, but it will be killed -- when 'handleSimpleNode' terminates. handleSimpleNode runP p2pMode tracers nc - (setNodeKernel nodeKernelData) + (\nk -> do + setNodeKernel nodeKernelData nk + traceWith (nodeStateTracer tracers) NodeKernelOnline) `finally` forM_ mLoggingLayer shutdownLoggingLayer diff --git a/cardano-node/src/Cardano/Node/Tracing/API.hs b/cardano-node/src/Cardano/Node/Tracing/API.hs index 909f3958d56..5d5cd1c26f2 100644 --- a/cardano-node/src/Cardano/Node/Tracing/API.hs +++ b/cardano-node/src/Cardano/Node/Tracing/API.hs @@ -66,12 +66,12 @@ initTraceDispatcher nc p networkMagic nodeKernel p2pMode = do startResourceTracer (resourcesTracer tracers) - (fromMaybe 1000 (tcResourceFreqency trConfig)) + (fromMaybe 1000 (tcResourceFrequency trConfig)) startPeerTracer (peersTracer tracers) nodeKernel - (fromMaybe 2000 (tcPeerFreqency trConfig)) + (fromMaybe 2000 (tcPeerFrequency trConfig)) now <- getCurrentTime prepareNodeInfo (ncProtocol nc) p trConfig now diff --git a/cardano-node/src/Cardano/Node/Tracing/Documentation.hs b/cardano-node/src/Cardano/Node/Tracing/Documentation.hs index eadf8fe2999..aef9380e36c 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Documentation.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Documentation.hs @@ -381,7 +381,7 @@ docTracers configFileName outputFileName _ _ _ = do mempoolTrDoc <- documentTracer trConfig mempoolTr (docMempool :: Documented (TraceEventMempool blk)) - forgeTr <- mkCardanoTracer + forgeTr <- mkCardanoTracer trBase trForward mbTrEKG "Forge" namesForForge @@ -389,24 +389,26 @@ docTracers configFileName outputFileName _ _ _ = do allPublic -- TODO Tracers docforgeThreadStatsTr? - forgeThreadStatsTr <- mkCardanoTracer' + forgeThreadStatsTr <- + mkCardanoTracer' trBase trForward mbTrEKG "ForgeStats" namesForForge severityForge allPublic forgeThreadStats + configureTracers trConfig docForge [forgeTr, forgeThreadStatsTr] forgeTrDoc <- documentTracer trConfig forgeTr (docForge :: Documented - (Either (Consensus.TraceLabelCreds (Consensus.TraceForgeEvent blk)) - (Consensus.TraceLabelCreds TraceStartLeadershipCheckPlus))) + (Either (Consensus.TraceForgeEvent blk) + TraceStartLeadershipCheckPlus)) forgeThreadStatsTrDoc <- documentTracer trConfig forgeThreadStatsTr (docForgeStats :: Documented (Either - (Consensus.TraceLabelCreds (Consensus.TraceForgeEvent blk)) - (Consensus.TraceLabelCreds TraceStartLeadershipCheckPlus))) + (Consensus.TraceForgeEvent blk) + TraceStartLeadershipCheckPlus)) blockchainTimeTr <- mkCardanoTracer trBase trForward mbTrEKG diff --git a/cardano-node/src/Cardano/Node/Tracing/StateRep.hs b/cardano-node/src/Cardano/Node/Tracing/StateRep.hs index 9fdfbef0e53..b45b1ddd727 100644 --- a/cardano-node/src/Cardano/Node/Tracing/StateRep.hs +++ b/cardano-node/src/Cardano/Node/Tracing/StateRep.hs @@ -2,6 +2,7 @@ {-# LANGUAGE DeriveGeneric #-} {-# LANGUAGE FlexibleInstances #-} {-# LANGUAGE GADTs #-} +{-# LANGUAGE LambdaCase #-} {-# LANGUAGE StandaloneDeriving #-} {-# OPTIONS_GHC -Wno-orphans #-} @@ -16,6 +17,9 @@ module Cardano.Node.Tracing.StateRep , traceNodeStateChainDB , traceNodeStateStartup , traceNodeStateShutdown + , namesNodeState + , severityNodeState + , docNodeState ) where import Cardano.Prelude @@ -99,11 +103,63 @@ data NodeState | NodeOpeningDbs OpeningDbs | NodeReplays Replays | NodeInitChainSelection InitChainSelection + | NodeKernelOnline | NodeAddBlock AddedToCurrentChain | NodeStartup StartupState | NodeShutdown ShutdownTrace deriving (Generic, FromJSON, ToJSON) +instance LogFormatting NodeState where + forMachine _ = \case + NodeOpeningDbs x -> mconcat + [ "kind" .= String "NodeOpeningDbs", "openingDb" .= toJSON x] + NodeReplays x -> mconcat + [ "kind" .= String "NodeReplays", "replays" .= toJSON x] + NodeInitChainSelection x -> mconcat + [ "kind" .= String "NodeInitChainSelection", "chainSel" .= toJSON x] + NodeAddBlock x -> mconcat + [ "kind" .= String "NodeAddBlock", "addBlock" .= toJSON x] + NodeStartup x -> mconcat + [ "kind" .= String "NodeStartup", "startup" .= toJSON x] + NodeShutdown x -> mconcat + [ "kind" .= String "NodeShutdown", "shutdown" .= toJSON x] + _ -> mempty + +docNodeState :: Documented NodeState +docNodeState = addDocumentedNamespace [] $ + Documented + [ DocMsg ["NodeTracingOnlineConfiguring"] [] "Tracing system came online, system configuring now" + , DocMsg ["NodeOpeningDbs"] [] "ChainDB components being opened" + , DocMsg ["NodeReplays"] [] "Replaying chain" + , DocMsg ["NodeInitChainSelection"] [] "Performing initial chain selection" + , DocMsg ["NodeKernelOnline"] [] "Node kernel online" + , DocMsg ["NodeAddBlock"] [] "Applying block" + , DocMsg ["NodeStartup"] [] "Node startup" + , DocMsg ["NodeShutdown"] [] "Node shutting down" + ] + +namesNodeState :: NodeState -> [Text] +namesNodeState = \case + NodeTracingOnlineConfiguring -> ["TracingOnlineConfiguring"] + NodeOpeningDbs _x -> ["OpeningDbs"] -- : namesOpeninDbs x + NodeReplays _x -> ["Replays"] -- : namesReplays x + NodeInitChainSelection _x -> ["InitChainSelection"] -- : namesInitChainSelection -- Worth it? + NodeKernelOnline -> ["NodeKernelOnline"] + NodeAddBlock _x -> ["AddBlock"] -- : namesAddBlock x + NodeStartup _x -> ["Startup"] -- : namesForStartup x -- Worth it? + NodeShutdown _x -> ["Shutdown"] -- : namesShutdown x + +severityNodeState :: NodeState -> SeverityS +severityNodeState = \case + NodeTracingOnlineConfiguring -> Info + NodeOpeningDbs _x -> Info + NodeReplays _x -> Notice + NodeInitChainSelection _x -> Notice + NodeKernelOnline -> Info + NodeAddBlock _x -> Notice + NodeStartup _x -> Info + NodeShutdown _x -> Warning + traceNodeStateChainDB :: SomeConsensusProtocol -> Trace IO NodeState diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers.hs index 218595de3ae..8127e5b3aa5 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers.hs @@ -95,10 +95,28 @@ mkDispatchTracers nodeKernel trBase trForward mbTrEKG trDataPoint trConfig enabl trDataPoint (const ["NodeState"]) + -- State tracer + stateTr <- mkCardanoTracer + trBase trForward mbTrEKG + "State" + SR.namesNodeState + SR.severityNodeState + allPublic + configureTracers trConfig SR.docNodeState [stateTr] + nodePeersTr <- mkDataPointTracer trDataPoint (const ["NodePeers"]) + -- Peers tracer + peersTr <- mkCardanoTracer + trBase trForward mbTrEKG + "Peers" + namesForPeers + severityPeers + allPublic + configureTracers trConfig docPeers [peersTr] + -- Resource tracer resourcesTr <- mkCardanoTracer trBase trForward mbTrEKG @@ -125,15 +143,6 @@ mkDispatchTracers nodeKernel trBase trForward mbTrEKG trDataPoint trConfig enabl allPublic configureTracers trConfig docShutdown [shutdownTr] - -- Peers tracer - peersTr <- mkCardanoTracer - trBase trForward mbTrEKG - "Peers" - namesForPeers - severityPeers - allPublic - configureTracers trConfig docPeers [peersTr] - chainDBTr <- mkCardanoTracer' trBase trForward mbTrEKG "ChainDB" @@ -202,7 +211,7 @@ mkDispatchTracers nodeKernel trBase trForward mbTrEKG trDataPoint trConfig enabl , startupTracer = Tracer $ \x -> traceWith startupTr x >> SR.traceNodeStateStartup nodeStateTr x , shutdownTracer = Tracer $ \x -> traceWith shutdownTr x >> SR.traceNodeStateShutdown nodeStateTr x , nodeInfoTracer = Tracer (traceWith nodeInfoTr) - , nodeStateTracer = Tracer (traceWith nodeStateTr) + , nodeStateTracer = Tracer (traceWith stateTr) <> Tracer (traceWith nodeStateTr) , resourcesTracer = Tracer (traceWith resourcesTr) , peersTracer = Tracer $ \x -> traceWith peersTr x >> traceNodePeers nodePeersTr x } @@ -351,8 +360,9 @@ mkConsensusTracers trBase trForward mbTrEKG _trDataPoint trConfig nodeKernel = d , Consensus.mempoolTracer = Tracer $ traceWith mempoolTr , Consensus.forgeTracer = - Tracer (traceWith (contramap Left forgeTr)) - <> Tracer (traceWith (contramap Left forgeThreadStatsTr)) + Tracer (\(Consensus.TraceLabelCreds _ x) -> traceWith (contramap Left forgeTr) x) + <> -- TODO: add the forge-thread-stats as a datapoint + Tracer (\(Consensus.TraceLabelCreds _ x) -> traceWith (contramap Left forgeThreadStatsTr) x) , Consensus.blockchainTimeTracer = Tracer $ traceWith blockchainTimeTr , Consensus.keepAliveClientTracer = Tracer $ diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs index b09a5d52bd4..b73177ee9ca 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs @@ -1142,7 +1142,7 @@ instance ( StandardHash blk mconcat [ "kind" .= String "DeletedSnapshot" , "snapshot" .= forMachine dtals snap ] forMachine dtals (LedgerDB.InvalidSnapshot snap failure) = - mconcat [ "kind" .= String "TraceLedgerEvent.InvalidSnapshot" + mconcat [ "kind" .= String "InvalidSnapshot" , "snapshot" .= forMachine dtals snap , "failure" .= show failure ] diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs index 841667aef9b..82d8006908f 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs @@ -111,7 +111,8 @@ import Ouroboros.Consensus.MiniProtocol.LocalTxSubmission.Server import Ouroboros.Consensus.Node.Run (SerialiseNodeToNodeConstraints, estimateBlockSize) import Ouroboros.Consensus.Node.Tracers import qualified Ouroboros.Consensus.Protocol.Ledger.HotKey as HotKey - +import qualified Ouroboros.Network.AnchoredFragment as AF +import qualified Ouroboros.Network.AnchoredSeq as AS @@ -258,16 +259,20 @@ namesForChainSyncServerEvent :: TraceChainSyncServerEvent blk -> [Text] namesForChainSyncServerEvent ev = "ChainSyncServerEvent" : namesForChainSyncServerEvent' ev +nameChainUpdate :: ChainUpdate block a -> Text +nameChainUpdate = \case + AddBlock{} -> "AddBlock" + RollBack{} -> "RollBack" namesForChainSyncServerEvent' :: TraceChainSyncServerEvent blk -> [Text] -namesForChainSyncServerEvent' TraceChainSyncServerRead {} = - ["ServerRead"] -namesForChainSyncServerEvent' TraceChainSyncServerReadBlocked {} = - ["ServerReadBlocked"] -namesForChainSyncServerEvent' TraceChainSyncRollForward {} = - ["RollForward"] -namesForChainSyncServerEvent' TraceChainSyncRollBackward {} = - ["RollBackward"] +namesForChainSyncServerEvent' (TraceChainSyncServerRead _ x) = + ["ServerRead", nameChainUpdate x] +namesForChainSyncServerEvent' (TraceChainSyncServerReadBlocked _ x) = + ["ServerReadBlocked", nameChainUpdate x] +namesForChainSyncServerEvent' TraceChainSyncRollForward{} = + ["RollForward"] +namesForChainSyncServerEvent' TraceChainSyncRollBackward{} = + ["RollBackward"] instance ConvertRawHash blk => LogFormatting (TraceChainSyncServerEvent blk) where @@ -450,23 +455,47 @@ namesForBlockFetchClient' BlockFetch.ClientTerminating {} = ["ClientTerminating"] -instance LogFormatting (BlockFetch.TraceFetchClientState header) where +instance (HasHeader header, ConvertRawHash header) => + LogFormatting (BlockFetch.TraceFetchClientState header) where forMachine _dtal BlockFetch.AddedFetchRequest {} = mconcat [ "kind" .= String "AddedFetchRequest" ] forMachine _dtal BlockFetch.AcknowledgedFetchRequest {} = mconcat [ "kind" .= String "AcknowledgedFetchRequest" ] - forMachine _dtal BlockFetch.SendFetchRequest {} = - mconcat [ "kind" .= String "SendFetchRequest" ] - forMachine _dtal BlockFetch.CompletedBlockFetch {} = - mconcat [ "kind" .= String "CompletedBlockFetch" ] + forMachine _dtal (BlockFetch.SendFetchRequest af) = + mconcat [ "kind" .= String "SendFetchRequest" + , "head" .= String (renderChainHash + (renderHeaderHash (Proxy @header)) + (AF.headHash af)) + , "length" .= toJSON (fragmentLength af)] + where + -- NOTE: this ignores the Byron era with its EBB complication: + -- the length would be underestimated by 1, if the AF is anchored + -- at the epoch boundary. + fragmentLength :: AF.AnchoredFragment header -> Int + fragmentLength f = fromIntegral . unBlockNo $ + case (f, f) of + (AS.Empty{}, AS.Empty{}) -> 0 + (firstHdr AS.:< _, _ AS.:> lastHdr) -> + blockNo lastHdr - blockNo firstHdr + 1 + forMachine _dtal (BlockFetch.CompletedBlockFetch pt _ _ _ delay blockSize) = + mconcat [ "kind" .= String "CompletedBlockFetch" + , "delay" .= (realToFrac delay :: Double) + , "size" .= blockSize + , "block" .= String + (case pt of + GenesisPoint -> "Genesis" + BlockPoint _ h -> renderHeaderHash (Proxy @header) h) + ] forMachine _dtal BlockFetch.CompletedFetchBatch {} = mconcat [ "kind" .= String "CompletedFetchBatch" ] forMachine _dtal BlockFetch.StartedFetchBatch {} = mconcat [ "kind" .= String "StartedFetchBatch" ] forMachine _dtal BlockFetch.RejectedFetchBatch {} = mconcat [ "kind" .= String "RejectedFetchBatch" ] - forMachine _dtal BlockFetch.ClientTerminating {} = - mconcat [ "kind" .= String "ClientTerminating" ] + forMachine _dtal (BlockFetch.ClientTerminating outstanding) = + mconcat [ "kind" .= String "ClientTerminating" + , "outstanding" .= outstanding + ] docBlockFetchClient :: @@ -906,59 +935,53 @@ docMempool' = Documented [ severityForge :: ForgeTracerType blk -> SeverityS severityForge (Left t) = severityForge' t -severityForge (Right t) = severityForge''' t - -severityForge' :: TraceLabelCreds (TraceForgeEvent blk) -> SeverityS -severityForge' (TraceLabelCreds _t e) = severityForge'' e - -severityForge'' :: TraceForgeEvent blk -> SeverityS -severityForge'' TraceStartLeadershipCheck {} = Info -severityForge'' TraceSlotIsImmutable {} = Error -severityForge'' TraceBlockFromFuture {} = Error -severityForge'' TraceBlockContext {} = Debug -severityForge'' TraceNoLedgerState {} = Error -severityForge'' TraceLedgerState {} = Debug -severityForge'' TraceNoLedgerView {} = Error -severityForge'' TraceLedgerView {} = Debug -severityForge'' TraceForgeStateUpdateError {} = Error -severityForge'' TraceNodeCannotForge {} = Error -severityForge'' TraceNodeNotLeader {} = Info -severityForge'' TraceNodeIsLeader {} = Info -severityForge'' TraceForgedBlock {} = Info -severityForge'' TraceDidntAdoptBlock {} = Error -severityForge'' TraceForgedInvalidBlock {} = Error -severityForge'' TraceAdoptedBlock {} = Info - -severityForge''' :: TraceLabelCreds TraceStartLeadershipCheckPlus -> SeverityS -severityForge''' _ = Info +severityForge (Right t) = severityForge'' t + +severityForge' :: TraceForgeEvent blk -> SeverityS +severityForge' TraceStartLeadershipCheck {} = Info +severityForge' TraceSlotIsImmutable {} = Error +severityForge' TraceBlockFromFuture {} = Error +severityForge' TraceBlockContext {} = Debug +severityForge' TraceNoLedgerState {} = Error +severityForge' TraceLedgerState {} = Debug +severityForge' TraceNoLedgerView {} = Error +severityForge' TraceLedgerView {} = Debug +severityForge' TraceForgeStateUpdateError {} = Error +severityForge' TraceNodeCannotForge {} = Error +severityForge' TraceNodeNotLeader {} = Info +severityForge' TraceNodeIsLeader {} = Info +severityForge' TraceForgedBlock {} = Info +severityForge' TraceDidntAdoptBlock {} = Error +severityForge' TraceForgedInvalidBlock {} = Error +severityForge' TraceAdoptedBlock {} = Info + +severityForge'' :: TraceStartLeadershipCheckPlus -> SeverityS +severityForge'' _ = Info namesForForge :: ForgeTracerType blk -> [Text] namesForForge (Left t) = namesForForge' t -namesForForge (Right t) = namesForForge''' t - -namesForForge' :: TraceLabelCreds (TraceForgeEvent blk) -> [Text] -namesForForge' (TraceLabelCreds _t e) = namesForForge'' e - -namesForForge'' :: TraceForgeEvent blk -> [Text] -namesForForge'' TraceStartLeadershipCheck {} = ["StartLeadershipCheck"] -namesForForge'' TraceSlotIsImmutable {} = ["SlotIsImmutable"] -namesForForge'' TraceBlockFromFuture {} = ["BlockFromFuture"] -namesForForge'' TraceBlockContext {} = ["BlockContext"] -namesForForge'' TraceNoLedgerState {} = ["NoLedgerState"] -namesForForge'' TraceLedgerState {} = ["LedgerState"] -namesForForge'' TraceNoLedgerView {} = ["NoLedgerView"] -namesForForge'' TraceLedgerView {} = ["LedgerView"] -namesForForge'' TraceForgeStateUpdateError {} = ["ForgeStateUpdateError"] -namesForForge'' TraceNodeCannotForge {} = ["NodeCannotForge"] -namesForForge'' TraceNodeNotLeader {} = ["NodeNotLeader"] -namesForForge'' TraceNodeIsLeader {} = ["NodeIsLeader"] -namesForForge'' TraceForgedBlock {} = ["ForgedBlock"] -namesForForge'' TraceDidntAdoptBlock {} = ["DidntAdoptBlock"] -namesForForge'' TraceForgedInvalidBlock {} = ["ForgedInvalidBlock"] -namesForForge'' TraceAdoptedBlock {} = ["AdoptedBlock"] - -namesForForge''' :: TraceLabelCreds TraceStartLeadershipCheckPlus -> [Text] -namesForForge''' (TraceLabelCreds _ TraceStartLeadershipCheckPlus {}) = +namesForForge (Right t) = namesForForge'' t + +namesForForge' :: TraceForgeEvent blk -> [Text] +namesForForge' TraceStartLeadershipCheck {} = ["StartLeadershipCheck"] +namesForForge' TraceSlotIsImmutable {} = ["SlotIsImmutable"] +namesForForge' TraceBlockFromFuture {} = ["BlockFromFuture"] +namesForForge' TraceBlockContext {} = ["BlockContext"] +namesForForge' TraceNoLedgerState {} = ["NoLedgerState"] +namesForForge' TraceLedgerState {} = ["LedgerState"] +namesForForge' TraceNoLedgerView {} = ["NoLedgerView"] +namesForForge' TraceLedgerView {} = ["LedgerView"] +namesForForge' TraceForgeStateUpdateError {} = ["ForgeStateUpdateError"] +namesForForge' TraceNodeCannotForge {} = ["NodeCannotForge"] +namesForForge' TraceNodeNotLeader {} = ["NodeNotLeader"] +namesForForge' TraceNodeIsLeader {} = ["NodeIsLeader"] +namesForForge' TraceForgedBlock {} = ["ForgedBlock"] +namesForForge' TraceDidntAdoptBlock {} = ["DidntAdoptBlock"] +namesForForge' TraceForgedInvalidBlock {} = ["ForgedInvalidBlock"] +namesForForge' TraceAdoptedBlock {} = ["AdoptedBlock"] + +namesForForge'' :: TraceStartLeadershipCheckPlus -> [Text] +namesForForge'' TraceStartLeadershipCheckPlus{} = ["StartLeadershipCheckPlus"] @@ -1200,12 +1223,12 @@ instance ( tx ~ GenTx blk instance LogFormatting TraceStartLeadershipCheckPlus where forMachine _dtal TraceStartLeadershipCheckPlus {..} = - mconcat [ "kind" .= String "TraceStartLeadershipCheckPlus" - , "slotNo" .= toJSON (unSlotNo tsSlotNo) - , "utxoSize" .= Number (fromIntegral tsUtxoSize) - , "delegMapSize" .= Number (fromIntegral tsUtxoSize) - , "chainDensity" .= Number (fromRational (toRational tsChainDensity)) - ] + mconcat [ "kind" .= String "TraceStartLeadershipCheck" + , "slot" .= toJSON (unSlotNo tsSlotNo) + , "utxoSize" .= Number (fromIntegral tsUtxoSize) + , "delegMapSize" .= Number (fromIntegral tsUtxoSize) + , "chainDensity" .= Number (fromRational (toRational tsChainDensity)) + ] forHuman TraceStartLeadershipCheckPlus {..} = "Checking for leadership in slot " <> showT (unSlotNo tsSlotNo) <> " utxoSize " <> showT tsUtxoSize @@ -1215,12 +1238,12 @@ instance LogFormatting TraceStartLeadershipCheckPlus where [IntM "cardano.node.utxoSize" (fromIntegral tsUtxoSize), IntM "cardano.node.delegMapSize" (fromIntegral tsDelegMapSize)] -docForge :: Documented (Either (TraceLabelCreds (TraceForgeEvent blk)) - (TraceLabelCreds TraceStartLeadershipCheckPlus)) +docForge :: Documented (Either (TraceForgeEvent blk) + TraceStartLeadershipCheckPlus) docForge = addDocumentedNamespace [] docForge' -docForge' :: Documented (Either (TraceLabelCreds (TraceForgeEvent blk)) - (TraceLabelCreds TraceStartLeadershipCheckPlus)) +docForge' :: Documented (Either (TraceForgeEvent blk) + TraceStartLeadershipCheckPlus) docForge' = Documented [ DocMsg ["StartLeadershipCheck"] diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/ForgingThreadStats.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/ForgingThreadStats.hs index d8dc1236917..a343e618fcd 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/ForgingThreadStats.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/ForgingThreadStats.hs @@ -1,4 +1,5 @@ {-# LANGUAGE FlexibleInstances #-} +{-# LANGUAGE LambdaCase #-} {-# LANGUAGE NamedFieldPuns #-} {-# LANGUAGE RecordWildCards #-} @@ -70,8 +71,8 @@ emptyForgeThreadStats = ForgeThreadStats 0 0 0 0 0 docForgeStats :: Documented (Either - (Consensus.TraceLabelCreds (Consensus.TraceForgeEvent blk)) - (Consensus.TraceLabelCreds TraceStartLeadershipCheckPlus)) + (Consensus.TraceForgeEvent blk) + TraceStartLeadershipCheckPlus) docForgeStats = Documented [ DocMsg ["ForgeStats"] @@ -130,7 +131,11 @@ emptyForgingStats = ForgingStats mempty 0 0 0 0 forgeThreadStats :: Trace IO (Folding (ForgeTracerType blk) ForgingStats) -> IO (Trace IO (ForgeTracerType blk)) -forgeThreadStats = foldMTraceM calculateThreadStats emptyForgingStats +forgeThreadStats = foldMCondTraceM calculateThreadStats emptyForgingStats + (\case + Left Consensus.TraceStartLeadershipCheck{} -> True + Left _ -> False + Right _ -> True) calculateThreadStats :: MonadIO m => ForgingStats @@ -138,14 +143,14 @@ calculateThreadStats :: MonadIO m -> ForgeTracerType blk -> m ForgingStats calculateThreadStats stats _context - (Left (TraceLabelCreds _ TraceNodeCannotForge {})) = do + (Left TraceNodeCannotForge {}) = do mapThreadStats stats (\fts -> (fts { ftsNodeCannotForgeNum = ftsNodeCannotForgeNum fts + 1} , Nothing)) (\fs _ -> (fs { fsNodeCannotForgeNum = fsNodeCannotForgeNum fs + 1 })) calculateThreadStats stats _context - (Left (TraceLabelCreds _ (TraceNodeIsLeader (SlotNo slot')))) = do + (Left (TraceNodeIsLeader (SlotNo slot'))) = do let slot = fromIntegral slot' mapThreadStats stats @@ -153,14 +158,14 @@ calculateThreadStats stats _context , ftsLastSlot = slot}, Nothing)) (\fs _ -> (fs { fsNodeIsLeaderNum = fsNodeIsLeaderNum fs + 1 })) calculateThreadStats stats _context - (Left (TraceLabelCreds _ TraceForgedBlock {})) = do + (Left TraceForgedBlock {}) = do mapThreadStats stats (\fts -> (fts { ftsBlocksForgedNum = ftsBlocksForgedNum fts + 1} , Nothing)) (\fs _ -> (fs { fsBlocksForgedNum = fsBlocksForgedNum fs + 1 })) calculateThreadStats stats _context - (Left (TraceLabelCreds _ (TraceNodeNotLeader (SlotNo slot')))) = do + (Left (TraceNodeNotLeader (SlotNo slot'))) = do let slot = fromIntegral slot' mapThreadStats stats diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/Peer.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/Peer.hs index a679a592848..f9670422c8c 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/Peer.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/Peer.hs @@ -123,11 +123,11 @@ namesForPeers :: [PeerT blk] -> [Text] namesForPeers _ = [] severityPeers :: [PeerT blk] -> SeverityS +severityPeers [] = Debug severityPeers _ = Notice instance LogFormatting [PeerT blk] where - forMachine DMinimal _ = mconcat [ "kind" .= String "NodeKernelPeers"] - forMachine _ [] = mconcat [ "kind" .= String "NodeKernelPeers"] + forMachine _ [] = mempty forMachine dtal xs = mconcat [ "kind" .= String "NodeKernelPeers" , "peers" .= toJSON (foldl' (\acc x -> forMachine dtal x : acc) [] xs) diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/StartLeadershipCheck.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/StartLeadershipCheck.hs index 315800e3963..75211865779 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/StartLeadershipCheck.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/StartLeadershipCheck.hs @@ -36,8 +36,8 @@ import Cardano.Slotting.Slot (fromWithOrigin) import Cardano.Ledger.BaseTypes (StrictMaybe (..), fromSMaybe) -type ForgeTracerType blk = Either (TraceLabelCreds (TraceForgeEvent blk)) - (TraceLabelCreds TraceStartLeadershipCheckPlus) +type ForgeTracerType blk = Either (TraceForgeEvent blk) + TraceStartLeadershipCheckPlus data TraceStartLeadershipCheckPlus = TraceStartLeadershipCheckPlus { @@ -56,8 +56,7 @@ forgeTracerTransform :: -> IO (Trace IO (ForgeTracerType blk)) forgeTracerTransform nodeKern (Trace tr) = pure $ Trace $ T.arrow $ T.emit $ \case - (lc, Right (Left (TraceLabelCreds creds - (TraceStartLeadershipCheck slotNo)))) -> do + (lc, Right (Left slc@(TraceStartLeadershipCheck slotNo))) -> do query <- mapNodeKernelDataIO (\nk -> (,,) @@ -65,7 +64,8 @@ forgeTracerTransform nodeKern (Trace tr) = pure $ Trace $ T.arrow $ T.emit $ <*> nkQueryLedger (ledgerDelegMapSize . ledgerState) nk <*> nkQueryChain fragmentChainDensity nk) nodeKern - fromSMaybe (pure ()) + fromSMaybe + (T.traceWith tr (lc, Right (Left slc))) (query <&> \(utxoSize, delegMapSize, chainDensity) -> let msg = TraceStartLeadershipCheckPlus @@ -73,7 +73,7 @@ forgeTracerTransform nodeKern (Trace tr) = pure $ Trace $ T.arrow $ T.emit $ utxoSize delegMapSize (fromRational chainDensity) - in T.traceWith tr (lc, Right (Right (TraceLabelCreds creds msg)))) + in T.traceWith tr (lc, Right (Right msg))) (lc, Right a) -> T.traceWith tr (lc, Right a) (lc, Left control) -> diff --git a/configuration/cardano/mainnet-config-new-tracing.yaml b/configuration/cardano/mainnet-config-new-tracing.yaml index a39490cbddf..5713c3e5fa0 100644 --- a/configuration/cardano/mainnet-config-new-tracing.yaml +++ b/configuration/cardano/mainnet-config-new-tracing.yaml @@ -107,9 +107,9 @@ TraceOptionForwarder: filePath: /tmp/forwarder.sock mode: Initiator -TraceOptionPeerFreqency: 2000 +TraceOptionPeerFrequency: 2000 -TraceOptionResourceFreqency: 5000 +TraceOptionResourceFrequency: 5000 ##### Stubs for legacy logging config ##### diff --git a/configuration/cardano/membench-config-new.yaml b/configuration/cardano/membench-config-new.yaml index 0a92ec389f0..7700a5171e7 100644 --- a/configuration/cardano/membench-config-new.yaml +++ b/configuration/cardano/membench-config-new.yaml @@ -133,9 +133,9 @@ TraceOptionForwarder: filePath: /tmp/forwarder.sock mode: Initiator -TraceOptionPeerFreqency: 2000 +TraceOptionPeerFrequency: 2000 -TraceOptionResourceFreqency: 5000 +TraceOptionResourceFrequency: 5000 ##### Stubs for legacy logging config ##### diff --git a/default.nix b/default.nix index 37f252ac093..e4ef016136f 100644 --- a/default.nix +++ b/default.nix @@ -6,12 +6,11 @@ in # override scripts with custom configuration withHoogle ? defaultCustomConfig.withHoogle , profileName ? defaultCustomConfig.localCluster.profileName -, autoStartCluster ? defaultCustomConfig.localCluster.autoStartCluster , workbenchDevMode ? defaultCustomConfig.localCluster.workbenchDevMode , customConfig ? { inherit withHoogle; localCluster = { - inherit autoStartCluster profileName workbenchDevMode; + inherit profileName workbenchDevMode; }; } }: diff --git a/doc/new-tracing/tracers_doc_generated.md b/doc/new-tracing/tracers_doc_generated.md index 91fb698073e..130e8f1df8d 100644 --- a/doc/new-tracing/tracers_doc_generated.md +++ b/doc/new-tracing/tracers_doc_generated.md @@ -12658,7 +12658,7 @@ Basic information about this node collected at startup *** -Configuration: TraceConfig {tcOptions = fromList [([],[ConfBackend [Stdout MachineFormat,EKGBackend],ConfDetail DNormal,ConfSeverity Notice]),(["Node","AcceptPolicy"],[ConfSeverity Info]),(["Node","BlockFetchClient","CompletedBlockFetch"],[ConfLimiter "CompletedBlockFetchLimiter" 2.0]),(["Node","ChainDB"],[ConfSeverity Info]),(["Node","ChainDB","AddBlockEvent","AddBlockValidation","ValidCandidate"],[ConfLimiter "ValidCandidateLimiter" 2.0]),(["Node","ChainDB","AddBlockEvent","AddedBlockToQueue"],[ConfLimiter "AddedBlockToQueueLimiter" 2.0]),(["Node","ChainDB","AddBlockEvent","AddedBlockToVolatileDB"],[ConfLimiter "AddedBlockToVolatileDBLimiter" 2.0]),(["Node","ChainDB","CopyToImmutableDBEvent","CopiedBlockToImmutableDB"],[ConfLimiter "CopiedBlockToImmutableDBLimiter" 2.0]),(["Node","DNSResolver"],[ConfSeverity Info]),(["Node","DNSSubscription"],[ConfSeverity Info]),(["Node","DiffusionInit"],[ConfSeverity Info]),(["Node","ErrorPolicy"],[ConfSeverity Info]),(["Node","Forge"],[ConfSeverity Info]),(["Node","IpSubscription"],[ConfSeverity Info]),(["Node","LocalErrorPolicy"],[ConfSeverity Info]),(["Node","Mempool"],[ConfSeverity Info]),(["Node","Resources"],[ConfSeverity Info])], tcForwarder = TraceOptionForwarder {tofAddress = LocalSocket "/tmp/forwarder.sock", tofMode = Initiator, tofConnQueueSize = 2000, tofDisconnQueueSize = 200000, tofVerbosity = Minimum}, tcNodeName = Nothing, tcPeerFreqency = Just 2000, tcResourceFreqency = Just 5000} +Configuration: TraceConfig {tcOptions = fromList [([],[ConfBackend [Stdout MachineFormat,EKGBackend],ConfDetail DNormal,ConfSeverity Notice]),(["Node","AcceptPolicy"],[ConfSeverity Info]),(["Node","BlockFetchClient","CompletedBlockFetch"],[ConfLimiter "CompletedBlockFetchLimiter" 2.0]),(["Node","ChainDB"],[ConfSeverity Info]),(["Node","ChainDB","AddBlockEvent","AddBlockValidation","ValidCandidate"],[ConfLimiter "ValidCandidateLimiter" 2.0]),(["Node","ChainDB","AddBlockEvent","AddedBlockToQueue"],[ConfLimiter "AddedBlockToQueueLimiter" 2.0]),(["Node","ChainDB","AddBlockEvent","AddedBlockToVolatileDB"],[ConfLimiter "AddedBlockToVolatileDBLimiter" 2.0]),(["Node","ChainDB","CopyToImmutableDBEvent","CopiedBlockToImmutableDB"],[ConfLimiter "CopiedBlockToImmutableDBLimiter" 2.0]),(["Node","DNSResolver"],[ConfSeverity Info]),(["Node","DNSSubscription"],[ConfSeverity Info]),(["Node","DiffusionInit"],[ConfSeverity Info]),(["Node","ErrorPolicy"],[ConfSeverity Info]),(["Node","Forge"],[ConfSeverity Info]),(["Node","IpSubscription"],[ConfSeverity Info]),(["Node","LocalErrorPolicy"],[ConfSeverity Info]),(["Node","Mempool"],[ConfSeverity Info]),(["Node","Resources"],[ConfSeverity Info])], tcForwarder = TraceOptionForwarder {tofAddress = LocalSocket "/tmp/forwarder.sock", tofMode = Initiator, tofConnQueueSize = 2000, tofDisconnQueueSize = 200000, tofVerbosity = Minimum}, tcNodeName = Nothing, tcPeerFrequency = Just 2000, tcResourceFrequency = Just 5000} 672 log messages. Generated at 2022-05-06 10:18:02.192098573 CEST. \ No newline at end of file diff --git a/flake.nix b/flake.nix index 36f56d43771..bf8e1a8264d 100644 --- a/flake.nix +++ b/flake.nix @@ -210,7 +210,7 @@ inherit (mkPackages project) projectPackages projectExes profiledProject assertedProject eventloggedProject pinned-workbench; - shell = import ./shell.nix { inherit pkgs customConfig; }; + shell = import ./shell.nix { inherit pkgs customConfig cardano-mainnet-mirror; }; devShells = { inherit (shell) devops; cluster = shell; diff --git a/legacy.mk b/legacy.mk new file mode 100644 index 00000000000..bd8fdadc391 --- /dev/null +++ b/legacy.mk @@ -0,0 +1,3 @@ +cluster-shell: CMD = start-cluster ## Enter Nix shell and start the workbench cluster +cluster-shell: + nix-shell --max-jobs 8 --cores 0 --show-trace --argstr profileName ${PROFILE} diff --git a/lib.mk b/lib.mk new file mode 100644 index 00000000000..f09bb64d249 --- /dev/null +++ b/lib.mk @@ -0,0 +1,24 @@ +## define_proftarget :: target -> profile -> devmode -> autostart -> IO () +define define_profile_target +$(1): shell +$(1): PROFILE = $(2)-${ERA} +ifeq ($(3),true) +$(1): ARGS += --arg 'workbenchDevMode' true +endif +ifeq ($(4),true) +$(1): CMD := start-cluster; exit +endif +ifeq ($(3)$(4),truefalse) +define EXTRA_HELP += +$(1): ## Shell for profile $(2) (also -auto -nix -autonix)\n +endef +endif + +endef + +define define_profile_targets +$$(foreach prof,$(1),$$(eval $$(call define_profile_target,$$(prof),$$(prof),true,false))) +$$(foreach prof,$(1),$$(eval $$(call define_profile_target,$$(prof)-auto,$$(prof),true,true))) +$$(foreach prof,$(1),$$(eval $$(call define_profile_target,$$(prof)-nix,$$(prof),false,false))) +$$(foreach prof,$(1),$$(eval $$(call define_profile_target,$$(prof)-autonix,$$(prof),false,true))) +endef diff --git a/nix.mk b/nix.mk new file mode 100644 index 00000000000..4ac423abb53 --- /dev/null +++ b/nix.mk @@ -0,0 +1,25 @@ +bump-cardano-node-workbench: ## Update the cardano-node-workbench flake input + nix flake lock --update-input cardano-node-workbench +bump-node-measured: ## Update the node-measured flake input + nix flake lock --update-input node-measured +bump-cardano-deployment: ## Sync the flake.lock to the CI check + nix run nixpkgs#nixUnstable -- build .#hydraJobs.cardano-deployment +membench-1: ## Membench: one iteration, current commit + nix build .#membench-node-this-1.batch-report --out-link result-batch-1-report +membench-1-at: ## Membench: one iteration, set commit by: make membench-1-at REV=[master] + nix build .#membench-node-measured-1.batch-report --out-link result-batch-1-report --override-input node-measured github:input-output-hk/cardano-node/${REV} +membench-5: ## Membench: 5 iterations, current commit + nix build .#membench-node-this-5.batch-report --out-link result-batch-5-report +membench-5-at: ## Membench: 5 iterations, set commit by: make membench-5-at REV=[master] + nix build .#membench-node-this-5.batch-report --out-link result-batch-5-report --override-input node-measured github:input-output-hk/cardano-node/${REV} + +test-smoke: smoke ## Build the 'workbench-smoke-test', same as the Hydra job +smoke: + nix build -f 'default.nix' 'workbench-smoke-test' --out-link result-smoke-run --cores 0 + +test-analysis: smoke-analysis ## Build the 'workbench-smoke-analysis', same as the Hydra job +smoke-analysis: + nix build -f 'default.nix' 'workbench-smoke-analysis' --out-link result-smoke-analysis --cores 0 --show-trace + +ci-analysis: + nix build -f 'default.nix' 'workbench-ci-analysis' --out-link result-ci-analysis --cores 0 --show-trace diff --git a/nix/TODO.org b/nix/TODO.org new file mode 100644 index 00000000000..4a2969ed917 --- /dev/null +++ b/nix/TODO.org @@ -0,0 +1,4 @@ +* A simple TODO list + +1. shell.nix has a separate pin of the =cardano-mainnet-mirror= flake -- that + could've been using the =flake.nix= reference somehow. diff --git a/nix/custom-config.nix b/nix/custom-config.nix index 4c5c5864902..23660b0e1ad 100644 --- a/nix/custom-config.nix +++ b/nix/custom-config.nix @@ -6,8 +6,6 @@ self: { batchName = "plain"; profileName = "default-alzo"; basePort = 30000; - autoStartCluster = false; - autoStartClusterArgs = ""; enableEKG = true; workbenchDevMode = false; extraSupervisorConfig = {}; diff --git a/nix/nixos/cardano-node-service.nix b/nix/nixos/cardano-node-service.nix index 33e683c861f..874c41235de 100644 --- a/nix/nixos/cardano-node-service.nix +++ b/nix/nixos/cardano-node-service.nix @@ -9,27 +9,42 @@ let envConfig = cfg.environments.${cfg.environment}; runtimeDir = if cfg.runtimeDir == null then cfg.stateDir else "/run/${cfg.runtimeDir}"; mkScript = cfg: - let baseConfig = recursiveUpdate (cfg.nodeConfig - // (mapAttrs' (era: epoch: - nameValuePair "Test${era}HardForkAtEpoch" epoch - ) cfg.forceHardForks) - // (optionalAttrs cfg.useNewTopology { - EnableP2P = true; - TargetNumberOfRootPeers = cfg.targetNumberOfRootPeers; - TargetNumberOfKnownPeers = cfg.targetNumberOfKnownPeers; - TargetNumberOfEstablishedPeers = cfg.targetNumberOfEstablishedPeers; - TargetNumberOfActivePeers = cfg.targetNumberOfActivePeers; - TestEnableDevelopmentNetworkProtocols = true; - MaxConcurrencyBulkSync = 2; - })) cfg.extraNodeConfig; + let baseConfig = + recursiveUpdate + (cfg.nodeConfig + // (mapAttrs' (era: epoch: + nameValuePair "Test${era}HardForkAtEpoch" epoch + ) cfg.forceHardForks) + // (optionalAttrs cfg.useNewTopology { + EnableP2P = true; + TargetNumberOfRootPeers = cfg.targetNumberOfRootPeers; + TargetNumberOfKnownPeers = cfg.targetNumberOfKnownPeers; + TargetNumberOfEstablishedPeers = cfg.targetNumberOfEstablishedPeers; + TargetNumberOfActivePeers = cfg.targetNumberOfActivePeers; + TestEnableDevelopmentNetworkProtocols = true; + MaxConcurrencyBulkSync = 2; + })) cfg.extraNodeConfig; + baseInstanceConfig = + i: + if !cfg.useLegacyTracing + then baseConfig // + { ## XXX: remove once legacy tracing is dropped + minSeverity = "Critical"; + setupScribes = []; + setupBackends = []; + defaultScribes = []; + defaultBackends = []; + options = {}; + } + else baseConfig // + (optionalAttrs (baseConfig ? hasEKG) { + hasEKG = baseConfig.hasEKG + i; + }) // + (optionalAttrs (baseConfig ? hasPrometheus) { + hasPrometheus = map (n: if isInt n then n + i else n) baseConfig.hasPrometheus; + }); in i: let - instanceConfig = recursiveUpdate (baseConfig - // (optionalAttrs (baseConfig ? hasEKG) { - hasEKG = baseConfig.hasEKG + i; - }) - // (optionalAttrs (baseConfig ? hasPrometheus) { - hasPrometheus = map (n: if isInt n then n + i else n) baseConfig.hasPrometheus; - })) (cfg.extraNodeInstanceConfig i); + instanceConfig = recursiveUpdate (baseInstanceConfig i) (cfg.extraNodeInstanceConfig i); nodeConfigFile = if (cfg.nodeConfigFile != null) then cfg.nodeConfigFile else toFile "config-${toString cfg.nodeId}-${toString i}.json" (toJSON instanceConfig); newTopology = { @@ -425,6 +440,14 @@ in { ''; }; + useLegacyTracing = mkOption { + type = types.bool; + default = true; + description = '' + Use the legacy tracing, based on iohk-monitoring-framework. + ''; + }; + usePeersFromLedgerAfterSlot = mkOption { type = types.nullOr types.int; default = if cfg.kesKey != null then null diff --git a/nix/workbench/analyse.sh b/nix/workbench/analyse.sh index 9cf6ae5cbd9..bef72048605 100644 --- a/nix/workbench/analyse.sh +++ b/nix/workbench/analyse.sh @@ -14,14 +14,16 @@ EOF } analyse() { -local dump_logobjects= preflt_jq= filters=() aws= -local dump_logobjects= dump_slots_raw= dump_slots= dump_chain_raw= dump_chain= dump_mach_views= +local filters=() aws= sargs=() +local dump_logobjects= dump_machviews= dump_chain_raw= dump_chain= dump_slots_raw= dump_slots= while test $# -gt 0 do case "$1" in - --dump-logobjects ) dump_logobjects='true';; - --prefilter-jq ) preflt_jq='true';; - --filters ) analysis_set_filters "base,$2"; shift;; - --no-filters ) analysis_set_filters "";; + --dump-logobjects | -lo ) sargs+=($1); dump_logobjects='true';; + --dump-machviews | -mw ) sargs+=($1); dump_machviews='true';; + --dump-chain-raw | -cr ) sargs+=($1); dump_chain_raw='true';; + --dump-chain | -c ) sargs+=($1); dump_chain='true';; + --filters ) sargs+=($1 $2); analysis_set_filters "base,$2"; shift;; + --no-filters ) sargs+=($1); analysis_set_filters "";; * ) break;; esac; shift; done if curl --connect-timeout 0.5 http://169.254.169.254/latest/meta-data >/dev/null 2>&1 @@ -35,76 +37,67 @@ else locli_rts_args=() echo "{ \"aws\": false }" fi -local op=${1:-$(usage_analyse)}; shift +local op=${1:-standard}; if test $# != 0; then shift; fi case "$op" in # 'read-mach-views' "${logs[@]/#/--log }" - standard | std ) + everything | full | all | standard | std ) + local script=( + logs $(test -n "$dump_logobjects" && echo 'dump-logobjects') + context + + build-mach-views $(test -n "$dump_machviews" && echo 'dump-mach-views') + build-chain $(test -n "$dump_chain_raw" && echo 'dump-chain-raw') + chain-timeline-raw + filter-chain $(test -n "$dump_chain" && echo 'dump-chain') + chain-timeline + + collect-slots $(test -n "$dump_slots_raw" && echo 'dump-slots-raw') + filter-slots $(test -n "$dump_slots" && echo 'dump-slots') + timeline-slots + + propagation + dump-propagation + report-prop-{forger,peers,endtoend,full} + + perfanalysis + dump-perfanalysis + report-perf-{full,brief} + ) + progress "analysis" "$(with_color white full), calling script: $(colorise ${script[*]})" + analyse ${sargs[*]} map "call ${script[*]}" "$@" + ;; + + performance | perf ) + local script=( + logs $(test -n "$dump_logobjects" && echo 'dump-logobjects') + context + + collect-slots $(test -n "$dump_slots_raw" && echo 'dump-slots-raw') + filter-slots $(test -n "$dump_slots" && echo 'dump-slots') + timeline-slots + + perfanalysis + dump-perfanalysis + report-perf-{full,brief} + ) + progress "analysis" "$(with_color white performance), calling script: $(colorise ${script[*]})" + analyse ${sargs[*]} map "call ${script[*]}" "$@" + ;; + + map ) + local usage="USAGE: wb analyse $op OP RUNS.." + + local preop=${1:?usage}; shift local runs=($*); if test $# = 0; then runs=(current); fi + local op_split=($preop) + local op=${op_split[0]} + local args=${op_split[*]:1} + progress "analyse" "mapping op $(with_color yellow $op) $(with_color cyan $args) over runs: $(with_color white ${runs[*]})" for r in ${runs[*]} - do analyse prepare $r - - local name=${1:-current}; if test $# != 0; then shift; fi - local dir=$(run get "$name") - local adir=$dir/analysis - test -n "$dir" -a -d "$adir" || fail "malformed run: $name" - - if test -z "${filters[*]}" - then local filter_names=$(jq '.analysis.filters - | join(",") - ' "$dir"/profile.json --raw-output) - analysis_set_filters "$filter_names" - fi - - local logs=("$adir"/logs-*.flt.json) - local args=( - 'meta-genesis' --run-metafile "$dir"/meta.json - --shelley-genesis "$dir"/genesis-shelley.json - - 'unlog' --host-from-log-filename ${logs[@]/#/--log } - $(if test -n "$dump_logobjects"; then echo \ - 'dump-logobjects'; fi) - - 'build-mach-views' - $(if test -n "$dump_mach_views"; then echo \ - 'dump-mach-views'; fi) - - 'build-chain' - $(if test -n "$dump_chain_raw"; then echo \ - 'dump-chain-raw' --chain "$adir"/chain-raw.json; fi) - - 'timeline-chain-raw' --timeline "$adir"/chain-raw.txt - - 'filter-chain' "${filters[@]}" - $(if test -n "$dump_chain"; then echo \ - 'dump-chain' --chain "$adir"/chain.json; fi) - - 'timeline-chain' --timeline "$adir"/chain.txt - - 'collect-slots' - $(if test -n "$dump_slots_raw"; then echo \ - 'dump-slots-raw'; fi) - - 'filter-slots' "${filters[@]}" - $(if test -n "$dump_slots"; then echo \ - 'dump-slots'; fi) - - 'timeline-slots' - - 'propagation' - 'dump-propagation' --analysis "$adir"/blockprop.json - 'report-prop-forger' --report "$adir"/blockprop-forger.txt - 'report-prop-peers' --report "$adir"/blockprop-peers.txt - 'report-prop-endtoend' --report "$adir"/blockprop-endtoend.txt - 'report-prop-full' --report "$adir"/blockprop-full.txt - - 'perfanalysis' - 'dump-perfanalysis' - 'report-perf-full' - 'report-perf-brief' - ) - time locli "${locli_rts_args[@]}" "${args[@]}" + do analyse ${sargs[*]} prepare $r + analyse ${sargs[*]} $op $r ${args[*]} done ;; @@ -117,26 +110,33 @@ case "$op" in test -n "$dir" -a -d "$adir" || fail "malformed run: $name" local logfiles=("$adir"/logs-*.flt.json) - local logs=( 'unlog' - ${logfiles[*]/#/--log }) - local run=( 'meta-genesis' - --run-metafile "$dir"/meta.json - --shelley-genesis "$dir"/genesis-shelley.json) - local chain_raw=( 'dump-chain-raw' - --chain "$adir"/chain-raw.json ) - local chain=( 'dump-chain-raw' - --chain "$adir"/chain.json ) - local flt_chain=( 'filter-chain' - "${filters[@]}") - local ops0=("$@") - local ops1=(${ops0[*]/#auto-logs/${logs[*]}}) - local ops2=(${ops1[*]/#auto-run/${run[*]}}) - local ops3=(${ops2[*]/#auto-dump-chain-raw/${chain_raw[*]}}) - local ops4=(${ops3[*]/#auto-filter-chain/${flt_chain[*]}}) - local ops5=(${ops4[*]/#auto-dump-chain/${chain[*]}}) - local ops_final=(${ops5[*]}) - - echo locli "${locli_rts_args[@]}" "${ops_final[@]}" + + if test -z "${filters[*]}" + then local filter_names=$(jq '.analysis.filters + | join(",") + ' "$dir"/profile.json --raw-output) + analysis_set_filters "$filter_names" + fi + + local v0=("$@") + local v1=(${v0[*]/#logs/ 'unlog' --host-from-log-filename ${logfiles[*]/#/--log }}) + local v2=(${v1[*]/#context/ 'meta-genesis' --run-metafile "$dir"/meta.json + --shelley-genesis "$dir"/genesis-shelley.json}) + local v3=(${v2[*]/#dump-chain-raw/ 'dump-chain-raw' --chain "$adir"/chain-raw.json}) + local v4=(${v3[*]/#chain-timeline-raw/ 'timeline-chain-raw' --timeline "$adir"/chain-raw.txt}) + local v5=(${v4[*]/#filter-chain/ 'filter-chain' ${filters[*]}}) + local v6=(${v5[*]/#dump-chain/ 'dump-chain' --chain "$adir"/chain.json}) + local v7=(${v6[*]/#chain-timeline/ 'timeline-chain' --timeline "$adir"/chain.txt}) + local v8=(${v7[*]/#filter-slots/ 'filter-slots' ${filters[*]}}) + local v9=(${v8[*]/#dump-propagation/ 'dump-propagation' --analysis "$adir"/blockprop.json}) + + local va=(${v9[*]/#report-prop-forger/ 'report-prop-forger' --report "$adir"/blockprop-forger.txt }) + local vb=(${va[*]/#report-prop-peers/ 'report-prop-peers' --report "$adir"/blockprop-peers.txt }) + local vc=(${vb[*]/#report-prop-endtoend/'report-prop-endtoend' --report "$adir"/blockprop-endtoend.txt}) + local vd=(${vc[*]/#report-prop-full/ 'report-prop-full' --report "$adir"/blockprop-full.txt }) + local ops_final=(${vd[*]}) + + progress "analysis | locli" "$(with_color reset ${locli_rts_args[@]}) $(colorise "${ops_final[@]}")" time locli "${locli_rts_args[@]}" "${ops_final[@]}" ;; @@ -147,12 +147,16 @@ case "$op" in local dir=$(run get "$name") test -n "$dir" || fail "malformed run: $name" + progress "analyse" "preparing run for analysis: $(with_color white $name)" local adir=$dir/analysis mkdir -p "$adir" ## 0. ask locli what it cares about local keyfile="$adir"/substring-keys - locli 'list-logobject-keys' --keys "$keyfile" + case $(jq '.node.tracing_backend // "trace-dispatcher"' --raw-output $dir/profile.json) in + trace-dispatcher ) locli 'list-logobject-keys' --keys "$keyfile";; + iohk-monitoring ) locli 'list-logobject-keys-legacy' --keys-legacy "$keyfile";; + esac ## 1. unless already done, filter logs according to locli's requirements local logdirs=($(ls -d "$dir"/node-*/ 2>/dev/null)) @@ -167,17 +171,14 @@ case "$op" in --compact-output 'delpaths([["app"],["env"],["loc"],["msg"],["ns"],["sev"]])' ) + progress "analyse" "filtering logs: $(with_color black ${logdirs[@]})" for d in "${logdirs[@]}" do throttle_shell_job_spawns local logfiles="$(ls "$d"/stdout* 2>/dev/null | tac) $(ls "$d"/node-*.json 2>/dev/null)" if test -z "$logfiles" then msg "no logs in $d, skipping.."; fi local output="$adir"/logs-$(basename "$d").flt.json - grep -hFf "$keyfile" $logfiles | - if test "$preflt_jq" = 'true' - then jq "${jq_args[@]}" --arg dirHostname "$(basename "$d")" - else cat - fi > "$output" & + grep -hFf "$keyfile" $logfiles > "$output" & done wait;; @@ -206,3 +207,46 @@ analysis_set_filters() { filters+=(${filter_files[*]/#/--filter }) } + +analysis_classify_traces() { + local name=${1:-current}; if test $# != 0; then shift; fi + local node=${1:-node-0}; if test $# != 0; then shift; fi + local dir=$(run get "$name") + + progress "analysis" "enumerating namespace from logs of $(with_color yellow $node)" + grep -h '^{' $dir/$node/stdout* | jq --raw-output '(try .ns[0] // .ns) + ":" + (.data.kind // "")' 2>/dev/null | sort -u + # grep -h '^{' $dir/$node/stdout* | jq --raw-output '.ns' 2>/dev/null | tr -d ']["' | sort -u +} + +analysis_trace_frequencies() { + local same_types= + while test $# -gt 0 + do case "$1" in + --same-types | --same | -s ) same_types='true';; + * ) break;; esac; shift; done + + local name=${1:-current}; if test $# != 0; then shift; fi + local dir=$(run get "$name") + local types=() + + if test -n "$same_types" + then types=($(analysis_classify_traces $name 'node-0')) + progress_ne "analysis" "message frequencies: "; fi + + for nodedir in $dir/node-*/ + do local node=$(basename $nodedir) + + if test -z "$same_types" + then types=($(analysis_classify_traces $name $node)) + progress "analysis" "message frequencies: $(with_color yellow $node)"; fi + + for type in ${types[*]} + do local ns=$(cut -d: -f1 <<<$type) + local kind=$(cut -d: -f2 <<<$type) + echo $(grep -h "\"$ns\".*\"$kind\"\|\"$kind\".*\"$ns\"" $nodedir/stdout* | wc -l) $type + done | + sort -nr > $nodedir/log-namespace-occurence-stats.txt + test -n "$same_types" && echo -n ' '$node >&2 + done + echo >&2 +} diff --git a/nix/workbench/backend.sh b/nix/workbench/backend.sh index ff5cdb21c1d..2250728a0b2 100644 --- a/nix/workbench/backend.sh +++ b/nix/workbench/backend.sh @@ -12,8 +12,12 @@ usage_backend() { describe-run RUNDIR start-cluster RUNDIR Start the cluster nodes - get-node-socket-path RUNDIR - Given a run directory, print the node socket path + start-node RUNDIR NODE-NAME + stop-node RUNDIR NODE-NAME + wait-node RUNDIR NODE-NAME + Start/stop/wait for a particular node in the cluster + get-node-socket-path RUNDIR [NODE] + Given a run directory, print a given node's node socket path for 'cardano-cli' start-generator RUNDIR Start generator @@ -40,6 +44,10 @@ case "${op}" in allocate-run ) backend_$WORKBENCH_BACKEND "$@";; describe-run ) backend_$WORKBENCH_BACKEND "$@";; start-cluster ) backend_$WORKBENCH_BACKEND "$@";; + start-node ) backend_$WORKBENCH_BACKEND "$@";; + stop-node ) backend_$WORKBENCH_BACKEND "$@";; + wait-node ) backend_$WORKBENCH_BACKEND "$@";; + wait-node-stopped ) backend_$WORKBENCH_BACKEND "$@";; get-node-socket-path ) backend_$WORKBENCH_BACKEND "$@";; start-generator ) backend_$WORKBENCH_BACKEND "$@";; wait-pools-stopped ) backend_$WORKBENCH_BACKEND "$@";; @@ -61,7 +69,7 @@ case "${op}" in assert-stopped ) backend is-running && - fatal "backend reports that cluster is already running. Please stop it first: stop-cluster" || + fatal "backend reports that cluster is already running. Please stop it first: $(yellow stop-cluster)" || true ;; diff --git a/nix/workbench/chaindb.sh b/nix/workbench/chaindb.sh new file mode 100644 index 00000000000..d31eb4523b9 --- /dev/null +++ b/nix/workbench/chaindb.sh @@ -0,0 +1,196 @@ +usage_chaindb() { + usage "chaindb" "Manage ChainDBs" </dev/null) + test -n "$shelleyGenesisHash" || + fail "Invalid Shelley genesis: $(jq .shelley <<<$geneses)" + + cp -r ${source} $out + chmod +w -R $out + + progress "chaindb" "deriving a ChainDB with ledger snapshot at slot $slotno" + + local cache_entry=$cachedir/ledger/mainnet-ledger.$slotno + if test -n "$mainnet" -a -d "$cachedir" -a -f $cache_entry + + then progress "chaindb" "using mainnet cache entry for slot $slotno" + mkdir -p $out/ledger/ + cp $cache_entry $out/ledger/$slotno + + else progress "chaindb" "reapplying blocks.." + + ## Actually produce the snapshot: + local maybe_precedent=$(chaindb_mainnet_ledger_snapshots_before_slot $cachedir $slotno) + args=( --configByron "$(jq -r .byron <<<$geneses)" + --configShelley "$(jq -r .shelley <<<$geneses)" + --configAlonzo "$(jq -r .alonzo <<<$geneses)" + --nonce "$shelleyGenesisHash" + --store-ledger $slotno + ) + if test -n "$maybe_precedent" + then progress "chaindb" "found a precedent snapshot at slot $maybe_precedent, using as base.." + local precedent_cache_entry=$cachedir/ledger/mainnet-ledger.$maybe_precedent + mkdir $out/ledger/ + cp $precedent_cache_entry $out/ledger/${maybe_precedent}_db-analyser + args+=(--only-immutable-db --analyse-from $maybe_precedent) + fi + db-analyser --db $out cardano "${args[@]}" + + (cd $out/ledger; + for x in *_db-analyser + do mv $x ${x/_db-analyser/}; done) + ls -ltrh $out/ledger + + mkdir $out/temp + mv $out/ledger/{$slotno,$(cd $out/ledger; ls | tail -n1)} $out/temp 2>/dev/null || true + rm $out/ledger/* 2>/dev/null || true + mv $out/temp/* $out/ledger/ + rmdir $out/temp + fi + + if test -n "$mainnet" -a -d "$cachedir" -a -f "$out/ledger/$slotno" + then cp $out/ledger/$slotno $cache_entry + fi + + local last_chunk=$(cd $out/immutable; ls | tail -n1 | cut -d. -f1) + + args=( --argjson snapshotSlot $slotno + --arg finalChunkNo $last_chunk + --arg shelleyGenesisHash $shelleyGenesisHash + ) + jq '{ snapshotSlot: $snapshotSlot + , finalChunkNo: $finalChunkNo + , shelleyGenesisHash: $shelleyGenesisHash + # , snapshottingConsensusNodeRev: $snapshottingConsensusNodeRev + } + ' --null-input "${args[@]}" > $out/snapshot-info.json + ;; + +validate ) + local usage="USAGE: wb chaindb $op DIR [LEDGER-SNAPSHOT-SLOTNO]" + local dir=${1:?$usage}; shift + local slot=${1:-} + + progress "chaindb" "validating.." + local args=( + --db "$dir" + $(if test -n "$slot" + then echo --only-immutable-db --analyse-from $slot + else echo --validate-all-blocks; fi) + cardano + --configByron "$(jq -r .byron <<<$geneses)" + --configShelley "$(jq -r .shelley <<<$geneses)" + --configAlonzo "$(jq -r .alonzo <<<$geneses)" + ) + db-analyser "${args[@]}" + ;; + +* ) usage_chaindb;; esac +} + +chaindb_mainnet_ledger_snapshots_before_slot() { + local cachedir=$1 + local slot=$2 + ( cd $cachedir/ledger && ls -1 mainnet-ledger.* | cut -d. -f2; echo $slot + ) | sort -n | grep -wB1 $slot | grep -v $slot | head -n1 2>/dev/null +} diff --git a/nix/workbench/default.nix b/nix/workbench/default.nix index 89d6c96d2cd..ee58466f72b 100644 --- a/nix/workbench/default.nix +++ b/nix/workbench/default.nix @@ -1,5 +1,6 @@ { pkgs , lib, jq, runCommand +, db-analyser , cardanoNodePackages }: @@ -40,6 +41,7 @@ let cardano-cli cardano-topology + db-analyser locli ]; diff --git a/nix/workbench/genesis.sh b/nix/workbench/genesis.sh index d1d02a59515..fdde67c9302 100644 --- a/nix/workbench/genesis.sh +++ b/nix/workbench/genesis.sh @@ -155,7 +155,7 @@ case "$op" in | . * ($p.genesis.shelley // {}) | . * ($p.genesis.alonzo // {}) ' --slurpfile prof "$profile_json" \ - "$global_basedir"/profiles/presets/mainnet/genesis/genesis-alonzo.json \ + "$global_basedir"/profiles/presets/mainnet/genesis/genesis.alonzo.json \ > "$dir"/genesis.alonzo.spec.json msg "genesis: creating initial genesis" @@ -198,10 +198,20 @@ case "$op" in local cache_entry=${3:?$usage} local outdir=${4:?$usage} - msg "genesis | derive-from-cache: $cache_entry -> $outdir" + mkdir -p "$outdir" + + local preset=$(profile preset "$profile"/profile.json) + if test -n "$preset" + then progress "genesis" "instantiating from preset $(with_color white $preset): $cache_entry" + mkdir -p "$outdir"/byron + cp -f $cache_entry/genesis*.json "$outdir" + cp -f $cache_entry/byron/*.json "$outdir"/byron + return + fi + + progress "genesis" "deriving from cache: $cache_entry -> $outdir" # ls -l $cache_entry - mkdir -p "$outdir" ( cd $outdir ln -s $profile ./profile ln -s $cache_entry cache-entry @@ -246,7 +256,7 @@ case "$op" in jq ' $prof[0] as $p | . * ($p.genesis.alonzo // {}) ' --slurpfile prof "$profile_json" \ - "$global_basedir"/profiles/presets/mainnet/genesis/genesis-alonzo.json \ + "$global_basedir"/profiles/presets/mainnet/genesis/genesis.alonzo.json \ > "$dir"/genesis.alonzo.json;; * ) usage_genesis;; esac diff --git a/nix/workbench/lib-cabal.sh b/nix/workbench/lib-cabal.sh index bb358c81592..3d903e15b22 100644 --- a/nix/workbench/lib-cabal.sh +++ b/nix/workbench/lib-cabal.sh @@ -10,7 +10,7 @@ function workbench-prebuild-executables() echo "workbench: prebuilding executables (because of useCabalRun)" unset NIX_ENFORCE_PURITY - for exe in cardano-node cardano-cli cardano-topology tx-generator + for exe in cardano-node cardano-cli cardano-topology tx-generator locli do echo "workbench: $(with_color blue prebuilding) $(with_color red $exe)" cabal -v0 build -- exe:$exe 2>&1 >/dev/null | { grep -v 'exprType TYPE'; true; } || return 1 diff --git a/nix/workbench/lib.jq b/nix/workbench/lib.jq index 1dfe53afca2..3213072b1bf 100644 --- a/nix/workbench/lib.jq +++ b/nix/workbench/lib.jq @@ -11,3 +11,6 @@ def color: def colorly($col; $x): "\(color[$col])\($x)\(color["off"])"; + +def drop_nulls: + map(select(. != null)); diff --git a/nix/workbench/lib.sh b/nix/workbench/lib.sh index 047d44dca04..d6b9fde14c2 100644 --- a/nix/workbench/lib.sh +++ b/nix/workbench/lib.sh @@ -60,6 +60,27 @@ with_color() { color reset } +colorise_colors=( + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset + red green yellow blue cyan white reset red green yellow blue cyan white reset +) +colorise() { + for ((i=0; $#!=0; i++)) + do echo -n "$(with_color ${colorise_colors[$i]} $1) " + shift + done +} + msg() { echo "workbench: $*" >&2 } @@ -68,11 +89,37 @@ msg_ne() { echo -ne "workbench: $*" >&2 } +green() { + with_color green $* +} + +white() { + with_color white $* +} + +yellow() { + with_color yellow $* +} + +red() { + with_color red $* +} + progress() { local subsys=$1; shift msg "$(with_color green $subsys): $(with_color blue $*)" } +progress_ne() { + local subsys=$1; shift + msg_ne "$(with_color green $subsys): $(with_color blue $*)" +} + +warn() { + local subsys=$1; shift + msg "$(with_color green $subsys): $(with_color yellow $*)" +} + fail() { msg "$(with_color red $*)" exit 1 diff --git a/nix/workbench/membench-run.nix b/nix/workbench/membench-run.nix index e81a5ff81ee..7682f8f6312 100644 --- a/nix/workbench/membench-run.nix +++ b/nix/workbench/membench-run.nix @@ -67,7 +67,7 @@ in '' yq ' . - | .TraceOptionResourceFreqency = 1000 + | .TraceOptionResourceFrequency = 1000 ' ${node-measured}/configuration/cardano/mainnet-config-new-tracing.yaml > config.json ''} cp -v ${node-measured}/configuration/cardano/*-genesis.json . diff --git a/nix/workbench/profile-run.jq b/nix/workbench/profile-run.jq index 37e840002f9..5eb01cd41f5 100644 --- a/nix/workbench/profile-run.jq +++ b/nix/workbench/profile-run.jq @@ -42,6 +42,7 @@ def profile_node_specs($env; $prof): | map({ i: . , kind: "bft" , pools: 0 + , autostart: true })) as $bfts | ([range($n_bfts; @@ -51,6 +52,7 @@ def profile_node_specs($env; $prof): , pools: (if . - $n_bfts < $n_singular_pools then 1 else $prof.composition.dense_pool_density end) + , autostart: true })) as $pools | ([range($n_bfts + $n_pools; @@ -59,19 +61,34 @@ def profile_node_specs($env; $prof): | map({ i: . , kind: "proxy" , pools: 0 + , autostart: true })) as $proxies | ([range($n_bfts + $n_pools + if $prof.composition.with_proxy then 1 else 0 end; $n_bfts + $n_pools + if $prof.composition.with_proxy then 1 else 0 end + + if $prof.composition.with_chaindb_server then 1 else 0 end)] + | map({ i: . + , kind: "chaindb-server" + , pools: 0 + , autostart: true + })) + as $chaindbs +| ([range($n_bfts + $n_pools + + if $prof.composition.with_proxy then 1 else 0 end + + if $prof.composition.with_chaindb_server then 1 else 0 end; + $n_bfts + $n_pools + + if $prof.composition.with_proxy then 1 else 0 end + + if $prof.composition.with_chaindb_server then 1 else 0 end + if $prof.composition.with_observer then 1 else 0 end)] | map({ i: . , kind: "observer" , pools: 0 + , autostart: false })) as $observers -| ($bfts + $pools + $proxies + $observers +| ($bfts + $pools + $proxies + $chaindbs + $observers | map(. + { name: "node-\(.["i"])" , isProducer: ([.kind == "bft", .kind == "pool"] | any) diff --git a/nix/workbench/profile.sh b/nix/workbench/profile.sh index 65f0bead1cd..a2fc46b3dcc 100644 --- a/nix/workbench/profile.sh +++ b/nix/workbench/profile.sh @@ -3,7 +3,7 @@ usage_profile() { list List profile names (json) all-profiles | all All profile contents (json) compose NAME.. Create a profile composed from named profiles - json-by-name NAME Get contents of either named profile, or profile JSON desc + json NAME Get contents of either named profile, or profile JSON desc describe NAME Print a human description of a profile node-specs PROFILE-NAME/JSON Print node specs JSON for the given profile and environment @@ -20,7 +20,7 @@ global_profile_eras=( ) profile() { -local op=${1:-list}; test $# -gt 0 && shift +local op=${1:-show}; test $# -gt 0 && shift case "$op" in list | names ) @@ -60,9 +60,9 @@ case "$op" in | add ';; - json-by-name ) - local usage="USAGE: wb profile $op NAME" - local name=${1:?$usage} + json | show ) + local usage="USAGE: wb profile $op [NAME=" + local name=${1:-${WORKBENCH_SHELL_PROFILE:?variable unset, no profile name to use as a default.}} if test -f "$name" then jq '.' "$name" @@ -74,7 +74,7 @@ case "$op" in local usage="USAGE: wb profile $op NAME" local name=${1:?$usage} - profile json-by-name $name | + profile json $name | jq 'include "derived"; profile_pretty_describe(.) @@ -83,7 +83,12 @@ case "$op" in has-preset ) local usage="USAGE: wb profile $op NAME" local profile=${1:?$usage} - profile json-by-name "$profile" | jqtest ".preset != null";; + profile json "$profile" | jqtest ".preset != null";; + + preset ) + local usage="USAGE: wb profile $op NAME" + local profile=${1:?$usage} + profile json "$profile" | jq -r '.preset // ""';; preset-get-file ) local usage="USAGE: wb profile $op PRESET-NAME DESC FILE" @@ -108,7 +113,7 @@ case "$op" in ) ## WARNING: this is structured in correspondence ## with the output generated by cardano-topology - profile json-by-name "$profile" | jq ' + profile json "$profile" | jq ' include "profile-run"; . as $prof | profile_node_specs($env; $prof) @@ -118,18 +123,29 @@ case "$op" in local usage="USAGE: wb profile $op PROFILE-JSON" local profile=${1:?$usage} - local offset=$(profile json-by-name "$profile" | - jq '.derived.genesis_future_offset' --raw-output) - local start=$(date '+%s' --date="now + $offset") + if profile has-preset "$profile" + then + local preset=$(profile json "$profile" | jq '.preset' -r) + local shelley=$(profile preset-get-file "$preset" 'genesis' 'genesis/genesis-shelley.json') + local start=$(jq '.systemStart | fromdateiso8601' $shelley) + local offset="$((start - $(date +%s))) seconds" + local start_tag=$(date --date=@$(date +%s) --utc +'%Y'-'%m'-'%d'-'%H.%M') + else + local offset=$(profile json "$profile" | + jq '.derived.genesis_future_offset' --raw-output) + local start=$(date '+%s' --date="now + $offset") + local start_tag=$(date --date=@$start --utc +'%Y'-'%m'-'%d'-'%H.%M') + fi local args=( -L "$global_basedir" --arg 'future_offset' "$offset" --arg 'start' "$start" --arg 'start_human' "$(date --date=@$start --utc +"%Y-%m-%dT%H:%M:%SZ")" - --arg 'start_tag' "$(date --date=@$start --utc +'%Y'-'%m'-'%d'-'%H.%M')" + --arg 'start_tag' "$start_tag" --arg 'systemStart' "$(date --date=@$start --utc --iso-8601=s | cut -c-19)Z" ) - profile json-by-name "$profile" | jq ' + + profile json "$profile" | jq ' include "profile-run"; . as $prof diff --git a/nix/workbench/profiles/default.nix b/nix/workbench/profiles/default.nix index e6f6284620a..cae5d0eadec 100644 --- a/nix/workbench/profiles/default.nix +++ b/nix/workbench/profiles/default.nix @@ -10,7 +10,7 @@ let baseJSON = runWorkbenchJqOnly "profile-${profileName}.json" - "profile json-by-name ${profileName}"; + "profile json ${profileName}"; JSON = if profileOverride == {} then baseJSON diff --git a/nix/workbench/profiles/defaults.jq b/nix/workbench/profiles/defaults.jq index 5546fe5d8a3..cd5d4c9e4d7 100644 --- a/nix/workbench/profiles/defaults.jq +++ b/nix/workbench/profiles/defaults.jq @@ -73,11 +73,12 @@ def era_defaults($era): , node: { rts_flags_override: [] , shutdown_on_slot_synced: null - , tracing_backend: "iohk-monitoring" ## or "trace-dispatcher" + , tracing_backend: "trace-dispatcher" ## or "iohk-monitoring" } , analysis: - { cluster_startup_overhead_s: 10 + { type: null + , cluster_startup_overhead_s: 10 , start_log_spread_s: 120 , last_log_spread_s: 120 , silence_since_last_block_s: 120 @@ -102,6 +103,15 @@ def era_defaults($era): } , alonzo: - { + { genesis: + { shelley: + { protocolParams: + { protocolVersion: + { major: 5 + , minor: 0 + } + } + } + } } } | (.common * .[$era]); diff --git a/nix/workbench/profiles/derived.jq b/nix/workbench/profiles/derived.jq index c593b8bfd4e..1d7da946418 100644 --- a/nix/workbench/profiles/derived.jq +++ b/nix/workbench/profiles/derived.jq @@ -6,7 +6,7 @@ def default_value_tx_size_estimate: 381; def may_mult($x): - if . == null then null else . * $x end; + if type != "number" then null else . * $x end; def may_attr($attr; $dict; $defdict; $scale; $suf): if ($dict[$attr] // @@ -26,8 +26,8 @@ def profile_name($p): then may_attr("dense_pool_density"; $p.composition; $composition_defaults; 1; "ppn") else [] end - + if $shutdown_slots - then [($p.node.shutdown_on_slot_synced | tostring) + "slots"] + + if $shutdown_slots | type == "number" + then [($shutdown_slots | tostring) + "slots"] else [ ($p.generator.epochs | tostring) + "ep" , ($p.generator.tx_count | . / 1000 | tostring) + "kTx" ] end @@ -52,6 +52,9 @@ def profile_name($p): + if $p.composition.with_proxy then ["prox"] else [] end + + if $p.composition.with_chaindb_server + then ["chdb"] + else [] end + if $p.composition.with_observer then ["obsrv"] else [] end @@ -63,10 +66,10 @@ def profile_name_era_suffix($era): def add_derived_params: (.genesis.utxo + .genesis.delegators) as $dataset_measure -| (if $dataset_measure < 10000 then 3 +| (if $dataset_measure < 10000 then 10 else $dataset_measure / 50000 end | ceil) as $dataset_induced_startup_delay_optimistic -| (if $dataset_measure < 10000 then 3 +| (if $dataset_measure < 10000 then 10 else $dataset_measure / 10000 end | ceil) as $dataset_induced_startup_delay_conservative | (.derived.genesis_future_offset // @@ -82,18 +85,20 @@ def add_derived_params: ## Absolute durations: | ($gsis.epoch_length * $gsis.slot_duration) as $epoch_duration | $node.shutdown_on_slot_synced as $shutdown_slots -| (if $shutdown_slots != null +| (if $shutdown_slots | type == "number" then $shutdown_slots / $gsis.epoch_length | ceil else $gtor.epochs end) as $effective_epochs -| ($epoch_duration * $effective_epochs) as $generator_duration +| ($epoch_duration * $effective_epochs) as $generator_requested_duration | ($shutdown_slots | may_mult($gsis.slot_duration)) as $shutdown_time +| ([ $generator_requested_duration + , $shutdown_time + ] | drop_nulls | min) as $generator_duration ## Tx count for inferred absolute duration. ## Note that this the workload would take longer, if we saturate the cluster. | ($gtor.tx_count // ($generator_duration * $gtor.tps)) as $generator_tx_count - ## Effective cluster composition: | (if $compo.dense_pool_density > 1 then { singular: $compo.n_singular_hosts @@ -101,49 +106,59 @@ def add_derived_params: else { singular: ($compo.n_singular_hosts + $compo.n_dense_hosts) , dense: 0 } end) as $hosts -| $hosts.singular as $n_singular_pools | ($hosts.dense * $compo.dense_pool_density) as $n_dense_pools -| ($n_singular_pools + $n_dense_pools) as $n_pools +| ($hosts.singular + $n_dense_pools) as $n_pools | ($gsis.delegators // $n_pools) as $effective_delegators -## Stuffed UTxO is what we need over requested-UTxO + delegators' UTxO: -| $effective_delegators as $utxo_delegated | ($generator_tx_count * $gtor.inputs_per_tx) as $utxo_generated -| ([ $gsis.utxo - $utxo_generated - $effective_delegators - , 0 - ] | max) as $utxo_stuffed | (($gsis.max_block_size / default_value_tx_size_estimate) | floor) as $default_value_tx_per_block_estimate -| ($generator_tx_count / $default_value_tx_per_block_estimate | . * 1.15 | ceil) - as $generator_blocks_lower_bound ## Note how derivations come in phases, too: ## | (## First derivation: { common: + (($gsis.per_pool_balance * $n_pools) as $supply_delegated + | { derived: - { utxo_delegated: $utxo_delegated + { supply_delegated: $supply_delegated + , supply_total: ($supply_delegated + $gsis.funds_balance) + + , utxo_delegated: $effective_delegators , utxo_generated: $utxo_generated - , utxo_stuffed: $utxo_stuffed + ## Stuffed UTxO is what we need over requested-UTxO + delegators' UTxO: + , utxo_stuffed: ([ $gsis.utxo - $utxo_generated - $effective_delegators + , 0 + ] | max) + + , delegators_effective: ([ $n_pools + , $gsis.delegators + ] | max) + , dataset_measure: $dataset_measure , dataset_induced_startup_delay_optimistic: $dataset_induced_startup_delay_optimistic , dataset_induced_startup_delay_conservative: $dataset_induced_startup_delay_conservative + , genesis_future_offset: $genesis_future_offset , epoch_duration: $epoch_duration - , effective_epochs: $effective_epochs , generator_duration: $generator_duration + , shutdown_time: $shutdown_time + + , effective_epochs: $effective_epochs + , generator_tx_count: $generator_tx_count + , default_value_tx_size_estimate: default_value_tx_size_estimate , default_value_tx_per_block_estimate: $default_value_tx_per_block_estimate - , generator_blocks_lower_bound: $generator_blocks_lower_bound - , shutdown_time: $shutdown_time + , generator_blocks_lower_bound: ($generator_tx_count / $default_value_tx_per_block_estimate + | . * 1.15 | ceil) } , composition: { n_hosts: ($compo.n_bft_hosts + $hosts.singular + $hosts.dense) , n_pools: $n_pools , n_singular_hosts: $hosts.singular - , n_singular_pools: $n_singular_pools + , n_singular_pools: $hosts.singular , n_dense_hosts: $hosts.dense , n_dense_pools: $n_dense_pools , n_pool_hosts: ($hosts.singular + $hosts.dense) @@ -177,7 +192,7 @@ def add_derived_params: { minimum_chain_density: ($gsis.active_slots_coeff * 0.5) , cluster_startup_overhead_s: $dataset_induced_startup_delay_conservative } - } + }) } | . * ## Second derivation: diff --git a/nix/workbench/profiles/generator-service.nix b/nix/workbench/profiles/generator-service.nix index 3abbe7c594d..3e86ad21746 100644 --- a/nix/workbench/profiles/generator-service.nix +++ b/nix/workbench/profiles/generator-service.nix @@ -42,7 +42,7 @@ let localNodeSocketPath = "../node-0/node.socket"; ## nodeConfig of the locally running node. - localNodeConf = exemplarNode.serviceConfig.value; + localNodeConf = removeAttrs exemplarNode.serviceConfig.value ["executable"]; ## The nodeConfig of the Tx generator itself. nodeConfig = backend.finaliseGeneratorConfig generatorNodeConfigDefault; diff --git a/nix/workbench/profiles/genesis.jq b/nix/workbench/profiles/genesis.jq index c5c58fc349b..ee2f30148aa 100644 --- a/nix/workbench/profiles/genesis.jq +++ b/nix/workbench/profiles/genesis.jq @@ -1,17 +1,15 @@ ## WARNING: keep in sync with 'profile-cache-key-input' below this one: vvv ## def profile_cli_args($p): -($p.genesis.per_pool_balance * $p.composition.n_pools) as $pools_balance -| { common: { createSpec: - [ "--supply", ($pools_balance + $p.genesis.funds_balance) + [ "--supply", $p.derived.supply_total , "--testnet-magic", $p.genesis.network_magic , "--gen-genesis-keys", $p.composition.n_bft_hosts , "--gen-utxo-keys", 1 ] , createFinalIncremental: - ([ "--supply", ($p.genesis.funds_balance) + ([ "--supply", $p.genesis.funds_balance , "--gen-utxo-keys", 1 ] + if $p.composition.dense_pool_density != 1 @@ -19,14 +17,12 @@ def profile_cli_args($p): [ ] else [] end) , createFinalBulk: - ([ "--supply", ($p.genesis.funds_balance) + ([ "--supply", $p.genesis.funds_balance , "--gen-utxo-keys", 1 , "--gen-genesis-keys", $p.composition.n_bft_hosts - , "--supply-delegated", $pools_balance + , "--supply-delegated", $p.derived.supply_delegated , "--gen-pools", $p.composition.n_pools - , "--gen-stake-delegs", ([ $p.composition.n_pools - , $p.genesis.delegators ] - | max) + , "--gen-stake-delegs", $p.derived.delegators_effective , "--testnet-magic", $p.genesis.network_magic , "--num-stuffed-utxo", $p.derived.utxo_stuffed ] + diff --git a/nix/workbench/profiles/node-services.nix b/nix/workbench/profiles/node-services.nix index 248fe59a2c4..ae7637e8e1c 100644 --- a/nix/workbench/profiles/node-services.nix +++ b/nix/workbench/profiles/node-services.nix @@ -44,74 +44,65 @@ let { TestEnableDevelopmentHardForkEras = true; TestEnableDevelopmentNetworkProtocols = true; + TurnOnLogMetrics = true; }; tracing = { - trace-dispatcher = { - UseTraceDispatcher = true; - - TraceOptionSeverity = [ - { ns = ""; severity = "Debug"; } - { ns = "Node.Resources"; severity = "Debug"; } - { ns = "Node.ChainDB"; severity = "Debug"; } - # { ns = "Node.Mempool"; severity = "Debug"; } - # { ns = "Node.ChainDB.ImmutableDBEvent"; severity = "Warning"; } - ]; - - TraceOptionDetail = [ - { ns = ""; detail = "DNormal"; } - { ns = "Node.BlockFetchClient"; detail = "DMinimal"; } - ]; - - TraceOptionBackend = [ - { ns = ""; - backends = [ - "Stdout MachineFormat" - "EKGBackend" - "Forwarder" - ]; - } - # { ns = "Node.ChainDB"; - # backends = ["Stdout HumanFormatColoured"]; - # } - ]; - - TraceOptionLimiter = [ - { ns = "Node.ChainDB.OpenEvent"; - limiterName = "ChainDB open limiter"; - limiterFrequency = 0.1; - } - ]; - - TraceOptionForwarder = { - mode = "Initiator"; - address = { - filePath = "/tmp/forwarder-${toString i}.sock"; - }; - }; - }; - iohk-monitoring = { - defaultScribes = [ - [ "StdoutSK" "stdout" ] - ]; - setupScribes = - [{ - scKind = "StdoutSK"; - scName = "stdout"; - scFormat = "ScJson"; - }]; - minSeverity = "Debug"; - TraceMempool = true; - TraceTxInbound = true; - TraceBlockFetchClient = true; - TraceBlockFetchServer = true; - TraceChainSyncHeaderServer = true; - TraceChainSyncClient = true; - options = { - mapBackends = { - "cardano.node.resources" = [ "KatipBK" ]; - }; - }; - }; + trace-dispatcher = import ./tracing.nix { inherit nodeSpec; profile = profile.value; }; + iohk-monitoring = import ./tracing-legacy.nix { inherit nodeSpec; profile = profile.value; }; + }; + tracing-transform = { + trace-dispatcher = xs: + ## For trace-dispatcher, we remove all legacy tracing options: + removeAttrs xs + [ + "TraceAcceptPolicy" + "TraceBlockFetchClient" + "TraceBlockFetchDecisions" + "TraceBlockFetchProtocol" + "TraceBlockFetchProtocolSerialised" + "TraceBlockFetchServer" + "TraceChainDb" + "TraceChainSyncBlockServer" + "TraceChainSyncClient" + "TraceChainSyncHeaderServer" + "TraceChainSyncProtocol" + "TraceConnectionManager" + "TraceDNSResolver" + "TraceDNSSubscription" + "TraceDiffusionInitialization" + "TraceErrorPolicy" + "TraceForge" + "TraceHandshake" + "TraceInboundGovernor" + "TraceIpSubscription" + "TraceLedgerPeers" + "TraceLocalChainSyncProtocol" + "TraceLocalErrorPolicy" + "TraceLocalHandshake" + "TraceLocalRootPeers" + "TraceLocalTxSubmissionProtocol" + "TraceLocalTxSubmissionServer" + "TraceMempool" + "TraceMux" + "TracePeerSelection" + "TracePeerSelectionActions" + "TracePublicRootPeers" + "TraceServer" + "TraceTxInbound" + "TraceTxOutbound" + "TraceTxSubmissionProtocol" + "TracingVerbosity" + "defaultBackends" + "defaultScribes" + "hasEKG" + "hasPrometheus" + "minSeverity" + "options" + "rotation" + "setupBackends" + "setupScribes" + ]; + iohk-monitoring = xs: xs; }; era_setup_hardforks = { shelley = @@ -139,21 +130,31 @@ let { inherit port; - ## For the definition of 'nodeConfigBits', please see below. + ## For the definition of 'nodeConfigBits', please see above. + ## Meaning: + ## 1. take the common base + ## 2. apply either the hardforks config, or the preset (typically mainnet) + ## 3. overlay the tracing config nodeConfig = - backend.finaliseNodeConfig nodeSpec - (recursiveUpdate - nodeConfigBits.base - (if __hasAttr "preset" profile.value - then readJSONMay (./presets + "/${profile.value.preset}/config.json") - else nodeConfigBits.era_setup_hardforks // - nodeConfigBits.tracing.${profile.value.node.tracing_backend})); + nodeConfigBits.tracing-transform.${profile.value.node.tracing_backend} + (backend.finaliseNodeConfig nodeSpec + (recursiveUpdate + (recursiveUpdate + nodeConfigBits.base + (if __hasAttr "preset" profile.value + then readJSONMay (./presets + "/${profile.value.preset}/config.json") + else nodeConfigBits.era_setup_hardforks)) + nodeConfigBits.tracing.${profile.value.node.tracing_backend})); extraArgs = let shutdownSlot = profile.value.node.shutdown_on_slot_synced; in backend.finaliseNodeArgs nodeSpec (if shutdownSlot != null - then ["--shutdown-on-slot-synced" (toString shutdownSlot)] + then if isAttrs shutdownSlot + then if shutdownSlot.${nodeSpec.kind} or null != null + then ["--shutdown-on-slot-synced" (toString shutdownSlot.${nodeSpec.kind})] + else [] + else ["--shutdown-on-slot-synced" (toString shutdownSlot)] else []); }; diff --git a/nix/workbench/profiles/presets/mainnet/genesis/genesis-alonzo.json b/nix/workbench/profiles/presets/mainnet/genesis/genesis.alonzo.json similarity index 100% rename from nix/workbench/profiles/presets/mainnet/genesis/genesis-alonzo.json rename to nix/workbench/profiles/presets/mainnet/genesis/genesis.alonzo.json diff --git a/nix/workbench/profiles/tracing-legacy.nix b/nix/workbench/profiles/tracing-legacy.nix new file mode 100644 index 00000000000..f81573afa8e --- /dev/null +++ b/nix/workbench/profiles/tracing-legacy.nix @@ -0,0 +1,24 @@ +{ profile, nodeSpec }: +{ + defaultScribes = [ + [ "StdoutSK" "stdout" ] + ]; + setupScribes = + [{ + scKind = "StdoutSK"; + scName = "stdout"; + scFormat = "ScJson"; + }]; + minSeverity = "Debug"; + TraceMempool = true; + TraceTxInbound = true; + TraceBlockFetchClient = true; + TraceBlockFetchServer = true; + TraceChainSyncHeaderServer = true; + TraceChainSyncClient = true; + options = { + mapBackends = { + "cardano.node.resources" = [ "KatipBK" ]; + }; + }; +} diff --git a/nix/workbench/profiles/tracing.nix b/nix/workbench/profiles/tracing.nix new file mode 100644 index 00000000000..4d3fd610a29 --- /dev/null +++ b/nix/workbench/profiles/tracing.nix @@ -0,0 +1,52 @@ +{ profile, nodeSpec }: +{ + UseTraceDispatcher = true; + + TraceOptions = { + "" = { severity = "Debug"; + backends = [ + "Stdout MachineFormat" + "EKGBackend" + # "Forwarder" + ]; + }; + "Node.AcceptPolicy" = { severity = "Info"; }; + "Node.ChainDB" = { severity = "Info"; }; + "Node.DNSResolver" = { severity = "Info"; }; + "Node.DNSSubscription" = { severity = "Info"; }; + "Node.DiffusionInit" = { severity = "Info"; }; + "Node.ErrorPolicy" = { severity = "Info"; }; + "Node.Forge" = { severity = "Info"; }; + "Node.IpSubscription" = { severity = "Info"; }; + "Node.LocalErrorPolicy" = { severity = "Info"; }; + "Node.Mempool" = { severity = "Info"; }; + "Node.Resources" = { severity = "Info"; }; + + "Node.BlockFetch.NodeToNode" = { severity = "Silence"; }; + "Node.BlockFetchDecision" = { severity = "Silence"; }; + "Node.BlockFetchSerialised" = { severity = "Silence"; }; + "Node.ChainSyncNode.NodeToNode" = { severity = "Silence"; }; + "Node.ChainSyncSerialised" = { severity = "Silence"; }; + "Node.LocalHandshake" = { severity = "Silence"; }; + "Node.Mux" = { severity = "Silence"; }; + "Node.MuxLocal" = { severity = "Silence"; }; + "Node.TxOutbound" = { severity = "Silence"; }; + "Node.TxSubmission2" = { severity = "Silence"; }; + + "Node.BlockFetchClient" = { detail = "DMinimal"; }; + "Node.TxSubmission2" = { detail = "DMinimal"; }; + ## Commented out because the legacy doesn't limit this message: + # "Node.BlockFetchClient.CompletedBlockFetch" = { maxFrequency = 2.0; }; + "Node.ChainDB.AddBlockEvent.AddBlockValidation.ValidCandidate" = { maxFrequency = 2.0; }; + "Node.ChainDB.AddBlockEvent.AddedBlockToQueue" = { maxFrequency = 2.0; }; + "Node.ChainDB.AddBlockEvent.AddedBlockToVolatileDB" = { maxFrequency = 2.0; }; + "Node.ChainDB.CopyToImmutableDBEvent.CopiedBlockToImmutableDB" = { maxFrequency = 2.0; }; + }; + + TraceOptionForwarder = { + mode = "Responder"; + address = { + filePath = "forwarder.sock"; + }; + }; +} diff --git a/nix/workbench/profiles/variants.jq b/nix/workbench/profiles/variants.jq index b2c91f6fd3e..963fce2b999 100644 --- a/nix/workbench/profiles/variants.jq +++ b/nix/workbench/profiles/variants.jq @@ -2,6 +2,120 @@ ## variations of genesis/generator/node axes. def genesis_profile_variants: + { scenario: "fixed-loaded" + , composition: + { n_singular_hosts: 2 + , n_dense_hosts: 0 + } + , genesis: + { utxo: 6000 + , delegators: 1300 + , max_block_size: 80000 + , epoch_length: 600 + , parameter_k: 3 + } + , node: + { shutdown_on_slot_synced: 10 + } + , generator: { tps: 15 } + , analysis: + { type: "standard" + } + } as $quick_base + | + { scenario: "fixed-loaded" + , composition: + { n_singular_hosts: 2 + , n_dense_hosts: 0 + } + , genesis: + { utxo: 6000000 + , delegators: 1300000 + , max_block_size: 80000 + , epoch_length: 600 + , parameter_k: 3 + } + , node: + { shutdown_on_slot_synced: 2400 + } + , generator: { tps: 15 } + } as $forge_stress_base + | + { genesis: + { alonzo: + { maxTxExUnits: + { exUnitsMem: 12500000 + } + } + } + , generator: + { inputs_per_tx: 1 + , outputs_per_tx: 1 + , plutusMode: true + , plutusAutoMode: true + } + , analysis: + { filters: ["base", "size-small"] + } + } as $plutus_base + | + { scenario: "chainsync" + , preset: "mainnet" + , composition: + { n_singular_hosts: 0 + , n_dense_hosts: 0 + , with_chaindb_server: true + , with_observer: true + } + , analysis: + { type: "performance" + , filters: [] + } + } as $chainsync_base + | + { node: + { tracing_backend: "iohk-monitoring" + } + } as $old_tracing + | + { chaindb: + { mainnet_chunks: + { chaindb_server: 10 + , observer: 0 + } + , ledger_snapshot: + { chaindb_server: 237599 + , observer: 0 + } + } + , node: + { shutdown_on_slot_synced: + { observer: 237599 + } + } + } as $chaindb_early_byron + | + { chaindb: + { mainnet_chunks: + { chaindb_server: 1800 + , observer: 1799 + } + , ledger_snapshot: + { chaindb_server: 38901589 + , observer: 37173650 + } + } + , node: + { shutdown_on_slot_synced: + { observer: 38901589 + } + } + , genesis: + { utxo: 6000000 + , delegators: 1300000 + } + } as $chaindb_early_alonzo + | ## Baseline: [ { genesis: { utxo: 4000000, delegators: 1000000 } } @@ -59,55 +173,47 @@ def genesis_profile_variants: } , generator: { tps: 10 } } - , { name: "forge-stress" - , scenario: "fixed-loaded" - , composition: - { n_singular_hosts: 2 - , n_dense_hosts: 0 - } - , genesis: - { utxo: 6000000 - , delegators: 1300000 - , max_block_size: 80000 - , epoch_length: 600 - , parameter_k: 3 - } - , node: - { shutdown_on_slot_synced: 2400 - } - , generator: { tps: 15 } + + , $forge_stress_base * + { name: "forge-stress" } - , { name: "quick" - , scenario: "fixed-loaded" + + , $forge_stress_base * $old_tracing * + { name: "forge-stress-oldtracing" + } + + , $forge_stress_base * + $plutus_base * + { name: "forge-stress-plutus" , composition: - { n_singular_hosts: 2 - , n_dense_hosts: 0 - } - , genesis: - { utxo: 6000 - , delegators: 1300 - , max_block_size: 80000 - , epoch_length: 600 - , parameter_k: 3 + { n_singular_hosts: 1 } - , node: - { shutdown_on_slot_synced: 10 + , generator: + { tx_count: 800 } - , generator: { tps: 15 } } - ## Chainsync: - , { name: "chainsync" - , scenario: "chainsync" - , preset: "mainnet" - , composition: - { locations: ["LO"] - , n_bft_hosts: 0 - , n_singular_hosts: 0 - , n_dense_hosts: 0 - , with_proxy: true - , with_observer: true - } } + , $quick_base * + { name: "quick" + } + + , $quick_base * $old_tracing * + { name: "quick-oldtracing" + } + + , $chainsync_base * $chaindb_early_byron * + { name: "chainsync-early-byron" + } + , $chainsync_base * $chaindb_early_byron * $old_tracing * + { name: "chainsync-early-byron-oldtracing" + } + + , $chainsync_base * $chaindb_early_alonzo * + { name: "chainsync-early-alonzo" + } + , $chainsync_base * $chaindb_early_alonzo * $old_tracing * + { name: "chainsync-early-alonzo-oldtracing" + } ]; def generator_profile_variants: diff --git a/nix/workbench/run.sh b/nix/workbench/run.sh index 1fa04d52a7a..5ff49a2cfee 100644 --- a/nix/workbench/run.sh +++ b/nix/workbench/run.sh @@ -96,8 +96,12 @@ case "$op" in local tag=${1:?$usage} local dir=$(run compute-path "$tag") - jq_check_json "$dir"/meta.json || - fatal "run $tag (at $dir) missing a file: meta.json" + if ! jq_check_json "$dir"/meta.json + then if test $tag = 'current' + then local alt=$(run list | tail -n1) + progress 'run | check' "$(with_color white current) missing, resetting to $(with_color white $alt)" + run set-current $alt + else fatal "run $tag (at $dir) missing a file: meta.json"; fi; fi test -f "$dir"/profile.json -a -f "$dir"/genesis-shelley.json || run fix-legacy-run-structure "$tag";; @@ -230,7 +234,7 @@ case "$op" in local batch=${1:?$usage}; shift local profile_name=${1:?$usage}; shift - local profile= topology= genesis_cache_entry= manifest= + local profile= topology= genesis_cache_entry= manifest= preset= while test $# -gt 0 do case "$1" in --manifest ) manifest=$2; shift;; @@ -241,7 +245,11 @@ case "$op" in --* ) msg "FATAL: unknown flag '$1'"; usage_run;; * ) break;; esac; shift; done - progress "run" "allocating a new one.." + if profile has-preset "$profile"/profile.json + then preset=$(profile json "$profile"/profile.json | jq '.preset' -r) + progress "run" "allocating from preset '$preset'" + else progress "run" "allocating a new one" + fi ## 0. report software manifest progress "run | manifest" "component versions:" @@ -302,7 +310,7 @@ case "$op" in else profile has-profile "$profile_name" || fatal "no such profile: $profile_name" - profile json-by-name "$profile_name" > "$dir"/profile.json + profile json "$profile_name" > "$dir"/profile.json fi jq '.' <<<$node_specs > "$dir"/node-specs.json @@ -332,13 +340,14 @@ case "$op" in else topology make "$dir"/profile.json "$dir"/topology fi - if test -n "$genesis_cache_entry" - then genesis derive-from-cache \ + if test -z "$genesis_cache_entry" + then fail "internal error: no genesis cache entry" + + else genesis derive-from-cache \ "$profile" \ "$timing" \ "$genesis_cache_entry" \ "$dir"/genesis - else fail "internal error: no genesis cache entry" fi ## Record geneses cp "$dir"/genesis/genesis-shelley.json "$dir"/genesis-shelley.json @@ -464,13 +473,14 @@ EOF start ) local usage="USAGE: wb run $op [--idle] [--scenario NAME] [--analyse] TAG" - local scenario_override= analyse= analysis_can_fail= + local scenario_override= analyse=yes analysis_can_fail= while test $# -gt 0 do case "$1" in --idle ) scenario_override='generic-idle';; --scenario | -s ) scenario_override=$2; shift;; - --analyse | -a ) analyse=t;; - --analysis-can-fail ) analysis_can_fail=t;; + --no-analysis ) analyse=;; + --analysis-can-fail | -f ) + analysis_can_fail=t;; --* ) msg "FATAL: unknown flag '$1'"; usage_run;; * ) break;; esac; shift; done @@ -488,14 +498,6 @@ EOF scenario "$scenario" "$dir" run compat-meta-fixups "$tag" - if test -n "$analyse" - then progress "run | analysis" "processing logs of $(with_color white $tag)" - analyse std $tag || - if test -n "$analysis_can_fail" - then progress "run | analysis" "log processing failed, but --analysis-can-fail prevents failure: $(with_color red $tag)" - else fail "analysis failed: $tag" - false; fi - fi ;; stop ) diff --git a/nix/workbench/scenario.sh b/nix/workbench/scenario.sh index 21904747022..850e141fa92 100644 --- a/nix/workbench/scenario.sh +++ b/nix/workbench/scenario.sh @@ -8,12 +8,9 @@ usage_scenario() { amount is submitted chainsync DIR Chain syncing: - 1. start the preset-defined proxy node, - using its respective connected topology mode, - fetching the chain up to the specified slot - 2. restart the proxy with a disconnected topogy mode, - effectively making it an idle chaindb server - 3. start the fetcher node, connected to the proxy + 1. start the preset-defined chaindb-server node, + feeding it a generated chaindb + 2. start the fetcher node, connected to the chaindb-server EOF } @@ -25,7 +22,7 @@ local dir=${1:?$usage}; shift local tag=$(jq '.meta.tag' -r $dir/meta.json) local p=$dir/profile.json -progress "run | scenario" "starting $(with_color blue $op)" +progress "run | scenario" "starting $(yellow $op)" case "$op" in idle | default ) backend start-cluster "$dir" @@ -58,11 +55,39 @@ case "$op" in ;; chainsync ) - ## This starts all nodes, due to unconditional start-up, - ## to start in default mode -- meaning that: - ## - the proxy does start, connected - ## - the fetcher doesn't - backend start-cluster "$dir" + local observer=( + mainnet-chunks-with-snapshot-at-slot + "$dir"/node-1/run/current/node-1/db-testnet + $(jq '.chaindb.ledger_snapshot.observer' $p) + $(jq '.chaindb.mainnet_chunks.observer' $p) + ) + progress "scenario" "preparing ChainDB for the $(green "observer (fetcher)")" + chaindb "${observer[@]}" + + local chaindb_server=( + mainnet-chunks-with-snapshot-at-slot + "$dir"/node-0/run/current/node-0/db-testnet + $(jq '.chaindb.ledger_snapshot.chaindb_server' $p) + $(jq '.chaindb.mainnet_chunks.chaindb_server' $p) + ) + progress "scenario" "preparing ChainDB for the $(green server node)" + chaindb "${chaindb_server[@]}" + + progress "scenario" "starting the $(yellow ChainDB server node)" + backend start-cluster "$dir" + + progress "scenario" "starting the $(yellow fetcher node)" + backend start-node "$dir" 'node-1' + ## TODO: + # +RTS -s$out/rts.dump + + scenario_setup_exit_trap "$dir" + backend wait-node-stopped "$dir" 'node-1' + scenario_cleanup_exit_trap + + backend stop-cluster "$dir" + + analysis_trace_frequencies 'current' ;; * ) usage_scenario;; esac @@ -75,6 +100,16 @@ scenario_exit_trap() { backend stop-cluster "$__scenario_exit_trap_dir" } +scenario_setup_exit_trap() { + local run_dir=$1 + export __scenario_exit_trap_dir=$run_dir + trap scenario_exit_trap EXIT +} + +scenario_cleanup_exit_trap() { + trap - EXIT +} + __scenario_watcher_pid= scenario_watcher() { while test $__scenario_watcher_end_time -gt $(date +%s) @@ -87,8 +122,8 @@ scenario_watcher() { scenario_setup_termination() { local run_dir=$1 - export __scenario_exit_trap_dir=$run_dir - trap scenario_exit_trap EXIT + + scenario_setup_exit_trap $run_dir export __scenario_watcher_self=$BASHPID local termination_tolerance_s=40 @@ -100,4 +135,5 @@ scenario_setup_termination() { scenario_cleanup_termination() { kill $__scenario_watcher_pid 2>/dev/null || true + scenario_cleanup_exit_trap } diff --git a/nix/workbench/shell.nix b/nix/workbench/shell.nix index 05ae545098b..4ad856dfa81 100644 --- a/nix/workbench/shell.nix +++ b/nix/workbench/shell.nix @@ -1,4 +1,5 @@ { lib +, profileName , workbenchDevMode ? false , useCabalRun ? false , checkoutWbMode ? "unknown" @@ -10,6 +11,7 @@ let shellHook = '' echo 'workbench shellHook: workbenchDevMode=${toString workbenchDevMode} useCabalRun=${toString useCabalRun}' export WORKBENCH_BACKEND=supervisor + export WORKBENCH_SHELL_PROFILE=${profileName} ${optionalString workbenchDevMode diff --git a/nix/workbench/supervisor-conf.nix b/nix/workbench/supervisor-conf.nix index f6e1479e9fc..4e64a5957ae 100644 --- a/nix/workbench/supervisor-conf.nix +++ b/nix/workbench/supervisor-conf.nix @@ -60,6 +60,8 @@ let stdout_logfile = "${service.value.stateDir}/stdout"; stderr_logfile = "${service.value.stateDir}/stderr"; startretries = 0; + autostart = nodeSpec.value.autostart + or true; ## Backward compatibility for profiles coming from old pinned workbench. autorestart = false; }; diff --git a/nix/workbench/supervisor.nix b/nix/workbench/supervisor.nix index c02c25e77bc..8e15568e2f7 100644 --- a/nix/workbench/supervisor.nix +++ b/nix/workbench/supervisor.nix @@ -32,6 +32,26 @@ let "127.0.0.1"; finaliseNodeService = + let time_fmtstr = + "{ " + escape [''"''] (concatStringsSep ''\n, '' time_entries) + " }"; + time_entries = [ + ''"wall_clock_s": %e'' + ''"user_cpu_s": %U'' + ''"sys_cpu_s": %S'' + ''"avg_cpu_pct": "%P"'' + ''"rss_peak_kb": %M'' + ''"signals_received": %k'' + ''"ctxsw_involuntary": %c'' + ''"ctxsw_volunt_waits": %w'' + ''"pageflt_major": %F'' + ''"pageflt_minor": %R'' + ''"swaps": %W'' + ''"io_fs_reads": %I'' + ''"io_fs_writes": %O'' + ''"cmdline": "%C"'' + ''"exit_code": %x'' + ]; + in { name, i, isProducer, ... }: svc: recursiveUpdate svc ({ stateDir = stateDir + "/${name}"; @@ -40,7 +60,7 @@ let topology = "topology.json"; nodeConfigFile = "config.json"; } // optionalAttrs useCabalRun { - executable = "cabal run exe:cardano-node --"; + executable = ''time -f "${time_fmtstr}" -o kernel-resource-summary.json cabal run exe:cardano-node -- +RTS -sghc-rts-report.txt -RTS''; } // optionalAttrs isProducer { operationalCertificate = "../genesis/node-keys/node${toString i}.opcert"; kesKey = "../genesis/node-keys/node-kes${toString i}.skey"; diff --git a/nix/workbench/supervisor.sh b/nix/workbench/supervisor.sh index 7be22848817..384166a2a7f 100755 --- a/nix/workbench/supervisor.sh +++ b/nix/workbench/supervisor.sh @@ -58,39 +58,69 @@ case "$op" in EOF ;; - start-cluster ) - local usage="USAGE: wb supervisor $op RUN-DIR" + start-node ) + local usage="USAGE: wb supervisor $op RUN-DIR NODE-NAME" local dir=${1:?$usage}; shift + local node=${1:?$usage}; shift - supervisord --config "$dir"/supervisor/supervisord.conf $@ + supervisorctl start $node + backend_supervisor wait-node "$dir" $node + backend_supervisor save-child-pids "$dir" + ;; - if test ! -v CARDANO_NODE_SOCKET_PATH - then export CARDANO_NODE_SOCKET_PATH=$(backend_supervisor get-node-socket-path "$dir") - fi + stop-node ) + local usage="USAGE: wb supervisor $op RUN-DIR NODE-NAME" + local dir=${1:?$usage}; shift + local node=${1:?$usage}; shift + + supervisorctl stop $node + ;; + + wait-node ) + local usage="USAGE: wb supervisor $op RUN-DIR [NODE-NAME]" + local dir=${1:?$usage}; shift + local node=${1:-$(dirname $CARDANO_NODE_SOCKET_PATH | xargs basename)}; shift + local socket=$(backend_supervisor get-node-socket-path "$dir" $node) local patience=$(jq '.analysis.cluster_startup_overhead_s | ceil' $dir/profile.json) i=0 - echo -n "workbench: supervisor: waiting ${patience}s for $CARDANO_NODE_SOCKET_PATH to appear: " >&2 - while test ! -S $CARDANO_NODE_SOCKET_PATH + echo -n "workbench: supervisor: waiting ${patience}s for socket of $node: " >&2 + while test ! -S $socket do printf "%3d" $i; sleep 1 i=$((i+1)) if test $i -ge $patience then echo - msg "FATAL: workbench: supervisor: patience ran out after ${patience}s" + progress "supervisor" "$(red FATAL): workbench: supervisor: patience ran out for $(white $node) after ${patience}s, socket $socket" backend_supervisor stop-cluster "$dir" - fatal "node startup did not succeed: check logs in $dir/node-0/stdout" + fatal "$node startup did not succeed: check logs in $(dirname $socket)/stdout & stderr" fi echo -ne "\b\b\b" done >&2 - echo " node-0 online after $i seconds" >&2 + echo " $node up (${i}s)" >&2 + ;; + + start-cluster ) + local usage="USAGE: wb supervisor $op RUN-DIR" + local dir=${1:?$usage}; shift + + supervisord --config "$dir"/supervisor/supervisord.conf $@ + + for node in $(jq_tolist keys "$dir"/node-specs.json) + do jqtest ".\"$node\".autostart" "$dir"/node-specs.json && + backend_supervisor wait-node "$dir" $node; done + + if test ! -v CARDANO_NODE_SOCKET_PATH + then export CARDANO_NODE_SOCKET_PATH=$(backend_supervisor get-node-socket-path "$dir" 'node-0') + fi backend_supervisor save-child-pids "$dir" backend_supervisor save-pid-maps "$dir";; get-node-socket-path ) - local usage="USAGE: wb supervisor $op STATE-DIR" + local usage="USAGE: wb supervisor $op STATE-DIR NODE-NAME" local state_dir=${1:?$usage} + local node_name=${2:?$usage} - echo -n $state_dir/node-0/node.socket + echo -n $state_dir/$node_name/node.socket ;; start-generator ) @@ -105,6 +135,19 @@ EOF supervisorctl start generator backend_supervisor save-child-pids "$dir";; + wait-node-stopped ) + local usage="USAGE: wb supervisor $op RUN-DIR NODE" + local dir=${1:?$usage}; shift + local node=${1:?$usage}; shift + + progress_ne "supervisor" "waiting until $node stops: ....." + local i=0 + while supervisorctl status $node > /dev/null + do echo -ne "\b\b\b\b\b"; printf "%5d" $i >&2; i=$((i+1)); sleep 1 + done >&2 + echo -e "\b\b\b\b\bdone, after $(with_color white $i) seconds" >&2 + ;; + wait-pools-stopped ) local usage="USAGE: wb supervisor $op RUN-DIR" local dir=${1:?$usage}; shift @@ -152,9 +195,9 @@ EOF pstree -p "$(cat "$svpid")" > "$pstree" local pidsfile="$dir"/supervisor/child.pids - { grep '\\---\|--=' "$pstree" || true; } | - sed 's/^.*\\--- \([0-9]*\) .*/\1/; s/^[ ]*[^ ]* \([0-9]+\) .*/\1/ - ' > "$pidsfile" + { grep -e '---\|--=' "$pstree" || true; } | + sed 's/^.*--[=-] \([0-9]*\) .*/\1/; s/^[ ]*[^ ]* \([0-9]+\) .*/\1/ + ' > "$pidsfile" ;; save-pid-maps ) @@ -164,13 +207,24 @@ EOF local mapn2p=$dir/supervisor/node2pid.map; echo '{}' > "$mapn2p" local mapp2n=$dir/supervisor/pid2node.map; echo '{}' > "$mapp2n" local pstree=$dir/supervisor/ps.tree + for node in $(jq_tolist keys "$dir"/node-specs.json) - do local service_pid=$(supervisorctl pid $node) - if test -z "$(ps h --ppid $service_pid)" - then local pid=$service_pid - else local pid=$(fgrep -e "= $(printf %05d $service_pid) " -A1 "$pstree" | - tail -n1 | sed 's/^.*\\--- \([0-9]*\) .*/\1/; s/^[ ]*[^ ]* \([0-9]*\) .*/\1/') + do ## supervisord's service PID is the immediately invoked binary, + ## ..which isn't necessarily 'cardano-node', but could be 'time' or 'cabal' or.. + local service_pid=$(supervisorctl pid $node) + if test $service_pid = '0' + then continue + elif test -z "$(ps h --ppid $service_pid)" ## Any children? + then local pid=$service_pid ## <-=^^^ none, in case we're running executables directly. + ## ..otherwise, it's a chain of children, e.g.: time -> cabal -> cardano-node + else local pid=$(grep -e "[=-] $(printf %05d $service_pid) " -A5 "$pstree" | + grep -e '---\|--=' | + head -n1 | + sed 's/^.*--[=-] \([0-9]*\) .*/\1/; + s/^[ ]*[^ ]* \([0-9]*\) .*/\1/') fi + if test -z "$pid" + then warn "supervisor" "failed to detect PID of $(white $node)"; fi jq_fmutate "$mapn2p" '. * { "'$node'": '$pid' }' jq_fmutate "$mapp2n" '. * { "'$pid'": "'$node'" }' done diff --git a/nix/workbench/topology.jq b/nix/workbench/topology.jq new file mode 100644 index 00000000000..8ad4fddfe04 --- /dev/null +++ b/nix/workbench/topology.jq @@ -0,0 +1,31 @@ +def loopback_node_topology_from_nixops_topology($topo; $i): + $topo.coreNodes[$i].producers as $producers + | ($producers | map(ltrimstr("node-") | fromjson)) as $prod_indices + | { Producers: + ( $prod_indices + | map + ({ addr: "127.0.0.1" + , port: ($basePort + .) + , valency: 1 + } + )) + }; + +def composition_block_sources_nr($compo): + $compo.n_bft_hosts ++ $compo.n_pool_hosts ++ if $compo.with_proxy then 1 else 0 end ++ if $compo.with_chaindb_server then 1 else 0 end; + +def composition_observer_topology_loopback($compo; $basePort): + [range(0; composition_block_sources_nr($compo))] + as $src_indices +| { Producers: + ( $src_indices + | map + ({ addr: "127.0.0.1" + , port: ($basePort + .) + , valency: 1 + } + )) + }; diff --git a/nix/workbench/topology.sh b/nix/workbench/topology.sh index 2cb859b5535..af3470dfa80 100644 --- a/nix/workbench/topology.sh +++ b/nix/workbench/topology.sh @@ -117,28 +117,17 @@ case "${op}" in local topo_dir=${4:?$usage} local basePort=${5:?$usage} - local prof=$(profile json-by-name $profile) + local prof=$(profile json $profile) case "$role" in local-bft | local-pool ) - args=(--slurpfile topology "$topo_dir"/topology-nixops.json + args=(-L$global_basedir + --slurpfile topology "$topo_dir"/topology-nixops.json --argjson basePort $basePort - --argjson i $i + --argjson i $i --null-input ) - jq ' - def loopback_node_topology_from_nixops_topology($topo; $i): - $topo.coreNodes[$i].producers as $producers - | ($producers | map(ltrimstr("node-") | fromjson)) as $prod_indices - | { Producers: - ( $prod_indices - | map - ({ addr: "127.0.0.1" - , port: ($basePort + .) - , valency: 1 - } - )) - }; + jq 'include "topology"; loopback_node_topology_from_nixops_topology($topology[0]; $i) ' "${args[@]}";; @@ -148,26 +137,17 @@ case "${op}" in local topo_proxy=$(profile preset-get-file "$preset" 'proxy topology' 'topology-proxy.json') jq . "$topo_proxy";; + local-chaindb-server ) + ## ChainDB servers are just that: + jq --null-input "{ Producers: [] }";; local-observer ) - args=(--slurpfile topology "$topo_dir"/topology-nixops.json - --argjson basePort $basePort - --null-input + args=(-L$global_basedir + --argjson basePort $basePort ) - jq ' - def loopback_observer_topology_from_nixops_topology($topo): - [range(0; $topo.coreNodes | length)] as $prod_indices - | { Producers: - ( $prod_indices - | map - ({ addr: "127.0.0.1" - , port: ($basePort + .) - , valency: 1 - } - )) - }; + jq 'include "topology"; - loopback_observer_topology_from_nixops_topology($topology[0]) - ' "${args[@]}";; + composition_observer_topology_loopback(.composition; $basePort) + ' "${args[@]}" <<<$prof;; * ) fail "unhandled role for topology node '$i': '$role'";; esac;; diff --git a/nix/workbench/wb b/nix/workbench/wb index 2bc2af1787a..81f72ef98b2 100755 --- a/nix/workbench/wb +++ b/nix/workbench/wb @@ -11,6 +11,7 @@ global_mode='unknown' . "$global_basedir"/lib.sh . "$global_basedir"/env.sh . "$global_basedir"/profile.sh +. "$global_basedir"/chaindb.sh . "$global_basedir"/genesis.sh . "$global_basedir"/topology.sh . "$global_basedir"/manifest.sh @@ -33,6 +34,7 @@ usage_main() { analyse (a) Analyse cluster runs env (e) Environment configuration + chaindb (c) ChainDB genesis (g) Genesis topology (t) Topology generation run (r) Managing cluster runs. Default op is 'list' @@ -96,6 +98,9 @@ start() local verbose= local manifest="{}" local iterations=1 + local no_retry_failed_runs=t + local no_analysis= analyse_args=() + local analysis_can_fail= local run_args=() local run_allocate_args=() @@ -104,7 +109,7 @@ start() do case "$1" in --batch-name ) batch_name=$2; shift;; --profile-name ) profile_name=$2; shift;; - --iterations | --times | --iter | -n ) iterations=$2; shift;; + --iterations | --times | --iter | -n ) iterations=$2; no_retry_failed_runs=; shift;; --cache-dir ) setenvjqstr 'cacheDir' $2; shift;; --base-port ) setenvjq 'basePort' $2; shift;; @@ -114,8 +119,12 @@ start() --idle ) run_start_args+=($1);; --scenario | -s ) run_start_args+=($1 $2); shift;; - --analyse | -a ) run_start_args+=($1);; - --analysis-can-fail ) run_start_args+=($1);; + + --no-analysis ) no_analysis=true;; + --analysis-can-fail | -af ) analysis_can_fail=t;; + --dump-logobjects | -lo ) analyse_args+=($1);; + --dump-machviews | -mw ) analyse_args+=($1);; + --filters ) analyse_args+=($1 $2); shift;; --cabal-mode | --cabal ) cabal_mode=t;; --supervisor | --backend-supervisor ) @@ -139,6 +148,7 @@ start() backend setenv-defaults "$profile" profile_name=${profile_name:-$(jq '.name' -r $profile/profile.json)} + analysis_type=$(jq '.analysis.type' -r $profile/profile.json) progress "top-level" "iterations of profile $(with_color 'yellow' $profile_name): $(with_color 'white' $iterations)" for ((i=0; i<$iterations; i++)) @@ -147,11 +157,22 @@ start() --manifest "$(manifest collect-from-checkout .)" ) run ${run_args[@]} 'allocate' $batch_name $profile_name "${args[@]}" + local tag=$(run current-tag) current_run_path=$(run current-path) mkdir -p "$current_run_path" - run ${run_args[@]} 'start' ${run_start_args[@]} $(run current-tag) + run ${run_args[@]} 'start' ${run_start_args[@]} $tag + + if test -n "$no_analysis" -o $analysis_type = null; then continue; fi + + progress "top-level | analysis" "analysis type $(with_color yellow $analysis_type) on $(with_color white $tag)" + analyse ${analyse_args[@]} $analysis_type $tag || + if test -n "$analysis_can_fail" -a -z "$no_retry_failed_runs" + then progress "run | analysis" "log processing failed, but --analysis-can-fail prevents failure: $(with_color red $tag)" + iterations=$((iterations + 1)) + else fail "analysis failed: $tag" + false; fi done } @@ -198,6 +219,7 @@ main() { ## Public, internals-y: env | e ) env "$@";; + chaindb | c ) chaindb "$@";; genesis | g ) genesis "$@";; topology | topo | t ) topology "$@";; run | runs | r ) run "$@";; diff --git a/shell.nix b/shell.nix index 3285203e9fe..bb62c1d30e0 100644 --- a/shell.nix +++ b/shell.nix @@ -4,22 +4,21 @@ let defaultCustomConfig = import ./nix/custom-config.nix defaultCustomConfig; in { withHoogle ? defaultCustomConfig.withHoogle , profileName ? defaultCustomConfig.localCluster.profileName -, autoStartCluster ? defaultCustomConfig.localCluster.autoStartCluster -, autoStartClusterArgs ? defaultCustomConfig.localCluster.autoStartClusterArgs , workbenchDevMode ? defaultCustomConfig.localCluster.workbenchDevMode , customConfig ? { inherit withHoogle; localCluster = { - inherit autoStartCluster autoStartClusterArgs profileName workbenchDevMode; + inherit profileName workbenchDevMode; }; } , pkgs ? import ./nix customConfig +, cardano-mainnet-mirror ? __getFlake "github:input-output-hk/cardano-mainnet-mirror/nix" }: with pkgs; let inherit (pkgs) customConfig; inherit (customConfig) withHoogle localCluster; - inherit (localCluster) autoStartCluster autoStartClusterArgs profileName workbenchDevMode; + inherit (localCluster) profileName workbenchDevMode; inherit (pkgs.haskell-nix) haskellLib; commandHelp = '' @@ -32,7 +31,6 @@ let * stop-cluster - stop a local development cluster * restart-cluster - restart the last cluster run (in 'run/current') (WARNING: logs & node DB will be wiped clean) - " ''; # Test cases will assume a UTF-8 locale and provide text in this character encoding. @@ -69,6 +67,7 @@ let nativeBuildInputs = with haskellPackages; with cardanoNodePackages; [ cardano-ping cabalWrapped + db-analyser ghcid haskellBuildUtils pkgs.graphviz @@ -100,27 +99,21 @@ let exactDeps = true; shellHook = '' - echo 'nix-shell top-level shellHook: withHoogle=${toString withHoogle} profileName=${profileName} autoStartCluster=${toString autoStartCluster} workbenchDevMode=${toString workbenchDevMode}' + echo 'nix-shell top-level shellHook: withHoogle=${toString withHoogle} profileName=${profileName} workbenchDevMode=${toString workbenchDevMode}' ${with customConfig.localCluster; - (import ./nix/workbench/shell.nix { inherit lib workbenchDevMode; useCabalRun = true; }).shellHook} + (import ./nix/workbench/shell.nix { inherit lib workbenchDevMode profileName; useCabalRun = true; }).shellHook} - ${lib.optionalString autoStartCluster '' function atexit() { if wb backend is-running - then echo "workbench: stopping cluster (because 'autoStartCluster' implies this):" - stop-cluster + then stop-cluster fi } trap atexit EXIT - ''} ${setLocale} - ${lib.optionalString autoStartCluster '' - echo "workbench: starting cluster (because 'autoStartCluster' is true):" - start-cluster ${autoStartClusterArgs} - ''} + export CARDANO_MAINNET_MIRROR=${cardano-mainnet-mirror.outputs.defaultPackage.x86_64-linux.outPath} ${commandHelp} @@ -165,7 +158,7 @@ let | ${lolcat}/bin/lolcat ${with customConfig.localCluster; - (import ./nix/workbench/shell.nix { inherit lib workbenchDevMode; useCabalRun = false; }).shellHook} + (import ./nix/workbench/shell.nix { inherit lib workbenchDevMode profileName; useCabalRun = false; }).shellHook} # Socket path default to first node launched by "start-cluster": export CARDANO_NODE_SOCKET_PATH=$(wb backend get-node-socket-path ${cluster.stateDir}) @@ -188,10 +181,6 @@ let echo ' edit ~/.config/nix/nix.conf and add line `access-tokens = "github.com=23ac...b289"`' ${commandHelp} - ${lib.optionalString autoStartCluster '' - echo "workbench: starting cluster (because 'autoStartCluster' is true):" - start-cluster - ''} ''; }; diff --git a/trace-dispatcher/examples/Examples/Configuration.hs b/trace-dispatcher/examples/Examples/Configuration.hs index d65816c3030..7d79d1f0b22 100644 --- a/trace-dispatcher/examples/Examples/Configuration.hs +++ b/trace-dispatcher/examples/Examples/Configuration.hs @@ -54,8 +54,8 @@ config1 = TraceConfig { , tofVerbosity = Minimum } , tcNodeName = Nothing - , tcPeerFreqency = Nothing - , tcResourceFreqency = Nothing + , tcPeerFrequency = Nothing + , tcResourceFrequency = Nothing } config2 :: TraceConfig @@ -73,8 +73,8 @@ config2 = TraceConfig { , tofVerbosity = Minimum } , tcNodeName = Just "node-1" - , tcPeerFreqency = Nothing - , tcResourceFreqency = Nothing + , tcPeerFrequency = Nothing + , tcResourceFrequency = Nothing } testConfig' :: diff --git a/trace-dispatcher/src/Cardano/Logging/Configuration.hs b/trace-dispatcher/src/Cardano/Logging/Configuration.hs index 7da90c7a1a2..04bf0d5bd2b 100644 --- a/trace-dispatcher/src/Cardano/Logging/Configuration.hs +++ b/trace-dispatcher/src/Cardano/Logging/Configuration.hs @@ -25,7 +25,7 @@ import Data.IORef (IORef, newIORef, readIORef, writeIORef) import Data.List (maximumBy, nub) import qualified Data.Map as Map import Data.Maybe (fromMaybe, mapMaybe) -import Data.Text (Text, pack, unpack) +import Data.Text (Text, intercalate, unpack) import Cardano.Logging.DocuGenerator (addFiltered, addLimiter) import Cardano.Logging.FrequencyLimiter (LimitingMessage (..), limitFrequency) @@ -317,7 +317,7 @@ getLimiterSpec :: TraceConfig -> Namespace -> Maybe (Text, Double) getLimiterSpec config ns = getOption limiterSelector config ns where limiterSelector :: ConfigOption -> Maybe (Text, Double) - limiterSelector (ConfLimiter f) = Just ((pack . show) ns, f) + limiterSelector (ConfLimiter f) = Just (intercalate "." ns, f) limiterSelector _ = Nothing -- | Searches in the config to find an option diff --git a/trace-dispatcher/src/Cardano/Logging/ConfigurationParser.hs b/trace-dispatcher/src/Cardano/Logging/ConfigurationParser.hs index af04a645e6c..83c2c4518de 100644 --- a/trace-dispatcher/src/Cardano/Logging/ConfigurationParser.hs +++ b/trace-dispatcher/src/Cardano/Logging/ConfigurationParser.hs @@ -67,15 +67,15 @@ parseRepresentation bs = transform (decodeEither' bs) to'' (traceOptionForwarder cr) (traceOptionNodeName cr) - (traceOptionPeerFreqency cr) - (traceOptionResourceFreqency cr) + (traceOptionPeerFrequency cr) + (traceOptionResourceFrequency cr) data ConfigRepresentation = ConfigRepresentation { traceOptions :: OptionsRepresentation , traceOptionForwarder :: TraceOptionForwarder , traceOptionNodeName :: Maybe Text - , traceOptionPeerFreqency :: Maybe Int - , traceOptionResourceFreqency :: Maybe Int + , traceOptionPeerFrequency :: Maybe Int + , traceOptionResourceFrequency :: Maybe Int } deriving (Eq, Ord, Show,Generic) @@ -86,8 +86,8 @@ instance AE.FromJSON ConfigRepresentation where <$> obj .: "TraceOptions" <*> obj .: "TraceOptionForwarder" <*> obj .:? "TraceOptionNodeName" - <*> obj .:? "TraceOptionPeerFreqency" - <*> obj .:? "TraceOptionResourceFreqency" + <*> obj .:? "TraceOptionPeerFrequency" + <*> obj .:? "TraceOptionResourceFrequency" data ConfigOptionRep = ConfigOptionRep { severity :: Maybe SeverityF diff --git a/trace-dispatcher/src/Cardano/Logging/FrequencyLimiter.hs b/trace-dispatcher/src/Cardano/Logging/FrequencyLimiter.hs index a9f7de85507..239c816a1ba 100644 --- a/trace-dispatcher/src/Cardano/Logging/FrequencyLimiter.hs +++ b/trace-dispatcher/src/Cardano/Logging/FrequencyLimiter.hs @@ -50,18 +50,15 @@ instance LogFormatting LimitingMessage where ". Suppressed " <> pack (show num) <> " messages." forHuman (RememberLimiting txt num) = "Frequency limiting still active for " <> txt <> ". Suppressed so far " <> pack (show num) <> " messages." - forMachine _dtl (StartLimiting txt) = mconcat + forMachine _dtl StartLimiting{} = mconcat [ "kind" .= String "StartLimiting" - , "name" .= String txt ] - forMachine _dtl (StopLimiting txt num) = mconcat + forMachine _dtl (StopLimiting _txt num) = mconcat [ "kind" .= String "StopLimiting" - , "name" .= String txt , "numSuppressed" .= Number (fromIntegral num) ] - forMachine _dtl (RememberLimiting txt num) = mconcat + forMachine _dtl (RememberLimiting _txt num) = mconcat [ "kind" .= String "RememberLimiting" - , "name" .= String txt , "numSuppressed" .= Number (fromIntegral num) ] asMetrics (StartLimiting _txt) = [] diff --git a/trace-dispatcher/src/Cardano/Logging/Trace.hs b/trace-dispatcher/src/Cardano/Logging/Trace.hs index e4401c46fac..7960496b6e2 100644 --- a/trace-dispatcher/src/Cardano/Logging/Trace.hs +++ b/trace-dispatcher/src/Cardano/Logging/Trace.hs @@ -25,12 +25,13 @@ module Cardano.Logging.Trace ( , withDetails , foldTraceM , foldMTraceM + , foldMCondTraceM , routingTrace ) where -import Control.Monad (join) +import Control.Monad (join, when) import Control.Monad.IO.Unlift import qualified Control.Tracer as T import Data.Maybe (isJust) @@ -250,6 +251,30 @@ foldMTraceM cata initial (Trace tr) = do (lc, Left control) -> do T.traceWith tr (lc, Left control) +-- | Like foldMTraceM, but filter the trace by a predicate. +foldMCondTraceM + :: forall a acc m . (MonadUnliftIO m) + => (acc -> LoggingContext -> a -> m acc) + -> acc + -> (a -> Bool) + -> Trace m (Folding a acc) + -> m (Trace m a) +foldMCondTraceM cata initial flt (Trace tr) = do + ref <- liftIO (newMVar initial) + let trr = mkTracer ref + pure $ Trace (T.arrow trr) + where + mkTracer ref = T.emit $ + \case + (lc, Right v) -> do + x' <- modifyMVar ref $ \x -> do + ! accu <- cata x lc v + pure $ join (,) accu + when (flt v) $ + T.traceWith tr (lc, Right (Folding x')) + (lc, Left control) -> do + T.traceWith tr (lc, Left control) + -- | Allows to route to different tracers, based on the message being processed. -- The second argument must mappend all possible tracers of the first -- argument to one tracer. This is required for the configuration! diff --git a/trace-dispatcher/src/Cardano/Logging/Types.hs b/trace-dispatcher/src/Cardano/Logging/Types.hs index 6f6eef78028..63ad9e04d34 100644 --- a/trace-dispatcher/src/Cardano/Logging/Types.hs +++ b/trace-dispatcher/src/Cardano/Logging/Types.hs @@ -362,9 +362,9 @@ data TraceConfig = TraceConfig { -- | Optional human-readable name of the node. , tcNodeName :: Maybe Text -- | Optional peer trace frequency in milliseconds. - , tcPeerFreqency :: Maybe Int + , tcPeerFrequency :: Maybe Int -- | Optional resource trace frequency in milliseconds. - , tcResourceFreqency :: Maybe Int + , tcResourceFrequency :: Maybe Int } deriving (Eq, Ord, Show) @@ -373,8 +373,8 @@ emptyTraceConfig = TraceConfig { tcOptions = Map.empty , tcForwarder = defaultForwarder , tcNodeName = Nothing - , tcPeerFreqency = Just 2000 -- Every 2 seconds - , tcResourceFreqency = Just 1000 -- Every second + , tcPeerFrequency = Just 2000 -- Every 2 seconds + , tcResourceFrequency = Just 1000 -- Every second } ---------------------------------------------------------------------------