diff --git a/lib/byron/bench/Latency.hs b/lib/byron/bench/Latency.hs index 9b378206bc0..d90464d1609 100644 --- a/lib/byron/bench/Latency.hs +++ b/lib/byron/bench/Latency.hs @@ -10,24 +10,16 @@ {-# LANGUAGE TypeFamilies #-} {-# LANGUAGE TypeOperators #-} -{-# OPTIONS_GHC -fno-warn-orphans #-} - module Main where import Prelude -import Cardano.BM.Backend.Switchboard - ( effectuate ) -import Cardano.BM.Configuration.Static - ( defaultConfigStdout ) import Cardano.BM.Data.LogItem - ( LOContent (..), LOMeta (..), LogObject (..) ) + ( LogObject ) import Cardano.BM.Data.Severity ( Severity (..) ) import Cardano.BM.Data.Tracer - ( ToObject (..), contramap, nullTracer ) -import Cardano.BM.Setup - ( setupTrace_, shutdown ) + ( contramap, nullTracer ) import Cardano.BM.Trace ( traceInTVarIO ) import Cardano.CLI @@ -60,6 +52,8 @@ import Cardano.Wallet.Byron.Faucet ( initFaucet ) import Cardano.Wallet.Byron.Launch ( withCardanoNode ) +import Cardano.Wallet.LatencyBenchShared + ( LogCaptureFunc, fmtResult, fmtTitle, measureApiLogs, withLatencyLogging ) import Cardano.Wallet.Logging ( trMessage ) import Cardano.Wallet.Network.Ports @@ -73,29 +67,19 @@ import Control.Concurrent.Async import Control.Concurrent.MVar ( newEmptyMVar, putMVar, takeMVar ) import Control.Concurrent.STM.TVar - ( TVar, newTVarIO, readTVarIO, writeTVar ) + ( TVar ) import Control.Exception - ( bracket, onException, throwIO ) + ( throwIO ) import Control.Monad - ( forM_, mapM_, replicateM, replicateM_ ) -import Control.Monad.STM - ( atomically ) -import Data.Aeson - ( FromJSON (..), ToJSON (..) ) + ( mapM_, replicateM, replicateM_ ) import Data.Generics.Internal.VL.Lens ( (^.) ) -import Data.Maybe - ( mapMaybe ) import Data.Proxy ( Proxy (..) ) -import Data.Text.Class - ( toText ) -import Data.Time - ( NominalDiffTime ) -import Data.Time.Clock - ( diffUTCTime ) +import Data.Text + ( Text ) import Fmt - ( Builder, build, fixedF, fmt, fmtLn, indentF, padLeftF, (+|), (|+) ) + ( build, fmtLn ) import Network.HTTP.Client ( defaultManagerSettings , managerResponseTimeout @@ -103,7 +87,7 @@ import Network.HTTP.Client , responseTimeoutMicro ) import Network.Wai.Middleware.Logging - ( ApiLog (..), HandlerLog (..) ) + ( ApiLog (..) ) import Numeric.Natural ( Natural ) import System.IO.Temp @@ -133,63 +117,93 @@ import Test.Integration.Framework.DSL import Test.Utils.Paths ( getTestData ) -import qualified Cardano.BM.Configuration.Model as CM import qualified Cardano.Wallet.Api.Link as Link import qualified Data.Text as T import qualified Network.HTTP.Types.Status as HTTP main :: forall t n. (t ~ Byron, n ~ 'Mainnet) => IO () -main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> - forM_ [ (fixtureRandomWallet, "Random wallets") - , (fixtureIcarusWallet, "Icarus wallets")] $ - \(fixtureByronWallet, walletName) -> do - fmtLn "\n" - fmtLn walletName +main = withUtf8Encoding $ + withLatencyLogging setupTracers $ \tracers capture -> do + let srv = benchWithByronServer tracers + mapM_ (walletApiBench @t @n capture srv) + [ RandomWallets + , IcarusWallets + ] - fmtTitle "Non-cached run" - runBareScenario logging tvar + where + setupTracers :: TVar [LogObject ApiLog] -> Tracers IO + setupTracers tvar = nullTracers + { apiServerTracer = trMessage $ contramap snd (traceInTVarIO tvar) } + +data FixtureWallets + = RandomWallets + | IcarusWallets + deriving (Show, Eq, Ord) + +fixtureWalletTitle :: FixtureWallets -> Text +fixtureWalletTitle RandomWallets = "Random wallets" +fixtureWalletTitle IcarusWallets = "Icarus wallets" + +type MakeWalletFixture t = Context t -> IO ApiByronWallet + +walletApiBench + :: forall t (n :: NetworkDiscriminant). (t ~ Byron, n ~ 'Mainnet) + => LogCaptureFunc ApiLog () + -> ((Context t -> IO ()) -> IO ()) + -> FixtureWallets + -> IO () +walletApiBench capture benchWithServer walletName = do + fmtLn "\n" + fmtLn $ build $ fixtureWalletTitle walletName - fmtTitle "Latencies for 2 fixture wallets scenario" - runScenario logging tvar (nFixtureWallet 2 fixtureByronWallet) + fmtTitle "Non-cached run" + runWarmUpScenario - fmtTitle "Latencies for 10 fixture wallets scenario" - runScenario logging tvar (nFixtureWallet 10 fixtureByronWallet) + fmtTitle "Latencies for 2 fixture wallets scenario" + runScenario (nFixtureWallet 2) - fmtTitle "Latencies for 100 fixture wallets scenario" - runScenario logging tvar (nFixtureWallet 100 fixtureByronWallet) + fmtTitle "Latencies for 10 fixture wallets scenario" + runScenario (nFixtureWallet 10) - fmtTitle "Latencies for 2 fixture wallets with 10 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 2 10 fixtureByronWallet) + fmtTitle "Latencies for 100 fixture wallets scenario" + runScenario (nFixtureWallet 100) - fmtTitle "Latencies for 2 fixture wallets with 20 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 2 20 fixtureByronWallet) + fmtTitle "Latencies for 2 fixture wallets with 10 txs scenario" + runScenario (nFixtureWalletWithTxs 2 10) - fmtTitle "Latencies for 2 fixture wallets with 100 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 2 100 fixtureByronWallet) + fmtTitle "Latencies for 2 fixture wallets with 20 txs scenario" + runScenario (nFixtureWalletWithTxs 2 20) - fmtTitle "Latencies for 10 fixture wallets with 10 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 10 10 fixtureByronWallet) + fmtTitle "Latencies for 2 fixture wallets with 100 txs scenario" + runScenario (nFixtureWalletWithTxs 2 100) - fmtTitle "Latencies for 10 fixture wallets with 20 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 10 20 fixtureByronWallet) + fmtTitle "Latencies for 10 fixture wallets with 10 txs scenario" + runScenario (nFixtureWalletWithTxs 10 10) - fmtTitle "Latencies for 10 fixture wallets with 100 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 10 100 fixtureByronWallet) + fmtTitle "Latencies for 10 fixture wallets with 20 txs scenario" + runScenario (nFixtureWalletWithTxs 10 20) - fmtTitle "Latencies for 2 fixture wallets with 100 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 100 walletName) + fmtTitle "Latencies for 10 fixture wallets with 100 txs scenario" + runScenario (nFixtureWalletWithTxs 10 100) - fmtTitle "Latencies for 2 fixture wallets with 200 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 200 walletName) + fmtTitle "Latencies for 2 fixture wallets with 100 utxos scenario" + runScenario (nFixtureWalletWithUTxOs 2 100) - fmtTitle "Latencies for 2 fixture wallets with 500 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 500 walletName) + fmtTitle "Latencies for 2 fixture wallets with 200 utxos scenario" + runScenario (nFixtureWalletWithUTxOs 2 200) - fmtTitle "Latencies for 2 fixture wallets with 1000 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 1000 walletName) + fmtTitle "Latencies for 2 fixture wallets with 500 utxos scenario" + runScenario (nFixtureWalletWithUTxOs 2 500) + + fmtTitle "Latencies for 2 fixture wallets with 1000 utxos scenario" + runScenario (nFixtureWalletWithUTxOs 2 1000) where + fixtureWallet = case walletName of + RandomWallets -> fixtureRandomWallet + IcarusWallets -> fixtureIcarusWallet + -- Creates n fixture wallets and return two of them - nFixtureWallet n fixtureWallet ctx = do + nFixtureWallet n ctx = do wal1 : wal2 : _ <- replicateM n (fixtureWallet ctx) pure (wal1, wal2) @@ -198,8 +212,8 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> -- additionally created source fixture wallet. Then we wait for the money -- to be accommodated in recipient wallet. After that the source fixture -- wallet is removed. - nFixtureWalletWithTxs n m fixtureByronWallet ctx = do - (wal1, wal2) <- nFixtureWallet n fixtureByronWallet ctx + nFixtureWalletWithTxs n m ctx = do + (wal1, wal2) <- nFixtureWallet n ctx let amt = (1 :: Natural) let batchSize = 10 @@ -216,19 +230,17 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> mapM_ (repeatPostTx ctx wal1 amt batchSize . amtExp) expInflows' pure (wal1, wal2) - nFixtureWalletWithUTxOs n utxoNumber walletName ctx = do + nFixtureWalletWithUTxOs n utxoNumber ctx = do let utxoExp = replicate utxoNumber 1 - wal1 <- if walletName == "Random wallets" then - fixtureRandomWalletWith @n ctx utxoExp - else - fixtureIcarusWalletWith @n ctx utxoExp - (_, wal2) <- if walletName == "Random wallets" then - nFixtureWallet n fixtureRandomWallet ctx - else - nFixtureWallet n fixtureIcarusWallet ctx + wal1 <- case walletName of + RandomWallets -> + fixtureRandomWalletWith @n ctx utxoExp + IcarusWallets -> + fixtureIcarusWalletWith @n ctx utxoExp + (_, wal2) <- nFixtureWallet n ctx eventually "Wallet balance is as expected" $ do - rWal1 <- request @ApiByronWallet ctx + rWal1 <- request @ApiByronWallet ctx (Link.getWallet @'Byron wal1) Default Empty verify rWal1 [ expectSuccess @@ -237,7 +249,7 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> (`shouldBe` fromIntegral utxoNumber) ] - rStat <-request @ApiUtxoStatistics ctx + rStat <- request @ApiUtxoStatistics ctx (Link.getUTxOsStatistics @'Byron wal1) Default Empty expectResponseCode @IO HTTP.status200 rStat expectWalletUTxO (fromIntegral <$> utxoExp) (snd rStat) @@ -248,14 +260,14 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> replicateM_ batchSize (postTx ctx (wSrc, Link.createTransaction @'Byron, fixturePassphrase) wDest amtToSend) eventually "repeatPostTx: wallet balance is as expected" $ do - rWal1 <- request @ApiByronWallet ctx (Link.getWallet @'Byron wDest) Default Empty + rWal1 <- request @ApiByronWallet ctx (Link.getWallet @'Byron wDest) Default Empty verify rWal1 [ expectSuccess , expectField (#balance . #available . #getQuantity) (`shouldBe` amtExp) ] - rDel <- request @ApiByronWallet ctx (Link.deleteWallet @'Byron wSrc) Default Empty + rDel <- request @ApiByronWallet ctx (Link.deleteWallet @'Byron wSrc) Default Empty expectResponseCode @IO HTTP.status204 rDel pure () @@ -277,26 +289,26 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> expectResponseCode HTTP.status202 r return r - runScenario logging tvar scenario = benchWithServer logging $ \ctx -> do + runScenario scenario = benchWithServer $ \ctx -> do (wal1, wal2) <- scenario ctx - t1 <- measureApiLogs tvar + t1 <- measureApiLogs capture (request @[ApiByronWallet] ctx (Link.listWallets @'Byron) Default Empty) fmtResult "listWallets " t1 - t2 <- measureApiLogs tvar - (request @ApiByronWallet ctx (Link.getWallet @'Byron wal1) Default Empty) + t2 <- measureApiLogs capture + (request @ApiByronWallet ctx (Link.getWallet @'Byron wal1) Default Empty) fmtResult "getWallet " t2 - t3 <- measureApiLogs tvar + t3 <- measureApiLogs capture (request @ApiUtxoStatistics ctx (Link.getUTxOsStatistics @'Byron wal1) Default Empty) fmtResult "getUTxOsStatistics " t3 - t4 <- measureApiLogs tvar + t4 <- measureApiLogs capture (request @[ApiAddress n] ctx (Link.listAddresses @'Byron wal1) Default Empty) fmtResult "listAddresses " t4 - t5 <- measureApiLogs tvar + t5 <- measureApiLogs capture (request @[ApiTransaction n] ctx (Link.listTransactions @'Byron wal1) Default Empty) fmtResult "listTransactions " t5 @@ -312,122 +324,29 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> } }] }|] - t6 <- measureApiLogs tvar $ request @ApiFee ctx + t6 <- measureApiLogs capture $ request @ApiFee ctx (Link.getTransactionFee @'Byron wal1) Default payload fmtResult "postTransactionFee " t6 - t7 <- measureApiLogs tvar $ request @ApiNetworkInformation ctx + t7 <- measureApiLogs capture $ request @ApiNetworkInformation ctx Link.getNetworkInfo Default Empty fmtResult "getNetworkInfo " t7 pure () - runBareScenario logging tvar = benchWithServer logging $ \ctx -> do + runWarmUpScenario = benchWithServer $ \ctx -> do -- this one is to have comparable results from first to last measurement -- in runScenario - t <- measureApiLogs tvar $ request @ApiNetworkInformation ctx + t <- measureApiLogs capture $ request @ApiNetworkInformation ctx Link.getNetworkInfo Default Empty fmtResult "getNetworkInfo " t pure () -meanAvg :: [NominalDiffTime] -> Double -meanAvg ts = sum (map realToFrac ts) * 1000 / fromIntegral (length ts) - -buildResult :: [NominalDiffTime] -> Builder -buildResult [] = "ERR" -buildResult ts = build $ fixedF 1 $ meanAvg ts - -fmtTitle :: Builder -> IO () -fmtTitle title = fmt (indentF 4 title) - -fmtResult :: String -> [NominalDiffTime] -> IO () -fmtResult title ts = - let titleExt = title|+" - " :: String - titleF = padLeftF 30 ' ' titleExt - in fmtLn (titleF+|buildResult ts|+" ms") - -isLogRequestStart :: ApiLog -> Bool -isLogRequestStart = \case - ApiLog _ LogRequestStart -> True - _ -> False - -isLogRequestFinish :: ApiLog -> Bool -isLogRequestFinish = \case - ApiLog _ LogRequestFinish -> True - _ -> False - -measureApiLogs - :: TVar [LogObject ApiLog] -- ^ Log message variable. - -> IO a -- ^ Action to run - -> IO [NominalDiffTime] -measureApiLogs = measureLatency isLogRequestStart isLogRequestFinish - --- | Run tests for at least this long to get accurate timings. -sampleTimeSeconds :: Int -sampleTimeSeconds = 5 - --- | Run tests for at least this long to get accurate timings. -sampleNTimes :: Int -sampleNTimes = 10 - --- | Measure how long an action takes based on trace points and taking an --- average of results over a short time period. -measureLatency - :: (msg -> Bool) -- ^ Predicate for start message - -> (msg -> Bool) -- ^ Predicate for end message - -> TVar [LogObject msg] -- ^ Log message variable. - -> IO a -- ^ Action to run - -> IO [NominalDiffTime] -measureLatency start finish tvar action = do - atomically $ writeTVar tvar [] - replicateM_ sampleNTimes action - extractTimings start finish . reverse <$> readTVarIO tvar - --- | Scan through iohk-monitoring logs and extract time differences between --- start and end messages. -extractTimings - :: (a -> Bool) -- ^ Predicate for start message - -> (a -> Bool) -- ^ Predicate for end message - -> [LogObject a] -- ^ Log messages - -> [NominalDiffTime] -extractTimings isStart isFinish msgs = map2 mkDiff filtered - where - map2 _ [] = [] - map2 f (a:b:xs) = (f a b:map2 f xs) - map2 _ _ = error "start trace without matching finish trace" - - mkDiff (False, start) (True, finish) = diffUTCTime finish start - mkDiff (False, _) _ = error "missing finish trace" - mkDiff (True, _) _ = error "missing start trace" - - filtered = mapMaybe filterMsg msgs - filterMsg logObj = case loContent logObj of - LogMessage msg | isStart msg -> Just (False, getTimestamp logObj) - LogMessage msg | isFinish msg -> Just (True, getTimestamp logObj) - _ -> Nothing - getTimestamp = tstamp . loMeta - -withLatencyLogging - ::(Tracers IO -> TVar [LogObject ApiLog] -> IO a) - -> IO a -withLatencyLogging action = do - tvar <- newTVarIO [] - cfg <- defaultConfigStdout - CM.setMinSeverity cfg Debug - bracket (setupTrace_ cfg "bench-latency") (shutdown . snd) $ \(_, sb) -> do - action (setupTracers tvar) tvar `onException` do - fmtLn "Action failed. Here are the captured logs:" - readTVarIO tvar >>= mapM_ (effectuate sb) . reverse - -setupTracers :: TVar [LogObject ApiLog] -> Tracers IO -setupTracers tvar = nullTracers - { apiServerTracer = trMessage $ contramap snd (traceInTVarIO tvar) } - -benchWithServer +benchWithByronServer :: Tracers IO -> (Context Byron -> IO ()) -> IO () -benchWithServer tracers action = do +benchWithByronServer tracers action = do ctx <- newEmptyMVar let setupContext np wAddr = do let baseUrl = "http://" <> T.pack (show wAddr) <> "/" @@ -464,11 +383,3 @@ benchWithServer tracers action = do block0 (gp, vData) (act gp) - -instance ToJSON ApiLog where - toJSON = toJSON . toText - -instance FromJSON ApiLog where - parseJSON _ = fail "FromJSON ApiLog stub" - -instance ToObject ApiLog diff --git a/lib/byron/cardano-wallet-byron.cabal b/lib/byron/cardano-wallet-byron.cabal index e58d3424035..a604c0723d7 100644 --- a/lib/byron/cardano-wallet-byron.cabal +++ b/lib/byron/cardano-wallet-byron.cabal @@ -277,8 +277,6 @@ benchmark latency , stm , temporary , text - , text-class - , time build-tools: cardano-wallet-byron type: diff --git a/lib/core-integration/cardano-wallet-core-integration.cabal b/lib/core-integration/cardano-wallet-core-integration.cabal index 525fae49e31..d7d7cbfd84d 100644 --- a/lib/core-integration/cardano-wallet-core-integration.cabal +++ b/lib/core-integration/cardano-wallet-core-integration.cabal @@ -47,16 +47,19 @@ library , directory , exceptions , extra + , fmt , generic-lens , hspec , hspec-expectations-lifted , http-api-data , http-client , http-types + , iohk-monitoring , memory , process , retry , scrypt + , stm , template-haskell , text , text-class @@ -92,3 +95,4 @@ library Test.Integration.Scenario.CLI.Network Test.Integration.Scenario.CLI.Port Cardano.Wallet.TransactionSpecShared + Cardano.Wallet.LatencyBenchShared diff --git a/lib/core-integration/src/Cardano/Wallet/LatencyBenchShared.hs b/lib/core-integration/src/Cardano/Wallet/LatencyBenchShared.hs new file mode 100644 index 00000000000..aff01b321c8 --- /dev/null +++ b/lib/core-integration/src/Cardano/Wallet/LatencyBenchShared.hs @@ -0,0 +1,143 @@ +{-# LANGUAGE DataKinds #-} +{-# LANGUAGE FlexibleContexts #-} +{-# LANGUAGE LambdaCase #-} +{-# LANGUAGE OverloadedLabels #-} +{-# LANGUAGE ScopedTypeVariables #-} +{-# LANGUAGE TypeFamilies #-} +{-# LANGUAGE TypeOperators #-} + +module Cardano.Wallet.LatencyBenchShared + ( -- * Measuring traces + withLatencyLogging + , measureApiLogs + , LogCaptureFunc + + -- * Formatting results + , fmtResult + , fmtTitle + ) where + +import Prelude + +import Cardano.BM.Backend.Switchboard + ( effectuate ) +import Cardano.BM.Configuration.Static + ( defaultConfigStdout ) +import Cardano.BM.Data.LogItem + ( LOContent (..), LOMeta (..), LogObject (..) ) +import Cardano.BM.Data.Severity + ( Severity (..) ) +import Cardano.BM.Setup + ( setupTrace_, shutdown ) +import Control.Concurrent.STM.TVar + ( TVar, newTVarIO, readTVarIO, writeTVar ) +import Control.Exception + ( bracket, onException ) +import Control.Monad + ( mapM_, replicateM_ ) +import Control.Monad.STM + ( atomically ) +import Data.Maybe + ( mapMaybe ) +import Data.Time + ( NominalDiffTime ) +import Data.Time.Clock + ( diffUTCTime ) +import Fmt + ( Builder, build, fixedF, fmt, fmtLn, indentF, padLeftF, (+|), (|+) ) +import Network.Wai.Middleware.Logging + ( ApiLog (..), HandlerLog (..) ) + +import qualified Cardano.BM.Configuration.Model as CM + +meanAvg :: [NominalDiffTime] -> Double +meanAvg ts = sum (map realToFrac ts) * 1000 / fromIntegral (length ts) + +buildResult :: [NominalDiffTime] -> Builder +buildResult [] = "ERR" +buildResult ts = build $ fixedF 1 $ meanAvg ts + +fmtTitle :: Builder -> IO () +fmtTitle title = fmt (indentF 4 title) + +fmtResult :: String -> [NominalDiffTime] -> IO () +fmtResult title ts = + let titleExt = title|+" - " :: String + titleF = padLeftF 30 ' ' titleExt + in fmtLn (titleF+|buildResult ts|+" ms") + +isLogRequestStart :: ApiLog -> Bool +isLogRequestStart = \case + ApiLog _ LogRequestStart -> True + _ -> False + +isLogRequestFinish :: ApiLog -> Bool +isLogRequestFinish = \case + ApiLog _ LogRequestFinish -> True + _ -> False + +measureApiLogs :: LogCaptureFunc ApiLog () -> IO a -> IO [NominalDiffTime] +measureApiLogs = measureLatency isLogRequestStart isLogRequestFinish + +-- | Run tests for at least this long to get accurate timings. +sampleNTimes :: Int +sampleNTimes = 10 + +-- | Measure how long an action takes based on trace points and taking an +-- average of results over a short time period. +measureLatency + :: (msg -> Bool) -- ^ Predicate for start message + -> (msg -> Bool) -- ^ Predicate for end message + -> LogCaptureFunc msg () -- ^ Log capture function. + -> IO a -- ^ Action to run + -> IO [NominalDiffTime] +measureLatency start finish capture action = do + (logs, ()) <- capture $ replicateM_ sampleNTimes action + pure $ extractTimings start finish logs + +-- | Scan through iohk-monitoring logs and extract time differences between +-- start and end messages. +extractTimings + :: (a -> Bool) -- ^ Predicate for start message + -> (a -> Bool) -- ^ Predicate for end message + -> [LogObject a] -- ^ Log messages + -> [NominalDiffTime] +extractTimings isStart isFinish msgs = map2 mkDiff filtered + where + map2 _ [] = [] + map2 f (a:b:xs) = (f a b:map2 f xs) + map2 _ _ = error "start trace without matching finish trace" + + mkDiff (False, start) (True, finish) = diffUTCTime finish start + mkDiff (False, _) _ = error "missing finish trace" + mkDiff (True, _) _ = error "missing start trace" + + filtered = mapMaybe filterMsg msgs + filterMsg logObj = case loContent logObj of + LogMessage msg | isStart msg -> Just (False, getTimestamp logObj) + LogMessage msg | isFinish msg -> Just (True, getTimestamp logObj) + _ -> Nothing + getTimestamp = tstamp . loMeta + + +type LogCaptureFunc msg b = IO b -> IO ([LogObject msg], b) + +withLatencyLogging + :: (TVar [LogObject ApiLog] -> tracers) + -> (tracers -> LogCaptureFunc ApiLog b -> IO a) + -> IO a +withLatencyLogging setupTracers action = do + tvar <- newTVarIO [] + cfg <- defaultConfigStdout + CM.setMinSeverity cfg Debug + bracket (setupTrace_ cfg "bench-latency") (shutdown . snd) $ \(_, sb) -> do + action (setupTracers tvar) (logCaptureFunc tvar) `onException` do + fmtLn "Action failed. Here are the captured logs:" + readTVarIO tvar >>= mapM_ (effectuate sb) . reverse + +logCaptureFunc :: TVar [LogObject ApiLog] -> LogCaptureFunc ApiLog b +logCaptureFunc tvar action = do + atomically $ writeTVar tvar [] + res <- action + logs <- readTVarIO tvar + pure (reverse logs, res) diff --git a/lib/core/src/Network/Wai/Middleware/Logging.hs b/lib/core/src/Network/Wai/Middleware/Logging.hs index fa1feba181a..fefffcece01 100644 --- a/lib/core/src/Network/Wai/Middleware/Logging.hs +++ b/lib/core/src/Network/Wai/Middleware/Logging.hs @@ -1,3 +1,4 @@ +{-# LANGUAGE DeriveAnyClass #-} {-# LANGUAGE DeriveGeneric #-} {-# LANGUAGE FlexibleInstances #-} {-# LANGUAGE LambdaCase #-} @@ -30,6 +31,8 @@ import Cardano.BM.Data.Severity ( Severity (..) ) import Cardano.BM.Data.Tracer ( HasPrivacyAnnotation (..), HasSeverityAnnotation (..) ) +import Cardano.BM.Tracing + ( ToObject ) import Control.Applicative ( (<|>) ) import Control.Arrow @@ -39,7 +42,7 @@ import Control.Concurrent.MVar import Control.Tracer ( Tracer, contramap, traceWith ) import Data.Aeson - ( Value (..) ) + ( FromJSON (..), ToJSON (..), Value (..) ) import Data.ByteString ( ByteString ) import Data.ByteString.Builder @@ -117,7 +120,7 @@ data ApiLoggerSettings = ApiLoggerSettings -- | Just a wrapper for readability newtype RequestId = RequestId Integer - deriving (Generic, Show, Eq) + deriving (Generic, Show, Eq, ToJSON) -- | Create a new opaque 'ApiLoggerSettings' newApiLoggerSettings :: IO ApiLoggerSettings @@ -216,7 +219,7 @@ data ApiLog = ApiLog -- ^ Unique integer associated with the request, for the purpose of tracing. , logMsg :: HandlerLog -- ^ Event trace for the handler. - } deriving (Generic, Show) + } deriving (Generic, Show, ToJSON) instance HasPrivacyAnnotation ApiLog where getPrivacyAnnotation (ApiLog _ msg) = getPrivacyAnnotation msg @@ -229,6 +232,11 @@ instance ToText ApiLog where "[" <> T.pack (show rid) <> "] " <> toText msg +-- These instance are required by iohk-monitoring +instance ToObject ApiLog +instance FromJSON ApiLog where + parseJSON _ = fail "FromJSON ApiLog stub" + -- | Tracer events related to the handling of a single request. data HandlerLog = LogRequestStart @@ -257,6 +265,9 @@ instance ToText HandlerLog where LogResponseBody body -> T.decodeUtf8 body LogRequestFinish -> "Completed response to API request" +instance ToJSON HandlerLog where + toJSON = String . toText + -- | Removes sensitive details from valid request payloads and completely -- obfuscate invalid payloads. sanitize :: [Text] -> ByteString -> Text diff --git a/lib/jormungandr/cardano-wallet-jormungandr.cabal b/lib/jormungandr/cardano-wallet-jormungandr.cabal index d939c6ccacc..55aa9f6cc04 100644 --- a/lib/jormungandr/cardano-wallet-jormungandr.cabal +++ b/lib/jormungandr/cardano-wallet-jormungandr.cabal @@ -312,8 +312,6 @@ benchmark latency , stm , temporary , text - , text-class - , time build-tools: cardano-wallet-jormungandr type: diff --git a/lib/jormungandr/test/bench/Latency.hs b/lib/jormungandr/test/bench/Latency.hs index 617760db354..8bd6c2d728f 100644 --- a/lib/jormungandr/test/bench/Latency.hs +++ b/lib/jormungandr/test/bench/Latency.hs @@ -17,18 +17,10 @@ module Main import Prelude -import Cardano.BM.Backend.Switchboard - ( effectuate ) -import Cardano.BM.Configuration.Static - ( defaultConfigStdout ) import Cardano.BM.Data.LogItem - ( LOContent (..), LOMeta (..), LogObject (..) ) -import Cardano.BM.Data.Severity - ( Severity (..) ) + ( LogObject (..) ) import Cardano.BM.Data.Tracer - ( ToObject (..), contramap ) -import Cardano.BM.Setup - ( setupTrace_, shutdown ) + ( contramap ) import Cardano.BM.Trace ( traceInTVarIO ) import Cardano.CLI @@ -59,6 +51,8 @@ import Cardano.Wallet.Jormungandr.Launch ( withConfig ) import Cardano.Wallet.Jormungandr.Network ( JormungandrBackend (..) ) +import Cardano.Wallet.LatencyBenchShared + ( LogCaptureFunc, fmtResult, measureApiLogs, withLatencyLogging ) import Cardano.Wallet.Logging ( trMessage ) import Cardano.Wallet.Network.Ports @@ -76,33 +70,23 @@ import Control.Concurrent.Async import Control.Concurrent.MVar ( newEmptyMVar, putMVar, takeMVar ) import Control.Concurrent.STM.TVar - ( TVar, newTVarIO, readTVarIO, writeTVar ) + ( TVar ) import Control.Exception - ( bracket, onException, throwIO ) + ( throwIO ) import Control.Monad ( mapM_, replicateM, replicateM_ ) -import Control.Monad.STM - ( atomically ) import Data.Aeson - ( FromJSON (..), ToJSON (..), Value ) + ( Value ) import Data.Aeson.QQ ( aesonQQ ) import Data.Generics.Internal.VL.Lens ( (^.) ) -import Data.Maybe - ( mapMaybe ) import Data.Proxy ( Proxy (..) ) import Data.Text ( Text ) -import Data.Text.Class - ( toText ) -import Data.Time - ( NominalDiffTime ) -import Data.Time.Clock - ( diffUTCTime ) import Fmt - ( Builder, build, fixedF, fmtLn, padLeftF, (+|), (|+) ) + ( fmtLn ) import Network.HTTP.Client ( defaultManagerSettings , managerResponseTimeout @@ -110,7 +94,7 @@ import Network.HTTP.Client , responseTimeoutMicro ) import Network.Wai.Middleware.Logging - ( ApiLog (..), HandlerLog (..) ) + ( ApiLog (..) ) import Numeric.Natural ( Natural ) import Test.Hspec @@ -133,55 +117,66 @@ import Test.Integration.Framework.DSL , verify ) -import qualified Cardano.BM.Configuration.Model as CM import qualified Cardano.Wallet.Api.Link as Link import qualified Data.Text as T import qualified Network.HTTP.Types.Status as HTTP main :: forall t n. (t ~ Jormungandr, n ~ 'Testnet 0) => IO () -main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> do - +main = withUtf8Encoding $ + withLatencyLogging setupTracers $ \tracers capture -> + walletApiBench @t @n capture (benchWithJormServer tracers) + where + setupTracers :: TVar [LogObject ApiLog] -> Tracers IO + setupTracers tvar = nullTracers + { apiServerTracer = trMessage $ contramap snd (traceInTVarIO tvar) } + +walletApiBench + :: forall t (n :: NetworkDiscriminant). (t ~ Jormungandr, n ~ 'Testnet 0) + => LogCaptureFunc ApiLog () + -> ((Context t -> IO ()) -> IO ()) + -> IO () +walletApiBench capture benchWithServer = do fmtLn "Non-cached run" - runBareScenario logging tvar + runWarmUpScenario fmtLn "Latencies for 2 fixture wallets scenario" - runScenario logging tvar (nFixtureWallet 2) + runScenario (nFixtureWallet 2) fmtLn "Latencies for 10 fixture wallets scenario" - runScenario logging tvar (nFixtureWallet 10) + runScenario (nFixtureWallet 10) fmtLn "Latencies for 100 fixture wallets scenario" - runScenario logging tvar (nFixtureWallet 100) + runScenario (nFixtureWallet 100) fmtLn "Latencies for 2 fixture wallets with 10 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 2 10) + runScenario (nFixtureWalletWithTxs 2 10) fmtLn "Latencies for 2 fixture wallets with 20 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 2 20) + runScenario (nFixtureWalletWithTxs 2 20) fmtLn "Latencies for 2 fixture wallets with 100 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 2 100) + runScenario (nFixtureWalletWithTxs 2 100) fmtLn "Latencies for 10 fixture wallets with 10 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 10 10) + runScenario (nFixtureWalletWithTxs 10 10) fmtLn "Latencies for 10 fixture wallets with 20 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 10 20) + runScenario (nFixtureWalletWithTxs 10 20) fmtLn "Latencies for 10 fixture wallets with 100 txs scenario" - runScenario logging tvar (nFixtureWalletWithTxs 10 100) + runScenario (nFixtureWalletWithTxs 10 100) fmtLn "Latencies for 2 fixture wallets with 100 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 1) + runScenario (nFixtureWalletWithUTxOs 2 1) fmtLn "Latencies for 2 fixture wallets with 200 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 2) + runScenario (nFixtureWalletWithUTxOs 2 2) fmtLn "Latencies for 2 fixture wallets with 500 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 5) + runScenario (nFixtureWalletWithUTxOs 2 5) fmtLn "Latencies for 2 fixture wallets with 1000 utxos scenario" - runScenario logging tvar (nFixtureWalletWithUTxOs 2 10) + runScenario (nFixtureWalletWithUTxOs 2 10) where -- Creates n fixture wallets and return two of them nFixtureWallet n ctx = do @@ -315,30 +310,30 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> do expectResponseCode HTTP.status202 r return () - runScenario logging tvar scenario = benchWithServer logging $ \ctx -> do + runScenario scenario = benchWithServer $ \ctx -> do (wal1, wal2) <- scenario ctx - t1 <- measureApiLogs tvar + t1 <- measureApiLogs capture (request @[ApiWallet] ctx (Link.listWallets @'Shelley) Default Empty) fmtResult "listWallets " t1 - t2 <- measureApiLogs tvar + t2 <- measureApiLogs capture (request @ApiWallet ctx (Link.getWallet @'Shelley wal1) Default Empty) fmtResult "getWallet " t2 - t3 <- measureApiLogs tvar + t3 <- measureApiLogs capture (request @ApiUtxoStatistics ctx (Link.getUTxOsStatistics @'Shelley wal1) Default Empty) fmtResult "getUTxOsStatistics " t3 - t4 <- measureApiLogs tvar + t4 <- measureApiLogs capture (request @[ApiAddress n] ctx (Link.listAddresses @'Shelley wal1) Default Empty) fmtResult "listAddresses " t4 - t5 <- measureApiLogs tvar + t5 <- measureApiLogs capture (request @[ApiTransaction n] ctx (Link.listTransactions @'Shelley wal1) Default Empty) fmtResult "listTransactions " t5 @@ -355,122 +350,36 @@ main = withUtf8Encoding $ withLatencyLogging $ \logging tvar -> do } }] }|] - t6 <- measureApiLogs tvar $ request @ApiFee ctx + t6 <- measureApiLogs capture $ request @ApiFee ctx (Link.getTransactionFee @'Shelley wal1) Default payload fmtResult "postTransactionFee " t6 - t7 <- measureApiLogs tvar $ request @[ApiStakePool] ctx + t7 <- measureApiLogs capture $ request @[ApiStakePool] ctx Link.listJormungandrStakePools Default Empty fmtResult "listStakePools " t7 - t8 <- measureApiLogs tvar $ request @ApiNetworkInformation ctx + t8 <- measureApiLogs capture $ request @ApiNetworkInformation ctx Link.getNetworkInfo Default Empty fmtResult "getNetworkInfo " t8 pure () - runBareScenario logging tvar = benchWithServer logging $ \ctx -> do + runWarmUpScenario = benchWithServer $ \ctx -> do -- this one is to have comparable results from first to last measurement -- in runScenario - t <- measureApiLogs tvar $ request @ApiNetworkInformation ctx + t <- measureApiLogs capture $ request @ApiNetworkInformation ctx Link.getNetworkInfo Default Empty fmtResult "getNetworkInfo " t pure () -meanAvg :: [NominalDiffTime] -> Double -meanAvg ts = sum (map realToFrac ts) * 1000 / fromIntegral (length ts) - -buildResult :: [NominalDiffTime] -> Builder -buildResult [] = "ERR" -buildResult ts = build $ fixedF 1 $ meanAvg ts - -fmtResult :: String -> [NominalDiffTime] -> IO () -fmtResult title ts = - let titleExt = title|+" - " :: String - titleF = padLeftF 25 ' ' titleExt - in fmtLn (titleF+|buildResult ts|+" ms") - -isLogRequestStart :: ApiLog -> Bool -isLogRequestStart = \case - ApiLog _ LogRequestStart -> True - _ -> False - -isLogRequestFinish :: ApiLog -> Bool -isLogRequestFinish = \case - ApiLog _ LogRequestFinish -> True - _ -> False - -measureApiLogs - :: TVar [LogObject ApiLog] -- ^ Log message variable. - -> IO a -- ^ Action to run - -> IO [NominalDiffTime] -measureApiLogs = measureLatency isLogRequestStart isLogRequestFinish - --- | Run tests for at least this long to get accurate timings. -sampleNTimes :: Int -sampleNTimes = 10 - --- | Measure how long an action takes based on trace points and taking an --- average of results over a short time period. -measureLatency - :: (msg -> Bool) -- ^ Predicate for start message - -> (msg -> Bool) -- ^ Predicate for end message - -> TVar [LogObject msg] -- ^ Log message variable. - -> IO a -- ^ Action to run - -> IO [NominalDiffTime] -measureLatency start finish tvar action = do - atomically $ writeTVar tvar [] - replicateM_ sampleNTimes action - extractTimings start finish . reverse <$> readTVarIO tvar - --- | Scan through iohk-monitoring logs and extract time differences between --- start and end messages. -extractTimings - :: (a -> Bool) -- ^ Predicate for start message - -> (a -> Bool) -- ^ Predicate for end message - -> [LogObject a] -- ^ Log messages - -> [NominalDiffTime] -extractTimings isStart isFinish msgs = map2 mkDiff filtered - where - map2 _ [] = [] - map2 f (a:b:xs) = (f a b:map2 f xs) - map2 _ _ = error "start trace without matching finish trace" - - mkDiff (False, start) (True, finish) = diffUTCTime finish start - mkDiff (False, _) _ = error "missing finish trace" - mkDiff (True, _) _ = error "missing start trace" - - filtered = mapMaybe filterMsg msgs - filterMsg logObj = case loContent logObj of - LogMessage msg | isStart msg -> Just (False, getTimestamp logObj) - LogMessage msg | isFinish msg -> Just (True, getTimestamp logObj) - _ -> Nothing - getTimestamp = tstamp . loMeta - -withLatencyLogging - ::(Tracers IO -> TVar [LogObject ApiLog] -> IO a) - -> IO a -withLatencyLogging action = do - tvar <- newTVarIO [] - cfg <- defaultConfigStdout - CM.setMinSeverity cfg Debug - bracket (setupTrace_ cfg "bench-latency") (shutdown . snd) $ \(_, sb) -> do - action (setupTracers tvar) tvar `onException` do - fmtLn "Action failed. Here are the captured logs:" - readTVarIO tvar >>= mapM_ (effectuate sb) . reverse - -setupTracers :: TVar [LogObject ApiLog] -> Tracers IO -setupTracers tvar = nullTracers - { apiServerTracer = trMessage $ contramap snd (traceInTVarIO tvar) } - -benchWithServer +benchWithJormServer :: Tracers IO -> (Context Jormungandr -> IO ()) -> IO () -benchWithServer tracers action = withConfig $ \jmCfg -> do +benchWithJormServer tracers action = withConfig $ \jmCfg -> do ctx <- newEmptyMVar race_ (takeMVar ctx >>= action) $ do res <- serveWallet @('Testnet 0) @@ -497,11 +406,3 @@ benchWithServer tracers action = withConfig $ \jmCfg -> do , _target = Proxy } throwIO $ ProcessHasExited "Server has unexpectedly exited" res - -instance ToJSON ApiLog where - toJSON = toJSON . toText - -instance FromJSON ApiLog where - parseJSON _ = fail "FromJSON ApiLog stub" - -instance ToObject ApiLog diff --git a/nix/.stack.nix/cardano-wallet-byron.nix b/nix/.stack.nix/cardano-wallet-byron.nix index 7cb8831b931..dac8e6320c0 100644 --- a/nix/.stack.nix/cardano-wallet-byron.nix +++ b/nix/.stack.nix/cardano-wallet-byron.nix @@ -198,8 +198,6 @@ (hsPkgs."stm" or (errorHandler.buildDepError "stm")) (hsPkgs."temporary" or (errorHandler.buildDepError "temporary")) (hsPkgs."text" or (errorHandler.buildDepError "text")) - (hsPkgs."text-class" or (errorHandler.buildDepError "text-class")) - (hsPkgs."time" or (errorHandler.buildDepError "time")) ]; build-tools = [ (hsPkgs.buildPackages.cardano-wallet-byron or (pkgs.buildPackages.cardano-wallet-byron or (errorHandler.buildToolDepError "cardano-wallet-byron"))) diff --git a/nix/.stack.nix/cardano-wallet-core-integration.nix b/nix/.stack.nix/cardano-wallet-core-integration.nix index 3c9d20b60e8..967647642b8 100644 --- a/nix/.stack.nix/cardano-wallet-core-integration.nix +++ b/nix/.stack.nix/cardano-wallet-core-integration.nix @@ -47,16 +47,19 @@ (hsPkgs."directory" or (errorHandler.buildDepError "directory")) (hsPkgs."exceptions" or (errorHandler.buildDepError "exceptions")) (hsPkgs."extra" or (errorHandler.buildDepError "extra")) + (hsPkgs."fmt" or (errorHandler.buildDepError "fmt")) (hsPkgs."generic-lens" or (errorHandler.buildDepError "generic-lens")) (hsPkgs."hspec" or (errorHandler.buildDepError "hspec")) (hsPkgs."hspec-expectations-lifted" or (errorHandler.buildDepError "hspec-expectations-lifted")) (hsPkgs."http-api-data" or (errorHandler.buildDepError "http-api-data")) (hsPkgs."http-client" or (errorHandler.buildDepError "http-client")) (hsPkgs."http-types" or (errorHandler.buildDepError "http-types")) + (hsPkgs."iohk-monitoring" or (errorHandler.buildDepError "iohk-monitoring")) (hsPkgs."memory" or (errorHandler.buildDepError "memory")) (hsPkgs."process" or (errorHandler.buildDepError "process")) (hsPkgs."retry" or (errorHandler.buildDepError "retry")) (hsPkgs."scrypt" or (errorHandler.buildDepError "scrypt")) + (hsPkgs."stm" or (errorHandler.buildDepError "stm")) (hsPkgs."template-haskell" or (errorHandler.buildDepError "template-haskell")) (hsPkgs."text" or (errorHandler.buildDepError "text")) (hsPkgs."text-class" or (errorHandler.buildDepError "text-class")) diff --git a/nix/.stack.nix/cardano-wallet-jormungandr.nix b/nix/.stack.nix/cardano-wallet-jormungandr.nix index 2b55bcb28d9..3109b254eb6 100644 --- a/nix/.stack.nix/cardano-wallet-jormungandr.nix +++ b/nix/.stack.nix/cardano-wallet-jormungandr.nix @@ -245,8 +245,6 @@ (hsPkgs."stm" or (errorHandler.buildDepError "stm")) (hsPkgs."temporary" or (errorHandler.buildDepError "temporary")) (hsPkgs."text" or (errorHandler.buildDepError "text")) - (hsPkgs."text-class" or (errorHandler.buildDepError "text-class")) - (hsPkgs."time" or (errorHandler.buildDepError "time")) ]; build-tools = [ (hsPkgs.buildPackages.cardano-wallet-jormungandr or (pkgs.buildPackages.cardano-wallet-jormungandr or (errorHandler.buildToolDepError "cardano-wallet-jormungandr")))