SCP-2804: budget profiling #4024

michaelpj · 2021-09-29T12:55:24Z

This PR is a bit of a mess, since it goes across a few things.

The first couple of commits do a few things:

Teach all our budget modes to be able to answer the question "how much budget has been spent?". This requires extra book-keeping for some, but not for the restricting budget, which is the one we care about.
Teach the emitter to get a reference to the current budget, so it can print it if it wants. This is a bit ugly, but I can't see a better way (would appreciate thoughts from @effectfully ).
Write an emitter mode that emits budgets with the logs.

Then I wanted to actually get this conveniently, so I dived into the executables. I ended up doing a fair bit of drive-by refactoring (sorry), but the end result is a workflow like this:

Compile your script with dump-plc
Run the script with uplc evaluate --if flat-namedDeBruijn -i ... --trace-mode LogsWithBudgets

Then once we have some log processors we can just pipe it into that.

Pre-submit checklist:

Branch
- Tests are provided (if possible)
- Commit sequence broadly makes sense
- Key commits have useful messages
- Relevant tickets are mentioned in commit messages
- Formatting, materialized Nix files, PNG optimization, etc. are updated
PR
- Self-reviewed the diff
- Useful pull request description
- Reviewer requested

michaelpj · 2021-09-29T12:57:29Z

plutus-core/executables/Common.hs

  let printMethod = getPrintMethod mode
  case outp of
        FileOutput file -> writeFile file . Prelude.show . printMethod $ prog
        StdOutput       -> print . printMethod $ prog

+writeToFileOrStd ::


This is currently still a bit wrong, since it overwrites any previous writes. I want to rewrite this to pass around a handle instead.

michaelpj · 2021-09-29T13:12:39Z

plutus-tx-plugin/test/Plugin/Profiling/addInt.plc.golden

@@ -1 +1,75 @@
-[entering addInt, exiting addInt]


I think these tests were actually meant to show the code that is generated so that we can see whether we're putting things in the right place, but instead they were showing the result of evaluating the (not-fully-applied) functions, which wasn't really showing us anything.

michaelpj · 2021-09-29T13:30:02Z

Hmmm, stylish haskell wants to remove a necessary language extension pragma, despite remove_redundant also being false? weird. Maybe I'll try bumping it.

michaelpj · 2021-09-29T13:34:18Z

Ah, I found the problem: a HLS bug that inserted the pragma in a random place in the file instead of the top, which then confuses stylish.

kwxm · 2021-10-01T04:30:32Z

plutus-core/executables/uplc/Main.hs

@@ -160,45 +165,44 @@ runApply (ApplyOptions inputfiles ifmt outp ofmt mode) = do
 ---------------- Evaluation ----------------

 runEval :: EvalOptions -> IO ()


This function just keeps getting more complicated with all the different branches. I suppose there's not much to be done though, because it has to handle all the different combinations of flags.

Yeah, I tried to make it less complicated, by e.g. handling the budget options once rather than repeatedly, but it's a mess.

kwxm

Looks plausible, although I'd really have to run it to make sure that it's behaving sensibly. We should also run the benchmarks to confirm that it's not affecting the performance in the default mode since there seem to be quite a number of changes in the CEK machine.

kwxm · 2021-10-01T04:50:54Z

plutus-core/executables/uplc/Main.hs

+                        Right v  -> writeToFileOrStd outputMode (show (getPrintMethod printMode v))
+                    case budgetMode of
+                        Silent    -> pure ()
+                        Verbose _ -> printBudgetState t cekModel budget


I think the budget state is always going to stdout, but the other things can be directed to a file instead. Is there likely to be a case where we really want that to happen, ie where we want to see the budget state on the screen but also want to save other info in a file? If that's not the case, would it not be simpler just to write everything to stdout and use shell redirection if we want it to go into a file (or a pipe if we want to feed it to another command)? That would also deal with the issue of having to pass a handle around. The --of option is used in some other places, but that's mostly for binary output like flat that you never want to see on your screen.

Yes, this is a bug. I need to pipe through a handle everywhere so things go to the right place. Maybe yes we should just send everything to stdout by default. We also need better verbosity options so you can get just the bit you want...

kwxm · 2021-10-01T04:56:17Z

plutus-core/untyped-plutus-core/src/UntypedPlutusCore/Evaluation/Machine/Cek/Internal.hs

@@ -501,17 +503,17 @@ runCekM
    -> (forall s. GivenCekReqs uni fun s => CekM uni fun s a)
    -> (Either (CekEvaluationException uni fun) a, cost, [Text])
 runCekM (MachineParameters costs runtime) (ExBudgetMode getExBudgetInfo) (EmitterMode getEmitterMode) a = runST $ do
-    exBudgetMode <- getExBudgetInfo
-    emitter <- getEmitterMode
+    ExBudgetInfo{_exBudgetModeSpender, _exBudgetModeGetFinal, _exBudgetModeGetCumulative} <- getExBudgetInfo


Do we still want the underscores here?

It's ugly but effective and I don't feel like messing with it right now.

effectfully

Seems fine, I don't have any suggestions.

…t usage

… code

michaelpj · 2021-10-06T16:28:06Z

Pushed a couple more commits:

