simulation: Add benchmarking #2187

ValarDragon · 2018-08-30T06:06:41Z

This PR adds simulation to benchmarking. It is slightly suboptimal of an implementation, as it involves alot of code duplication. However we do want to avoid invariant checking or logging (as logs are significant time increase), amongst other things. I think including this as a separate function is preferable to a single mega function. Once we implement something like an "OperationContext" I will combine these two functions more. (That will make it easier to do cleanly)

Doing this without code duplication was super easy, not sure what I was thinking when I wrote the above.

Sample benchmark output:

/usr/local/go/bin/go test -benchmem -run=^$ github.com/cosmos/cosmos-sdk/cmd/gaia/app -bench ^BenchmarkFullGaiaSimulation$ -cpuprofile cpu.out
Event statistics: 
                                  bank/sendAndVerifyMsgSend/ok => 35
                                     beginblock/signing/missed => 176
                                     beginblock/signing/signed => 905
                               endblock/validatorupdates/added => 77
                             endblock/validatorupdates/updated => 10
                                          gov/MsgDeposit/false => 32
                                           gov/MsgDeposit/true => 7
                                    gov/MsgSubmitProposal/true => 34
                                             gov/MsgVote/false => 29
                                              gov/MsgVote/true => 9
                                      slashing/MsgUnjail/false => 42
                                stake/MsgBeginRedelegate/false => 42
                                 stake/MsgBeginUnbonding/false => 35
                             stake/MsgCompleteRedelegate/false => 35
                              stake/MsgCompleteUnbonding/false => 41
                                stake/MsgCreateValidator/false => 9
                                 stake/MsgCreateValidator/true => 27
                                       stake/MsgDelegate/false => 24
                                        stake/MsgDelegate/true => 10
                                  stake/MsgEditValidator/false => 24
                                   stake/MsgEditValidator/true => 11
Benchmark simulation ran 453 operations
goos: linux
goarch: amd64
pkg: github.com/cosmos/cosmos-sdk/cmd/gaia/app
BenchmarkFullGaiaSimulation-8   	       1	6665959645 ns/op	732741160 B/op	19666343 allocs/op
PASS
ok  	github.com/cosmos/cosmos-sdk/cmd/gaia/app	6.945s

Running this through a profiler, we see that amino unmarshalling takes 75% of the time!!! We should consider using protobuf where applicable, as their implementation has been optimized to enable inlining. (They've fought the golang compiler)

In the process I discovered our current "test validator existswhen deleting it" is broken. I will open a seperate PR to demonstrate that, this PR should be good merge.

Targeted PR against correct branch (see CONTRIBUTING.md)
Wrote tests
Added entries in PENDING.md with issue #
rereviewed Files changed in the github PR explorer

For Admin Use:

Added appropriate labels to PR (ex. wip, ready-for-review, docs)
Reviewers Assigned
Squashed all commits, uses message "Merge pull request #XYZ: [title]" (coding standards)

codecov · 2018-08-30T06:10:43Z

Codecov Report

❗ No coverage uploaded for pull request base (develop@d214952). Click here to learn what that means.
The diff coverage is 75%.

@@            Coverage Diff            @@
##             develop   #2187   +/-   ##
=========================================
  Coverage           ?   64.2%           
=========================================
  Files              ?     140           
  Lines              ?    8579           
  Branches           ?       0           
=========================================
  Hits               ?    5508           
  Misses             ?    2694           
  Partials           ?     377

ValarDragon · 2018-08-30T07:11:49Z

Interestingly, tx processing is only 2% of the entire time here. (No IAVL writes, no signature verification), the rest of the time is just slashing logic in EndBlock, and most of the hold up is in amino unmarshalling. (This translates to about 5.25 out of 7 seconds spent on amino unmarshalling, with only 453 msgs, and 10 blocks. This is a lot of time spent on unmarshalling)

I highly recommend looking through a profilers view of this.

/usr/local/go/bin/go test -benchmem -run=^$ github.com/cosmos/cosmos-sdk/cmd/gaia/app -bench ^BenchmarkFullGaiaSimulation$ -cpuprofile cpu.out -memprofile mem.out
go tool pprof cpu.out
web
go tool pprof mem.out
web

ValarDragon · 2018-08-30T07:14:56Z

x/gov/simulation/msgs.go

 		ctx, write := ctx.CacheContext()
-		result := gov.NewHandler(k)(ctx, msg)
+		result := handler(ctx, msg)


I switched from creating a new handler on each message, just to help avoid skewing memory write stats.

melekes · 2018-08-30T12:40:16Z

x/mock/simulation/random_simulate_blocks.go

 	DisplayEvents(events)
 }

