Skip to content

Commit

Permalink
Add counter emitter and golden tests for profiling.
Browse files Browse the repository at this point in the history
  • Loading branch information
thealmarty committed Sep 16, 2021
1 parent 0f152db commit fda50f6
Show file tree
Hide file tree
Showing 15 changed files with 243 additions and 8 deletions.
27 changes: 26 additions & 1 deletion plutus-core/common/PlcTestUtils.hs
Expand Up @@ -16,6 +16,7 @@ module PlcTestUtils (
rethrow,
runTPlc,
runUPlc,
runUPlcFlamegraph,
goldenTPlc,
goldenTPlcCatch,
goldenUPlc,
Expand All @@ -24,6 +25,7 @@ module PlcTestUtils (
goldenUEval,
goldenTEvalCatch,
goldenUEvalCatch,
goldenUEvalProfile,
NoMarkRenameT(..),
noMarkRename,
NoRenameT(..),
Expand Down Expand Up @@ -53,9 +55,10 @@ import qualified PlutusCore.Rename.Monad as TPLC

import qualified UntypedPlutusCore as UPLC
import qualified UntypedPlutusCore.Evaluation.Machine.Cek as UPLC
import UntypedPlutusCore.Evaluation.Machine.Cek.EmitterMode (logWithTimeEmitter)
import UntypedPlutusCore.Evaluation.Machine.Cek.EmitterMode (logWithCounter, logWithTimeEmitter)

import Control.Exception
import Control.Lens.Combinators (_2)
import Control.Monad.Except
import Control.Monad.Reader
import Control.Monad.State
Expand Down Expand Up @@ -139,19 +142,35 @@ runUPlc values = do
let (UPLC.Program _ _ t) = foldl1 UPLC.applyProgram ps
liftEither $ first toException $ TPLC.extractEvaluationResult $ UPLC.evaluateCekNoEmit TPLC.defaultCekParameters t

-- For golden tests of profiling.
runUPlcProfile :: ToUPlc a DefaultUni UPLC.DefaultFun =>
[a]
-> ExceptT
SomeException
IO
(UPLC.Term UPLC.Name DefaultUni UPLC.DefaultFun (), [Text])
runUPlcProfile values = do
ps <- traverse toUPlc values
let (UPLC.Program _ _ t) = foldl1 UPLC.applyProgram ps
(result, logOut) = UPLC.evaluateCek logWithCounter TPLC.defaultCekParameters t
res <- either (throwError . SomeException) pure result
pure (res, logOut)

-- For golden tests of profiling.
runUPlcFlamegraph :: ToUPlc a DefaultUni UPLC.DefaultFun =>
[a]
-> ExceptT
SomeException
IO
(UPLC.Term UPLC.Name DefaultUni UPLC.DefaultFun (), [Text])
runUPlcFlamegraph values = do
ps <- traverse toUPlc values
let (UPLC.Program _ _ t) = foldl1 UPLC.applyProgram ps
(result, logOut) = UPLC.evaluateCek logWithTimeEmitter TPLC.defaultCekParameters t
res <- either (throwError . SomeException) pure result
pure (res, logOut)


ppCatch :: PrettyPlc a => ExceptT SomeException IO a -> IO (Doc ann)
ppCatch value = either (PP.pretty . show) prettyPlcClassicDebug <$> runExceptT value

Expand Down Expand Up @@ -206,6 +225,12 @@ goldenUEvalCatch
=> String -> [a] -> TestNested
goldenUEvalCatch name values = nestedGoldenVsDocM name $ ppCatch $ runUPlc values

-- | Similar to @goldenUEval@ but with profiling turned on.
goldenUEvalProfile
:: ToUPlc a DefaultUni TPLC.DefaultFun
=> String -> [a] -> TestNested
goldenUEvalProfile name values = nestedGoldenVsDocM name $ pretty . view _2 <$> (rethrow $ runUPlcProfile values)

-- See Note [Marking].
-- | A version of 'RenameT' that fails to take free variables into account.
newtype NoMarkRenameT ren m a = NoMarkRenameT
Expand Down
@@ -1,27 +1,32 @@
{-# LANGUAGE OverloadedStrings #-}

module UntypedPlutusCore.Evaluation.Machine.Cek.EmitterMode (noEmitter, logEmitter, logWithTimeEmitter) where
module UntypedPlutusCore.Evaluation.Machine.Cek.EmitterMode (
noEmitter,
logEmitter,
logWithTimeEmitter,
logWithCounter
) where

import UntypedPlutusCore.Evaluation.Machine.Cek.Internal

import Control.Monad.ST.Unsafe (unsafeIOToST)
import qualified Data.DList as DList
import Data.STRef (modifySTRef, newSTRef, readSTRef)
import Data.STRef (modifySTRef, newSTRef, readSTRef, writeSTRef)
import Data.Text (pack)
import Data.Time.Clock (getCurrentTime)

-- | Emitter for when @EmitterOption@ is @NoEmit@.
-- | No emitter.
noEmitter :: EmitterMode uni fun
noEmitter = EmitterMode $ pure $ CekEmitterInfo (\_ -> pure ()) (pure mempty)

-- | Emitter for when @EmitterOption@ is @Emit@. Emits log but not timestamp.
-- | Emits log but not timestamp.
logEmitter :: EmitterMode uni fun
logEmitter = EmitterMode $ do
logsRef <- newSTRef DList.empty
let emitter str = CekCarryingM $ modifySTRef logsRef (`DList.snoc` str)
pure $ CekEmitterInfo emitter (DList.toList <$> readSTRef logsRef)

-- | Emitter for when @EmitterOption@ is @EmitWithTimestamp@. Emits log with timestamp.
-- | Emits log with timestamp.
logWithTimeEmitter :: EmitterMode uni fun
logWithTimeEmitter = EmitterMode $ do
logsRef <- newSTRef DList.empty
Expand All @@ -30,3 +35,16 @@ logWithTimeEmitter = EmitterMode $ do
let withTime = "[" <> pack (show time) <> "]" <> " " <> str
modifySTRef logsRef (`DList.snoc` withTime)
pure $ CekEmitterInfo emitter (DList.toList <$> readSTRef logsRef)

-- | Emits log with a counter.
logWithCounter :: EmitterMode uni fun
logWithCounter =
EmitterMode $ do
logsRef <- newSTRef DList.empty
counterRef <- newSTRef (0::Int)
let emitter str = CekCarryingM $ do
counter <- readSTRef counterRef
writeSTRef counterRef (counter + 1)
let withCounter = "[" <> pack (show counter) <> "]" <> " " <> str
modifySTRef logsRef (`DList.snoc` withCounter)
pure $ CekEmitterInfo emitter (DList.toList <$> readSTRef logsRef)
4 changes: 2 additions & 2 deletions plutus-tx-plugin/executables/profile/Main.hs
Expand Up @@ -12,7 +12,7 @@

module Main where
import Common
import PlcTestUtils (ToUPlc (toUPlc), rethrow, runUPlcProfile)
import PlcTestUtils (ToUPlc (toUPlc), rethrow, runUPlcFlamegraph)
import Plugin.Basic.Spec

import qualified PlutusTx.Builtins as Builtins
Expand Down Expand Up @@ -82,7 +82,7 @@ writeLogToFile ::
[a] ->
IO ()
writeLogToFile fileName values = do
log <- pretty . view _2 <$> (rethrow $ runUPlcProfile values)
log <- pretty . view _2 <$> (rethrow $ runUPlcFlamegraph values)
withFile
("plutus-tx-plugin/executables/profile/"<>fileName)
WriteMode
Expand Down
1 change: 1 addition & 0 deletions plutus-tx-plugin/plutus-tx-plugin.cabal
Expand Up @@ -93,6 +93,7 @@ test-suite plutus-tx-tests
Plugin.Functions.Spec
Plugin.Laziness.Spec
Plugin.Primitives.Spec
Plugin.Profiling.Spec
Plugin.Typeclasses.Spec
Plugin.Typeclasses.Lib
Plugin.Lib
Expand Down
2 changes: 2 additions & 0 deletions plutus-tx-plugin/src/PlutusTx/Compiler/Expr.hs
Expand Up @@ -443,6 +443,8 @@ mkTrace ty str v =
(PIR.TyInst () (PIR.Builtin () PLC.Trace) ty)
[PLC.mkConstant () str, v]

-- | Trace inside a term's lambda. I.e., turn
-- @trace (\a b -> body)@ to @\a -> \b -> trace body@.
traceInside ::
PLC.Name
-> PIR.Name
Expand Down
90 changes: 90 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/Spec.hs
@@ -0,0 +1,90 @@
{-# LANGUAGE DataKinds #-}
{-# LANGUAGE FlexibleContexts #-}
{-# LANGUAGE OverloadedStrings #-}
{-# LANGUAGE ScopedTypeVariables #-}
{-# LANGUAGE TypeApplications #-}
{-# OPTIONS_GHC -fplugin PlutusTx.Plugin #-}
{-# OPTIONS_GHC -fplugin-opt PlutusTx.Plugin:defer-errors #-}
{-# OPTIONS_GHC -fplugin-opt PlutusTx.Plugin:debug-context #-}
{-# OPTIONS_GHC -fplugin-opt PlutusTx.Plugin:profile-all #-}

-- | Tests for the profiling machinery.

module Plugin.Profiling.Spec where
import Common
import Lib (goldenPir)
import PlcTestUtils (ToUPlc (toUPlc), goldenUEvalProfile, rethrow, runUPlcProfile)
import Plugin.Basic.Spec
import Plugin.Lib (MyExternalRecord (myExternal), andExternal, evenDirect)

import Plugin.Data.Spec
import Plugin.Functions.Spec hiding (fib, recursiveFunctions)
import Plugin.Typeclasses.Spec
import qualified PlutusCore.Default as PLC
import qualified PlutusTx.Builtins as Builtins
import PlutusTx.Code (CompiledCode)
import PlutusTx.Plugin (plc)

import Control.Lens.Combinators (_2)
import Control.Lens.Getter (view)
import Data.Proxy
import Data.Text (Text)
import Prettyprinter.Internal (pretty)
import Prettyprinter.Render.Text (hPutDoc)
import System.IO (IOMode (WriteMode), withFile)

profiling :: TestNested
profiling = testNested "Profiling" [
goldenUEvalProfile "fib" [toUPlc fibTest]
, goldenUEvalProfile "fib4" [toUPlc fibTest, toUPlc $ plc (Proxy @"4") (4::Integer)]
, goldenUEvalProfile "addInt" [toUPlc addIntTest]
, goldenUEvalProfile "addInt3" [toUPlc addIntTest, toUPlc $ plc (Proxy @"3") (3::Integer)]
, goldenUEvalProfile "letInFun" [toUPlc letInFunTest, toUPlc $ plc (Proxy @"1") (1::Integer), toUPlc $ plc (Proxy @"4") (4::Integer)]
, goldenUEvalProfile "letInFunMoreArg" [toUPlc letInFunMoreArgTest, toUPlc $ plc (Proxy @"1") (1::Integer), toUPlc $ plc (Proxy @"4") (4::Integer), toUPlc $ plc (Proxy @"5") (5::Integer)]
-- ghc does the function application
, goldenUEvalProfile "id" [toUPlc idTest]
, goldenUEvalProfile "swap" [toUPlc swapTest]
]

fib :: Integer -> Integer
fib n = if Builtins.equalsInteger n 0
then 0
else if Builtins.equalsInteger n 1
then 1
else Builtins.addInteger (fib(Builtins.subtractInteger n 1)) (fib(Builtins.subtractInteger n 2))

fibTest :: CompiledCode (Integer -> Integer)
-- not using case to avoid literal cases
fibTest = plc (Proxy @"fib") fib

addInt :: Integer -> Integer -> Integer
addInt x = Builtins.addInteger x

addIntTest :: CompiledCode (Integer -> Integer -> Integer)
addIntTest = plc (Proxy @"addInt") addInt

-- \x y -> let f z = z + 1 in f x + f y
letInFunTest :: CompiledCode (Integer -> Integer -> Integer)
letInFunTest =
plc
(Proxy @"letInFun")
(\(x::Integer) (y::Integer)
-> let f z = Builtins.addInteger z 1 in Builtins.addInteger (f x) (f y))

-- \x y z -> let f n = n + 1 in z * (f x + f y)
letInFunMoreArgTest :: CompiledCode (Integer -> Integer -> Integer -> Integer)
letInFunMoreArgTest =
plc
(Proxy @"letInFun")
(\(x::Integer) (y::Integer) (z::Integer)
-> let f n = Builtins.addInteger n 1 in
Builtins.multiplyInteger z (Builtins.addInteger (f x) (f y)))

idTest :: CompiledCode Integer
idTest = plc (Proxy @"id") (id (1::Integer))

swap :: (a,b) -> (b,a)
swap (a,b) = (b,a)

swapTest :: CompiledCode (Integer,Bool)
swapTest = plc (Proxy @"swap") (swap (True,1))
2 changes: 2 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/addInt.plc.golden
@@ -0,0 +1,2 @@
[ [0] entering Name {nameString = "addInt", nameUnique = Unique {unUnique = 81}}
, [1] exiting Name {nameString = "addInt", nameUnique = Unique {unUnique = 81}} ]
2 changes: 2 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/addInt3.plc.golden
@@ -0,0 +1,2 @@
[ [0] entering Name {nameString = "addInt", nameUnique = Unique {unUnique = 81}}
, [1] exiting Name {nameString = "addInt", nameUnique = Unique {unUnique = 81}} ]
1 change: 1 addition & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/fib.plc.golden
@@ -0,0 +1 @@
[]
74 changes: 74 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/fib4.plc.golden
@@ -0,0 +1,74 @@
[ [0] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [1] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [2] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [3] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [4] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [5] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [6] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [7] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [8] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [9] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [10] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [11] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [12] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [13] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [14] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [15] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [16] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [17] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [18] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [19] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [20] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [21] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [22] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [23] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [24] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [25] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [26] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [27] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [28] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [29] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [30] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [31] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [32] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [33] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [34] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [35] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [36] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [37] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [38] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [39] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [40] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [41] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [42] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [43] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [44] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [45] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [46] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [47] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [48] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [49] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [50] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [51] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [52] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [53] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [54] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [55] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [56] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [57] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [58] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [59] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [60] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [61] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [62] entering Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [63] exiting Name {nameString = "subtractInteger", nameUnique = Unique {unUnique = 97}}
, [64] entering Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [65] entering Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [66] exiting Name {nameString = "equalsInteger", nameUnique = Unique {unUnique = 87}}
, [67] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [68] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [69] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [70] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}}
, [71] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [72] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 93}}
, [73] exiting Name {nameString = "fib", nameUnique = Unique {unUnique = 81}} ]
2 changes: 2 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/id.plc.golden
@@ -0,0 +1,2 @@
[ [0] entering Name {nameString = "id", nameUnique = Unique {unUnique = 82}}
, [1] exiting Name {nameString = "id", nameUnique = Unique {unUnique = 82}} ]
6 changes: 6 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/letInFun.plc.golden
@@ -0,0 +1,6 @@
[ [0] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 84}}
, [1] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 84}}
, [2] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 84}}
, [3] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 84}}
, [4] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 84}}
, [5] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 84}} ]
@@ -0,0 +1,8 @@
[ [0] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 85}}
, [1] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 85}}
, [2] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 85}}
, [3] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 85}}
, [4] entering Name {nameString = "addInteger", nameUnique = Unique {unUnique = 85}}
, [5] exiting Name {nameString = "addInteger", nameUnique = Unique {unUnique = 85}}
, [6] entering Name {nameString = "multiplyInteger", nameUnique = Unique {unUnique = 90}}
, [7] exiting Name {nameString = "multiplyInteger", nameUnique = Unique {unUnique = 90}} ]
2 changes: 2 additions & 0 deletions plutus-tx-plugin/test/Plugin/Profiling/swap.plc.golden
@@ -0,0 +1,2 @@
[ [0] entering Name {nameString = "swap", nameUnique = Unique {unUnique = 88}}
, [1] exiting Name {nameString = "swap", nameUnique = Unique {unUnique = 88}} ]
2 changes: 2 additions & 0 deletions plutus-tx-plugin/test/Plugin/Spec.hs
Expand Up @@ -10,6 +10,7 @@ import Plugin.Errors.Spec
import Plugin.Functions.Spec
import Plugin.Laziness.Spec
import Plugin.Primitives.Spec
import Plugin.Profiling.Spec
import Plugin.Typeclasses.Spec

tests :: TestNested
Expand All @@ -21,4 +22,5 @@ tests = testNested "Plugin" [
, laziness
, errors
, typeclasses
, profiling
]

0 comments on commit fda50f6

Please sign in to comment.