Skip to content

Commit

Permalink
Feat: loadtest improvements (#135)
Browse files Browse the repository at this point in the history 
* feat: latency distribution chart

* feat: static bucket width

* docs: loadtest usage

* feat: some refactor to make time-limit report output

- removed bucketed time distribution because time to mine is kinda janky (weird loadtest system clock time - miner system clock time bug)
- time-limit includes report outputs

* lint: remove unused var

* lint: cleanup variable shadowing

* log: start and end nonce

* feat: init current nonce before loadtest

* feat: wait until successful block mining finish

* log: oops wrong var

* feat: correct tps output

* lint: remove printResults
  • Loading branch information
@IdrisHanafi
IdrisHanafi authored Oct 20, 2023
1 parent 3f5f77f commit 81c2bf9
Show file tree
Hide file tree
Showing 4 changed files with 97 additions and 71 deletions.
2 changes: 2 additions & 0 deletions .gitignore
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,3 +4,5 @@ coverage.out

.vscode
.idea
*.swp
*.swo
9 changes: 8 additions & 1 deletion cmd/loadtest/app.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ import (
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
"github.com/spf13/cobra"
"golang.org/x/time/rate"
)

type (
Expand All @@ -29,7 +30,7 @@ type (
GoRoutineID int64
RequestID int64
RequestTime time.Time
WaitTime time.Duration
WaitTime time.Duration // Wait time for transaction to be broadcasted
Receipt string
IsError bool
Nonce uint64
Expand Down Expand Up @@ -96,6 +97,12 @@ var (
inputLoadTestParams loadTestParams
loadTestResults []loadTestSample
loadTestResutsMutex sync.RWMutex
startBlockNumber uint64
finalBlockNumber uint64
startNonce uint64
currentNonce uint64
currentNonceMutex sync.RWMutex
rl *rate.Limiter

hexwords = []byte{
0x00, 0x0F, 0xF1, 0xCE,
Expand Down
110 changes: 71 additions & 39 deletions cmd/loadtest/loadtest.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -283,6 +283,49 @@ func hexToBigInt(raw any) (bi *big.Int, err error) {
return
}

func initNonce(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client) error {
var err error
startBlockNumber, err = c.BlockNumber(ctx)
if err != nil {
log.Error().Err(err).Msg("Failed to get current block number")
return err
}

currentNonce, err = c.NonceAt(ctx, *inputLoadTestParams.FromETHAddress, new(big.Int).SetUint64(startBlockNumber))
startNonce = currentNonce

if err != nil {
log.Error().Err(err).Msg("Unable to get account nonce")
return err
}

return nil
}

func completeLoadTest(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client) error {
log.Debug().Uint64("startNonce", startNonce).Uint64("lastNonce", currentNonce).Msg("Finished main load test loop")
log.Debug().Msg("Waiting for remaining transactions to be completed and mined")

var err error
finalBlockNumber, err = waitForFinalBlock(ctx, c, rpc, startBlockNumber, startNonce, currentNonce)
if err != nil {
log.Error().Err(err).Msg("there was an issue waiting for all transactions to be mined")
}
endTime := time.Now()
startTime := loadTestResults[0].RequestTime
log.Debug().Uint64("currentNonce", currentNonce).Uint64("final block number", finalBlockNumber).Msg("got final block number")

if *inputLoadTestParams.ShouldProduceSummary {
err = summarizeTransactions(ctx, c, rpc, startBlockNumber, startNonce, finalBlockNumber, currentNonce)
if err != nil {
log.Error().Err(err).Msg("There was an issue creating the load test summary")
}
}
lightSummary(loadTestResults, startTime, endTime, rl)

return nil
}

func runLoadTest(ctx context.Context) error {
log.Info().Msg("Starting Load Test")

Expand Down Expand Up @@ -331,7 +374,10 @@ func runLoadTest(ctx context.Context) error {
}
}

printResults(loadTestResults)
err = completeLoadTest(ctx, ec, rpc)
if err != nil {
log.Error().Err(err).Msg("Encountered error while wrapping up loadtest")
}

log.Info().Msg("Finished")
return nil
Expand Down Expand Up @@ -376,7 +422,6 @@ func mainLoop(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client) erro
mode := ltp.Mode
steadyStateTxPoolSize := *ltp.SteadyStateTxPoolSize
adaptiveRateLimitIncrement := *ltp.AdaptiveRateLimitIncrement
var rl *rate.Limiter
rl = rate.NewLimiter(rate.Limit(*ltp.RateLimit), 1)
if *ltp.RateLimit <= 0.0 {
rl = nil
Expand Down Expand Up @@ -460,21 +505,11 @@ func mainLoop(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client) erro
Msg("retrieved recent indexed activity")
}

var currentNonceMutex sync.Mutex
var i int64
startBlockNumber, err := c.BlockNumber(ctx)
err = initNonce(ctx, c, rpc)
if err != nil {
log.Error().Err(err).Msg("Failed to get current block number")
return err
}

currentNonce, err := c.NonceAt(ctx, *ltp.FromETHAddress, new(big.Int).SetUint64(startBlockNumber))
if err != nil {
log.Error().Err(err).Msg("Unable to get account nonce")
return err
}

startNonce := currentNonce
log.Debug().Uint64("currentNonce", currentNonce).Msg("Starting main load test loop")
var wg sync.WaitGroup
for i = 0; i < routines; i = i + 1 {
Expand Down Expand Up @@ -542,7 +577,7 @@ func mainLoop(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client) erro
}
recordSample(i, j, tErr, startReq, endReq, myNonceValue)
if tErr != nil {
log.Error().Err(tErr).Uint64("nonce", myNonceValue).Msg("Recorded an error while sending transactions")
log.Error().Err(tErr).Uint64("nonce", myNonceValue).Int64("request time", endReq.Sub(startReq).Milliseconds()).Msg("Recorded an error while sending transactions")
// The nonce is used to index the recalled transactions in call-only mode. We don't want to retry a transaction if it legit failed on the chain
if !*ltp.CallOnly {
retryForNonce = true
Expand All @@ -566,23 +601,10 @@ func mainLoop(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client) erro
log.Trace().Msg("Finished starting go routines. Waiting..")
wg.Wait()
cancel()
log.Debug().Uint64("currentNonce", currentNonce).Msg("Finished main load test loop")
log.Debug().Msg("Waiting for transactions to actually be mined")
if *ltp.CallOnly {
return nil
}
finalBlockNumber, err := waitForFinalBlock(ctx, c, rpc, startBlockNumber, startNonce, currentNonce)
if err != nil {
log.Error().Err(err).Msg("there was an issue waiting for all transactions to be mined")
}

lightSummary(ctx, c, rpc, startBlockNumber, startNonce, finalBlockNumber, currentNonce, rl)
if *ltp.ShouldProduceSummary {
err = summarizeTransactions(ctx, c, rpc, startBlockNumber, startNonce, finalBlockNumber, currentNonce)
if err != nil {
log.Error().Err(err).Msg("There was an issue creating the load test summary")
}
}
return nil
}

Expand Down Expand Up @@ -703,13 +725,13 @@ func blockUntilSuccessful(ctx context.Context, c *ethclient.Client, f func() err
numberOfBlocksToWaitFor := *inputLoadTestParams.ContractCallNumberOfBlocksToWaitFor
blockInterval := *inputLoadTestParams.ContractCallBlockInterval
start := time.Now()
startBlockNumber, err := c.BlockNumber(ctx)
currStartBlockNumber, err := c.BlockNumber(ctx)
if err != nil {
log.Error().Err(err).Msg("Error getting block number")
return err
}
log.Trace().
Uint64("startBlockNumber", startBlockNumber).
Uint64("currStartBlockNumber", currStartBlockNumber).
Uint64("numberOfBlocksToWaitFor", numberOfBlocksToWaitFor).
Uint64("blockInterval", blockInterval).
Msg("Starting blocking loop")
Expand All @@ -722,10 +744,10 @@ func blockUntilSuccessful(ctx context.Context, c *ethclient.Client, f func() err
default:
elapsed := time.Since(start)
var blockDiff uint64
if startBlockNumber == 0 {
blockDiff = startBlockNumber
if currStartBlockNumber == 0 {
blockDiff = currStartBlockNumber
} else {
blockDiff = currentBlockNumber % startBlockNumber
blockDiff = currentBlockNumber % currStartBlockNumber
}
if blockDiff > numberOfBlocksToWaitFor {
log.Error().Err(err).Dur("elapsedTimeSeconds", elapsed).Msg("Exhausted waiting period")
Expand Down Expand Up @@ -845,6 +867,12 @@ func getSuggestedGasPrices(ctx context.Context, c *ethclient.Client) (*big.Int,
}
gp, pErr := c.SuggestGasPrice(ctx)
gt, tErr := c.SuggestGasTipCap(ctx)

// In the case of an EVM compatible system not supporting EIP-1559
if *inputLoadTestParams.LegacyTransactionMode {
gt = big.NewInt(0)
}

if pErr == nil && (tErr == nil || !isDynamic) {
cachedBlockNumber = bn
cachedGasPrice = gp
Expand Down Expand Up @@ -1326,22 +1354,26 @@ func waitForFinalBlock(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Cli
ltp := inputLoadTestParams
var err error
var lastBlockNumber uint64
var currentNonce uint64
var initialWaitCount = 50
var prevNonceForFinalBlock uint64
var currentNonceForFinalBlock uint64
var initialWaitCount = 20
var maxWaitCount = initialWaitCount
for {
lastBlockNumber, err = c.BlockNumber(ctx)
if err != nil {
return 0, err
}
currentNonce, err = c.NonceAt(ctx, *ltp.FromETHAddress, new(big.Int).SetUint64(lastBlockNumber))
currentNonceForFinalBlock, err = c.NonceAt(ctx, *ltp.FromETHAddress, new(big.Int).SetUint64(lastBlockNumber))
if err != nil {
return 0, err
}
if currentNonce < endNonce && maxWaitCount > 0 {
log.Trace().Uint64("endNonce", endNonce).Uint64("currentNonce", currentNonce).Msg("Not all transactions have been mined. Waiting")
if currentNonceForFinalBlock < endNonce && maxWaitCount > 0 {
log.Trace().Uint64("endNonce", endNonce).Uint64("currentNonceForFinalBlock", currentNonceForFinalBlock).Uint64("prevNonceForFinalBlock", prevNonceForFinalBlock).Msg("Not all transactions have been mined. Waiting")
time.Sleep(5 * time.Second)
maxWaitCount = maxWaitCount - 1
if currentNonceForFinalBlock == prevNonceForFinalBlock {
maxWaitCount = maxWaitCount - 1 // only decrement if currentNonceForFinalBlock doesn't progress
}
prevNonceForFinalBlock = currentNonceForFinalBlock
continue
}
if maxWaitCount <= 0 {
Expand All @@ -1350,7 +1382,7 @@ func waitForFinalBlock(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Cli
break
}

log.Trace().Uint64("currentNonce", currentNonce).Uint64("startblock", startBlockNumber).Uint64("endblock", lastBlockNumber).Msg("It looks like all transactions have been mined")
log.Trace().Uint64("currentNonceForFinalBlock", currentNonceForFinalBlock).Uint64("startblock", startBlockNumber).Uint64("endblock", lastBlockNumber).Msg("It looks like all transactions have been mined")
return lastBlockNumber, nil
}

Expand Down
47 changes: 16 additions & 31 deletions cmd/loadtest/output.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -377,6 +377,7 @@ func summarizeTransactions(ctx context.Context, c *ethclient.Client, rpc *ethrpc
log.Debug().Float64("txHours", txLatency.Hours()).Uint64("nonce", tx.Nonce.ToUint64()).Uint64("blockNumber", bs.Block.Number.ToUint64()).Time("mineTime", mineTime).Time("requestTime", requestTime).Msg("Encountered transaction with more than 2 hours latency")
}
bs.Latencies[tx.Nonce.ToUint64()] = txLatency

if txLatency < minLatency {
minLatency = txLatency
}
Expand All @@ -396,16 +397,16 @@ func summarizeTransactions(ctx context.Context, c *ethclient.Client, rpc *ethrpc
printBlockSummary(c, blockData, startNonce, endNonce)

log.Trace().Str("summaryTime", (endReceipt.Sub(startReceipt)).String()).Msg("Total Summary Time")
return nil

return nil
}

func isEmptyJSONResponse(r *json.RawMessage) bool {
rawJson := []byte(*r)
return len(rawJson) == 0
}

func printResults(lts []loadTestSample) {
func lightSummary(lts []loadTestSample, startTime, endTime time.Time, rl *rate.Limiter) {
if len(lts) == 0 {
log.Error().Msg("No results recorded")
return
Expand All @@ -414,8 +415,6 @@ func printResults(lts []loadTestSample) {
log.Info().Msg("* Results")
log.Info().Int("samples", len(lts)).Msg("Samples")

var startTime = lts[0].RequestTime
var endTime = lts[len(lts)-1].RequestTime
var meanWait float64
var totalWait float64 = 0
var numErrors uint64 = 0
Expand All @@ -428,35 +427,21 @@ func printResults(lts []loadTestSample) {
}
meanWait = totalWait / float64(len(lts))

log.Info().Time("startTime", startTime).Msg("Start")
log.Info().Time("endTime", endTime).Msg("End")
log.Info().Float64("meanWait", meanWait).Msg("Mean Wait")
log.Info().Uint64("numErrors", numErrors).Msg("Num errors")
}

func lightSummary(ctx context.Context, c *ethclient.Client, rpc *ethrpc.Client, startBlockNumber, startNonce, endBlockNumber, endNonce uint64, rl *rate.Limiter) {
startBlock, err := c.BlockByNumber(ctx, new(big.Int).SetUint64(startBlockNumber))
if err != nil {
log.Error().Err(err).Msg("unable to get start block for light summary")
return
}
endBlock, err := c.BlockByNumber(ctx, new(big.Int).SetUint64(endBlockNumber))
if err != nil {
log.Error().Err(err).Msg("unable to get end block for light summary")
return
}
endTime := time.Unix(int64(endBlock.Time()), 0)
startTime := time.Unix(int64(startBlock.Time()), 0)

testDuration := endTime.Sub(startTime)
tps := float64(len(loadTestResults)) / testDuration.Seconds()

var rlLimit float64
if rl != nil {
rlLimit = float64(rl.Limit())
}

log.Info().Time("startTime", startTime).Msg("Start time of loadtest (first transaction sent)")
log.Info().Time("endTime", endTime).Msg("End time of loadtest (final transaction mined)")
log.Info().Float64("tps", tps).Msg("Estimated tps")
log.Info().Float64("meanWait between sending transactions", meanWait).Msg("Mean Wait")
log.Info().
Time("firstBlockTime", startTime).
Time("lastBlockTime", endTime).
Int("transactionCount", len(loadTestResults)).
Float64("testDuration", testDuration.Seconds()).
Float64("tps", tps).
Float64("final rate limit", float64(rl.Limit())).
Msg("rough test summary (ignores errors)")
Float64("testDuration (seconds)", testDuration.Seconds()).
Float64("final rate limit", rlLimit).
Msg("rough test summary")
log.Info().Uint64("numErrors", numErrors).Msg("Num errors")
}

0 comments on commit 81c2bf9

Please sign in to comment.