Emitting and parsing the logs as CSV lines instead, which gives us a much more consistent format.
Tidying up the executable in order to give it a --column argument that lets you select e.g. either the CPU or the memory column in the log output with budgets.

Putting this together, I just did something like:

cabal run uplc -- evaluate -i ../scripts-profiling/stablecoin_1-1.flat --if flat-deBruijn --trace-mode LogsWithBudgets -o logs-sc
cat logs-sc | cabal run -v0 logToStacks | flamegraph.pl > sc.svg

I can't quite make this one line because of the dodgy output processing by uplc... but I lack the will to wade back into that right now, and what I've got works okay.

The last thing I'd like to do is move the executable to plutus-core, since it doesn't depend on anything in plutus-tx-plugin any more, which I'll do in a separate commit.

kwxm · 2021-10-08T08:29:25Z

plutus-core/untyped-plutus-core/src/UntypedPlutusCore/Evaluation/Machine/Cek/EmitterMode.hs

+-- A wrapper around encoding a reocrd. `cassava` insists on including a trailing newline, which is
+-- annoying since we're recording the output line-by-line.
+encodeRecord :: CSV.ToRecord a => a -> T.Text
+encodeRecord a = T.stripEnd $ T.decodeUtf8 $ BSL.toStrict $ BS.toLazyByteString $ CSV.encodeRecord a


I had a quick look at the documentation to see why we have to go through so many types. It says that encodeRecord returns Data.Binary.Builder, but I think BS.toLazyByteString is expecting Data.ByteString.Builder. I assume these types are identical, but I couldn't quite see where that was happening. Anyway, should we be using Data.Binary.Builder.toLazyByteString instead?

binary re-exports the Builder type from bytestring. So yeah, they're the same. I don't think it's that weird to use the bytestring-exported versions of the fucntions...

kwxm · 2021-10-08T08:44:31Z

plutus-core/untyped-plutus-core/src/UntypedPlutusCore/Evaluation/Machine/Cek/EmitterMode.hs

            modifySTRef logsRef (`DList.snoc` withTime)
    pure $ CekEmitterInfo emitter (DList.toList <$> readSTRef logsRef)
+
+instance CSV.ToField ExCPU where
+    toField (ExCPU t) = CSV.toField $ toInteger t


It's kind of annoying that we don't have unExCPU for this. I've been having to put in lots of matches to extract the numbers recently.

michaelpj requested review from effectfully and thealmarty September 29, 2021 12:55

michaelpj commented Sep 29, 2021

View reviewed changes

michaelpj force-pushed the mpj/budget-profiling branch from ccee19c to f049275 Compare September 29, 2021 13:18

michaelpj force-pushed the mpj/budget-profiling branch 2 times, most recently from 4169278 to bcb87a7 Compare September 29, 2021 15:33

kwxm reviewed Oct 1, 2021

View reviewed changes

kwxm approved these changes Oct 1, 2021

View reviewed changes

effectfully approved these changes Oct 2, 2021

View reviewed changes

michaelpj added 10 commits October 6, 2021 11:48

Teach ExBudgetInfo to always be able to tell you the cumulative budge…

ed100a3

…t usage

Allow emitters to access the current budget, use it

e95484a

Teach uplc to print logs, refactor a bit

36072aa

Fix the profiling tests to have some examples of the actual generated…

0cb3d64

… code

Plugin: Don't dump to console as well as to file

3f17f96

Teach uplc to load named debruijn files also

2cb66e5

Some tidying

a13dc78

Fix plc

41826e1

Emit logs as CSV

750f971

Tidy up executable

02c82b4

michaelpj force-pushed the mpj/budget-profiling branch from bcb87a7 to 02c82b4 Compare October 6, 2021 16:24

michaelpj added 2 commits October 6, 2021 17:33

Move executable to plutus-core

027af64

Update materialized

1e30d88

michaelpj requested a review from kwxm October 6, 2021 16:49

kwxm approved these changes Oct 8, 2021

View reviewed changes

michaelpj merged commit 83992a5 into master Oct 11, 2021

kwxm deleted the mpj/budget-profiling branch February 2, 2022 08:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

SCP-2804: budget profiling #4024

SCP-2804: budget profiling #4024

michaelpj commented Sep 29, 2021

michaelpj Sep 29, 2021

michaelpj Sep 29, 2021

michaelpj commented Sep 29, 2021

michaelpj commented Sep 29, 2021

kwxm Oct 1, 2021

michaelpj Oct 6, 2021

kwxm left a comment

kwxm Oct 1, 2021

michaelpj Oct 6, 2021

kwxm Oct 1, 2021

michaelpj Oct 6, 2021

effectfully left a comment

michaelpj commented Oct 6, 2021

kwxm Oct 8, 2021

michaelpj Oct 8, 2021

kwxm Oct 8, 2021

		@@ -160,45 +165,44 @@ runApply (ApplyOptions inputfiles ifmt outp ofmt mode) = do
		---------------- Evaluation ----------------

		runEval :: EvalOptions -> IO ()

SCP-2804: budget profiling #4024

SCP-2804: budget profiling #4024

Conversation

michaelpj commented Sep 29, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michaelpj commented Sep 29, 2021

michaelpj commented Sep 29, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kwxm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

effectfully left a comment

Choose a reason for hiding this comment

michaelpj commented Oct 6, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment