Debug timing

Author: newhoggy

.github/workflows/haskell.yml

@@ -141,6 +141,11 @@ jobs:
       run: |
         cabal test cardano-testnet cardano-node cardano-node-chairman cardano-submit-api
 
+    - name: Timings
+      run: |
+        cd cardano-testnet
+        stat -c "%y %n" * | grep '\(start\|stop\)' | sort
+
     - name: Tar failed tests workspaces
       if: ${{ failure() }}
       env:

cardano-testnet/hprop_cli_queries.start

@@ -0,0 +1 @@
+hprop_cli_queries

cardano-testnet/hprop_cli_queries.stop

@@ -0,0 +1 @@
+hprop_cli_queries

cardano-testnet/hprop_drep_retirement.start

@@ -0,0 +1 @@
+hprop_drep_retirement

cardano-testnet/hprop_drep_retirement.stop

@@ -0,0 +1 @@
+hprop_drep_retirement

cardano-testnet/hprop_kes_period_info.start

@@ -0,0 +1 @@
+hprop_kes_period_info

cardano-testnet/hprop_kes_period_info.stop

@@ -0,0 +1 @@
+hprop_kes_period_info

cardano-testnet/hprop_leadershipSchedule.start

@@ -0,0 +1 @@
+hprop_leadershipSchedule

cardano-testnet/hprop_leadershipSchedule.stop

@@ -0,0 +1 @@
+hprop_leadershipSchedule

cardano-testnet/hprop_ledger_events_drep_deposits.start

@@ -0,0 +1 @@
+hprop_ledger_events_drep_deposits

cardano-testnet/hprop_ledger_events_drep_deposits.stop

@@ -0,0 +1 @@
+hprop_ledger_events_drep_deposits

cardano-testnet/hprop_ledger_events_propose_new_constitution.start

@@ -0,0 +1 @@
+hprop_ledger_events_propose_new_constitution

cardano-testnet/hprop_ledger_events_propose_new_constitution.stop

@@ -0,0 +1 @@
+hprop_ledger_events_propose_new_constitution

cardano-testnet/hprop_ledger_events_propose_new_constitution_spo.start

@@ -0,0 +1 @@
+hprop_ledger_events_propose_new_constitution_spo

cardano-testnet/hprop_ledger_events_propose_new_constitution_spo.stop

@@ -0,0 +1 @@
+hprop_ledger_events_propose_new_constitution_spo

cardano-testnet/hprop_ledger_events_sanity_check.start

@@ -0,0 +1 @@
+hprop_ledger_events_sanity_check

cardano-testnet/hprop_ledger_events_sanity_check.stop

@@ -0,0 +1 @@
+hprop_ledger_events_sanity_check

cardano-testnet/hprop_plutus_v3.start

@@ -0,0 +1 @@
+hprop_plutus_v3

cardano-testnet/hprop_plutus_v3.stop

@@ -0,0 +1 @@
+hprop_plutus_v3

cardano-testnet/hprop_querySlotNumber.start

@@ -0,0 +1 @@
+hprop_querySlotNumber

cardano-testnet/hprop_querySlotNumber.stop

@@ -0,0 +1 @@
+hprop_querySlotNumber

cardano-testnet/hprop_shutdownOnSigint.start

@@ -0,0 +1 @@
+hprop_shutdownOnSigint

cardano-testnet/hprop_shutdownOnSigint.stop

@@ -0,0 +1 @@
+hprop_shutdownOnSigint

cardano-testnet/hprop_stakeSnapshot-b.start

@@ -0,0 +1 @@
+hprop_stakeSnapshot

cardano-testnet/hprop_stakeSnapshot-b.stop

@@ -0,0 +1 @@
+hprop_stakeSnapshot

cardano-testnet/hprop_transaction-b.start

@@ -0,0 +1 @@
+hprop_transaction

cardano-testnet/hprop_transaction-b.stop

@@ -0,0 +1 @@
+hprop_transaction

cardano-testnet/hprop_transaction-c.start

@@ -0,0 +1 @@
+hprop_transaction

cardano-testnet/hprop_transaction-c.stop

@@ -0,0 +1 @@
+hprop_transaction

cardano-testnet/prop_check_if_treasury_is_growing.start

@@ -0,0 +1 @@
+prop_check_if_treasury_is_growing

cardano-testnet/prop_check_if_treasury_is_growing.stop

@@ -0,0 +1 @@
+prop_check_if_treasury_is_growing

cardano-testnet/prop_foldBlocks.start

@@ -0,0 +1 @@
+prop_foldBlocks

cardano-testnet/prop_foldBlocks.stop

@@ -0,0 +1 @@
+prop_foldBlocks

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Babbage/LeadershipSchedule.hs

@@ -55,6 +55,9 @@ import qualified Hedgehog.Extras.Test.File as H
 -- @DISABLE_RETRIES=1 cabal test cardano-testnet-test --test-options '-p "/leadership-schedule/"'@
 hprop_leadershipSchedule :: Property
 hprop_leadershipSchedule = H.integrationRetryWorkspace 2 "babbage-leadership-schedule" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_leadershipSchedule.start" "hprop_leadershipSchedule"
+
   H.note_ SYS.os
   conf@Conf { tempAbsPath=tempAbsPath@(TmpAbsolutePath work) } <- mkConf tempAbsBasePath'
   let tempBaseAbsPath = makeTmpBaseAbsPath tempAbsPath
@@ -355,3 +358,4 @@ hprop_leadershipSchedule = H.integrationRetryWorkspace 2 "babbage-leadership-sch
     H.noteShow_ (expectedLeadershipSlotNumbers \\ leaderSlots)
     H.assert $ L.null (expectedLeadershipSlotNumbers \\ leaderSlots)
 -}
+  H.writeFile "hprop_leadershipSchedule.stop" "hprop_leadershipSchedule"

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Babbage/StakeSnapshot.hs

@@ -29,10 +29,13 @@ import           Testnet.Runtime
 import           Hedgehog (Property, (===))
 import qualified Hedgehog as H
 import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
-import qualified Hedgehog.Extras.Test.Base as H
+import qualified Hedgehog.Extras.Test as H
 
 hprop_stakeSnapshot :: Property
 hprop_stakeSnapshot = H.integrationRetryWorkspace 2 "babbage-stake-snapshot" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_stakeSnapshot-b.start" "hprop_stakeSnapshot"
+
   H.note_ SYS.os
   conf@Conf { tempAbsPath } <- mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -69,3 +72,5 @@ hprop_stakeSnapshot = H.integrationRetryWorkspace 2 "babbage-stake-snapshot" $ \
         Aeson.Object kmPools -> KM.size kmPools === 3
         _ -> H.failure
     _ -> H.failure
+
+  H.writeFile "hprop_stakeSnapshot-b.stop" "hprop_stakeSnapshot"

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Babbage/Transaction.hs

@@ -41,6 +41,9 @@ import qualified Hedgehog.Extras.Test.File as H
 
 hprop_transaction :: Property
 hprop_transaction = H.integrationRetryWorkspace 0 "babbage-transaction" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_transaction-b.start" "hprop_transaction"
+
   H.note_ SYS.os
   conf@Conf { tempAbsPath } <- mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -121,6 +124,7 @@ hprop_transaction = H.integrationRetryWorkspace 0 "babbage-transaction" $ \tempA
     UTxO utxo2 <- H.noteShowM $ decodeEraUTxO sbe utxo2Json
     txouts2 <- H.noteShow $ L.unCoin . txOutValueLovelace . txOutValue . snd <$> Map.toList utxo2
     H.assert $ 5_000_001 `List.elem` txouts2
+  H.writeFile "hprop_transaction-b.stop" "hprop_transaction"
 
 txOutValue :: TxOut ctx era -> TxOutValue era
 txOutValue (TxOut _ v _ _) = v

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Conway/DRepRetirement.hs

@@ -40,6 +40,9 @@ sbe = ShelleyBasedEraConway
 -- @DISABLE_RETRIES=1 cabal test cardano-testnet-test --test-options '-p "/DRepRetirement/"'@
 hprop_drep_retirement :: Property
 hprop_drep_retirement = H.integrationRetryWorkspace 2 "drep-retirement" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_drep_retirement.start" "hprop_drep_retirement"