+func updateLog(testingmode bool, log string, update string, args ...interface{}) (updatedLog string) {
+	if testingmode == true {


== true can be dropped

ValarDragon · 2018-08-30T18:49:11Z

Use

/usr/local/go/bin/go test -benchmem -run=^$ github.com/cosmos/cosmos-sdk/cmd/gaia/app -bench ^BenchmarkFullGaiaSimulation$ -SimulationGoLevelDB=true -SimulationCommit=true -cpuprofile cpu.out

to profile with GoLevelDB and commits. Even with both of these, amino dominates the runtime. (65%!!) Note that most of these calls are in keeper.UpdateValidator, perhaps we can reduce the number of state reads there.

ValarDragon · 2018-08-30T21:00:55Z

Also I just want to note, that the time signature verification is going to add is neglible. It will add .5ms per operation, which translates to 25ms, which is nothing compared to the time spent in amino.

ValarDragon · 2018-08-31T06:44:01Z

I looked into this a bit more, alot of the problem is that in the simple 10 block example we have, there are 2258 calls to the governance slash function. We should optimize the usage of governance slashing, and the slash functions amino calls. Alternatively we could just cache the keeper.GetValidator calls.

We also should prioritize getting future ops implemented so we can have voting proceed properly.

However I am slightly suspicious about the governance req'd number of blocks. The proposals should be lasting longer than this.

For referrence though, there were 160876 calls to the keeper.GetValidator function (not even keeper.GetValidatorByPubkey)

cwgoes

This could be better separated, but since it's not modifying the state machine it's a bit less critical. See comments.

cwgoes · 2018-08-31T13:14:04Z

cmd/gaia/app/sim_test.go

+	blockSize    int
+	enabled      bool
+	verbose      bool
+	usegoleveldb bool


camelCase please

cwgoes · 2018-08-31T13:15:02Z

cmd/gaia/app/sim_test.go

@@ -36,6 +39,8 @@ func init() {
 	flag.IntVar(&blockSize, "SimulationBlockSize", 200, "Operations per block")
 	flag.BoolVar(&enabled, "SimulationEnabled", false, "Enable the simulation")
 	flag.BoolVar(&verbose, "SimulationVerbose", false, "Verbose log output")
+	flag.BoolVar(&usegoleveldb, "SimulationGoLevelDB", false, "Use GoLevelDB instead of memdb")


Can we just always do this with the benchmark? Looks like this flag doesn't apply to non-benchmarking simulation anyways

cwgoes · 2018-08-31T13:15:18Z

x/gov/simulation/msgs.go

 		ctx, write := ctx.CacheContext()
-		result := gov.NewHandler(k)(ctx, msg)
+		result := handler(ctx, msg)


cwgoes · 2018-08-31T13:16:10Z

x/mock/simulation/random_simulate_blocks.go

-
-		// Log the header time for future lookup
-		pastTimes = append(pastTimes, header.Time)
+	if !testingmode {


cwgoes · 2018-08-31T13:17:56Z

x/mock/simulation/random_simulate_blocks.go

 	evidence := make([]abci.Evidence, 0)
 	for r.Float64() < evidenceFraction {
 		height := header.Height
 		time := header.Time
 		if r.Float64() < pastEvidenceFraction {
 			height = int64(r.Intn(int(header.Height)))
-			time = pastTimes[height]
+			time = lastHeaderTime


Can you explain this change? Isn't this supposed to be the timestamp when the infraction was committed (which was the previous header)?

your right, my bad. I misread height as header.Height, not sure how I missed the random.

ValarDragon · 2018-08-31T15:31:15Z

I actually think we should consider removing gocyclo. I think it does more harm then good. To fix gocyclo errors, I had to refactor some of the code, which made this PR hard to review unless you were going commit by commit.

In simulation, this was shown to cause a 4x speedup. There are no safety concerns here, as amino encoding is deterministic.

ValarDragon · 2018-09-01T20:14:53Z

After properly initializing governance proposal time (Thanks Sunny!) the simulator can quickly get to much larger block sizes. (Currently set to 210 blocks, this has 10 blocks of governance slashing)

This now shows that GetValidator, and the way we do sorting in the iterators are bottlenecks. The PR for GetValidator still eliminates that part of the time, which is quite significant. Jae and I discussed a bit about what the cause of the iterator being slow is, and how to speed it up, I'll write that up into another issue. (However we could make that postlaunch, as its probably not going to be a simple change like the get validator change was)

Improve GetValidator speed

simulation: display db size at end of simulation, add makefile entries

cwgoes

utACK

simulation: Add benchmarking

46bbada

ValarDragon added ready-for-review labels Aug 30, 2018

ValarDragon assigned cwgoes Aug 30, 2018

ValarDragon requested a review from cwgoes August 30, 2018 06:06

ValarDragon requested review from ebuchman and rigelrozanski as code owners August 30, 2018 06:06

Update PENDING

31ca2e0

ValarDragon commented Aug 30, 2018

View reviewed changes

ValarDragon added 2 commits August 30, 2018 00:28

Remove code duplication

03d2f73

minor cleanup

b3d08bc

melekes reviewed Aug 30, 2018

View reviewed changes

ValarDragon added 3 commits August 30, 2018 09:32

Address Anton's comment

d1a5808

Fix cyclomatic complexity, add ability to use GoLevelDB

4be6907

Add method to benchmark with commits

a69725d

cwgoes mentioned this pull request Aug 30, 2018

Cache the decoded structs instead of the encoded bytes #2194

Closed

cleanup goleveldb dirs

e64c6da

cwgoes reviewed Aug 31, 2018

View reviewed changes

ValarDragon and others added 3 commits August 31, 2018 21:57

simulation: Initialize governance properly

7502572

Address @cwgoes comments

3c21007

Merge branch 'develop' into dev/benchmark_simulation

5643c08

ValarDragon force-pushed the dev/benchmark_simulation branch from a43a7f8 to 5643c08 Compare September 1, 2018 19:38

ValarDragon mentioned this pull request Sep 1, 2018

Remove gocyclo #2211

Closed

4 tasks

Improve GetValidator speed

a991a2e

In simulation, this was shown to cause a 4x speedup. There are no safety concerns here, as amino encoding is deterministic.

fix lint

3b4caa5

ValarDragon and others added 2 commits September 1, 2018 13:21

Add comments

f29fdca

Merge branch 'develop' into dev/benchmark_simulation

311c5f8

ValarDragon mentioned this pull request Sep 2, 2018

simulation: display db size at end of simulation, add makefile entries #2214

Merged

4 tasks

ValarDragon and others added 4 commits September 1, 2018 19:09

simulation: display db size at end of simulation, add makefile entries

8a452b9

extra comment on cache key usage

2c66ba0

Merge pull request #2200 from cosmos/dev/GetValidator_speed_improvement

a4f36aa

Improve GetValidator speed

Merge pull request #2214 from cosmos/dev/display_db_info

e1ce5d4

simulation: display db size at end of simulation, add makefile entries

cwgoes approved these changes Sep 3, 2018

View reviewed changes

cwgoes merged commit 7f1b06a into develop Sep 3, 2018

ValarDragon deleted the dev/benchmark_simulation branch September 4, 2018 04:46

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

simulation: Add benchmarking #2187

simulation: Add benchmarking #2187

ValarDragon commented Aug 30, 2018 •

edited

Loading

codecov bot commented Aug 30, 2018 •

edited

Loading

ValarDragon commented Aug 30, 2018 •

edited

Loading

ValarDragon Aug 30, 2018 •

edited

Loading

cwgoes Aug 31, 2018

melekes Aug 30, 2018

ValarDragon commented Aug 30, 2018

ValarDragon commented Aug 30, 2018 •

edited

Loading

ValarDragon commented Aug 31, 2018 •

edited

Loading

cwgoes left a comment

cwgoes Aug 31, 2018

cwgoes Aug 31, 2018

ValarDragon Sep 1, 2018

cwgoes Aug 31, 2018

cwgoes Aug 31, 2018

cwgoes Aug 31, 2018

ValarDragon Aug 31, 2018

ValarDragon commented Aug 31, 2018

ValarDragon commented Sep 1, 2018 •

edited

Loading

cwgoes left a comment

simulation: Add benchmarking #2187

simulation: Add benchmarking #2187

Conversation

ValarDragon commented Aug 30, 2018 • edited Loading

codecov bot commented Aug 30, 2018 • edited Loading

Codecov Report

ValarDragon commented Aug 30, 2018 • edited Loading

ValarDragon Aug 30, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ValarDragon commented Aug 30, 2018

ValarDragon commented Aug 30, 2018 • edited Loading

ValarDragon commented Aug 31, 2018 • edited Loading

cwgoes 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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ValarDragon commented Aug 31, 2018

ValarDragon commented Sep 1, 2018 • edited Loading

cwgoes left a comment

Choose a reason for hiding this comment

ValarDragon commented Aug 30, 2018 •

edited

Loading

codecov bot commented Aug 30, 2018 •

edited

Loading

ValarDragon commented Aug 30, 2018 •

edited

Loading

ValarDragon Aug 30, 2018 •

edited

Loading

ValarDragon commented Aug 30, 2018 •

edited

Loading

ValarDragon commented Aug 31, 2018 •

edited

Loading

ValarDragon commented Sep 1, 2018 •

edited

Loading