diff --git a/.gitignore b/.gitignore index 2d9a5d76..b18058e0 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,5 @@ coverage.out .vscode .idea +*.swp +*.swo diff --git a/cmd/loadtest/app.go b/cmd/loadtest/app.go index b3e694c1..f6b8561e 100644 --- a/cmd/loadtest/app.go +++ b/cmd/loadtest/app.go @@ -15,6 +15,7 @@ import ( "github.com/rs/zerolog" "github.com/rs/zerolog/log" "github.com/spf13/cobra" + "golang.org/x/time/rate" ) type ( @@ -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 @@ -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, diff --git a/cmd/loadtest/loadtest.go b/cmd/loadtest/loadtest.go index 063c0894..106ea80d 100644 --- a/cmd/loadtest/loadtest.go +++ b/cmd/loadtest/loadtest.go @@ -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") @@ -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 @@ -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 @@ -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 { @@ -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 @@ -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 } @@ -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") @@ -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") @@ -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 @@ -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 { @@ -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 } diff --git a/cmd/loadtest/output.go b/cmd/loadtest/output.go index ce5d24e5..2a30ae02 100644 --- a/cmd/loadtest/output.go +++ b/cmd/loadtest/output.go @@ -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 } @@ -396,8 +397,8 @@ 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 { @@ -405,7 +406,7 @@ func isEmptyJSONResponse(r *json.RawMessage) bool { 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 @@ -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 @@ -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") }