+
   -- Start a local test net
   conf@Conf { tempAbsPath } <- H.noteShowM $ mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -141,3 +144,4 @@ hprop_drep_retirement = H.integrationRetryWorkspace 2 "drep-retirement" $ \tempA
   -- to witness that the number of dreps indeed decreased.
   checkDRepsNumber sbe configFile' socketPath' execConfig (sizeBefore - 1)
   H.success
+  H.writeFile "hprop_drep_retirement.stop" "hprop_drep_retirement"

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Conway/Plutus.hs

@@ -49,6 +49,9 @@ import qualified Hedgehog.Extras as H
 -- Proposing NO
 hprop_plutus_v3 :: Property
 hprop_plutus_v3 = H.integrationWorkspace "all-plutus-script-purposes" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_plutus_v3.start" "hprop_plutus_v3"
+
   H.note_ SYS.os
   conf@Conf { tempAbsPath } <- mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -220,5 +223,6 @@ hprop_plutus_v3 = H.integrationWorkspace "all-plutus-script-purposes" $ \tempAbs
     , "--tx-file", spendScriptUTxOTx
     ]
   H.success
+  H.writeFile "hprop_plutus_v3.stop" "hprop_plutus_v3"
 
 

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Conway/StakeSnapshot.hs

@@ -26,10 +26,13 @@ import           Testnet.Runtime
 import           Hedgehog (Property, (===))
 import qualified Hedgehog as H
 import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
-import qualified Hedgehog.Extras.Test.Base as H
+import qualified Hedgehog.Extras.Test as H
 
 hprop_stakeSnapshot :: Property
 hprop_stakeSnapshot = H.integrationRetryWorkspace 2 "conway-stake-snapshot" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_stakeSnapshot-c.start" "hprop_stakeSnapshot"
+
   H.note_ SYS.os
   conf@Conf { tempAbsPath } <- mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -66,3 +69,4 @@ hprop_stakeSnapshot = H.integrationRetryWorkspace 2 "conway-stake-snapshot" $ \t
         Aeson.Object kmPools -> KM.size kmPools === 3
         _ -> H.failure
     _ -> H.failure
+  H.writeFile "hprop_stakeSnapshot-c.stop" "hprop_stakeSnapshot"

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/KesPeriodInfo.hs

@@ -47,6 +47,9 @@ import qualified Hedgehog.Extras.Test.File as H
 
 hprop_kes_period_info :: Property
 hprop_kes_period_info = H.integrationRetryWorkspace 2 "kes-period-info" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_kes_period_info.start" "hprop_kes_period_info"
+
   H.note_ SYS.os
   conf@Conf { tempAbsPath=tempAbsPath@(TmpAbsolutePath work) }
     -- TODO: Move yaml filepath specification into individual node options
@@ -341,3 +344,4 @@ hprop_kes_period_info = H.integrationRetryWorkspace 2 "kes-period-info" $ \tempA
 
   spoLogFile <- H.note nodeStdout
   prop_node_minted_block spoLogFile
+  H.writeFile "hprop_kes_period_info.stop" "hprop_kes_period_info"

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/Queries.hs

@@ -43,6 +43,9 @@ import qualified Hedgehog.Extras.Test.Golden as H
 -- RECREATE_GOLDEN_FILES=1 as its prefix
 hprop_cli_queries :: Property
 hprop_cli_queries = H.integrationWorkspace "cli-queries" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_cli_queries.start" "hprop_cli_queries"
+
   conf@Conf { tempAbsPath=tempAbsPath@(TmpAbsolutePath work) }
     <- mkConf tempAbsBasePath'
   let tempBaseAbsPath = makeTmpBaseAbsPath tempAbsPath
@@ -123,6 +126,7 @@ hprop_cli_queries = H.integrationWorkspace "cli-queries" $ \tempAbsBasePath' ->
   H.noteM_ $ H.execCli' execConfig [ "conway", "query", "drep-state", "--all-dreps"
                                    , "--out-file", drepStateOutFile]
   _ :: Aeson.Value <- H.leftFailM . H.readJsonFile $ drepStateOutFile
+  H.writeFile "hprop_cli_queries.stop" "hprop_cli_queries"
 
   H.success
 
@@ -152,4 +156,3 @@ assertArrayOfSize v n =
      failWrongType got = do
        H.note_ $ "Expected a JSON object, but received: " <> got
        H.failure
-

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/Cli/QuerySlotNumber.hs

@@ -31,12 +31,15 @@ import           Testnet.Runtime
 
 import           Hedgehog (Property)
 import qualified Hedgehog.Extras.Stock as H
-import qualified Hedgehog.Extras.Test.Base as H
+import qualified Hedgehog.Extras.Test as H
 import qualified Hedgehog.Internal.Property as H
 
 -- | Tests @query slot-number@ cardano-cli command that it returns correct slot numbers for provided utc time
 hprop_querySlotNumber :: Property
 hprop_querySlotNumber = H.integrationRetryWorkspace 2 "query-slot-number" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_querySlotNumber.start" "hprop_querySlotNumber"
+
   H.note_ SYS.os
   conf <- mkConf tempAbsBasePath'
 
@@ -119,6 +122,8 @@ hprop_querySlotNumber = H.integrationRetryWorkspace 2 "query-slot-number" $ \tem
       ]
     H.assertWith result isLeft
 
+  H.writeFile "hprop_querySlotNumber.stop" "hprop_querySlotNumber"
+
 formatTime :: DT.UTCTime -> String
 formatTime = DT.formatTime DT.defaultTimeLocale "%Y-%m-%dT%H:%M:%SZ"
 

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/FoldBlocks.hs

@@ -40,6 +40,9 @@ instance Show FoldBlocksException where
 -- that main thread blocks on.
 prop_foldBlocks :: H.Property
 prop_foldBlocks = H.integrationRetryWorkspace 2 "foldblocks" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "prop_foldBlocks.start" "prop_foldBlocks"
+
   -- Start testnet
   conf <- TN.mkConf tempAbsBasePath'
 
@@ -77,4 +80,5 @@ prop_foldBlocks = H.integrationRetryWorkspace 2 "foldblocks" $ \tempAbsBasePath'
   -- test to finish.
   _ <- H.evalIO $ H.timeout 30_000_000 $ IO.readMVar lock
   H.assert True
+  H.writeFile "prop_foldBlocks.stop" "prop_foldBlocks"
 

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/LedgerEvents/Gov/DRepDeposits.hs

@@ -36,6 +36,8 @@ import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
 -- @DISABLE_RETRIES=1 cabal test cardano-testnet-test --test-options '-p "/DRep Deposits/"'@
 hprop_ledger_events_drep_deposits :: Property
 hprop_ledger_events_drep_deposits = H.integrationWorkspace "drep-deposits" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_ledger_events_drep_deposits.start" "hprop_ledger_events_drep_deposits"
 
   -- Start a local test net
   conf@Conf { tempAbsPath } <- mkConf tempAbsBasePath'
@@ -110,5 +112,6 @@ hprop_ledger_events_drep_deposits = H.integrationWorkspace "drep-deposits" $ \te
 
   checkDRepState sbe (File configurationFile) (File socketPath) execConfig
     (\m -> if map L.drepDeposit (Map.elems m) == [L.Coin minDRepDeposit] then Just () else Nothing)
+  H.writeFile "hprop_ledger_events_drep_deposits.stop" "hprop_ledger_events_drep_deposits"
 
 

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/LedgerEvents/Gov/InfoAction.hs

@@ -46,6 +46,8 @@ import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
 -- @DISABLE_RETRIES=1 cabal test cardano-testnet-test --test-options '-p "/InfoAction/'@
 hprop_ledger_events_info_action :: Property
 hprop_ledger_events_info_action = H.integrationRetryWorkspace 0 "info-hash" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_ledger_events_info_action.start" "hprop_ledger_events_info_action"
 
   -- Start a local test net
   conf@Conf { tempAbsPath } <- H.noteShowM $ mkConf tempAbsBasePath'
@@ -225,6 +227,7 @@ hprop_ledger_events_info_action = H.integrationRetryWorkspace 0 "info-hash" $ \t
       H.failMessage callStack
         $ "foldBlocksCheckInfoAction failed with: " <> displayError e
     Right _events -> success
+  H.writeFile "hprop_ledger_events_info_action.stop" "hprop_ledger_events_info_action"
 
 -- | Fold accumulator for checking action state
 data InfoActionState = InfoActionState

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/LedgerEvents/Gov/ProposeNewConstitution.hs

@@ -53,6 +53,9 @@ import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
 -- @DISABLE_RETRIES=1 cabal test cardano-testnet-test --test-options '-p "/ProposeAndRatifyNewConstitution/"'@
 hprop_ledger_events_propose_new_constitution :: Property
 hprop_ledger_events_propose_new_constitution = H.integrationWorkspace "propose-new-constitution" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_ledger_events_propose_new_constitution.start" "hprop_ledger_events_propose_new_constitution"
+
   -- Start a local test net
   conf@Conf { tempAbsPath } <- mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -279,6 +282,7 @@ hprop_ledger_events_propose_new_constitution = H.integrationWorkspace "propose-n
   length (filter (== "VoteNo") votes) === 3
   length (filter (== "Abstain") votes) === 2
   length votes === numVotes
+  H.writeFile "hprop_ledger_events_propose_new_constitution.stop" "hprop_ledger_events_propose_new_constitution"
 
 foldBlocksCheckConstitutionWasRatified
   :: String -- submitted constitution hash

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/LedgerEvents/Gov/ProposeNewConstitutionSPO.hs

@@ -52,6 +52,9 @@ import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
 -- @cabal test cardano-testnet-test --test-options '-p "/ProposeNewConstitutionSPO/"'@
 hprop_ledger_events_propose_new_constitution_spo :: Property
 hprop_ledger_events_propose_new_constitution_spo = H.integrationWorkspace "propose-new-constitution-spo" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_ledger_events_propose_new_constitution_spo.start" "hprop_ledger_events_propose_new_constitution_spo"
+
   conf@Conf { tempAbsPath=tempAbsPath@(TmpAbsolutePath work) }
     <- mkConf tempAbsBasePath'
   let tempAbsPath' = unTmpAbsPath tempAbsPath
@@ -224,6 +227,7 @@ hprop_ledger_events_propose_new_constitution_spo = H.integrationWorkspace "propo
 
   exitCode H./== ExitSuccess -- Dit it fail?
   H.assert $ "DisallowedVoters" `isInfixOf` stderr -- Did it fail for the expected reason?
+  H.writeFile "hprop_ledger_events_propose_new_constitution_spo.stop" "hprop_ledger_events_propose_new_constitution_spo"
 
 getConstitutionProposal
   :: (HasCallStack, MonadCatch m, MonadIO m, MonadTest m)

cardano-testnet/test/cardano-testnet-test/Cardano/Testnet/Test/LedgerEvents/SanityCheck.hs

@@ -25,7 +25,7 @@ import           Testnet.Runtime
 
 import           Hedgehog
 import qualified Hedgehog.Extras.Stock.IO.Network.Sprocket as IO
-import qualified Hedgehog.Extras.Test.Base as H
+import qualified Hedgehog.Extras.Test as H
 
 newtype AdditionalCatcher
   = IOE IOException
@@ -42,6 +42,9 @@ newtype AdditionalCatcher
 -- setting timeouts for expected results etc.
 hprop_ledger_events_sanity_check :: Property
 hprop_ledger_events_sanity_check = H.integrationWorkspace "ledger-events-sanity-check" $ \tempAbsBasePath' -> do
+  H.threadDelay 1000
+  H.writeFile "hprop_ledger_events_sanity_check.start" "hprop_ledger_events_sanity_check"
+
   -- Start a local test net
   conf <- mkConf tempAbsBasePath'
 
@@ -75,6 +78,7 @@ hprop_ledger_events_sanity_check = H.integrationWorkspace "ledger-events-sanity-
     Right (Left e) ->
       H.failMessage callStack $ "foldBlocks failed with: " <> displayError e
     Right (Right _v) -> success
+  H.writeFile "hprop_ledger_events_sanity_check.stop" "hprop_ledger_events_sanity_check"
 
 
 foldBlocksAccumulator